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

Add filters for emitting Tracing diagnostics #656

Merged
merged 28 commits into from
Jul 17, 2020

Conversation

hawkw
Copy link
Contributor

@hawkw hawkw commented Jul 16, 2020

The tracing crate and related libraries provide an interface for Rust
libraries and applications to emit and consume structured, contextual,
and async-aware diagnostic information. tracing is maintained by the
Tokio project and is becoming widely adopted by other libraries in the
stack Warp uses, such as hyper, h2, and tonic and in other
parts of the broader Rust ecosystem.

This PR provides a new warp::trace module with filters to be used
when instrumenting Warp applications with tracing. This has to be
implemented inside of warp, because correctly instrumenting futures
with tracing spans requires the ability to wrap the future returned
by the inner filter. This branch is based on my PR #655, which migrates
Warp's internal diagnostics to Tracing.

This branch builds on the work done by @barskern in #408. I've updated
his branch to be based on the latest Warp master, added the convenience
filter for naming routes, example, and improved documentation from [my
initial attempt][1] at adding Tracing support to Warp, and made some
tweaks to the formatting of the generated traces and the user-facing
API. But, an equal amount of the credit goes to @barskern! <3

Here's some sample output from the tracing example:
Screenshot_20200716_162141

Closes #288
Depends on #655

Co-authored-by: Ole Martin Ruud barskern@outlook.com
Signed-off-by: Eliza Weisman eliza@buoyant.io

hawkw and others added 15 commits July 16, 2020 10:10
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
...we can still avoid round-tripping through the subscriber to clone the
span, though.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
we are not building an access log with our structured fields

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added 2 commits July 16, 2020 14:41
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
src/filters/trace.rs Outdated Show resolved Hide resolved
src/filters/trace.rs Outdated Show resolved Hide resolved
src/filters/trace.rs Outdated Show resolved Hide resolved
@seanmonstar
Copy link
Owner

I merged #655, which looks like this was based on. Mind rebasing master with this?

@hawkw
Copy link
Contributor Author

hawkw commented Jul 17, 2020

@seanmonstar should be good now, I think?

src/filters/trace.rs Outdated Show resolved Hide resolved
wmain and others added 3 commits July 17, 2020 10:15
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added 4 commits July 17, 2020 10:28
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
Copy link
Contributor Author

hawkw commented Jul 17, 2020

@seanmonstar okay, I fixed the mismatched targets, and also made a couple more tweaks to hopefully get more readable logs from the default warp::trace::request() filter. The user-agent string and request headers are now in a debug event inside the request span, rather than added to the span context, as they make every log line incredibly long:
Screenshot_20200717_103137

Hopefully you folks agree that this is more usable?

@seanmonstar
Copy link
Owner

Yes, that's a nice improvement! Looking again, perhaps the user-agent shouldn't be included separately if the full headers are also included, because then it appears twice.

@hawkw
Copy link
Contributor Author

hawkw commented Jul 17, 2020

Yes, that's a nice improvement! Looking again, perhaps the user-agent shouldn't be included separately if the full headers are also included, because then it appears twice.

Good call --- fixed it!

Comment on lines +245 to +247
Ok((Traced(resp),)) => {
tracing::info!(target: "warp::filters::trace", status = resp.status().as_u16(), "finished processing with success");
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it intentional that the log level (INFO/WARN/ERROR) is determined based on whether the result is Ok or a Err(Rejection)?

I would expect that if a filter returns an explicit reply (*) with 4xx or 5xx, this should still be logged as WARN/ERROR respectively, same as built-in known rejections that result in 4xx/5xx.

(*) such as when adhering to "not all errors are rejections" philosophy

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add tracing support
6 participants