feat(client,server): rework logging #1692

mxinden · 2024-02-28T17:57:49Z

In neqo-client and neqo-server use neqo_common::log instead of println! and eprintln!.
Add -q, -v, -vv, -vvv, -vvvv log level flags via clap_verbosity_flag.
Set default log level to INFO. Demote many qinfo! to qdebug!.

Fixes #685.

neqo-client/src/main.rs

mxinden · 2024-03-01T10:42:41Z

Maybe add a -v command line parameter to increase the log level?

Would -v then set the RUST_LOG environment variable to be later picked up by neqo_common::log::init? That looks like spaghetti code to me. An alternative would be to introduce a neqo_common::log::init_with_level. Though in case you want this, I suggest doing so in a separate pull request to keep this one focused on #685.

Exploring another alternative: I removed the RUST_LOG hint (514e0ac) and instead changed neqo-client to continue printing request content (or content metadata) to the console (28bed42).

A request to google.com now looks like the below. Always printing request content is somewhat similar to curl's default behavior.

➜  neqo git:(common-log) cargo run --bin neqo-client -- 'https://google.com/'                   
    Finished dev [unoptimized + debuginfo] target(s) in 0.13s
     Running `target/debug/neqo-client 'https://google.com/'`
READ[0]: 220 bytes
READ[0]: 0 bytes
READ[0]: 0 bytes

➜  neqo git:(common-log) cargo run --bin neqo-client -- 'https://google.com/' --output-read-data   
    Finished dev [unoptimized + debuginfo] target(s) in 0.16s
     Running `target/debug/neqo-client 'https://google.com/' --output-read-data`
READ[0]: <HTML><HEAD><meta http-equiv="content-type" content="text/html;charset=utf-8">
<TITLE>301 Moved</TITLE></HEAD><BODY>
<H1>301 Moved</H1>
The document has moved
<A HREF="https://www.google.com/">here</A>.
</BODY></HTML>

@larseggert let me know what you think.

mxinden · 2024-03-05T13:16:16Z

Friendly ping @larseggert.

I don't feel strongly about any of the proposals in this pull request. I want to start on #1696, laying the groundwork for #1693. For the sake of keeping merge conflicts small, shall we merge or close here?

larseggert · 2024-03-05T14:41:34Z

I don't feel strongly either. I have a mile preference that if we're going to use the logging framework for things, we should use it as much as possible, i.e., avoid esp. eprintln! but probably also println!. Adding a neqo_common::log::init_with_level to set the level based on a command line options seems fine.

KershawChang · 2024-03-05T16:36:31Z

Friendly ping @larseggert.

I don't feel strongly about any of the proposals in this pull request. I want to start on #1696, laying the groundwork for #1693. For the sake of keeping merge conflicts small, shall we merge or close here?

Probably close?
I am fine with leaving eprintln! and println! in neqo_client and neqo_server.

larseggert · 2024-03-18T03:42:11Z

I've changed my mind on this, we should use the neqo log functions, and also use clap_verbosity_flag to control verbosity. The demo client and server can be quite noisy on the console when large amounts of data are transferred, and it would be good if the less interesting output could be suppressed.

(Also, because right now http3.rs uses println! whereas old_http.rs uses eprintln!...)

mxinden · 2024-03-18T07:56:34Z

and also use clap_verbosity_flag to control verbosity

Neat!

I will revive the pull request.

- In `neqo-client` and `neqo-server` use `neqo_common::log` instead of `println!` and `eprintln!`. - Add `-q`, `-v`, `-vv`, `-vvv`, `-vvvv` log level flags via `clap_verbosity_flag`. - Set default log level to INFO. Demote many `qinfo!` to `qdebug!`.

mxinden · 2024-03-19T13:26:36Z

I updated the pull request with the above suggestion, i.e. to use clap_verbosity_flag.

