Improve Logging about rocket HOT 60 OPEN

👋 Hi, I'm the primary author of tracing. Based on my understanding of Rocket's requirements, it does seem like tracing was designed pretty much for this exact use-case, especially in the upcoming async version of Rocket.. If you all are interested, I'd be happy to help out with a move to tracing, either by opening a PR or by providing guidance and answering questions.

Rocket could probably provide its own tracing Subscriber that implements formatting similar to what Rocket provides now (potentially enriched with the additional data available in tracing). However, given that tracing is capable of more than just logging (e.g. integrating with distributed tracing such as OpenTelemetry or Honeycomb; generating flamegraphs and histograms, etc), I think users will want to be able to override the default subscriber provided by Rocket to layer in additional functionality. This would also allow customizing the format if users prefer something different.

from rocket.

Another requirement: only include emojis on when running on OSX 😃

from rocket.

@NoraCodes Thanks to the efforts by @jebrosen and @hawkw, this will make it into 0.5!

from rocket.

Hello. I'm the author of slog. Since i released slog 2.0.0, I was going to do some toying with Rocket to relax and noticed this issue. I did some late evening investigation, and I think slog would work well in Rocket, due it it's flexibility and support for structured data. I even started to prototype something, but I'm unclear about what would be the best APIs.

Generally right now, the way I see it Rocket builder would get a new method, let's say set_logger. Now the biggest question is how to expose it to the request handler. It would be possible to implement FromRequest for Logger object. But it's kind of a noise, while I'm guessing Requests are going to be mostly linear in nature so having them always handy in a thread_local makes sense. Something like mentioned already slog-scope would work, though maybe rocket should just have the macros copied inside itself, so user doesn't even have to do #[macro_use] extern crate slog-scope.

Now the question is how the stream of logging records from user-provided handler should relate to the logging messages logged by rocket framework itself. Generally slog allows expressing any combination. User-provided Logger could get Rocket messages along with user handler messages, rocket could have it's own Drain and print it's messages separately or both.

Once I find some time, I'll attempt to complete some PoC, and will keep my eyes on opinions here.

from rocket.

@flybayer That's not possible to detect as its a configuration issue on your end with your font missing the glyphs.

I'd prefer it if we just dropped the emojii but this isn't my decision.

from rocket.

I believe the development story for Rocket's logger could be improved.

Rocket currently logs an incoming request like:

GET /239:
    => Matched: GET /<id>
    => Outcome: Success
    => Response succeeded.

Here are some possible improvement (during development):'

• Matched could include the file and line number where the matched function is.
• Response succeeded. is redundant. Response: 200 OK (20ms) provides useful additional information.
• Not a huge fan of printing the Outcome unless its a Forward as its redundant otherwise.

Here is what I want for a production log (for the sake of discussion).

• (before request) generates a request ID (uuid v1) or uses X-Request-ID and stores the current time
• sets a slog_scope that allows me to log inside a request handler and be associated with the request ID
• (after request) log:

{
    "timestamp": "2017-03-17T01:19:36Z",
    "request_id": "...",
    "remote_ip": "127.0.0.1",
    "host": "...",
    "bytes_in": 210,
    "referer": "...",
    "user_agent": "...",
    "method": "GET",
    "uri": "/contact?friend=true",
    "status": 200,
    "bytes_out": 5302,
    "latency": 3200
}

That's in JSON because that's how I want it, in JSON. My eventual plan was to use rocket::custom and setup a drain in fn main after I finished that PR.

@SergioBenitez We've talked about "compressed" vs "expanded" logs.

Here's an idea how a "single-line" version of Rocket's current logs could look. I still feel that a before-request log entry should not be an "info" log.

Mar 17 01:43:56 DEBG GET /contact?friend=true => GET /contact?{friend} [./handlers/contact.rs:10]
Mar 17 01:44:56 INFO GET /contact?friend=true => 200 (3.12ms)

To be honest I like this format as-it-stands much better than Rocket's current log format. My idea to make it work is to use https://github.com/slog-rs/term but submit a PR to slog-term that would allow us to define a "format method" to format the structured record. This way we can shove a big bunch of data that I would love and would expose via slog-json in production usage.

from rocket.

@SergioBenitez @jebrosen I just thought I'd let you know that I've just opened #1410 for the initial tracing adoption. I've tried to include a decent amount of documentation in that PR, hopefully it's helpful.

