Skip to content

progress bar desync #1967

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
mathstuf opened this issue Aug 15, 2019 · 10 comments
Closed

progress bar desync #1967

mathstuf opened this issue Aug 15, 2019 · 10 comments
Labels

Comments

@mathstuf
Copy link

Problem

This is more an observation than a detailed issue report. I'd treat it as a BOLO for some underlying problem.

During an update, it seems that a component (clippy) update came in during a progress update. The next line had a really weird progress status at that point:

173.2 MiB / 173.2 MiB (100 %)  24.2 MiB/s in  7s ETA:  0s
info: installing component 'cargo'
info: installing component 'rust-docs'
  8.5 MiB /  11.7 MiB ( 73 %)   5.4 MiB/s in  2s ETA:  0sinfo: installing component 'clippy'
 13.5 MiB /   1.8 MiB (752 %)   4.2 MiB/s in  2s ETA: 49710d  6h 28m 14s

The progress report is just internally inconsistent. This, to me, indicates some kind of race, underflow and/or I/O locking bug lurking around.

Full command output
% rustup update
info: syncing channel updates for 'stable-x86_64-unknown-linux-gnu'
info: latest update on 2019-08-15, rust version 1.37.0 (eae3437df 2019-08-13)
info: downloading component 'rustc'
 85.3 MiB /  85.3 MiB (100 %)   9.1 MiB/s in  9s ETA:  0s
info: downloading component 'rust-std'
 61.2 MiB /  61.2 MiB (100 %)   9.3 MiB/s in  7s ETA:  0s
info: downloading component 'cargo'
info: downloading component 'rust-docs'
 11.3 MiB /  11.3 MiB (100 %)   9.1 MiB/s in  1s ETA:  0s
info: downloading component 'clippy'
info: downloading component 'rustfmt'
info: removing component 'rustc'
info: removing component 'rust-std'
info: removing component 'cargo'
info: removing component 'rust-docs'
info: removing component 'clippy'
info: removing component 'rustfmt'
info: installing component 'rustc'
 85.3 MiB /  85.3 MiB (100 %)  11.8 MiB/s in  7s ETA:  0s
info: installing component 'rust-std'
 61.2 MiB /  61.2 MiB (100 %)  14.2 MiB/s in  4s ETA:  0s
info: installing component 'cargo'
info: installing component 'rust-docs'
 11.3 MiB /  11.3 MiB (100 %)   3.3 MiB/s in  3s ETA:  0s
info: installing component 'clippy'
info: installing component 'rustfmt'
info: syncing channel updates for 'beta-x86_64-unknown-linux-gnu'
info: latest update on 2019-08-13, rust version 1.38.0-beta.1 (e450539c2 2019-08-13)
info: downloading component 'rustc'
 66.1 MiB /  66.1 MiB (100 %)   9.9 MiB/s in  6s ETA:  0s
info: downloading component 'rust-std'
173.2 MiB / 173.2 MiB (100 %)   9.8 MiB/s in 18s ETA:  0s
info: downloading component 'cargo'
info: downloading component 'rust-docs'
 11.7 MiB /  11.7 MiB (100 %)  10.3 MiB/s in  1s ETA:  0s
info: downloading component 'clippy'
info: downloading component 'rustfmt'
info: removing component 'rustc'
info: removing component 'rust-std'
info: removing component 'cargo'
info: removing component 'rust-docs'
info: removing component 'clippy'
info: removing component 'rustfmt'
info: installing component 'rustc'
 66.1 MiB /  66.1 MiB (100 %)  10.9 MiB/s in  6s ETA:  0s
info: installing component 'rust-std'
173.2 MiB / 173.2 MiB (100 %)  24.2 MiB/s in  7s ETA:  0s
info: installing component 'cargo'
info: installing component 'rust-docs'
  8.5 MiB /  11.7 MiB ( 73 %)   5.4 MiB/s in  2s ETA:  0sinfo: installing component 'clippy'
 13.5 MiB /   1.8 MiB (752 %)   4.2 MiB/s in  2s ETA: 49710d  6h 28m 14s
