interop: Improve logging level of tests by jxs · Pull Request #114 · libp2p/test-plans

jxs · 2023-01-24T20:25:31Z

By reducing the redis container logs to warning, and changing the target of the rust ping test to stdout instead of stderr.

instead of stderr

thomaseizinger · 2023-01-24T22:04:23Z

multidim-interop/rust/src/lib.rs

    info!("Running ping test: {}", swarm.local_peer_id());
-    env_logger::Builder::from_env(Env::default().default_filter_or("info")).init();
+    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
+        .target(Target::Stdout)


AFAIK, it is good unix behaviour to send logs to stderr. Why change to stdout?

to make them available in the interop tests. Currently interop tests only show stdout see here.
I read a couple of discussions like this one as I also found it surprising that the default for env_logger was stderr but as I didn't see an industry wide status quo, so I thought it would be easier to just change the Rust tests, since the Go ones already log to stdout.

at least the “ping successful” should be on stdout. The rest can be on stderr. https://pubs.opengroup.org/onlinepubs/9699919799/functions/stderr.html

If ping successful is part of the test contract, we should probably be printing that on stdout with println. Logs should be on stderr IMO.

I am sure you thought about this @MarcoPolo: It would be nice if we could rely on the exit code instead of scanning stdout for a string. Would it make sense to push a listenerDone to redis and thus synchronise the shutdown between the two?

This is untested but have you explored using depends-on to express the relationship between dialer and listener? If we tell docker compose that dialer depends on listener and have listener run an endless loop at the end, we may get a cleaner shutdown behaviour where only the dialer exits by itself.

It would be a little easier to parse JSON. But I don't have a preference here. Matching against output strings is only marginally more work. And it's a little nicer to see "Ping Successful: " then {"pingDuration": <duration>}. But this is purely subjective.

Happy to define the stdout schema to print a JSON result at the end.

What multiple values?

RTT, as measured by the ping protocol

Duration of the handshake

What multiple values?

thinking about it more I like the “leave listener around for a bit”. It removes a redis sync point and lets us use the exit code as source of truth.

I opened an issue: #115

And it's a little nicer to see "Ping Successful: " then {"pingDuration": <duration>}.

Depending on how we define the JSON structure, the test runner can parse it and print something more human-focused :)

Following up on the concrete discussion for this pull request I suggest:

Logging to stderr

Print ping successful to stdout via println!.

mxinden

Comment on logging to stderr, otherwise this looks good to me.

Thanks for the patch for the redis log level. Will make my life a lot easier.

mxinden · 2023-01-26T11:13:00Z

multidim-interop/rust/src/lib.rs

    info!("Running ping test: {}", swarm.local_peer_id());
-    env_logger::Builder::from_env(Env::default().default_filter_or("info")).init();
+    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
+        .target(Target::Stdout)


Following up on the concrete discussion for this pull request I suggest:

Logging to stderr

Print ping successful to stdout via println!.

jxs · 2023-01-26T12:54:42Z

Yeah also makes sense to me after reading the conversation, thanks for elaborating and researching @thomaseizinger and @MarcoPolo. Should we then also print stderr from the compose runner? As logs from the rust ping test will not be shown (can be done in another PR)

MarcoPolo · 2023-01-26T16:09:52Z

Is it useful? We print stderr when there’s a failure. But only stdout on success.

thomaseizinger · 2023-01-26T21:29:51Z

Is it useful? We print stderr when there’s a failure. But only stdout on success.

That is the way to go IMO. Quiet by default, noisy on failure.

marten-seemann · 2023-01-26T22:17:29Z

Is it useful? We print stderr when there’s a failure. But only stdout on success.

That is the way to go IMO. Quiet by default, noisy on failure.

Judging from the experience with the QUIC interop runner, having nodes output (very) detailed logs by default has proved very useful in debugging failures, especially when you're debugging a failure involving an implementation you're not familiar with.

MarcoPolo · 2023-01-26T22:26:01Z