Sorry for keeping you all waiting!

from rocket.

Two ideas for general requirements (sorry, I know it's late in the process); take them or leave them.

1. It would be really nice if we could programmatically configure values to censor from our logs, or at least turn off specific config flags during the initial log lines. I was none too pleased to see my Oauth2 credentials logged out on startup.
2. For those of us emitting JSON logs to ELK & similar, it would be nice if we could configure application wide tags (fields in tracing parlance) to be emitted by all log calls for things like application name, version, etc. This would save a lot of duplication at log call site.

from rocket.

No. If an issue is open, it is not resolved.

from rocket.

I don't know if anyone has commented on this before, but I noticed that the launch_info macro logs as an error:

macro_rules! launch_info {
    ($format:expr, $($args:expr),*) => {
        error!(target: "launch", $format, $($args),*)
    }
}

This means that when you launch rocket, in your logs, you end up with something like this:
2017-09-09T19:40:06.856260+02:00 ERROR launch - 🚀 Rocket has launched from http://localhost:8000

Do you think maybe it should be info! rather than error! ?

Thanks.

from rocket.

@hawkw It's increasingly clear that we should use tracing for logging. I'd love an initial PR migrating Rocket to the library in which we can discuss design decisions.

from rocket.

Oh, and, I forgot to mention: if I change the hello_world example to configure a different tracing subscriber before calling rocket::ignite, like this:

#[launch]
fn rocket() -> rocket::Rocket {
    tracing_subscriber::fmt().init();
    rocket::ignite().mount("/", routes![hello])
}

I get tracing_subscriber::fmt's default format, and the logs are still quite nice:

The Rocket-specific fanciness is gone, but the reader still gets all of the same contextual information.

from rocket.

Check this out:

from rocket.

@jebrosen @SergioBenitez here is a rough attempt at writing a Rocket-style formatter using tracing_subscriber:

In contrast, here's the current master (so you can see how it looks with my terminal color scheme, etc):

It's a little less fancy than what Rocket does currently, but in return for that, we get: the ability to generate contexts automatically from tracing spans, rather than by hand with magic _ targets, emit structured logs that can be consumed by other tracing subscribers as well, and format per-request contexts nicely even when multiple concurrrent requests are in flight (which I'll demo soon).

from rocket.

A while back I wrote a small Fairing for slog loggers that you can use. I just dusted it off and fixed it up a little bit, and published it: https://crates.io/crates/rocket-slog.

There is an example in the README: https://gitlab.com/pwoolcoc/rocket-slog-fairing/blob/master/README.adoc that shows how it's used. The API to use it within handlers is still a bit rough, I'm looking into what I can do to make it better. The API is in a pretty good place now. I set up a small test project that is basically the example from the README, and this is the output from application start-up and a request to GET /:

    Finished dev [unoptimized + debuginfo] target(s) in 9.68s                                                                                                                                
     Running `target/debug/rocket-test-proj`
Oct 11 12:39:14.617 INFO config, value: Development, key: environment, version: 0.1.0
Oct 11 12:39:14.618 INFO config, value: localhost, key: address, version: 0.1.0
Oct 11 12:39:14.619 INFO config, value: 8000, key: port, version: 0.1.0
Oct 11 12:39:14.619 INFO config, value: 8, key: workers, version: 0.1.0
Oct 11 12:39:14.620 INFO config, value: Normal, key: log_level, version: 0.1.0
Oct 11 12:39:14.621 INFO config, value: 32768, key: forms limit, version: 0.1.0
Oct 11 12:39:14.621 INFO config, value: "/home/paul/code/rocket-test-proj/Rocket.custom.toml", key: config_path, version: 0.1.0                                                              
Oct 11 12:39:14.622 INFO route, method: GET, path: /, base: /, version: 0.1.0
Oct 11 12:39:14.623 INFO listening, address: http://localhost:8000, version: 0.1.0
Oct 11 12:39:28.492 INFO request, uri: "/", method: Get, version: 0.1.0
Oct 11 12:39:28.493 DEBG THIS IS A CUSTOM MESSAGE, version: 0.1.0
Oct 11 12:39:28.493 INFO response, status: 200 OK, route: GET /, version: 0.1.0