info: installing component 'rustfmt'
info: syncing channel updates for 'nightly-x86_64-unknown-linux-gnu'
info: latest update on 2019-08-15, rust version 1.38.0-nightly (c43d03a19 2019-08-14)
info: downloading component 'rustc'
 66.0 MiB /  66.0 MiB (100 %)  10.3 MiB/s in  6s ETA:  0s
info: downloading component 'rust-std'
173.1 MiB / 173.1 MiB (100 %)   8.9 MiB/s in 18s ETA:  0s
info: downloading component 'cargo'
info: downloading component 'rust-docs'
 11.7 MiB /  11.7 MiB (100 %)   9.6 MiB/s in  1s ETA:  0s
info: downloading component 'clippy'
info: downloading component 'rustfmt'
info: removing component 'rustc'
info: removing component 'rust-std'
info: removing component 'cargo'
info: removing component 'rust-docs'
info: removing component 'clippy'
info: removing component 'rustfmt'
info: installing component 'rustc'
 66.0 MiB /  66.0 MiB (100 %)  10.8 MiB/s in  6s ETA:  0s
info: installing component 'rust-std'
173.1 MiB / 173.1 MiB (100 %)  22.0 MiB/s in  7s ETA:  0s
info: installing component 'cargo'
info: installing component 'rust-docs'
 11.7 MiB /  11.7 MiB (100 %)   4.2 MiB/s in  2s ETA:  0s
info: installing component 'clippy'
info: installing component 'rustfmt'
info: checking for self-updates

stable-x86_64-unknown-linux-gnu updated - rustc 1.37.0 (eae3437df 2019-08-13)
beta-x86_64-unknown-linux-gnu updated - rustc 1.38.0-beta.1 (e450539c2 2019-08-13)
nightly-x86_64-unknown-linux-gnu updated - rustc 1.38.0-nightly (c43d03a19 2019-08-14)

Steps

  1. Install the 1.37.0 toolchain
  2. rustup update Maybe something else is involved here?

Possible Solution(s)

Something is allowing interleaved output and the progress bar seems to get confused at that point (assuming causation from correlation here).

Notes

Output of rustup --version: rustup 1.18.3 (435397f 2019-05-22)
Output of rustup show:

Default host: x86_64-unknown-linux-gnu

installed toolchains
--------------------

stable-x86_64-unknown-linux-gnu
beta-x86_64-unknown-linux-gnu
nightly-x86_64-unknown-linux-gnu
1.20.0-x86_64-unknown-linux-gnu
1.21.0-x86_64-unknown-linux-gnu
1.22.1-x86_64-unknown-linux-gnu
1.23.0-x86_64-unknown-linux-gnu
1.24.1-x86_64-unknown-linux-gnu
1.25.0-x86_64-unknown-linux-gnu
1.26.2-x86_64-unknown-linux-gnu
1.27.2-x86_64-unknown-linux-gnu
1.28.0-x86_64-unknown-linux-gnu
1.29.2-x86_64-unknown-linux-gnu
1.30.1-x86_64-unknown-linux-gnu
1.31.1-x86_64-unknown-linux-gnu
1.32.0-x86_64-unknown-linux-gnu
1.33.0-x86_64-unknown-linux-gnu
1.34.2-x86_64-unknown-linux-gnu
1.35.0-x86_64-unknown-linux-gnu
1.36.0-x86_64-unknown-linux-gnu
1.37.0-x86_64-unknown-linux-gnu

active toolchain
----------------

stable-x86_64-unknown-linux-gnu (default)
rustc 1.37.0 (eae3437df 2019-08-13)

@mathstuf mathstuf added the bug label Aug 15, 2019
@srinivasreddy
Copy link
Contributor

I think something else involved here than rustup install 1.37.0 && rustup update,
Console output on my system.

