Stream: t-compiler/rust-analyzer

Topic: test failures


Jeremy Kolb (Feb 11 2021 at 18:22, on Zulip):

I'm not sure why these are failing: https://github.com/rust-analyzer/rust-analyzer/pull/7639 I can't reproduce locally in Linux or Windows

Lukas Wirth (Feb 11 2021 at 18:35, on Zulip):

cant seem to reproduce either on my windows machine :confused:

matklad (Feb 11 2021 at 18:39, on Zulip):

can you change cargo.toml to kill caches?

matklad (Feb 11 2021 at 18:39, on Zulip):

.lock

Jeremy Kolb (Feb 11 2021 at 18:43, on Zulip):

Trying now...

Jonas Schievink [he/him] (Feb 11 2021 at 18:55, on Zulip):

didn't seem to work

Jonas Schievink [he/him] (Feb 11 2021 at 18:55, on Zulip):

when are we supposed to return "content modified"?

Jeremy Kolb (Feb 11 2021 at 18:58, on Zulip):

I think when there's typing going on or something that invalidates an LSP request

Jeremy Kolb (Feb 11 2021 at 19:02, on Zulip):

I wonder if we have a race condition somewhere

Jonas Schievink [he/him] (Feb 11 2021 at 22:26, on Zulip):

Oh, looks like I can reproduce these locally

Laurențiu (Feb 12 2021 at 10:56, on Zulip):

It's failing even on 1.49: https://github.com/rust-analyzer/rust-analyzer/pull/7648

Jonas Schievink [he/him] (Feb 12 2021 at 11:06, on Zulip):

Doesn't CI use the stable channel?

Jonas Schievink [he/him] (Feb 12 2021 at 11:07, on Zulip):

Can anyone else repro this with env RUN_SLOW_TESTS=1 cargo test -p rust-analyzer on Rust 1.50.0?

Yoshua Wuyts (Feb 12 2021 at 11:08, on Zulip):

Oh, I was wondering what was causing these failures. Running into that too on: https://github.com/rust-analyzer/rust-analyzer/pull/7650

Jonas Schievink [he/him] (Feb 12 2021 at 11:09, on Zulip):

We do use toolchain: stable, so all CI runs on Rust 1.50.0 right now

Yoshua Wuyts (Feb 12 2021 at 11:10, on Zulip):

Ohh, yeah I'm still on 1.49 locally. Will try and repro to see if that fails my branch

Yoshua Wuyts (Feb 12 2021 at 11:16, on Zulip):

okay, upgrading to 1.50 made my build fail locally

Yoshua Wuyts (Feb 12 2021 at 11:16, on Zulip):

I suspect rustfmt was upgraded and the formatting is now different

Yoshua Wuyts (Feb 12 2021 at 11:17, on Zulip):

(now validating, will submit a patch if I can get this to pass)

Yoshua Wuyts (Feb 12 2021 at 11:18, on Zulip):

And that fixed it!

Jonas Schievink [he/him] (Feb 12 2021 at 11:18, on Zulip):

We'll run CI on 1.49.0 for now https://github.com/rust-analyzer/rust-analyzer/pull/7651

Florian Diebold (Feb 12 2021 at 11:18, on Zulip):

there's already a PR for that, whose build is failing because of this other issue @Yoshua Wuyts

Jonas Schievink [he/him] (Feb 12 2021 at 11:18, on Zulip):

let's hope this is benign and not a miscompilation

Yoshua Wuyts (Feb 12 2021 at 11:18, on Zulip):

oh okay!

Florian Diebold (Feb 12 2021 at 11:19, on Zulip):

that's actually a problem though, if we're pinning CI to 1.49 everyone will have to run 1.49 rustfmt

Yoshua Wuyts (Feb 12 2021 at 11:19, on Zulip):