In addition I demoted multiple qinfo! to qdebug!. (Note, I don't feel strongly about any particular one, though I do believe most of them are useful for debugging, not informational purposes.)

Sample output:

➜  neqo git:(common-log) cargo run --bin neqo-client -- http://127.0.0.1:12345/10        
   Compiling neqo-bin v0.7.2 (/home/mxinden/code/github.com/mozilla/neqo/neqo-bin)
    Finished dev [unoptimized + debuginfo] target(s) in 0.87s
     Running `target/debug/neqo-client 'http://127.0.0.1:12345/10'`
0s  0ms INFO H3 Client connecting: 0.0.0.0:48590 -> 127.0.0.1:12345
0s  3ms INFO [Http3 connection] Fetch method=GET target: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Ipv4(127.0.0.1)), port: Some(12345), path: "/10", query: None, fragment: None }
0s  3ms INFO [Client 09f5ee994b496ebc] Connection established
0s  3ms WARN Crypto operation failed NssError { name: "SEC_ERROR_BAD_DATA", code: -8190, desc: "security library: received bad data." }
0s  3ms WARN [Client ...] Dropped received packet: Decryption failure; Total: 1
0s  3ms INFO [Http3 connection] Fetch method=GET target: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Ipv4(127.0.0.1)), port: Some(12345), path: "/10", query: None, fragment: None }
0s  5ms INFO [Http3 connection] Fetch method=GET target: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Ipv4(127.0.0.1)), port: Some(12345), path: "/10", query: None, fragment: None }
0s  9ms INFO [Http3 client] Close the connection error=0 msg=kthxbye!.
0s  9ms WARN close(0) called when streams still active
0s  9ms WARN Unhandled event StateChange(Closing(Application(0)))
0s  9ms INFO [Http3 client] Close the connection error=0 msg=kthxbye!.
0s 32ms INFO [Http3 client] Close the connection error=0 msg=kthxbye!.
0s 32ms INFO Closing timer expired

@larseggert @KershawChang would you mind taking another look? I am not familiar with how Neqo logging is used within Firefox, thus please review carefully.

larseggert

LGTM but want to hear from the other owners.

neqo-transport/src/cc/classic_cc.rs

Needed in order for mozlog_neqo_cwnd.py to analyze cc.

mozilla#1692 introduced verbosity command line flags in `neqo-server` and `neqo-client`. This commit makes use of the flags instead of the `RUST_LOG` environment variable.

There are two ways to specify the maximum log level of `neqo-server` and `neqo-client`. Via the `RUST_LOG` environment variable and since mozilla#1692 via the verbosity flags (e.g. `-v`). Previously, if no verbosity flag was provided, `INFO` was set as the maximum log level, the `RUST_LOG` environment variable was simply ignored. With this commit, if no flag is set, the `RUST_LOG` environment variable is considered, and only then the `env_logger` crate default value (`ERROR`) is used. In other words, the precedence order now is: 1. command line flags (e.g. `-v`) 2. `RUST_LOG` environment variable 3. default `ERROR` level

* fix(bin): consider env when no verbosity flag is set There are two ways to specify the maximum log level of `neqo-server` and `neqo-client`. Via the `RUST_LOG` environment variable and since #1692 via the verbosity flags (e.g. `-v`). Previously, if no verbosity flag was provided, `INFO` was set as the maximum log level, the `RUST_LOG` environment variable was simply ignored. With this commit, if no flag is set, the `RUST_LOG` environment variable is considered, and only then the `env_logger` crate default value (`ERROR`) is used. In other words, the precedence order now is: 1. command line flags (e.g. `-v`) 2. `RUST_LOG` environment variable 3. default `ERROR` level * clippy * Move `verbose` into `SharedArgs`

There are two server implementations based on neqo: 1. https://github.com/mozilla/neqo/tree/main/neqo-bin/src/server - http3 and http09 implementation - used for manual testing and QUIC Interop 2. https://searchfox.org/mozilla-central/source/netwerk/test/http3server/src/main.rs - used to test Firefox I assume one was once an exact copy of the other. Both implement their own I/O, event loop, ... Since then, the two implementations diverged significantly. Especially (1) saw a lot of improvements in recent months: - mozilla#1564 - mozilla#1569 - mozilla#1578 - mozilla#1581 - mozilla#1604 - mozilla#1612 - mozilla#1676 - mozilla#1692 - mozilla#1707 - mozilla#1708 - mozilla#1727 - mozilla#1753 - mozilla#1756 - mozilla#1766 - mozilla#1772 - mozilla#1786 - mozilla#1787 - mozilla#1788 - mozilla#1794 - mozilla#1806 - mozilla#1808 - mozilla#1848 - mozilla#1866 At this point, bugs in (2) are hard to fix, see e.g. mozilla#1801. This commit merges (2) into (1), thus removing all duplicate logic and having (2) benefit from all the recent improvements to (1).

