Make libtest logfile respect --format #96290

felipeamp · 2022-04-21T17:50:21Z

I recently ran into an issue caused by the libtest output in logfile not respecting the --format flag. I've seen that a bug has been filed (#57147) but no PR was ever sent.

This PR makes the logfile follow the same format used for STDOUT printing. It removes the log_out field from ConsoleTestState and inlines its creation where needed, wrapping the logfile in an OutputFormatter. I've also deleted a couple of (now unused) methods in ConsoleTestState.

Let me know if you think there is a cleaner solution than the direction I've followed. Thanks!

closes #57147

rust-highfive · 2022-04-21T17:50:24Z

Hey! It looks like you've submitted a new PR for the library teams!

If this PR contains changes to any rust-lang/rust public library APIs then please comment with r? rust-lang/libs-api @rustbot label +T-libs-api -T-libs to request review from a libs-api team reviewer. If you're unsure where your change falls no worries, just leave it as is and the reviewer will take a look and make a decision to forward on if necessary.

Examples of T-libs-api changes:

Stabilizing library features
Introducing insta-stable changes such as new implementations of existing stable traits on existing stable types
Introducing new or changing existing unstable library APIs (excluding permanently unstable features / features without a tracking issue)
Changing public documentation in ways that create new stability guarantees
Changing observable runtime behavior of library APIs

rust-highfive · 2022-04-21T17:50:25Z

Thanks for the pull request, and welcome! The Rust team is excited to review your changes, and you should hear from @yaahc (or someone else) soon.

Please see the contribution instructions for more information.

felipeamp · 2022-04-29T08:53:13Z

Hi Jane,

Did I forget to do something to mark this PR as ready for review? Since this is my first PR to the Rust codebase I don't know if I missed some steps. Let me know if that's the case :)

Thanks!

yaahc · 2022-04-29T17:14:09Z

Hi Jane,

Did I forget to do something to mark this PR as ready for review? Since this is my first PR to the Rust codebase I don't know if I missed some steps. Let me know if that's the case :)

Thanks!

No, sorry, you didn't do anything wrong. I've just behind on my reviews and actually planning on taking a break from the review rotation. Sorry for the delay, I'll reassign the PR.

r? rust-lang/libs

thomcc · 2022-04-29T23:07:36Z

I think this counts as a behavior change, and thus falls under t-libs-api rather than t-libs. So I'm going to reassign. This may be an overabundance of caution, though.

r? rust-lang/libs-api @rustbot label +T-libs-api -T-libs

felipeamp · 2022-05-09T07:21:31Z

Hey, is the process for a T-libs-api contribution the same as a T-libs one or do I need to do something else before this PR can be reviewed? :)

Thanks!

JohnCSimon · 2022-06-20T04:13:15Z

triage:

@m-ou-se - can you answer this?

m-ou-se · 2022-06-20T09:03:04Z

Changes to the flags of test are a public API change, so require an FCP. Can you summarize the publicly visible change, maybe with a clear "before vs after" showcase?

Can we make this change without breaking any users?

felipeamp · 2022-06-28T16:28:38Z

Hi Mara,

Thanks for the reply!

The behavior only changes when a user runs a test or benchmark and sets both the --format and the --logfile flags. Currently the content printed to logfile is just a list of test case names with the strings "ok" or "failed" printed before them (depending on each test case result); while the content printed to STDOUT is always in the format given by the --format flag. This PR makes the content printed to the logfile also be in the format specified in the --format flag, just like STDOUT.

Example:

Create a new Rust project with a single file ./src/lib.rs with the following content:

#[test]
fn it_works() {
  let result = 2 + 2;
  assert_eq!(result, 4);
}

#[test]
fn it_does_not_work() {
  let result = 2 + 2;
  assert_eq!(result, 5);
}

Now run the following command:
cargo +nightly test -- -Z unstable-options --format=json --logfile=logfile.txt 1>stdout.txt

Current behavior:

logfile.txt contains:

ok it_works
failed it_does_not_work

stdout.txt contains:

{ "type": "suite", "event": "started", "test_count": 2 }
{ "type": "test", "event": "started", "name": "it_does_not_work" }
{ "type": "test", "event": "started", "name": "it_works" }
{ "type": "test", "name": "it_works", "event": "ok" }
{ "type": "test", "name": "it_does_not_work", "event": "failed", "stdout": "thread 'it_does_not_work' panicked at 'assertion failed: `(left == right)`\n  left: `4`,\n right: `5`', src/lib.rs:10:3\nnote: run with `RUST_BACKTRACE=1` environment variable to display a backtrace\n" }
{ "type": "suite", "event": "failed", "passed": 1, "failed": 1, "ignored": 0, "measured": 0, "filtered_out": 0, "exec_time": 0.000431658 }

New behavior:
Both stdout.txt and logfile.txt contain:

{ "type": "suite", "event": "started", "test_count": 2 }
{ "type": "test", "event": "started", "name": "it_does_not_work" }
{ "type": "test", "event": "started", "name": "it_works" }
{ "type": "test", "name": "it_works", "event": "ok" }
{ "type": "test", "name": "it_does_not_work", "event": "failed", "stdout": "thread 'it_does_not_work' panicked at 'assertion failed: `(left == right)`\n  left: `4`,\n right: `5`', src/lib.rs:10:3\nnote: run with `RUST_BACKTRACE=1` environment variable to display a backtrace\n" }
{ "type": "suite", "event": "failed", "passed": 1, "failed": 1, "ignored": 0, "measured": 0, "filtered_out": 0, "exec_time": 0.000431658 }

Re: Can we make this change without breaking any users?

Currently this change breaks users who rely on the current logfile output format.

I've thought about protecting this change behind a flag, thus not breaking users who rely on the current logfile behavior. The problem is that in this PR I've restructured the code to reuse the stdout-writing logic for the logfile writing as well, but the old logfile output didn't follow any specific format (as per the --format flag). Therefore I don't know if it's possible to restructure the code in a way that both the old and new behavior co-exist (at least I don't easily see how to do it). I could spend a few hours thinking hard about this if you'd like me to try. Just let me know how essential you think this is.

Please let me know how to proceed from here, especially since I don't know how the FCP process works :)

Thanks!

JohnCSimon · 2022-10-08T23:01:08Z

@m-ou-se - triage: can you help with this?

Please let me know how to proceed from here, especially since I don't know how the FCP process works :)

bors · 2022-10-30T11:04:38Z