(ah yes, my bad -- now seeing the content of https://github.com/rust-analyzer/rust-analyzer/pull/7639)

Florian Diebold (Feb 12 2021 at 11:21, on Zulip):

I get a failure on test_will_rename_files_same_level, but not on the ones failing in CI :/

Jonas Schievink [he/him] (Feb 12 2021 at 11:22, on Zulip):

it's spurious for me, I usually get between 1 to 7 failures

Florian Diebold (Feb 12 2021 at 11:22, on Zulip):

ok, I'll try a few more times

Yoshua Wuyts (Feb 12 2021 at 11:24, on Zulip):

Jonas Schievink said:

Can anyone else repro this with env RUN_SLOW_TESTS=1 cargo test -p rust-analyzer on Rust 1.50.0?

Just tried this on Windows w/ 1.50 after running cargo fmt -- tests are passing for me

Florian Diebold (Feb 12 2021 at 11:26, on Zulip):

ok yeah, I get failures as well when running all tests in parallel. I didn't get them when I just ran completes_items_from_standard_library in a loop, so this might be concurrency related?

Florian Diebold (Feb 12 2021 at 11:28, on Zulip):

trying with --test-threads 1 now

Florian Diebold (Feb 12 2021 at 11:37, on Zulip):

I'm still getting random failures with 1 thread

Laurențiu (Feb 12 2021 at 11:37, on Zulip):

Strange, everything except formatting works for me in nightly

Laurențiu (Feb 12 2021 at 11:37, on Zulip):

Oh

Laurențiu (Feb 12 2021 at 11:37, on Zulip):
test test_will_rename_files_same_level ... FAILED
test completes_items_from_standard_library ... FAILED
test test_format_document_2018 ... FAILED
test out_dirs_check ... FAILED
test resolve_proc_macro ... FAILED
Jonas Schievink [he/him] (Feb 12 2021 at 11:56, on Zulip):

boy I love debugging CI

Laurențiu (Feb 12 2021 at 11:58, on Zulip):

I'm trying to bisect it in RA (not rustc). Those tests seem to work for me in older commits

Jonas Schievink [he/him] (Feb 12 2021 at 11:59, on Zulip):

ah, interesting

Laurențiu (Feb 12 2021 at 12:06, on Zulip):

It might be https://github.com/rust-analyzer/rust-analyzer/pull/7478/files

Florian Diebold (Feb 12 2021 at 12:07, on Zulip):

RA_LOG=info RUN_SLOW_TESTS=1 cargo test -p rust-analyzer -- test_runnables_project --test-threads 1 --nocapture actually fails reliably for me

Laurențiu (Feb 12 2021 at 12:10, on Zulip):

@Florian Diebold can you try on f421ee672253499b8ca8d1badf98db42525a5216?

Laurențiu (Feb 12 2021 at 12:10, on Zulip):

I think it's actually the async macro loading, not the test change

Florian Diebold (Feb 12 2021 at 12:10, on Zulip):

I'm trying the commit before that right now

Florian Diebold (Feb 12 2021 at 12:12, on Zulip):

92a6dcc3605410f9af2214b6565aa1f9898c85ea looks good

Florian Diebold (Feb 12 2021 at 12:12, on Zulip):

now f421ee672253499b8ca8d1badf98db42525a5216...

Laurențiu (Feb 12 2021 at 12:13, on Zulip):

Yup, it's 9358eecc042d8b551f58d2d5ddb9c88d258880c1

Laurențiu (Feb 12 2021 at 12:14, on Zulip):

https://github.com/rust-analyzer/rust-analyzer/pull/7412/commits/9358eecc042d8b551f58d2d5ddb9c88d258880c1

Florian Diebold (Feb 12 2021 at 12:14, on Zulip):

yeah, makes sense actually

Florian Diebold (Feb 12 2021 at 12:15, on Zulip):

yep, that one fails

Laurențiu (Feb 12 2021 at 12:19, on Zulip):

But why didn't we notice it until 1.50?

Jonas Schievink [he/him] (Feb 12 2021 at 12:19, on Zulip):

I do wonder why it works on 1.49.0 though. Does 1.50.0 optimize so much better that something runs much faster?

Florian Diebold (Feb 12 2021 at 12:21, on Zulip):

or the other way around :/

Florian Diebold (Feb 12 2021 at 12:21, on Zulip):

maybe it's the compiler being faster, actually

Laurențiu (Feb 12 2021 at 12:22, on Zulip):

I can confirm, it works on 1.49

Florian Diebold (Feb 12 2021 at 12:23, on Zulip):

since our tests running slower because of logging makes it trigger reliably, I'd guess it's a) our tests being slower in general with 1.50, or b) the compiler being faster (since it seems to be a race with the compiler for out dir loading?)

Jonas Schievink [he/him] (Feb 12 2021 at 12:24, on Zulip):

oh that sounds plausible

Florian Diebold (Feb 12 2021 at 12:24, on Zulip):

b) would certainly be nicer than a) :grimacing:

Florian Diebold (Feb 12 2021 at 12:25, on Zulip):

might be worth to ping @matklad and @Edwin Cheng about this btw?

matklad (Feb 12 2021 at 12:25, on Zulip):

I can take a look later today, yeah

matklad (Feb 12 2021 at 12:26, on Zulip):

synchronization is tricky stuff...

matklad (Feb 12 2021 at 12:27, on Zulip):

placing some printfs here would be the first step: https://github.com/rust-analyzer/rust-analyzer/blob/e0fc2af1184bed5af0a74276c261c79f685fa5d7/crates/rust-analyzer/src/reload.rs#L94

Florian Diebold (Feb 12 2021 at 12:29, on Zulip):

will try

Edwin Cheng (Feb 12 2021 at 12:29, on Zulip):

ReadyPartial means outdir is not yet loaded and IIRC we wait for Ready but not ReadyPartial in that macro test.

Florian Diebold (Feb 12 2021 at 12:30, on Zulip):

@Edwin Cheng it's all the heavy tests that are (sporadically) failing, with "content modified" errors from the server

Edwin Cheng (Feb 12 2021 at 12:30, on Zulip):

Oh.

Florian Diebold (Feb 12 2021 at 12:31, on Zulip):

hmmm

[INFO  ide_db::apply_change] apply_change AnalysisChange { roots: [snip...], files_changed: 13 }
[INFO  rust_analyzer::reload] did switch workspaces
[INFO  rust_analyzer::main_loop] handle_event(Progress { n_total: 22, n_done: 0 })
transition to Loading
transition to Ready { partial: false }
Workspace loaded! ----------------------
[INFO  ide_db::apply_change] apply_change AnalysisChange { roots: [snip...], files_changed: 672 }
Florian Diebold (Feb 12 2021 at 12:32, on Zulip):

it seems to be reloading again directly after reporting ready

Jonas Schievink [he/him] (Feb 12 2021 at 12:34, on Zulip):

cool a new CI failure https://github.com/rust-analyzer/rust-analyzer/runs/1887096611

matklad (Feb 12 2021 at 12:35, on Zulip):

I think I see it

matklad (Feb 12 2021 at 12:35, on Zulip):

we report rediness once we've loaded vfs from metadata and various stuff from cargo check

matklad (Feb 12 2021 at 12:36, on Zulip):

that "stuff" includes additional VFS roots

matklad (Feb 12 2021 at 12:39, on Zulip):

ah, it seems even worse that that -- we do ask vfs to load the new set of roots, but it reports "I've finished loading old set of roots" which we confuse with "I've finised loading new set of roots"

matklad (Feb 12 2021 at 12:40, on Zulip):

Seems like vfs::Config needs to include a version number, and Message::Progress should refer to this config number.

matklad (Feb 12 2021 at 12:41, on Zulip):

Fearless concurrency they say...

matklad (Feb 12 2021 at 12:41, on Zulip):

well, at least it doesn't segfault)

Florian Diebold (Feb 12 2021 at 12:45, on Zulip):

aah, I think I see

Florian Diebold (Feb 12 2021 at 12:46, on Zulip):

I can try to implement that