Nodes should always output diagnostic logs. Just on stderr. If there's a failure we'll show stderr. If everything looks good, I'm currently thinking that the node simply output a json string in stdout {"pingRTT": <duration>}. This is inline with the purpose of stderr: https://pubs.opengroup.org/onlinepubs/9699919799/functions/stderr.html.

thomaseizinger · 2023-01-26T22:27:16Z

Is it useful? We print stderr when there’s a failure. But only stdout on success.

That is the way to go IMO. Quiet by default, noisy on failure.

Judging from the experience with the QUIC interop runner, having nodes output (very) detailed logs by default has proved very useful in debugging failures, especially when you're debugging a failure involving an implementation you're not familiar with.

I am not sure whether you are agreeing or disagreeing with the quoted statement? :)

marten-seemann · 2023-01-26T22:49:11Z

My general take on this:

Logs are useful. Let's encourage implementation to dial up the log level. No particular preference for stdout vs. stderr.
Not sure why we need the ping successful output. We get the success / fail bit from the exit code, no need to parse any output. Parsing stdout seems error prone.
Any test more sophisticated than a simple ping will want to export more results. These results might be measurements, or even binary files (e.g. a file downloaded via protocol X). I expect us to introduce a convention that nodes put all their output into a predefined directory, and the runner to run some validation / evaluation steps based on that output.

thomaseizinger · 2023-01-26T23:12:41Z

Not sure why we need the ping successful output. We get the success / fail bit from the exit code, no need to parse any output. Parsing stdout seems error prone.

See @MarcoPolo's comment here: #114 (comment)

Any test more sophisticated than a simple ping will want to export more results. These results might be measurements, or even binary files (e.g. a file downloaded via protocol X). I expect us to introduce a convention that nodes put all their output into a predefined directory, and the runner to run some validation / evaluation steps based on that output.

Without wanting to go too much OT: Another way of solving this would be to use stdout to output metadata and if a certain tests outputs a binary file, we can emit the path to it via stdout. Having said that, let's see what makes the most sense once we have a concrete requirement at hand.

This reverts commit b595b5d.

MarcoPolo · 2023-02-08T17:45:12Z

Cherry picked this commit, so closing this

jxs added 2 commits January 24, 2023 20:24

interop: reduce redis container log level to warning.

07a7eeb

interop: set rust ping logs to target stdout

b595b5d

instead of stderr

jxs changed the title ~~Improve logging level~~ interop: Improve logging level of tests Jan 24, 2023

MarcoPolo approved these changes Jan 24, 2023

View reviewed changes

thomaseizinger reviewed Jan 24, 2023

View reviewed changes

thomaseizinger mentioned this pull request Jan 25, 2023

Interop test runner: Use exit code of dialer as source of truth #115

Closed

mxinden approved these changes Jan 26, 2023

View reviewed changes

Revert "interop: set rust ping logs to target stdout"

49b89fe

This reverts commit b595b5d.

jxs mentioned this pull request Feb 2, 2023

Update Go & JS tests to conform to the multidim interop test spec. #121

Merged

MarcoPolo closed this Feb 8, 2023

Conversation

jxs commented Jan 24, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jxs Jan 24, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

thomaseizinger Jan 25, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mxinden left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jxs commented Jan 26, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

MarcoPolo commented Jan 26, 2023

Uh oh!

thomaseizinger commented Jan 26, 2023

Uh oh!

marten-seemann commented Jan 26, 2023

Uh oh!

MarcoPolo commented Jan 26, 2023

Uh oh!

thomaseizinger commented Jan 26, 2023

Uh oh!

marten-seemann commented Jan 26, 2023

Uh oh!

thomaseizinger commented Jan 26, 2023

Uh oh!

MarcoPolo commented Feb 8, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

jxs commented Jan 24, 2023 •

edited

Loading

jxs Jan 24, 2023 •

edited

Loading

thomaseizinger Jan 25, 2023 •

edited

Loading

jxs commented Jan 26, 2023 •

edited

Loading