There isn't much involved in the fairing, I'm sure there is a lot of room for improvement, so PRs welcome, etc etc.

cc @dpc @wfxr @SergioBenitez

from rocket.

@Thomasdezeeuw If and when log gets support for structured output, then slog will most probably become a library on top of log (instead of being alternative with a backward and forward adapters to log). Right now there is no will to add "context" to log, so for any bigger, multi-threaded system, that carries a lot of context slog will probably stay a primary choice.

Relevant log issue: rust-lang/log#149
log RFC on structured logging: rust-lang/log#296

from rocket.

It is now clear that this will not sadly not make it to 0.5. Pushing forward.

from rocket.

Is there any progress?

from rocket.

@SergioBenitez Great! I'm currently pretty busy, but I can definitely find the time for an initial PR that others can build on once it lands. I might need to ask some additional questions about Rocket internals...

from rocket.

@mehcode I'd love to see how this would look! I have a few requirements for Rocket's "next-gen" logging:

1. Every log statement should have a Request associated with it for easy filtering.
2. You should be able to log without using a macro.
3. Log messages should look pretty by default. I really like the way they look now.
4. You should be able to switch to a "compact" mode.
5. Logging should not look garbled amidst concurrent requests.
6. Logging should have zero overhead in the presence of no errors after initialization in release.
7. Users should be able to log at any level trivially.
8. Rocket should be able to colorize output as it wishes.

Whatever log solution we go with should meet these requirements.

from rocket.

Is there currently no way for me to use log or slog? Everytime I try to, the compiler complains about error: macro `error` may not be used in attributes because both rocket and (s)log provide an error macro. Even if I drop the error macro and i.e. macro_use just log, I get

error: no method named `log` found for type `&'static str` in the current scope
 --> src/routes/user/mod.rs:7:1
  |
7 | #[get("/login")]

from rocket.

Some notes and questions after taking a quick look at the current state of Rocket logging:

We can provide a default tracing subscriber implementation, and set it as the default if the user hasn't already configured a subscriber. This is similar to how the current approach works when env_logger (or similar) are used. However, unlike log, tracing also provides a system for composing together multiple Layers that implement different behavior. We may also want to provide the default Rocket logging behavior as a public Layer type, so that users can combine it with Layers that implement other behaviors (like distributed tracing, or metrics).

How important is it to match the current formatting exactly with the default subscriber? I noticed that Rocket currently uses indentation to indicate contexts. We definitely can implement something similar for displaying tracing spans. However, my experience has been that using indentation introduces some complexity in asynchronous systems: events may occur in multiple contexts, in an interleaved order. In order for indentation to properly communicate contexts, it's necessary to re-print the current span context whenever it changes, or to buffer the events occuring in a span until it ends, and then print them all in order, indented under that span. This may means not printing log lines as they're recorded, but waiting until a span (such as for a request) completes, like the tracing-tree crate does.

Alternatively, we could format contexts in a more line-oriented way which is what tracing_subscriber::fmt (the most commonly used log formatting subscriber in the tracing ecosystem) does. However, this would be a departure from the current format.

@SergioBenitez, any thoughts?

from rocket.

@jebrosen

I agree Rocket should provide some suitable default subscriber, and it should be possible to use a different subscriber - this all sounds relatively straightforward with feature flags, configuration, and/or runtime detection.

I think the easiest solution to this is to just have Rocket::mount call tracing::subscriber::set_global_default with its default subscriber, and ignore any errors returned by that function. Since the global default subscriber can only be set once, an error would indicate that the user code has already configured a default subscriber, and that's fine; if one has not been provided, Rocket will simply provide its own.

it looks to me so far like Rocket's "default subscriber" could be based on fmt::Subscriber/fmt::SubscriberBuilder (maybe only as an implementation detail)

Yup, I think the easiest way to get Rocket-specific formatting without having to reinvent the world is to just write a custom formatter for tracing_subscriber::fmt :)

Is it typical or recommended in the tracing ecosystem for layers to impl<S: Subscriber> Layer<S> for LayerType, or is it common to have subscriber-specific layers?