Florian Diebold (Feb 12 2021 at 13:27, on Zulip):

hm actually that doesn't seem to be the problem, it's still failing sometimes, and when it does it's because the reloading code decides to fetch workspaces a second time after the workspace was already loaded

matklad (Feb 12 2021 at 13:28, on Zulip):

why does it do this? Some vfs change triggers that?

matklad (Feb 12 2021 at 13:28, on Zulip):

(we watch cargo lock & toml, as well as "magic" files like the ones in tests dir)

Florian Diebold (Feb 12 2021 at 13:30, on Zulip):

yes... this is a working log:

about to transition to Ready { partial: false }, 22 of 22 done for version 1
transition to Ready { partial: false }
Workspace loaded! ----------------------
global_state apply_change
[INFO  ide_db::apply_change] apply_change AnalysisChange { roots: [SourceRoot { is_library: false, file_set: FileSet { n_files: 2 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 52 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 172 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 1 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 10 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 11 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 1 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 403 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 9 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 21 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 2 } }, SourceRoot { is_library: false, file_set: FileSet { n_files: 1 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }], files_changed: 431 }

and this one fails:

about to transition to Ready { partial: false }, 22 of 22 done for version 1
transition to Ready { partial: false }
Workspace loaded! ----------------------
global_state apply_change
[INFO  ide_db::apply_change] apply_change AnalysisChange { roots: [SourceRoot { is_library: false, file_set: FileSet { n_files: 2 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 52 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 172 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 1 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 10 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 11 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 1 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 403 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 9 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 21 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 2 } }, SourceRoot { is_library: false, file_set: FileSet { n_files: 1 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }, SourceRoot { is_library: true, file_set: FileSet { n_files: 0 } }], files_changed: 672 }
[INFO  rust_analyzer::reload] will fetch workspaces
Florian Diebold (Feb 12 2021 at 13:31, on Zulip):

the only difference seems to be fewer changed files in the analysis change in the working version

matklad (Feb 12 2021 at 13:32, on Zulip):

We probably should log the reason for reloads

Laurențiu (Feb 12 2021 at 13:33, on Zulip):

Is it a cargo metadata having finished?

Florian Diebold (Feb 12 2021 at 13:44, on Zulip):

no interesting changes when it works;

Florian Diebold (Feb 12 2021 at 13:44, on Zulip):
Interesting changes: /home/florian/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/collections/btree/map/tests/ord_chaos.rs

when it doesn't

Florian Diebold (Feb 12 2021 at 14:18, on Zulip):

it seems kind of wrong to have VFS loading of a file cause a workspace refresh?

Florian Diebold (Feb 12 2021 at 14:19, on Zulip):

ah wait, does that analysis change come from Vfs loading?

Florian Diebold (Feb 12 2021 at 14:21, on Zulip):

ah yeah I think so

Florian Diebold (Feb 12 2021 at 14:22, on Zulip):

the problem may be that we transition to loaded before actually applying the last changes

Florian Diebold (Feb 12 2021 at 14:45, on Zulip):

if we're applying a change before the transition to loaded, we ignore it w.r.t. reloading the workspace. So it depends on which files happen to be loaded in that last change whether it works

Florian Diebold (Feb 12 2021 at 14:48, on Zulip):

delaying the status transition until after the process_changes call makes all tests pass, but I'm not sure whether skipping statuses might be a problem

matklad (Feb 12 2021 at 14:49, on Zulip):

You mean if we just jump to ready from loading, bypassing partial?

matklad (Feb 12 2021 at 14:50, on Zulip):

That should be fine, clients shouldn't assume any particular state machine we us internally

Florian Diebold (Feb 12 2021 at 14:50, on Zulip):

ok, let me clean up and make a PR

Florian Diebold (Feb 12 2021 at 15:00, on Zulip):

https://github.com/rust-analyzer/rust-analyzer/pull/7652

Laurențiu (Feb 12 2021 at 20:38, on Zulip):

Hmm, pinning Rust to 1.49 shows up in https://rust-analyzer.github.io/metrics/ (see ripgrep/type mismatches), but reverting that didn't bring the number back down. I wonder what's up besides our type mismatch figure.

Jonas Schievink [he/him] (Feb 12 2021 at 20:40, on Zulip):

huh, that makes no sense

Jonas Schievink [he/him] (Feb 12 2021 at 20:40, on Zulip):

maybe it's attributed incorrectly?

Laurențiu (Feb 12 2021 at 20:43, on Zulip):

It shouldn't be

Laurențiu (Feb 12 2021 at 20:44, on Zulip):

But at least it should be easy to check, as https://github.com/rust-analyzer/rust-analyzer/issues/1552 seems to be fixed

Laurențiu (Feb 12 2021 at 20:53, on Zulip):

Yup, it's 79

Laurențiu (Feb 12 2021 at 20:55, on Zulip):

But I also get 79 on b0f20a795d6b1f8d36d1cbe294e54ac592b98f5e (which has 9 in the JSON)

Jonas Schievink [he/him] (Feb 12 2021 at 20:55, on Zulip):

ripgrep repo has no notable changes

Jonas Schievink [he/him] (Feb 12 2021 at 20:55, on Zulip):

(not sure if the commit we test is pinned)

Laurențiu (Feb 12 2021 at 20:56, on Zulip):

It's pinned, it's from rustc-perf

Laurențiu (Feb 12 2021 at 21:06, on Zulip):

Ah, the metrics workflow uses stable, so we're seeing the upgrade to 1.50

Jonas Schievink [he/him] (Feb 12 2021 at 21:07, on Zulip):

so the type mismatches come from libstd changes?

Laurențiu (Feb 12 2021 at 21:08, on Zulip):

They must be

Laurențiu (Feb 12 2021 at 21:09, on Zulip):

We could rustup default a pinned compiler version, but I'm not sure it's worth it

Laurențiu (Feb 12 2021 at 21:09, on Zulip):

We still want to know the current status, not what happens on an old libstd

Jonas Schievink [he/him] (Feb 12 2021 at 21:10, on Zulip):

perhaps we can store rustc -V along the metric output and display it on hover?

Jonas Schievink [he/him] (Feb 12 2021 at 21:10, on Zulip):

maybe the work isn't worth it though

Laurențiu (Feb 12 2021 at 21:12, on Zulip):

I'd rather have a nicer display of the metrics. This one shows the past 8 months, and you can't zoom to the last couple of days, so that commit hash on hover is useless

Laurențiu (Feb 12 2021 at 21:22, on Zulip):

I might set up a Grafana somewhere, but my feeling is that nobody else would look at it

Jonas Schievink [he/him] (Feb 12 2021 at 21:22, on Zulip):

yeah I'd love some improvements in this area

Jonas Schievink [he/him] (Feb 12 2021 at 21:23, on Zulip):

is there any way to use grafana on a static website?

Laurențiu (Feb 12 2021 at 21:24, on Zulip):

I don't think so, it runs the queries on the backend

Laurențiu (Feb 12 2021 at 21:25, on Zulip):

I can host one on my NAS, but only on a "works unless I'm rebooting for kernel upgrades" SLA

Laurențiu (Feb 12 2021 at 21:27, on Zulip):

Might be a fun exercise

Laurențiu (Feb 13 2021 at 09:42, on Zulip):

Laurențiu Nicola said:

Might be a fun exercise

Less fun once you realize that Grafana really wants a time series on the X axis

Laurențiu (Feb 13 2021 at 12:37, on Zulip):

image.png

Laurențiu (Feb 13 2021 at 16:49, on Zulip):

https://grafana.dend.ro/d/XF6z6oPMk/rust-analyzer-metrics

Laurențiu (Feb 13 2021 at 16:49, on Zulip):

No automatic sync yet

Edwin Cheng (Feb 13 2021 at 23:09, on Zulip):

Look so good !!

Last update: Jul 28 2021 at 03:45UTC