Add a tracing filter which enables contextual, structured logging #408
Conversation
|
I'm certainly interested in this, I think |
|
Part of the reason I hadn't (yet) was I figured that applications that wanted `tracing` could add it themselves. Do you find that's not the case?
I am not sure this would be possible to add with the current public API due to the fact that I used `Filter::with`. This gives a very nice abstraction over a wrapping a `Filter` with a tracing logger.
However in retrospect I think one could also get similar functionality by appending the span to the future returned by `Server::bind`. I will try this out. A limitation of this is that one cannot add different spans to different filters, which the implementation using `Filter::with` allows.
What would you say is key in this PR solving that problem?
Instead of providing tracing in warp, one could also expose e.g. `With` so that other libraries can create structs which wrap a filter.
…On 23/01/20 14:55, Sean McArthur wrote:
I'm certainly interested in this, I think `tracing` can add a lot of value. Part of the reason I hadn't (yet) was I figured that applications that wanted `tracing` could add it themselves. Do you find that's not the case? What would you say is key in this PR solving that problem?
--
You are receiving this because you authored the thread.
Reply to this email directly or view it on GitHub:
#408 (comment)
|
After some testing I haven't figured out a way to do this without access to In conclusion I think the best way forward would be to consider making |
|
hi, have you tried the new Filter to Service conversion? you can now wrap a warp filter: use std::convert::Infallible;
use warp::Filter;
use hyper::{Body, Request};
use tower_service::Service;
#[tokio::main]
async fn main() -> Result<(), hyper::error::Error> {
let route = warp::any().map(|| "Hello From Warp!");
let mut warp_svc = warp::service(route);
let make_svc = hyper::service::make_service_fn(move |_| async move {
let svc = hyper::service::service_fn(move |req: Request<Body>| async move {
println!("before request");
let resp = warp_svc.call(req).await;
println!("after request");
resp
});
Ok::<_, Infallible>(svc)
});
hyper::Server::bind(&([127, 0, 0, 1], 3030).into())
.serve(make_svc)
.await?;
Ok(())
} |
Oh no I haven't tried that. That looks very promising! Thank you for the tip. I will try it out a bit later today. |
|
There is also an in progress |
|
@jxs Your suggestion works perfectly (despite being a bit more verbose). Hence it is probably smarter to use this solution rather than adding dependencies and modifying If you are still interested in exploring using use hyper::{Body, Request};
use std::convert::Infallible;
use tower_service::Service;
use tracing_futures::Instrument;
use warp::Filter;
#[tokio::main]
async fn main() -> Result<(), hyper::error::Error> {
// Setup a log subscriber (responsible to print to output)
let subscriber = tracing_subscriber::fmt::Subscriber::builder()
.with_env_filter("tracing_service=trace")
.without_time()
.finish();
// Set the previously created subscriber as the global subscriber
tracing::subscriber::set_global_default(subscriber).unwrap();
// Redirect normal log messages to the tracing subscriber
tracing_log::LogTracer::init().unwrap();
let route = warp::any().map(|| "Hello From Warp!");
let mut warp_svc = warp::service(route);
let make_svc = hyper::service::make_service_fn(move |_| {
async move {
let svc = hyper::service::service_fn(move |req: Request<Body>| {
// FIXME instead of printing the entire request, we probably want to filter out
// some fields?
let span = tracing::info_span!("request", req = ?req);
async move {
tracing::info!("processing request");
let resp = warp_svc.call(req).await;
tracing::info!(status = ?resp.as_ref().unwrap().status().as_u16(), "processed request");
resp
}
.instrument(span)
});
Ok::<_, Infallible>(svc)
}
});
hyper::Server::bind(&([127, 0, 0, 1], 3030).into())
.serve(make_svc)
.await?;
Ok(())
}@LucioFranco I would probably rather use that if it was published, I will keep my eye on it. Thank you for the tip! EDIT: Modified the example to fix the usage of |
|
As an aside, would you be interested in having the code above as an example? |
|
Using the service function solution above I met some issues when the https://www.reddit.com/r/rust/comments/ettmfs/trouble_moving_clonable_hyperservice_into_async/ |
|
@barskern thank you! Also, you can avoid this issue cloning the service on every move, like that: |
Thanks for sharing this example. I have a question about this portion of the snippet: let span = tracing::info_span!("request", req = ?req);
let _guard = span.enter();In the |
|
Actually, in the service I am using this I have some problems with nested spans, and I think you just figured it out! I didn't know that was an issue in async code, but I will read the docs about it and edit the example accordingly. Thank you! 😄
EDIT: I fixed the example now 😄
…On 13/03/20 03:09, Corentin Henry wrote:
> @jxs Your suggestion works perfectly (despite being a bit more verbose). Hence it is probably smarter to use this solution rather than adding dependencies and modifying `warp`.
>
> If you are still interested in exploring using `tracing` instead of `log` in warp, I will leave this PR open for now. Feel free to close it or merge it when you find it applicable.
>
> ```rust
> use hyper::{Body, Request};
> use std::convert::Infallible;
> use tower_service::Service;
> use tracing_futures::Instrument;
> use warp::Filter;
>
> #[tokio::main]
> async fn main() -> Result<(), hyper::error::Error> {
> // Setup a log subscriber (responsible to print to output)
> let subscriber = tracing_subscriber::fmt::Subscriber::builder()
> .with_env_filter("tracing_service=trace")
> .without_time()
> .finish();
>
> // Set the previously created subscriber as the global subscriber
> tracing::subscriber::set_global_default(subscriber).unwrap();
> // Redirect normal log messages to the tracing subscriber
> tracing_log::LogTracer::init().unwrap();
>
>
> let route = warp::any().map(|| "Hello From Warp!");
> let mut warp_svc = warp::service(route);
>
> let make_svc = hyper::service::make_service_fn(move |_| {
> async move {
> let svc = hyper::service::service_fn(move |req: Request<Body>| {
> async move {
> // FIXME instead of printing the entire request, we probably want to filter out
> // some fields?
> let span = tracing::info_span!("request", req = ?req);
> let _guard = span.enter();
>
> tracing::info!("processing request");
> let resp = warp_svc.call(req).in_current_span().await;
> tracing::info!(status = ?resp.as_ref().unwrap().status().as_u16(), "processed request");
>
> resp
> }
> });
> Ok::<_, Infallible>(svc)
> }
> });
>
> hyper::Server::bind(&([127, 0, 0, 1], 3030).into())
> .serve(make_svc)
> .await?;
>
> Ok(())
> }
> ```
>
> @LucioFranco I would probably rather use that if it was published, I will keep my eye on it. Thank you for the tip!
Thanks for sharing this example. I have a question about this portion of the snippet:
```rust
let span = tracing::info_span!("request", req = ?req);
let _guard = span.enter();
```
In the `tracing` repo [there is a warning](https://github.com/tokio-rs/tracing#in-asynchronous-code) against using `span.enter()` in async code. Is it actually ok in this specific example?
--
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub:
#408 (comment)
|
|
Welp, I just went and wrote my own PR to add a Looks like @barskern and I have implemented more or less the same thing. My code is here if you want to compare notes. The one main difference in my PR is that I also added a let hello = warp::path("hello")
.and(warp::get())
.map(|| {
tracing::info!("saying hello...");
"Hello, World!"
})
.with(warp::trace::context("hello"));
let goodbye = warp::path("goodbye")
.and(warp::get())
.map(|| {
tracing::info!("saying goodbye...");
"So long and thanks for all the fish!"
})
.with(warp::trace::context("goodbye"));Using that, we can get nice nested traces like this: As for the question of whether or not Warp should provide |
|
That is why I didn't close this PR yet, because I sort of expected others to want this functionality aswell, and leaving it open makes it a bit easier to discover for others.
I really like the addition you made using `context`! That is a great way of adding useful information.
Further I think your argument regarding the "warp-ier" code by including this in `warp` is a good one. Currently using `tracing` with warp using my workaround (see earlier comment in this issue) is very verbose, quite "messy" and easy to get wrong (as I first had some borrowing issues and then a wrong usage of tracing).
I do however understand the maintenance burden of adding this feature, and that the nice API of warp is certainly due to a lack of non-essential features.
I think that it would be better to try to stabilize and unseal a version of the `With` (with the functionality of `WithSealed`) trait to enable this to be created in a separate library (see #16).
…On 30/03/20 17:33, Eliza Weisman wrote:
Welp, I just went and wrote my own PR to add a `tracing` filter PR, and only noticed this PR after I finished. Whoops!
Looks like @barskern and I have implemented more or less the same thing. My code is [here](master...hawkw:eliza/tracing) if you want to compare notes.
The one main difference in my PR is that I also added a `warp::trace::context` filter. This is just a convenience API for using `tracing` spans to name different filter stacks, like
```rust
let hello = warp::path("hello")
.and(warp::get())
.map(|| {
tracing::info!("saying hello...");
"Hello, World!"
})
.with(warp::trace::context("hello"));
let goodbye = warp::path("goodbye")
.and(warp::get())
.map(|| {
tracing::info!("saying goodbye...");
"So long and thanks for all the fish!"
})
.with(warp::trace::context("goodbye"));
```
Using that, we can get nice nested traces like this:
---
As for the question of whether or not Warp _should_ provide `tracing` support, I have some thoughts. It's definitely possible to get traces from Warp filters using the Tower compatibility, as folks have discussed above. However, this seems pretty ungainly, and something that's always seemed appealing to me about Warp is that it has a remarkably nice, fluent API. Providing Tracing `Filter`s instead of going through the Tower compatibility layer lets users write more concise, nicer looking, "warp-ier" code. I also appreciate Warp's relative minimalism, but the Tracing filters could always be a default-off feature.
--
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub:
#408 (comment)
|
|
With this implementation would the request's span be available in Right now this is my problem: I create a span for the request in Here is a snippet from my code to illustrate the problem: let download_global_weights = warp::get()
.and(warp::path::param::<ClientId>())
.and(warp::path::param::<Token>())
.and(handle.clone())
// handler
.and_then(move |id, token, handle| {
// in this span, I have the `client_id`
let span =
trace_span!(parent: parent_span.clone(), "api_download_request", client_id = %id);
handle_download_request(id, token, handle).instrument(span)
})
// here I won't have the `client_id` in the logs
.recover(handle_download_rejection)
.recover(handle_rejection) |
@little-dude I haven't tested, but I am quite certain that this implementation would make the span avaliable in the |
|
Super excited for this! |
|
Is there any progress on this issue? Or is there something we can do to help to fix it? As tracing is fundamental in my company, this is becoming a blocking issue for us. I know that there is a workaround using the We tried to reimplement it by ourselves but that implementation depends on private traits (BTW is there a reason not to make those traits/struct public?). |
|
I would really like tracing functionality added to Warp, and I don't think its practical to implement it outside of the library due to |
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
|
Thanks for exploring this, we've merged |
Tracing enables us to keep track of some contextual state throughout the lifetime of a request. This means that any logging done when processing a request will automatically also log the context. This is especially useful when processing requests in parallel because it means that one can separate intertwined logs.
The author of tracing made a good and informative video about the subject, and showing off some of the benefits.
This is based upon @emschwartz issue and his previous work.
This is mainly a rough first implementation to see if you would like this feature. If you are interested in this feature I was planning to go through all uses of
login the crate to replace with appropriatespan's andevent's. What do you think @seanmonstar ?Closes #288