☔ The latest upstream changes (presumably #103755) made this pull request unmergeable. Please resolve the merge conflicts.

voidbar · 2022-12-07T14:57:01Z

Hey @felipeamp , any updates on that? You're doing god's work here!

rustbot · 2023-01-12T13:35:59Z

Hey! It looks like you've submitted a new PR for the library teams!

If this PR contains changes to any rust-lang/rust public library APIs then please comment with @rustbot label +T-libs-api -T-libs to tag it appropriately. If this PR contains changes to any unstable APIs please edit the PR description to add a link to the relevant API Change Proposal or create one if you haven't already. If you're unsure where your change falls no worries, just leave it as is and the reviewer will take a look and make a decision to forward on if necessary.

Examples of T-libs-api changes:

Stabilizing library features
Introducing insta-stable changes such as new implementations of existing stable traits on existing stable types
Introducing new or changing existing unstable library APIs (excluding permanently unstable features / features without a tracking issue)
Changing public documentation in ways that create new stability guarantees
Changing observable runtime behavior of library APIs

Manishearth · 2023-04-17T07:02:48Z

cc @calebcartwright since you were looking in to doing more libtest stuff and may be able to review this

hlopko · 2023-10-25T08:21:16Z

Friendly ping @m-ou-se or @calebcartwright, it would be great to get this merged, thank you!

Manishearth · 2023-10-25T15:38:48Z

cc @rust-lang/testing-devex

epage · 2023-10-25T16:00:47Z

Speaking for myself, with my testing-devex hat on, I was hoping to hold off on changes like this until we laid out a vision document so we can see what aligns with that vision.

For instance, in my own personal view of how all of this would go, we'd be shifting a lot of these responsibilities from test harnesses (e.g. libtest) to test reporters (e.g. cargo-test, cargo-nextest, cargo-criterion) and de-emphasizing, maybe even deprecating, reporter related flags (obviously not removing them as that would be a breaking change).

Manishearth · 2023-10-25T16:07:56Z

@epage Hm. I think that's fair, but this is effectively fixing a bug in existing functionality, and the requisite work to make it possible to shift focus over hasn't happened yet. This PR has been open for more than a year, I really don't think it should wait on all that happening.

epage · 2023-10-27T16:31:48Z

If people have determined this to be a bug and want to move forward with merging it, go for it. As for testing-devex, we've not done any prerequisite work to make any determinations like that on our side.

jieyouxu · 2024-02-18T17:36:27Z

cc @felipeamp from triage: I am marking this PR as waiting-on-author because merge conflicts.
@rustbot author

Rationale for adding this functionality: * Bazel (build system) doesn't provide a way to process output from a binary (in this case, Rust test binary's output) other using a wrapper binary. However, using a wrapper binary potentially breaks debugging, because Bazel would suggest to debug the wrapper binary rather than the Rust test itself. * See bazelbuild/rules_rust#1303. * Cargo is not used in Rust Bazel rules. * Although we could wait for rust-lang#96290 and then modify Rust Bazel rules to pass `--logfile` on the command line to provisionally unblock bazelbuild/rules_rust#1303, that solution still wouldn't allow advanced test output postprocessing such as changing JSON/XML schema and injecting extra JUnit properties. * Due to limitations of Rust libtest formatters, Rust developers often use a separate tool to postprocess the test results output (see comments to rust-lang#85563). * Examples of existing postprocessing tools: * https://crates.io/crates/cargo2junit * https://crates.io/crates/gitlab-report * https://crates.io/crates/cargo-suity * For these use cases, it might be helpful to use the new flags `--output_postprocess_executable`, `--output_postprocess_args` instead of piping the test output explicitly, e.g. to more reliably separate test results from other output. Rationale for implementation details: * Use platform-dependent scripts (.sh, .cmd) because it doesn't seem to be possible to enable unstable feature `bindeps` (https://rust-lang.github.io/rfcs/3028-cargo-binary-dependencies.html) in "x.py" by default. * Here's a preexisting test that also uses per-platform specialization: `library/std/src/process/tests.rs`. How to use: ``` ./testbinary --format=junit -Zunstable-options --output_postprocess_executable=/usr/bin/echo --output_postprocess_args=abc123 ```

