feat(logging): add a tracing span per JSON-RPC call
#722
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
niklasad1
changed the title
tracing span per calltracing span per call
niklasad1
force-pushed
the
na-make-logging-less-verbose
branch
from
27391f2 to
5fbdcbf
Compare
niklasad1
changed the title
tracing span per calltracing span per call
jsdw
reviewed
Jun 16, 2022
|
|
||
| /// Find the next char boundary to truncate at. | ||
| fn truncate_at_char_boundary(s: &str, max: u32) -> &str { | ||
| match s.char_indices().nth(max as usize) { |
There was a problem hiding this comment.
This is quite an expensive thing to do relatively speaking, but I guess we only do it for TRACE level logs which are only used in exceptional cases!
A quick optimisation might be to check s.len() < max first, and if that is true, there is def no need to truncate?
jsdw
reviewed
Jun 16, 2022
|
|
||
| /// Find the next char boundary to truncate at. | ||
| fn truncate_at_char_boundary(s: &str, max: u32) -> &str { | ||
| match s.char_indices().nth(max as usize) { |
There was a problem hiding this comment.
This is quite an expensive thing to do relatively speaking, but I guess we only do it for TRACE level logs which are only used in exceptional cases!
A quick optimisation might be to check s.len() < max first, and if that is true, there is def no need to truncate?
jsdw
approved these changes
Jun 16, 2022
lexnv
approved these changes
Jun 20, 2022
niklasad1
commented
Jun 20, 2022
niklasad1
commented
Jun 20, 2022
niklasad1
commented
Jun 20, 2022
| serde_json::from_slice::<serde_json::Value>(&raw) | ||
| ); | ||
| return Err(Error::Custom("Unparsable response".into())); | ||
| let json = serde_json::from_slice::<serde_json::Value>(&raw); |
There was a problem hiding this comment.
the connection is killed here, we can propagate the entire response in the error then.
niklasad1
commented
Jun 20, 2022
niklasad1
changed the title
tracing span per calltracing span per JSON-RPC call
niklasad1
changed the title
tracing span per JSON-RPC calltracing span per JSON-RPC call
This was referenced Jun 21, 2022
niklasad1
added a commit
that referenced
this pull request
Jun 21, 2022
To include the bugfix for `tracing::enabled!` when `log` is enabled. Follow up on #722
niklasad1
added a commit
that referenced
this pull request
Jun 21, 2022
To include the bugfix for `tracing::enabled!` when `log` is enabled. Follow up on #722
longbowlu
reviewed
Jul 28, 2022
| /// | ||
| /// To enable this you need to call `RpcTracing::method_call("some_method").span().enable()`. | ||
| pub fn method_call(method: &str) -> Self { | ||
| Self(tracing::span!(tracing::Level::DEBUG, "method_call", %method)) |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Essentially this PR downgrades to only print request and response bodies when
trace!is enabled.In addition I have added a tracing span per call so it's possible to just trace specific method calls which could be quite useful I reckon.
For batches it's possible to just
log/traceby the targetbatchbecause the span is calledbatchso not possible to trace the individual calls inside it.The main motivation for tracing spans is for the servers where this can be super useful.
Example WS
2022-05-27T16:02:00.688793Z DEBUG jsonrpsee_client_transport::ws: Connecting to target: Target { sockaddrs: [127.0.0.1:35045], host: "127.0.0.1", host_header: "127.0.0.1:35045", _mode: Plain, path_and_query: "/" } 2022-05-27T16:02:00.689003Z INFO jsonrpsee_ws_server::server: Accepting new connection 1/100 2022-05-27T16:02:00.689562Z INFO jsonrpsee_client_transport::ws: Connection established to target: Target { sockaddrs: [], host: "127.0.0.1", host_header: "127.0.0.1:35045", _mode: Plain, path_and_query: "/" } 2022-05-27T16:02:00.689759Z TRACE method_call{method=say_hello}: jsonrpsee_core::tracing: send="{\"jsonrpc\":\"2.0\",\"id\":0,\"method\":\"say_hello\"}" 2022-05-27T16:02:00.689826Z TRACE jsonrpsee_client_transport::ws: send: {"jsonrpc":"2.0","id":0,"method":"say_hello"} 2022-05-27T16:02:00.690105Z TRACE method_call{method=say_hello}: jsonrpsee_core::tracing: recv="{\"jsonrpc\":\"2.0\",\"id\":0,\"method\":\"say_hello\",\"params\":null}" 2022-05-27T16:02:00.690160Z TRACE method_call{method=say_hello}: jsonrpsee_core::tracing: send="{\"jsonrpc\":\"2.0\",\"result\":\"lo\",\"id\":0}" 2022-05-27T16:02:00.690394Z TRACE method_call{method=say_hello}: jsonrpsee_core::tracing: recv="{\"jsonrpc\":\"2.0\",\"result\":\"lo\",\"id\":0}"Example HTTP
2022-05-27T15:30:09.114372Z TRACE method_call{method=say_hello}: jsonrpsee_core::tracing: send="{\"jsonrpc\":\"2.0\",\"id\":0,\"method\":\"say_hello\",\"params\":[1,2,3]}" 2022-05-27T15:30:09.114518Z TRACE method_call{method=say_hello}: hyper::client::pool: checkout waiting for idle connection: ("http", 127.0.0.1:45057) 2022-05-27T15:30:09.114600Z TRACE method_call{method=say_hello}: hyper::client::connect::http: Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(45057)) 2022-05-27T15:30:09.114653Z DEBUG method_call{method=say_hello}: hyper::client::connect::http: connecting to 127.0.0.1:45057 2022-05-27T15:30:09.114761Z TRACE method_call{method=say_hello}: mio::poll: registering event source with poller: token=Token(2), interests=READABLE | WRITABLE 2022-05-27T15:30:09.114968Z DEBUG method_call{method=say_hello}: hyper::client::connect::http: connected to 127.0.0.1:45057 2022-05-27T15:30:09.115012Z TRACE method_call{method=say_hello}: hyper::client::conn: client handshake Http1 2022-05-27T15:30:09.115048Z TRACE method_call{method=say_hello}: hyper::client::client: handshake complete, spawning background dispatcher task 2022-05-27T15:30:09.115162Z TRACE method_call{method=say_hello}: want: poll_want: taker wants! 2022-05-27T15:30:09.115199Z TRACE method_call{method=say_hello}: hyper::client::pool: checkout dropped for ("http", 127.0.0.1:45057) 2022-05-27T15:30:09.115715Z TRACE method_call{method=say_hello}: jsonrpsee_core::tracing: recv="{\"jsonrpc\":\"2.0\",\"id\":0,\"method\":\"say_hello\",\"params\":[1,2,3]}" 2022-05-27T15:30:09.115776Z TRACE method_call{method=say_hello}: jsonrpsee_core::tracing: send="{\"jsonrpc\":\"2.0\",\"result\":\"lo\",\"id\":0}" 2022-05-27T15:30:09.116148Z TRACE method_call{method=say_hello}: jsonrpsee_core::tracing: recv="{\"id\":0,\"jsonrpc\":\"2.0\",\"result\":\"lo\"}"