info: syncing channel updates for '1.37.0-x86_64-apple-darwin'
info: latest update on 2019-08-15, rust version 1.37.0 (eae3437df 2019-08-13)
info: downloading component 'rustc'
 78.7 MiB /  78.7 MiB (100 %)   5.7 MiB/s in 17s ETA:  0s
info: downloading component 'rust-std'
 56.3 MiB /  56.3 MiB (100 %)   5.9 MiB/s in 13s ETA:  0s
info: downloading component 'cargo'
info: downloading component 'rust-docs'
 11.3 MiB /  11.3 MiB (100 %)   5.5 MiB/s in  2s ETA:  0s
info: installing component 'rustc'
 78.7 MiB /  78.7 MiB (100 %)  16.7 MiB/s in  4s ETA:  0s
info: installing component 'rust-std'
 56.3 MiB /  56.3 MiB (100 %)  19.6 MiB/s in  2s ETA:  0s
info: installing component 'cargo'
info: installing component 'rust-docs'
 11.3 MiB /  11.3 MiB (100 %)   2.7 MiB/s in  3s ETA:  0s

  1.37.0-x86_64-apple-darwin installed - rustc 1.37.0 (eae3437df 2019-08-13)

info: checking for self-updates
(casper) ➜  redblack git:(master) ✗ rustup update
info: syncing channel updates for 'stable-x86_64-apple-darwin'
info: latest update on 2019-08-15, rust version 1.37.0 (eae3437df 2019-08-13)
info: downloading component 'rustc'
 78.7 MiB /  78.7 MiB (100 %)   5.1 MiB/s in 18s ETA:  0s
info: downloading component 'rust-std'
 56.3 MiB /  56.3 MiB (100 %)   1.7 MiB/s in 17s ETA:  0s
info: downloading component 'cargo'
info: downloading component 'rust-docs'
 11.3 MiB /  11.3 MiB (100 %)   6.3 MiB/s in  1s ETA:  0s
info: removing component 'rustc'
info: removing component 'rust-std'
info: removing component 'cargo'
info: removing component 'rust-docs'
info: installing component 'rustc'
 78.7 MiB /  78.7 MiB (100 %)  17.0 MiB/s in  4s ETA:  0s
info: installing component 'rust-std'
 56.3 MiB /  56.3 MiB (100 %)  19.4 MiB/s in  2s ETA:  0s
info: installing component 'cargo'
info: installing component 'rust-docs'
 11.3 MiB /  11.3 MiB (100 %)   2.7 MiB/s in  3s ETA:  0s
info: syncing channel updates for 'nightly-x86_64-apple-darwin'
info: latest update on 2019-08-20, rust version 1.39.0-nightly (29a54035c 2019-08-19)
info: downloading component 'rustc'
 60.4 MiB /  60.4 MiB (100 %)   1.6 MiB/s in 14s ETA:  0s
info: downloading component 'rust-std'
171.6 MiB / 171.6 MiB (100 %)   3.1 MiB/s in 47s ETA:  0s
info: downloading component 'cargo'
info: downloading component 'rust-docs'
 11.7 MiB /  11.7 MiB (100 %)   5.8 MiB/s in  2s ETA:  0s
info: downloading component 'rust-analysis'
526.3 KiB / 526.3 KiB (100 %) 470.5 KiB/s in  2s ETA:  0s
info: downloading component 'rust-src'
info: downloading component 'rust-std' for 'wasm32-unknown-unknown'
 10.7 MiB /  10.7 MiB (100 %)   6.5 MiB/s in  1s ETA:  0s
info: removing component 'rustc'
info: removing component 'rust-std'
info: removing component 'cargo'
info: removing component 'rust-docs'
info: removing component 'rust-analysis'
info: removing component 'rust-src'
info: removing component 'rust-std' for 'wasm32-unknown-unknown'
info: installing component 'rustc'
 60.4 MiB /  60.4 MiB (100 %)  14.6 MiB/s in  4s ETA:  0s
