Adopt Tracing

[hawkw]

This branch begins the process of migrating Rocket from using the log
crate for diagnostics to using tracing.

The motivation for switching from log to tracing was discussed in
detail on issue #21, in particular, in this comment and later. In
summary, tracing allows detailed tracking of contexts in programs,
including asynchronous ones. This is essentially a structured,
machine-readable form of the contexts that Rocket's current logging
system conveys through indentation. Additionally, tracing data can be
consumed to emit data in a wide variety of formats, and is
backward-compatible with libraries that use the log crate.

This branch begins the migration by doing the following:

• Adding a trace module with re-exports of core tracing APIs
• Adding a tracing_subscriber::Layer implementation that performs
  "Rocket-style" log formatting for tracing spans and events, and
  setting it as the default unless a tracing subscriber is set by
  the user
• Replacing all existing uses of the log macros with their tracing
  equivalents.

Furthermore, I've begun the process of converting the existing logging
to more idiomatic tracing. I've added tracing spans to several
top-level scopes in Rocket, converted some log messages to structured
events, and replaced some existing uses of indentation with tracing
spans. Hopefully, this can serve as an example for others to continue
the migration and add tracing instrumentation in new code.

When possible, I've tried to keep the logging format as close to
Rocket's existing logging. I've made a few tweaks to help communicate
more of the structured data that tracing diagnostics record, but
the emoji and stuff are all still there. Of course, I am open to making
additional changes to the default format if desired.

I've also re-exported some core tracing APIs to try to provide a`
batteries-included experience, which seems in keeping with Rocket's
philosophy. If other folks like this, we can add more re-exports; if
we don't, it's fine to remove them.

Potential future work that this PR unlocks includes:

• Adding Rocket middleware for adding additional user-provided
  tracing instrumentation.
• Adding middleware for integrating with distributed tracing
  using tracing-opentelemetry and trace propagation
  headers like b3.
• Adding middleware for emitting [Server-Timing] headers using
  tracing data (similar to tide-server-timing).
• Adding more detailed instrumentation to Rocket's internals.
• Integrating with error handling (using tracing-error).
• Ensuring that Rocket's code generation and tracing's
  #[instrument] attribute work together.

Enjoy, and please let me know if there are any questions!

[igalic]

i only see four or five instances of using a parent: &span. can you briefly elaborate under which circumstances you decide to actually group tracing messages in such a way?

[igalic]

🙋🏻‍♀️

[hawkw]

i only see four or five instances of using a parent: &span. can you briefly elaborate under which circumstances you decide to actually group tracing messages in such a way?

first, the parent span context of an event can actually be set in two ways: it can be explicitly passed in via parent:, or, if no value for parent: is provided, it's inferred from the current span (the last span that was entered in the current scope). so,

let span = tracing::info_span!(...);
tracing::info!(parent: &span, ...);

and

let span = tracing::info_span!(...);
let _entered = span.enter();
// ...
tracing::info!(...);

will result in equivalent formatting for the event. as i mentioned in #1410 (comment), i used a mix of enter and explicit parents to try and reduce the number of lines in the diff, but maybe that was not a great idea, since it introduces more complexity for reviewers — i'll make it more consistent.

second, the reason that parents are not set everywhere is just because i started the process of replacing Rocket's current indentation-based logging contexts with spans, but didn't really have time to finish it. i made the change to some of the primary files in core, and then (in the interests of getting a PR up sooner rather than later) did the rest of the change via find-and-replace so that the code would still compile. the hope was that the parts of the codebase i did get to could be used as a model for other Rocket contributors to make the same changes elsewhere.

i'm happy to finish applying this transformation, but i got busy with other responsibilities and, after speaking with @SergioBenitez and @jebrosen, we decided that it was better to at least open a PR now, at least to start socializing the changes to other contributors. if we'd rather merge it in one go, i'm happy to keep the PR open while i update the rest of Rocket to use the same style.

[jebrosen]

rocket::support=info doesn't quite do what I wanted after all: I was trying to implement "show any messages at warn or above, and also any rocket::support messages at info or above", but it doesn't look like I can do that with EnvFilter since the global level warn takes precedence.

On the subject of logging levels, I would be slightly in favor of renaming some of LogLevel and/or changing the log level of some messages (e.g. info -> debug). It took me a while to get used to Debug also logging events at the trace level, and having no way to see events at the debug level without also getting info events.

---

I think the log output formatting at this point is pretty close to "good enough", and it's at least as good and in some ways better than current master. Here's one little wart that I'm still working on:

Warning: test warning 2, from log, log.target: "fairings", log.module_path: "fairings", log.file: "examples/fairings/src/main.rs", log.line: 63

• Skip printing the fields starting with log., and interpret them in WithFile instead.

[SergioBenitez]

rocket::support=info doesn't quite do what I wanted after all: I was trying to implement "show any messages at warn or above, and also any rocket::support messages at info or above", but it doesn't look like I can do that with EnvFilter since the global level warn takes precedence.

What does this mean for the state of "support" messages in the current PR?

On the subject of logging levels, I would be slightly in favor of renaming some of LogLevel and/or changing the log level of some messages (e.g. info -> debug). It took me a while to get used to Debug also logging events at the trace level, and having no way to see events at the debug level without also getting info events.

I agree. Perhaps we should simply use the names native to log/tracing.

[hawkw]

I think the log output formatting at this point is pretty close to "good enough", and it's at least as good and in some ways better than current master. Here's one little wart that I'm still working on:

Warning: test warning 2, from log, log.target: "fairings", log.module_path: "fairings", log.file: "examples/fairings/src/main.rs", log.line: 63

* [ ]  Skip printing the fields starting with `log.`, and interpret them in `WithFile` instead.

There's existing machinery for normalizing the log crate's metadata into the same format used by tracing events, the default formatters in tracing-subscriber use this. I can push a commit to add it in Rocket's formatter, as well --- i forgot to when I wrote the initial implementation.

[jebrosen]

What does this mean for the state of "support" messages in the current PR?

I believe this is unchanged: "support" messages are not specially surfaced either before or after this PR. AFAICT the main obstacle is setting only support messages to log at a more verbose level than the global limit; neither log nor tracing seems to support this directly.

I agree. Perhaps we should simply use the names native to log/tracing.

In that vein, does this look appropriate?

        LogLevel::Error => "error,hyper=off,rustls=off",
        LogLevel::Warn => "warn,hyper=off,rustls=off",
        LogLevel::Info => "info,hyper=off,rustls=off",
        LogLevel::Debug => "debug",
        LogLevel::Trace => "trace",
        LogLevel::Off => "off",

If we're concerned about compatibility, we could also accept critical as an alias for warn, and normal as an alias for info.

Then either in this PR or separately we could, if we wish, downgrade some info messages to debug, thereby making info more useful or maybe even identical to the desired "support" log level.

Use of span and entering a span is inconsistent.

I haven't forgotten this!

[hawkw]

rocket::support=info doesn't quite do what I wanted after all: I was trying to implement "show any messages at warn or above, and also any rocket::support messages at info or above", but it doesn't look like I can do that with EnvFilter since the global level warn takes precedence.

Hmm, that seems like a bug in the EnvFilter implementation? If you don't mind, can you make sure that Rocket depends on the latest tracing version, and if it isn't, open an issue against tracing? That should work...

[jebrosen]

The "wrong" behavior with support was actually my typo; it actually works exactly how I hoped it would. The CI failures are #1477.

[hawkw]

The "wrong" behavior with support was actually my typo; it actually works exactly how I hoped it would. The CI failures are #1477.

Oh, whoops! Glad it wasn't an upstream bug! :)

[jebrosen]

I'm pretty happy with this. Here are the last few things I think this needs at this point:

• A rebase to get CI passing.
• Consider changing 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 ad-hoc together that seemed to look nice on 64-bit systems.
• A review from @SergioBenitez
• Any remaining touchups on docs, and re-exports.
  • Potentially re-export the entire tracing and tracing-subscriber crates, like is done for futures, tokio, and figment today.

[felipesere]

Anything that I could do to help this along? I've locally merged master into it and worked as I expected.

[SergioBenitez]

@felipesere This is currently waiting on me to merge a big change before we rebase this on master.

[SergioBenitez]

Okay, after forever, I am now ready to review this, pending a rebase on/fix-up for master, of course.

Really excited for this.

[jebrosen]

I have tentatively pushed this to my fork to run CI and pick up any obvious mistakes (master...jebrosen:tracing-rebase-202103).

Due to merge commits and the recent changes in master, I decided again this time to manually re-apply all of the changes at once. So, this will need at least one more full look-through from me to make sure I did not lose anything important along the way. Before or after that I can either open a new PR or force-push over the branch - any preferences here, @hawkw @SergioBenitez?

[SergioBenitez]

Before or after that I can either open a new PR or force-push over the branch - any preferences here, @hawkw @SergioBenitez?

Whatever makes life easier for you two!

[SergioBenitez]

@jebrosen Just checking in: should I be reviewing something somewhere?

[SergioBenitez]

Moved to #1579.