In general, Layer implementations will either support any S: Subscriber, or require S: Subscriber + for<'a> LookupSpan<'a> to require that the root subscriber also be capable of providing storage for span data that they can consume (like tracing_subscriber's Registry type). I haven't personally seen a Layer implementation that only layers with a specific Subscriber type, and I suspect that if someone does write them, it would probably be in order to implement functionality that is specific to and tightly coupled with that specific Subscriber.

Some responses will intentionally never finish completely, so I think we would either need to replace indentation with the line-oriented repetition, provide a flush mechanism to force early printing of queued messages, and/or start+stop spans at certain points - e.g. at the boundary between response generation and I/O. From some limited experimentation with tracing in a hyper server without rocket, I find the line-oriented approach readable albeit redundant:

This is my thought as well. FWIW, note that the "line-oriented" approach doesn't really have to be single-line; it would be fine to use newlines and/or indentation to make the formatting prettier, as long as all the context is included in each log entry. For example, a pair of log lines (borrowed from your example, with the addition of a second span) that the tracing_subscriber::fmt default formatter would format like this:

Jul 21 11:39:14.618 DEBUG connection{remote_addr=127.0.0.1:6218}:request{path=/favicon.ico method=GET}: tokio_postgres::simple_query: executing simple query:
Jul 21 11:39:14.619 DEBUG connection{remote_addr=127.0.0.1:6218}:request{path=/favicon.ico method=GET}: tokio_postgres::prepare: preparing query s1: SELECT data FROM file WHERE name = $1  

could just as easily be rendered like

connection: remote_addr: 127.0.0.1:6218
  => request: path: /favicon.ico, method: GET
  => executing simple query

connection: remote_addr: 127.0.0.1:6218
  => request: path: /favicon.ico, method: GET
  =>  preparing query s1: SELECT data FROM file WHERE name = $1  

or something, which seems much closer to the pretty formatting that Rocket emits currently.

from rocket.

@SergioBenitez Thanks! Writing a formatter for tracing_subscriber::fmt that kept Rocket's personality without relying on special cases that won't play nice with other formatters was kind of a fun challenge. :)

from rocket.

Sorry, I missed this one.

Glad you're already thinking about it. Any thoughts around supporting structured logging? The main blocker I see is that sometimes for the same "event" (i.e. an error) you generate a warn and an error message instead of just one.

Is this something you'd be looking for help with? I'm happy to propose something but seems like you're already thinking about it.

from rocket.

I assume this is still up for grabs? I have some time off at the end of the year and I'm looking for a project to do and would like to give this a try. Slog has come up a few times here and seems like the right way to go to me. I've done a little bit of exploratory work switching Rocket to use slog internally, and expose a slog logger to handlers.

@SergioBenitez before I get any deeper in, any reservations about moving forward with slog? I'm not sure it meets all of your criteria but I don't think the log crate is superior in any areas you describe, and I'd be hesitant to try to build something new from scratch. Blow by blow below to be thorough, apologies it came out a little bit long. Assuming there's nothing below you'd consider a show stopper, I'll post a more detailed plan.

1. Every log statement should have a Request associated with it for easy filtering.

This is the clearest win for slog where we can initialize a logger object for a given request with a context, and every log message generated through that logger object will automatically include that context. Assuming we're good here.

2. You should be able to log without using a macro.

How big a concern is this? The reason given was to avoid requiring macro_use but that should no longer be necessary with the 2018 edition. Both log and slog canonically use macros to log and it seems well motivated to me:

• It allows the source location to be captured in the log message, which can be useful.
• It allows format! type functionality to be built in rather than having to compose with it.
• Slog will actually potentially compile out log calls below a threshold from production builds if you want so you can make a very chatty debug mode with 0 performance impact. That can't be done without the call happening through a macro.

3. Log messages should look pretty by default. I really like the way they look now.

Slog is a framework so a back-end that printed out console differently would be possible. I'd propose for MVP I just use default terminal logger (unless overridden by the user) and someone can make a prettier version later if it isn't to your taste. Screenshot on the slog github page: https://github.com/slog-rs/slog. I've confirmed the way Rocket adds color will continue to work with slog. The way Rocket does indentation doesn't really fit in and probably doesn't make sense concurrent things happening, so I'm probably going to remove that as part of the rework. I will be honest that I don't have the best artistic eye but would be happy to bikeshed the details of this in the ultimate PR assuming we have agreement the architectural direction I'm thinking of going in makes sense.

4. You should be able to switch to a "compact" mode.