info: installing component 'rust-std'
171.6 MiB / 171.6 MiB (100 %)  33.0 MiB/s in  5s ETA:  0s
info: installing component 'cargo'
info: installing component 'rust-docs'
 11.7 MiB /  11.7 MiB (100 %)   2.8 MiB/s in  3s ETA:  0s
info: installing component 'rust-analysis'
info: installing component 'rust-src'
info: installing component 'rust-std' for 'wasm32-unknown-unknown'
info: checking for self-updates

   stable-x86_64-apple-darwin updated - rustc 1.37.0 (eae3437df 2019-08-13)
  nightly-x86_64-apple-darwin updated - rustc 1.39.0-nightly (29a54035c 2019-08-19)

(casper) ➜  redblack git:(master) ✗ rustup show
Default host: x86_64-apple-darwin

installed toolchains
--------------------

stable-x86_64-apple-darwin
nightly-2018-11-20-x86_64-apple-darwin
nightly-2018-12-04-x86_64-apple-darwin
nightly-2019-03-15-x86_64-apple-darwin
nightly-2019-04-12-x86_64-apple-darwin
nightly-x86_64-apple-darwin (default)
1.37.0-x86_64-apple-darwin

installed targets for active toolchain
--------------------------------------

wasm32-unknown-unknown
x86_64-apple-darwin

active toolchain
----------------

nightly-x86_64-apple-darwin (default)
rustc 1.39.0-nightly (29a54035c 2019-08-19)

@mathstuf
Copy link
Author

Oh certainly. I think it was more incidental that I had installed 1.37.0 before updating all the other toolchains.

@kinnison
Copy link
Contributor

@rbtcollins Do you have any idea how this could have happened?

@mathstuf
Copy link
Author

Some observations:

  • 11.7 (previous total) + 1.8 (new total) = 13.5 (new progress)
  • the time (49710d 6h 28m 14s) is 4294967294 (0xfffffffe) seconds

@rbtcollins
Copy link
Contributor

So we have a hygiene problem here which I went 'lalalalala' at when I started improving IO, but perhaps its time to tackle.

The lack of a newline after the 0s before the 'info' statement. That suggests we haven't closed off the progress bar, which happens as a kind of hack/thunk around the decompressing/extraction of the tars to disk. Checking exactly where the newlines are meant to be emitted and working back would be appropriate. There's no reference counting involved per se, but there is now threaded logic and I suppose the bug must lie in one of those interactions.

The progress bar then gets reused for the next component by receiving a new event through the pub-sub system, which resets its state, and things proceed.

The hygiene problem is that the type system really doesn't enforce any sort of correct use of this state machine, because things are too abstracted out.

Have we done a release recently? E.g. is the threaded IO code enabled on this machine, or is it still just the threaded close logic?

@kinnison
Copy link
Contributor

We've not done a new release yet, so the threading is only for the close logic currently.

@kinnison
Copy link
Contributor

kinnison commented Nov 9, 2019

I wonder if the OP has encountered this in any more recent rustup?

@mathstuf
Copy link
Author

I haven't seen it again, but is there any cause for thinking it has been fixed? I suspect this is more a rare occurrence than something I could reliably check for.

@kinnison
Copy link
Contributor

@mathstuf I was wondering based on @rbtcollins 's question about whether we'd released the threaded IO code or not. Since we have done so since August, I was hoping that might have fixed it. If you've only ever seen this once rather than reproducibly, then I guess this stays open until and unless we know we've done something we think fixes such an issue. Thanks.

@kinnison
Copy link
Contributor

kinnison commented Dec 8, 2019

As part of #2121 I fixed a situation where we could leave a download tracker unfinalised. I believe that should resolve this as I couldn't spot any other pathways which could have this effect. If, after 1.21.0 is out, you still have this issue, please reopen or file a fresh one.

Thanks,

D.

@kinnison kinnison closed this as completed Dec 8, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants