Improve Logging: Migrate to tracing

[SergioBenitez]

It's currently not possible to tap into Rocket's logging infrastructure in any easy way. Of course, logging is important, and so it's necessary to have a nice, clean API for Rocket applications to log messages. Libraries like slog and log, the latter currently used by Rocket, provide nice, structured ways to do this. Look into restructuring Rocket's logging to expose their functionalities.

The current alternative is to simply println to log.

[divoxx]

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.

[mehcode]

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.

[SergioBenitez]

@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.

[marcusball]

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?

[mehcode]

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

[SergioBenitez]

@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.

[Rukenshia]

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")]

[mehcode]

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.

[flybayer]

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

[marcusball]

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

[flybayer]

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

[mehcode]

@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.

[SergioBenitez]

Pushing to 0.4.

[dpc]

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.

[SergioBenitez]

@dpc Excited to see what you come up with!

[Boscop]

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

[jamesmunns]

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

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

[Boscop]

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!() :/

[Keshi]

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?

[SergioBenitez]

I have started implementing this in the tracing branch. I am ensuring that builds continue to work as I make progress so you can test as I work as I know there are many that have been waiting for this feature. As it stands, the branch contains complete but rudimentary support for tracing and completely removes all uses of log. Furthermore, Rocket's logger (now a Subscriber) is feature-gated behind the trace feature. If you disable the feature, Rocket will log zero messages and you can install your own Subscriber that logs exactly as you wish.

The rest of the work is as follows:

• assigning IDs to requests (there is a new RequestId layer that can tag requests with unique IDs)
• resolving latent issues with existing log messages such as Don't log error for HEAD requests which later match a GET route #1098 (these are now info messages)
• enable tracing-tree-like logging by default (no garbled concurrent requests) (new compact format)
• measuring the overhead of using tracing (~0.5%)
• converting all existing log messages to structured tracing events and spans
• add config option to switch between log formats

My work is building off of the incredible work done some time ago by @jebrosen and @hawkw - thank you.

[amyipdev]

I have a project in development using log that I'm upgrading from Rocket 0.5 to 0.6 to utilize the new HTTP/3 support. Is there a way to forward tracing logs through log to help keep my output looking consistent?

[the10thWiz]

@amyipdev Yes and no. The default Rocket subscriber can be disabled, and [https://docs.rs/tracing/latest/tracing/index.html#log-compatibility] explains how to configure tracing to produce a log on every span and event.

However, there will still be differences. There have been a number of other changes to how logging is handled within Rocket. I would actually recommend trying to use tracing instead. Tracing adds a unique request id, making it possible to identify what event are associated with which request. This is actually one of the primary motivations behind tracing, and Rocket's switch - multithreaded servers like Rocket often wind up with mixed logs, and it's impossible to follow a single request. Much like the older logging, you can take advantage of other tracing subscribers, and customize the output to look however you want.