Skip to content
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

Bugfix: avoid panic on invalid json output from libtest #109484

Merged
merged 1 commit into from
Mar 25, 2023

Conversation

raoulstrackx
Copy link
Contributor

@raoulstrackx raoulstrackx commented Mar 22, 2023

#108659 introduces a custom test display implementation. It does so by using libtest to output json. The stdout is read and parsed; The code trims the line read and checks whether it starts with a { and ends with a }. If so, it concludes that it must be a json encoded Message. Unfortunately, this does not work in all cases:

  • This assumes that tests running with --nocapture will never start and end lines with { and } characters
  • Output is generated by issuing multiple write_message statements. Where only the last one issues a \n. This likely results in a race condition as we see multiple json outputs on the same line when running tests for the x86_64-fortanix-unknown-sgx target:
10:21:04 �[0m�[0m�[1m�[32m     Running�[0m tests/run-time-detect.rs (build/x86_64-unknown-linux-gnu/stage1-std/x86_64-fortanix-unknown-sgx/release/deps/run_time_detect-8c66026bd4b1871a)
10:21:04 
10:21:04 running 1 tests
10:21:04 test x86_all ... ok
10:21:04 �[0m�[0m�[1m�[32m     Running�[0m tests/thread.rs (build/x86_64-unknown-linux-gnu/stage1-std/x86_64-fortanix-unknown-sgx/release/deps/thread-ed5456a7d80a6193)
10:21:04 thread 'main' panicked at 'failed to parse libtest json output; error: trailing characters at line 1 column 135, line: "{ \"type\": \"suite\", \"event\": \"ok\", \"passed\": 1, \"failed\": 0, \"ignored\": 0, \"measured\": 0, \"filtered_out\": 0, \"exec_time\": 0.000725911 }{ \"type\": \"suite\", \"event\": \"started\", \"test_count\": 1 }\n"', render_tests.rs:108:25

This PR implements a partial fix by being much more conservative of what it asserts is a valid json encoded Message. This prevents panics, but still does not resolve the race condition. A discussion is needed where this race condition comes from exactly and how it best can be avoided.

cc: @jethrogb, @pietroalbini

@rustbot
Copy link
Collaborator

rustbot commented Mar 22, 2023

r? @albertlarsan68

(rustbot has picked a reviewer for you, use r? to override)

@rustbot rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. T-bootstrap Relevant to the bootstrap subteam: Rust's build system (x.py and src/bootstrap) labels Mar 22, 2023
@raoulstrackx
Copy link
Contributor Author

r? @Mark-Simulacrum

@raoulstrackx raoulstrackx force-pushed the raoul/bugfix_libtest_json_output branch from 0810f68 to 0d1a054 Compare March 22, 2023 13:01
@jethrogb
Copy link
Contributor

I don't fully understand the problem or the solution, but shouldn't the fix be to avoid any race conditions from occurring in the first place?

@raoulstrackx
Copy link
Contributor Author

Fixing the race condition does not fully fix the problem here. Any test output (e.g. with --nocapture) that starts and end with { and } will result in json deserialization errors.
I've considered adding a lock or double buffer in the write_message function, but I'm not convinced that would fully fix the race condition when tests are being executed in parallel. The root of the problem is that various outputs are combined and then parsed again. In #108659 there was a discussion on an alternative approach where --logfile would be extended. I'm wondering if that would also fix this issue. If that'd be the way to go, I'd prefer to revert #108659 until the alternative approach lands.

@jyn514
Copy link
Member

jyn514 commented Mar 22, 2023

cc @pietroalbini

@pietroalbini
Copy link
Member

@bors r+ rollup

Fixing the race condition does not fully fix the problem here. Any test output (e.g. with --nocapture) that starts and end with { and } will result in json deserialization errors.

Agreed, that was a mistake on my end here, sorry about that!

I've considered adding a lock or double buffer in the write_message function, but I'm not convinced that would fully fix the race condition when tests are being executed in parallel. The root of the problem is that various outputs are combined and then parsed again. In #108659 there was a discussion on an alternative approach where --logfile would be extended. I'm wondering if that would also fix this issue. If that'd be the way to go, I'd prefer to revert #108659 until the alternative approach lands.

So, I think here we should fix the race condition in libtest by potentially adding locking when emitting the messages. While #108659 exposes the problem to users of the Rust build system, the underlying problem of broken and overlapping JSON being emitted is a bug of libtest's --format json, and it will affect other users of it.

@bors
Copy link
Contributor

bors commented Mar 24, 2023

📌 Commit 0d1a054 has been approved by pietroalbini

It is now in the queue for this repository.

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Mar 24, 2023
bors added a commit to rust-lang-ci/rust that referenced this pull request Mar 25, 2023
…iaskrgr

Rollup of 7 pull requests

Successful merges:

 - rust-lang#109355 (Fix bad suggestion for clone/is_some in field init shorthand)
 - rust-lang#109484 (Bugfix: avoid panic on invalid json output from libtest)
 - rust-lang#109539 (Refactor `find_*_stability` functions)
 - rust-lang#109542 (rustdoc: clean up `storage.js`)
 - rust-lang#109545 (Deeply check well-formedness of return-position `impl Trait` in trait)
 - rust-lang#109568 (miri: fix raw pointer dyn receivers)
 - rust-lang#109570 (Add GUI test for "Auto-hide item methods' documentation" setting)

Failed merges:

r? `@ghost`
`@rustbot` modify labels: rollup
@bors bors merged commit 65220b5 into rust-lang:master Mar 25, 2023
@rustbot rustbot added this to the 1.70.0 milestone Mar 25, 2023
bors added a commit to rust-lang-ci/rust that referenced this pull request May 2, 2023
…ynchronization, r=pietroalbini

Ensure test library issues json string line-by-line

rust-lang#108659 introduces a custom test display implementation. It does so by using libtest to output json. The stdout is read line by line and parsed. The code trims the line read and checks whether it starts with a `{` and ends with a `}`.

Unfortunately, there is a race condition in how json data is written to stdout. The `write_message` function calls `self.out.write_all` repeatedly to write a buffer that contains (partial) json data, or a new line. There is no lock around the `self.out.write_all` functions. Similarly, the `write_message` function itself is called with only partial json data. As these functions are called from concurrent threads, this may result in json data ending up on the same stdout line. This PR avoids this by buffering the complete json data before issuing a single `self.out.write_all`.

(rust-lang#109484 implemented a partial fix for this issue; it only avoids that failed json parsing would result in a panic.)

cc: `@jethrogb,` `@pietroalbini`
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. T-bootstrap Relevant to the bootstrap subteam: Rust's build system (x.py and src/bootstrap)
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants