Use 'tracing' library instead of 'log'.

[jebrosen]

Supersedes #1410.

I likely missed a few spots and will need to make a few minor changes in follow-on commits, but this basically "ready to review".

TODOs:

• [x] examples/todo should use rocket::tracing, not log
• [x] trace_env_logger example: hi should take and return an &str, not String. And every macro except trace is used via rocket::; should we just import them?
• [x] Some config values on launch are colored white and others aren't.
• [ ] Change the hash used to disambiguate requests in the log, and/or the way it is formatted. Span Ids generated by Registry are a multi-level bit-packed generation index, and I threw something together that seemed to look nice on 64-bit systems.
• [x] Lots of lines now exceed 100 characters, largely those that name the trace/span. We should avoid this.
• [ ] Remove in_scope calls
  • [x] especially the large ones.
• [ ] Benchmark compile and run time with and without tracing's compile time filters to estimate overhead
• [ ] Integrate additions and changes made in logger.rs that have not been rebased into trace.rs
• [ ] Review every log message and make sure it's been updated if necessary
  • [ ] name spans consistently, to avoid confusion with message
  • [ ] Use span fields in more places. e.g.: config errors
• [ ] API organization, re-exports, and docs
  • [ ] Potentially re-export the entire tracing and tracing-subscriber crates, like is done for futures, tokio, and figment today.

[jebrosen]

I added most of those comments to the top-level comment as additional TODOs, and will keep working through them along with the other inline comments.

* The `trace_env_logger` example needs some motivation. Is it just there to
  check that `log` integration "works"?

I believe it was, yes. That, and/or as a demonstration to users how Rocket's and users's tracing messages look as viewed by a log-based logger. @hawkw ?

* In some places, tracing fields come before the message and sometimes after.
  We should be consistent. `trace!("msg", field = foo);`

The order is not flexible in that way: info!(field = value ..., "format", arguments) or info_span!("span_name", field = value ..., "format", arguments). I think this is a actually a consequence of:

* Why add a name to some spans and not others? What is the utility? Can we
  just use `module_name!()` or something to that effect?

Every span has a name. I mixed several of these up very early on, which now look like they have only a message, and never cleaned them all up.

* Running arbitrary, non-trace related code `in_scope()` feels quite wrong to
  me. There must be a better way.

Earlier versions of this PR did use the Span::enter API in more places, which returns a guard that exits the span when Dropped. However, the API depends on having some sort of task-local or thread-local state, which hasn't been nicely solved for async/await and is easy to misuse accidentally (see caveats in documentation). in_scope() is much more difficult to use in an incorrect way.

I do agree that some of the in_scope calls would be better as enter(), so that's also on the top-level todo list now.

[hawkw]

Answering some of the questions from above:

@jebrosen

I believe it was, yes. That, and/or as a demonstration to users how Rocket's and users's tracing messages look as viewed by a log-based logger. @hawkw ?

Yeah, that's correct; the example was supposed to demonstrate how to use Rocket with the log ecosystem. I thought this was valuable to provide for users who might already have a preferred log logger that they want to continue to use. It's probably not hugely important to provide an example of this, but I thought it's better to have more examples when possible?

@SergioBenitez

• Running arbitrary, non-trace related code in_scope() feels quite wrong to me. There must be a better way.

Running "arbitrary, non-trace related code" in in_scope is actually an intended use of the API; see the documentation for details. In general, correct use of tracing places any code that's part of the logical unit of work or context represented by a span inside that span --- this allows spans to be used not only for providing context to log messages, but also for timing code sections or for distributed tracing.

@jebrosen

• In some places, tracing fields come before the message and sometimes after. We should be consistent. trace!("msg", field = foo);

The order is not flexible in that way: info!(field = value ..., "format", arguments) or info_span!("span_name", field = value ..., "format", arguments).

Yeah, this is correct. Format-string-based messages must always come last in the tracing macros, as the macros must parse them as any number of arbitrary token trees in order to pass them to format_args!. Spans always have names, which are string literals that come first in the macro invocation, and may optionally have format string messages at the end of the macro invocation.

@SergioBenitez

• What is the overhead this is adding? This is now in the critical path. If we could really disable the feature, resulting in trace macro calls compiling to nothing, we should be able to measure this accurately.

See here for details on statically disabling specific tracing levels, or all traces, at compile-time. :)

Since the compile-time filtering is based on feature flags, which are always additive, a library dependency like Rocket should generally not enable them, since this prevents the user application from being able to configure them. However, we might want to document the existence of these feature flags in Rocket's docs so that users are aware of them, and they can be used for benchmarking.

[hawkw]

• ~The rocket library feature should be called tracing or similar.~ I see now that the log feature is for enabling compatibility with the log crate. It does not appear that we can disable tracing at all. What kind of compile-time overhead are we adding? What kind of runtime overhead are we adding?

• ~Is the feature intended to be disabled? If so,~ it should be documented in lib.rs, ~be added as a tested feature in scripts/test.sh, and explicitly enabled in examples that make use of it. If not, why is it a feature at all? At the moment, codegen seem to depend on this being enabled, so either this should be fixed or it shouldn't be a feature.~

It would also definitely be possible to make the tracing dependency itself optional. To do this, we would need to wrap the macros with Rocket's own macros that expand to nothing when the feature flag is disabled. I didn't do this since tracing's compile-time filtering is sufficient to avoid runtime overhead, and it was a lot of extra code. However, this would allow us to avoid downloading and compiling the tracing dependency when it's not in use.

[oren0e]

Hi, any news about when should we expect the move to tracing to be completed? I was just trying to do something related in https://github.com/SergioBenitez/Rocket/issues/982, i.e., insert a request_id to monitor the full cycle of a request-response. Currently I have to setup a custom subscriber and formatting layer like:

    LogTracer::init().expect("Unable to setup log tracer!");

    let (non_blocking_writer, _guard) = tracing_appender::non_blocking(std::io::stdout());
    let formatting_layer = fmt::layer().json().with_writer(non_blocking_writer);
    let subscriber = Registry::default()
        .with(EnvFilter::new(env!("LOG_LEVEL")))
        .with(formatting_layer);
    tracing::subscriber::set_global_default(subscriber).expect("Failed to set global subscriber");

    rocket_builder().launch();

Which is not ideal because it interferes with rocket's logging configuration and then I end up getting ugly jsons with terminal color codes in raw form, which look like the following:

{"timestamp":"2022-01-06T10:23:04.323575Z","level":"INFO","fields":{"message":"\u001b[1;49;39mOutcome:\u001b[0m \u001b[49;32mSuccess\u001b[0m","log.target":"_","log.module_path":"rocket::rocket","log.file":"/Users/me/.cargo/registry/src/github.com-1ecc6299db9ec823/rocket-0.4.10/src/rocket.rs","log.line":303},"target":"_"}

And notice that I don't have a request_id here as well for some reason...

[SohumB]

Hi there,

I notice this PR has stalled. Is there anything a third party (like me) can do to help push it along? I'm eagerly looking forward to using tracing in Rocket and would absolutely be willing to put work into making it happen.

Thanks!

[SergioBenitez]

I'm closing this as Jeb has indicated that he won't be able to push it forward. This is something I will personally prioritize for Rocket 0.6.

[SergioBenitez]

By the way: if anyone is interested in making this happen, I would love to actively mentor that person.

[oren0e]

I might be interested, let me check availability over the weekend and I'll get back to you with an answer.

[SergioBenitez]

@oren0e Sounds good! Hop on the Matrix channel if/when you're ready.

[oren0e]

ah what is the Matrix channel? You have a discord server?

[SergioBenitez]

It's in the README and the website. Here's a direct link: https://chat.mozilla.org/#/room/#rocket:mozilla.org

[wrenix]

any news @oren0e or @SergioBenitez or newer state of work?

maybe i would like to take a look

[oren0e]

You're welcome to work on this, I will try to help with this as much as I can but I think I can't be the owner of this migration currently. I initially thought that I will have much more time to devote to this task where in reality I have something like only 10% of my initial estimation. I'm sorry that I inform of this only now.