Multiple back ends are possible so this shouldn't be an issue in principle. The terminal logger slog comes with has a full or compact mode, although I'm not 100% sure their compact mode is the same as what you're asking for. If that compact mode isn't what you're looking for and would like something on this up front, can you be more precise?

5. Logging should not look garbled amidst concurrent requests.

This would use the slog async crate so there'd be one logging thread that'd actually do IO and other threads would send messages through a channel. This should both prevent threads doing actual work from blocking and make sure only one log line is written at a time to prevent garbling.

6. Logging should have zero overhead in the presence of no errors after initialization in release.

I'm not sure I follow. Obviously logging a piece of data is doing some amount of work and would have some non-zero cost, right? See https://github.com/slog-rs/slog/wiki/What-makes-slog-fast on performance details for slog. Let me know if any concerns or specific things to dig in to.

7. Users should be able to log at any level trivially.

There's a macro for each log level, assuming we're good with macros this should be fine.

8. Rocket should be able to colorize output as it wishes.

Confirmed the terminal logger for slog will work with what Rocket does to color logs today.

from rocket.

I think with the ongoing async rewrite tracing would fulfill all requirements mentioned in #21 (comment) perfectly.

from rocket.

Please see #1579.

from rocket.

Heh. Guess I wasn't the only one who missed this. Apologies.

@SergioBenitez I'm itching to jump in and do something here. I can implement slog-rs in Rocket in a PR if that's the direction you'd like to go.

from rocket.

I pretty much agree with all of those. Though, I'm curious, what's your motivation behind 2?

I really like 5, but I'm concerned how that would be achieved. The most aesthetically pleasing would be to have logs associated with each request grouped together into a block; The simplest implementation of that—off the top of my head—would be to buffer the logs and dump them at the end of each request. Unfortunately, that wouldn't work well for debugging, as presumably you'd want to see logs leading to, for example, an incomplete request due to a panic.

An alternative would be to just prefix log lines with a request identifier, but that's not the most "pretty" of options. Perhaps these two could be used in combination with point 4, using the former for "non-compact", and the latter as a "compact" debug option, assuming I'm understanding the implication of "compact" correctly.

Do any of Rust's current log options meet point 6?

from rocket.

@SergioBenitez 👍 I'll take a crack at this then. You should have a PR in the next couple days.

from rocket.

@marcusball The main motivation for 2) is to be able to log messages from generated code without requiring the user to macro_use.

Number 5 is indeed pretty tricky, and I don't have a particularly good solution there. During development, we could simply set workers to 1, preventing this from happening at all. But this will stop being a solution when Rocket becomes async.

I think both log and slog try to meet point 6, but I'm not sure if they actually do.

from rocket.

Why only OSX? They work on Windows, and presumably other *nix variants as well.

from rocket.

@marcusball good point. Then only include them when supported :)

from rocket.

Pushing to 0.4.

from rocket.

@dpc Excited to see what you come up with!

from rocket.

