Improve Logging

[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 :+1: 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 :smiley:

[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: https://github.com/SergioBenitez/Rocket/issues/109 - particularly this comment: https://github.com/SergioBenitez/Rocket/issues/109#issuecomment-300326193

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

[scuzzycheese]

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.

[Michael-F-Bryan]

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 :disappointed:

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)

[SergioBenitez]

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.

[wfxr]

Is there any progress?

[pwoolcoc]

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

[biot023]

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.

[pwoolcoc]

@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");

[davidhalperin]

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.

[Thomasdezeeuw]

@davidhalperin log is gaining to ability to log structured data, see https://github.com/rust-lang-nursery/log/pull/296. It might take a little longer then this december though.

[davidhalperin]

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

[Thomasdezeeuw]

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

[dpc]

@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: https://github.com/rust-lang-nursery/log/issues/149 log RFC on structured logging: https://github.com/rust-lang-nursery/log/pull/296