* refactor(bin): introduce server/http3.rs and server/http09.rs The QUIC Interop Runner requires an http3 and http09 implementation for both client and server. The client code is already structured into an http3 and an http09 implementation since #1727. This commit does the same for the server side, i.e. splits the http3 and http09 implementation into separate Rust modules. * refactor: merge mozilla-central http3 server into neqo-bin There are two server implementations based on neqo: 1. https://github.com/mozilla/neqo/tree/main/neqo-bin/src/server - http3 and http09 implementation - used for manual testing and QUIC Interop 2. https://searchfox.org/mozilla-central/source/netwerk/test/http3server/src/main.rs - used to test Firefox I assume one was once an exact copy of the other. Both implement their own I/O, event loop, ... Since then, the two implementations diverged significantly. Especially (1) saw a lot of improvements in recent months: - #1564 - #1569 - #1578 - #1581 - #1604 - #1612 - #1676 - #1692 - #1707 - #1708 - #1727 - #1753 - #1756 - #1766 - #1772 - #1786 - #1787 - #1788 - #1794 - #1806 - #1808 - #1848 - #1866 At this point, bugs in (2) are hard to fix, see e.g. #1801. This commit merges (2) into (1), thus removing all duplicate logic and having (2) benefit from all the recent improvements to (1). * Move firefox.rs to mozilla-central * Reduce HttpServer trait functions * Extract constructor * Remove unused deps * Remove clap color feature Nice to have. Adds multiple dependencies. Hard to justify for mozilla-central.

mxinden requested review from KershawChang, martinthomson and larseggert as code owners February 28, 2024 17:57

mxinden commented Feb 28, 2024

View reviewed changes

neqo-client/src/main.rs Outdated Show resolved Hide resolved

mxinden changed the title ~~feat(client.server): use neqo_common::log~~ feat(client,server): use neqo_common::log Feb 28, 2024

feat(client,server): rework logging

e2732e6

- In `neqo-client` and `neqo-server` use `neqo_common::log` instead of `println!` and `eprintln!`. - Add `-q`, `-v`, `-vv`, `-vvv`, `-vvvv` log level flags via `clap_verbosity_flag`. - Set default log level to INFO. Demote many `qinfo!` to `qdebug!`.

mxinden force-pushed the common-log branch from 97945a4 to e2732e6 Compare March 19, 2024 13:20

mxinden changed the title ~~feat(client,server): use neqo_common::log~~ feat(client,server): rework logging Mar 19, 2024

larseggert reviewed Mar 19, 2024

View reviewed changes

KershawChang reviewed Mar 19, 2024

View reviewed changes

neqo-transport/src/cc/classic_cc.rs Show resolved Hide resolved

martinthomson approved these changes Mar 19, 2024

View reviewed changes

mxinden added 3 commits March 21, 2024 09:23

fix(upload_test.sh): set RUST_LOG debug for neqo_transport::cc

b090a93

Needed in order for mozlog_neqo_cwnd.py to analyze cc.

Additional level reductions

46bcb9b

Trigger CI

3a048af

larseggert enabled auto-merge March 21, 2024 21:56

larseggert approved these changes Mar 21, 2024

View reviewed changes

Merge branch 'main' into common-log

4227f8d

larseggert added this pull request to the merge queue Mar 21, 2024

Merged via the queue into mozilla:main with commit e4bc0c1 Mar 21, 2024
12 of 13 checks passed

mxinden mentioned this pull request Apr 19, 2024

fix(bin): consider env when no verbosity flag is set #1848

Merged

mxinden mentioned this pull request May 4, 2024

refactor: enable mozilla-central http3server to use neqo-bin #1878

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(client,server): rework logging #1692

feat(client,server): rework logging #1692

mxinden commented Feb 28, 2024 •

edited

Loading

mxinden commented Mar 1, 2024

mxinden commented Mar 5, 2024

larseggert commented Mar 5, 2024

KershawChang commented Mar 5, 2024

larseggert commented Mar 18, 2024 •

edited

Loading

mxinden commented Mar 18, 2024

mxinden commented Mar 19, 2024

larseggert left a comment

feat(client,server): rework logging #1692

feat(client,server): rework logging #1692

Conversation

mxinden commented Feb 28, 2024 • edited Loading

mxinden commented Mar 1, 2024

mxinden commented Mar 5, 2024

larseggert commented Mar 5, 2024

KershawChang commented Mar 5, 2024

larseggert commented Mar 18, 2024 • edited Loading

mxinden commented Mar 18, 2024

mxinden commented Mar 19, 2024

larseggert left a comment

Choose a reason for hiding this comment

mxinden commented Feb 28, 2024 •

edited

Loading

larseggert commented Mar 18, 2024 •

edited

Loading