I also get error: macro error may not be used in attributes :(
Is there any workaround?

from rocket.

Hey @Boscop - Check out this thread: #109 - particularly this comment: #109 (comment)

@SergioBenitez provides a reasonable workaround until this issue can be resolved.

from rocket.

Yes, I'm using this:

#[macro_use(trace, info, warn)] extern crate log;

But I wish there was a way to import the error macro as a different name.
Also I wish Rocket had a log level that logs debug but not trace messages.
Right now I have to use info!() instead of debug!() :/

from rocket.

Now the biggest question is how to expose it to the request handler. It would be possible to implement FromRequest for Logger object. But it's kind of a noise, while I'm guessing Requests are going to be mostly linear in nature so having them always handy in a thread_local makes sense.

I like @dpc's idea of passing a (wrapped) slog logger in via a request guard. That way you get nice things like a unique request ID, "scoped" logging, and you could make it so the logged statements are buffered up and then flushed in the Drop impl. It means you'd need to include a Logger parameter on all functions which need logging functionality though 😞

Comparing using a Logger request guard wrapping slog against @SergioBenitez's earlier checklist:

• 1 - generate a unique ID in the FromRequest impl and attach that to the logger
• 2 - I think... depends on how slog works under the hood though.
• 3 - depends on your definition of "pretty", although their terminal output example looks quite readable
• 4 - via the usual config mechanism
• 5 - The slog wrapper buffers log statements and only flushes on Drop
• 6 - if you don't include the request guard, you don't get a logger. You'd still have the startup costs that accompany logging though
• 7 - I don't know enough about slog to say, but I imagine this is doable
• 8 - (refer to point 3)

from rocket.

It seems pretty clear that this will slip to 0.5, so I'm officially marking it as such. If anyone is interested in spearheading the development here, I am happy to mentor.

from rocket.

I'd definitely bump this -- I'm really struggling developing with rocket atm because I can't debug.
Unless anyone can offer a simple way to debug in development?
I tried the example you gave, @pwoolcoc , but I got this error:

error: format argument must be a string literal           
  --> src/main.rs:63:26                                   
   |                                                      
63 |     debug!(logger.get(), debug_output);              
   |                          ^^^^^^^^^^^^                
help: you might be missing a string literal to format with
   |                                                      
63 |     debug!(logger.get(), "{}", debug_output);        
   |                          ^^^^^                       
                                                          
error: aborting due to previous error                     
                                                          
error: Could not compile `rocket-pastebin`.               
                                                          
To learn more, run the command again with --verbose.      

I was just trying to confirm that a filename that the code generates was correct -- is that sort of thing more easily possible?
I'm just on the pastebin example from the rocket guide atm but want to start proper development really soon.
Cheers,
Doug.

EDIT:
I should add that the variable debug_output in the error output is a String generated by the format!(...) macro.

from rocket.

@biot023 yes, just like the various format!, write!, and log crate macros, you'll need to have a format string where the error message indicates. If the format! call you are making comes right before the debug! call, you can collapse them into the same call:

before:

let msg = format!("{}", "this is my message");
debug!(logger.get(), "{}", msg);

after:

debug!(logger.get(), "{}", "this is my message");

from rocket.

@davidhalperin log is gaining to ability to log structured data, see rust-lang/log#296. It might take a little longer then this december though.

from rocket.

@Thomasdezeeuw I will of course, defer to the maintainers, but I'd argue for moving forward with slog for now anyway, unless there are other reasons to prefer log and wait for that. That's just feature parity with something slog can already do. Unless there's something I'm missing there, you'd need to manually pass the same set of key value pairs to every log statement associated with a request. That addresses structured data but not context and that seems important for this use case. So slog still seems preferable to me all else being equal. Additionally, it's not like we're taking away the choice of using the log facade for end users building on top of Rocket. They can still use the log + the slog_stdlog crate.

from rocket.

@davidhalperin I agree that slog is currently the better choice. However log aims to be the standard for logging in the Rust ecosystem. Which means that if it succeeds Rocket might be encouraged to change to log in the future. Which is something I wanted to point out to consider.

from rocket.

I just want to chime in and say that @hawkw is absolutely right. Wider adoption of Rocket in the organization I'm working with right now is significantly limited because we can't easily integrate with our cloud provider's log management solution.

from rocket.

We can provide a default tracing subscriber implementation, and set it as the default if the user hasn't already configured a subscriber. This is similar to how the current approach works when env_logger (or similar) are used. However, unlike log, tracing also provides a system for composing together multiple Layers that implement different behavior. We may also want to provide the default Rocket logging behavior as a public Layer type, so that users can combine it with Layers that implement other behaviors (like distributed tracing, or metrics).

I agree Rocket should provide some suitable default subscriber, and it should be possible to use a different subscriber - this all sounds relatively straightforward with feature flags, configuration, and/or runtime detection. I am still learning how all the different parts of tracing-subscriber interact and what types do and don't compose together; it looks to me so far like Rocket's "default subscriber" could be based on fmt::Subscriber/fmt::SubscriberBuilder (maybe only as an implementation detail). We should ideally support other Layers as you mentioned, whatever that looks like. Is it typical or recommended in the tracing ecosystem for layers to impl<S: Subscriber> Layer<S> for LayerType, or is it common to have subscriber-specific layers?

How important is it to match the current formatting exactly with the default subscriber? I noticed that Rocket currently uses indentation to indicate contexts. We definitely can implement something similar for displaying tracing spans. However, my experience has been that using indentation introduces some complexity in asynchronous systems: events may occur in multiple contexts, in an interleaved order. In order for indentation to properly communicate contexts, it's necessary to re-print the current span context whenever it changes, or to buffer the events occuring in a span until it ends, and then print them all in order, indented under that span. This may means not printing log lines as they're recorded, but waiting until a span (such as for a request) completes, like the tracing-tree crate does

Alternatively, we could format contexts in a more line-oriented way which is what tracing_subscriber::fmt (the most commonly used log formatting subscriber in the tracing ecosystem) does. However, this would be a departure from the current format.

This is tough! Some responses will intentionally never finish completely, so I think we would either need to replace indentation with the line-oriented repetition, provide a flush mechanism to force early printing of queued messages, and/or start+stop spans at certain points - e.g. at the boundary between response generation and I/O. From some limited experimentation with tracing in a hyper server without rocket, I find the line-oriented approach readable albeit redundant:

Jul 21 11:39:14.618 DEBUG request{path=/favicon.ico method=GET}: tokio_postgres::simple_query: executing simple query:     
Jul 21 11:39:14.619 DEBUG request{path=/favicon.ico method=GET}: tokio_postgres::prepare: preparing query s1: SELECT data FROM file WHERE name = $1    
Jul 21 11:39:14.624 DEBUG request{path=/favicon.ico method=GET}: tokio_postgres::query: executing statement s1 with parameters: ["favicon"]    
Jul 21 11:39:14.631  WARN request{path=/favicon.ico method=GET}: server: Responding with status 404 Not Found

from rocket.

@hawkw This is looking absolutely fantastic! Very excited for what you'll show us next.

from rocket.

@hawkw How are your efforts proceeding? Would absolutely love to ship your work in the next major release!

from rocket.

@hawkw How are your efforts proceeding? Would absolutely love to ship your work in the next major release!

Sorry, I've been quite busy, so I haven't had a whole lot of time to work on it.

Right now, I have a pretty solid implementation of a Subscriber for Rocket-style logging, and I've added tracing spans and more structured instrumentation to some of the top-level APIs and components in Rocket, but I haven't converted most of the more verbose debug and trace logging to use idiomatic tracing.

How would you feel about a PR for that initial work that the Rocket contributors could then use as a model for converting other parts of Rocket to use idiomatic tracing?

Note that the tracing subscriber I've implemented can currently collect all of the existing log records emitted by Rocket without any modification; the remaining work is largely just around adding tracing spans to represent scopes, and converting the existing events to emit more structured diagnostics.

from rocket.

How would you feel about a PR for that initial work that the Rocket contributors could then use as a model for converting other parts of Rocket to use idiomatic tracing?

That would be wonderful! If you could leave some notes/comments about what would be needed to finish the conversion, even better!

from rocket.

How would you feel about a PR for that initial work that the Rocket contributors could then use as a model for converting other parts of Rocket to use idiomatic tracing?

That would be wonderful! If you could leave some notes/comments about what would be needed to finish the conversion, even better!

That's the plan!

from rocket.

To be clear: this won't be coming in 0.5, correct? This affects product roadmaps at my employer (and, while I wish I could use company time to contribute to the project, I'm the only Rust dev and currently don't have time 😭).

from rocket.

That's amazing! Thank you @jebrosen @hawkw @SergioBenitez

from rocket.

@AshtonKem

It would be really nice if we could programmatically configure values to censor from our logs, or at least turn off specific config flags during the initial log lines. I was none too pleased to see my Oauth2 credentials logged out on startup.

I just want to point out that there is a crate for this, secrecy.

from rocket.

@AshtonKem

It would be really nice if we could programmatically configure values to censor from our logs, or at least turn off specific config flags during the initial log lines. I was none too pleased to see my Oauth2 credentials logged out on startup.

I just want to point out that there is a crate for this, secrecy.

That wouldn't solve help with the issue in 0.4. Nevertheless, this is already resolved in master, which no longer prints extras (because the concept of extras is gone).

from rocket.

Is this currently in 0.5.0-dev, or has it not landed yet?

from rocket.

This is sad news indeed but given the magnitude of things included in 0.5 it's perfectly understandable.

May I ask what were the main blockers for it not to make it to 0.5?
Are there specific areas where I might help to secure this for an ulterior release?

from rocket.

The issue mentioned in the last comment as the main blocker appears to be now closed, and the only remaining open linked issue sounds like it's blocked on this one. Is this issue currently still blocked by another issue?

from rocket.