Add the following two optional flags to `libtest` (rustc's built-in unit-test framework), in order to support postprocessing of the test results using a separate executable: * `--output_postprocess_executable [PATH]` * `--output_postprocess_args [ARGUMENT]` (can be repeated.) If you don't pass `--output_postprocess_executable [PATH]`, the behavior stays the same as before this commit. That is, the test results are sent to stdout. If you pass `--output_postprocess_executable [PATH]`, `libtest` will 1. Spawn a child process from the executable binary (aka *postprocessor*) at the given path. 2. Pass the arguments from the `--output_postprocess_args [ARGUMENT]` flags (if any) to the child process. If `--output_postprocess_args` was used multiple times, all listed arguments will be passed in the original order. 3. Propagate the environment variables to the child process. The *postprocessor* executable is expected to wait for the end of input (EOF) and then terminate. Usage example #1: Filter lines of the test results ```shell $ LD_LIBRARY_PATH=$(pwd) ./test-05daf44cb501aee6 --output_postprocess_executable=/usr/bin/grep --output_postprocess_args="test result" test result: ok. 59 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.31s ``` Usage example rust-lang#2: Save test results into a file ```shell $ LD_LIBRARY_PATH=$(pwd) ./test-05daf44cb501aee6 --output_postprocess_executable=/usr/bin/sh --output_postprocess_args=-c --output_postprocess_args="cat > /tmp/output.txt" ``` Usage example rust-lang#3: Save test results into a file while keeping the command line output ```shell $ LD_LIBRARY_PATH=$(pwd) ./test-05daf44cb501aee6 --output_postprocess_executable=/usr/bin/tee --output_postprocess_args="/tmp/output.txt" running 60 tests ... ``` Usage example rust-lang#4: Prepend every line of test results with the value of an environment variable (to demonstrate environment variable propagation) ```shell $ LOG_PREFIX=">>>" LD_LIBRARY_PATH=$(pwd) ./test-05daf44cb501aee6 --output_postprocess_executable=/usr/bin/sh --output_postprocess_args=-c --output_postprocess_args="sed s/^/\$LOG_PREFIX/" >>> >>>running 60 tests ... ``` Usage example rust-lang#5: Change format of JSON output (using https://jqlang.github.io/jq/) ```shell $ LD_LIBRARY_PATH=$(pwd) ./test-05daf44cb501aee6 -Zunstable-options --format=json --output_postprocess_executable=/usr/bin/jq ``` Usage example rust-lang#6: Print test execution time in machine-readable format ```shell $ LD_LIBRARY_PATH=$(pwd) ./test-05daf44cb501aee6 -Zunstable-options --format=json --output_postprocess_executable=/usr/bin/jq --output_postprocess_args=".exec_time | numbers" 0.234317996 ``` Rationale for adding this functionality: * Bazel (build system) doesn't provide a way to process output from a binary (in this case, Rust test binary's output) other using a wrapper binary. However, using a wrapper binary potentially breaks debugging, because Bazel would suggest to debug the wrapper binary rather than the Rust test itself. * See bazelbuild/rules_rust#1303. * Cargo is not used in Rust Bazel rules. * Although we could wait for rust-lang#96290 and then modify Rust Bazel rules to pass `--logfile` on the command line to provisionally unblock bazelbuild/rules_rust#1303, that solution still wouldn't allow advanced test results postprocessing such as changing JSON/XML schema and injecting extra JUnit properties. * Due to limitations of Rust libtest formatters, Rust developers often use a separate tool to postprocess the test results output (see comments to rust-lang#85563). * Examples of existing postprocessing tools: * https://crates.io/crates/cargo2junit * https://crates.io/crates/gitlab-report * https://crates.io/crates/cargo-suity * For these use cases, it might be helpful to use the new flags `--output_postprocess_executable`, `--output_postprocess_args` instead of piping the test results explicitly, e.g. to more reliably separate test results from other output. Rationale for implementation details: * Use platform-dependent scripts (.sh, .cmd) because it doesn't seem to be possible to enable unstable feature `bindeps` (https://rust-lang.github.io/rfcs/3028-cargo-binary-dependencies.html) in "x.py" by default. * Here's a preexisting test that also uses per-platform specialization: `library/std/src/process/tests.rs`.

Dylan-DPC · 2024-03-11T13:53:02Z

@felipeamp any updates on this? thanks

felipeamp · 2024-03-12T15:47:02Z

I'm a bit busy in the next couple of weeks (going on vacation and all), but will fix the merge conflicts around Easter.

JohnCSimon · 2024-05-26T23:16:59Z

@felipeamp triage - pinging again, to be sure you haven't forgotten this 🙂

felipeamp · 2024-05-27T09:41:25Z

Hi John,

I've taken a look and the merge conflict (and moving this PR forward in general) requires a bit more work than I have the capacity at the moment. Luckily aspotashev has taken over the work in #123365, which is current under review by T-testing-devex folks.

Thanks

Dylan-DPC · 2024-07-23T17:29:40Z

Closing this as it is superseded by #123365

rustbot added the T-libs Relevant to the library team, which will review and decide on the PR/issue. label Apr 21, 2022

rust-highfive assigned yaahc Apr 21, 2022

rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Apr 21, 2022

This comment has been minimized.

Sign in to view

felipeamp force-pushed the issue-57147-fix branch from 529020c to 317764a Compare April 22, 2022 09:25

rust-highfive assigned thomcc and unassigned yaahc Apr 29, 2022

rust-highfive assigned m-ou-se and unassigned thomcc Apr 29, 2022

rustbot added T-libs-api Relevant to the library API team, which will review and decide on the PR/issue. and removed T-libs Relevant to the library team, which will review and decide on the PR/issue. labels Apr 29, 2022

JohnCSimon added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Jul 24, 2022

felipeamp force-pushed the issue-57147-fix branch from 317764a to 98a690a Compare January 12, 2023 13:35

Make logfile respect --format.

105d648

felipeamp force-pushed the issue-57147-fix branch from 98a690a to 105d648 Compare January 12, 2023 14:38

rustbot added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Feb 18, 2024

aspotashev mentioned this pull request Mar 7, 2024

Support test output postprocessing by a child process. #122145

Closed

aspotashev mentioned this pull request Apr 2, 2024

At test discovery, write to logfile in the same format as to stdout #123365

Open

Dylan-DPC closed this Jul 23, 2024

Dylan-DPC removed the S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. label Jul 23, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make libtest logfile respect --format #96290

Make libtest logfile respect --format #96290

felipeamp commented Apr 21, 2022

rust-highfive commented Apr 21, 2022

rust-highfive commented Apr 21, 2022

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

felipeamp commented Apr 29, 2022

yaahc commented Apr 29, 2022

thomcc commented Apr 29, 2022

felipeamp commented May 9, 2022

JohnCSimon commented Jun 20, 2022

m-ou-se commented Jun 20, 2022

felipeamp commented Jun 28, 2022 •

edited

Loading

JohnCSimon commented Oct 8, 2022

bors commented Oct 30, 2022

voidbar commented Dec 7, 2022

rustbot commented Jan 12, 2023

Manishearth commented Apr 17, 2023

hlopko commented Oct 25, 2023

Manishearth commented Oct 25, 2023

epage commented Oct 25, 2023

Manishearth commented Oct 25, 2023

epage commented Oct 27, 2023

jieyouxu commented Feb 18, 2024

Dylan-DPC commented Mar 11, 2024

felipeamp commented Mar 12, 2024

JohnCSimon commented May 26, 2024

felipeamp commented May 27, 2024

Dylan-DPC commented Jul 23, 2024

Make libtest logfile respect --format #96290

Make libtest logfile respect --format #96290

Conversation

felipeamp commented Apr 21, 2022

rust-highfive commented Apr 21, 2022

rust-highfive commented Apr 21, 2022

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

felipeamp commented Apr 29, 2022

yaahc commented Apr 29, 2022

thomcc commented Apr 29, 2022

felipeamp commented May 9, 2022

JohnCSimon commented Jun 20, 2022

m-ou-se commented Jun 20, 2022

felipeamp commented Jun 28, 2022 • edited Loading

Example:

Re: Can we make this change without breaking any users?

JohnCSimon commented Oct 8, 2022

bors commented Oct 30, 2022

voidbar commented Dec 7, 2022

rustbot commented Jan 12, 2023

Manishearth commented Apr 17, 2023

hlopko commented Oct 25, 2023

Manishearth commented Oct 25, 2023

epage commented Oct 25, 2023

Manishearth commented Oct 25, 2023

epage commented Oct 27, 2023

jieyouxu commented Feb 18, 2024

Dylan-DPC commented Mar 11, 2024

felipeamp commented Mar 12, 2024

JohnCSimon commented May 26, 2024

felipeamp commented May 27, 2024

Dylan-DPC commented Jul 23, 2024

felipeamp commented Jun 28, 2022 •

edited

Loading