Use 'tracing' library instead of 'log'. #1579

jebrosen · 2021-03-15T16:51:57Z

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:

SergioBenitez

I haven't read through trace.rs itself - I'll hold off on this until the rest of the code has undergone review - but I've left some comments on the rest of the changes. Some higher-level comments:

~~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.
~~If codegen depends on this, why are the --core tests passing?~~
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.
examples/todo should use rocket/tracing, not log.
The trace_env_logger example needs some motivation. Is it just there to
check that log integration "works"? In any case, hi should take and
return an &str, not String. What's more, every macro except trace is
used via rocket::; should we just import them?
Some config values on launch are colored white and others aren't.
In some places, tracing fields come before the message and sometimes after.
We should be consistent. trace!("msg", field = foo);
Sometimes span fields are used, sometimes they aren't. For example, when
logging config errors, why aren't all of those {} fields?
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?
Lots of lines now exceed 100 characters, largely those that name the
trace/span. We should avoid this.
The config changes are particularly difficult to read.
Running arbitrary, non-trace related code in_scope() feels quite wrong to
me. There must be a better way.

It seems like we really want a second macro, to avoid all of the .in_scope(|| { }):

// the `, $expr` should be optional.
error_span!("Some message", {
    info!("inside the span's scope");
});

contrib/lib/src/databases/connection.rs

contrib/lib/src/helmet/helmet.rs

SergioBenitez · 2021-03-17T01:09:22Z

contrib/lib/src/lib.rs

@@ -40,7 +40,7 @@
 //! This crate is expected to grow with time, bringing in outside crates to be
 //! officially supported by Rocket.

-#[allow(unused_imports)] #[macro_use] extern crate log;
+#[allow(unused_imports)] #[macro_use] extern crate tracing;


Should we be using whatever rocket is using?

What do you suggest changing here? I assume #[macro_use] was used to avoid needing to add use statements to each file, and I'm not aware of another way to do this (aside from making all of the different logging macros top-level exports from rocket, and #[macro_use] extern crate rocket;)

contrib/lib/src/serve.rs

contrib/lib/src/templates/context.rs

SergioBenitez · 2021-03-17T01:57:48Z

core/lib/src/rocket.rs

-                warn!("secrets enabled without a stable `secret_key`");
-                info_!("disable `secrets` feature or configure a `secret_key`");
-                info_!("this becomes an {} in non-debug profiles", Paint::red("error"));
+                warn_span!("unconfigured_secret_key", "secrets enabled without a stable `secret_key`").in_scope(|| {


Same here with code in_scope.

I don't think I agree on this particular usage. The more distance, if statements, etc. between calling enter() and the end of the scope, the harder it is to tell which messages are still "indented"; that's why I have (so far) used in_scope here. There is also the alternative of info!(parent: span, ..), although it is more repetitive than the other options.

SergioBenitez · 2021-03-17T02:01:51Z

core/lib/src/server.rs

+            .instrument(span)
+            .await
+
+    }.in_current_span());


Do we need both of these?

The instrument call is what set ups the Request: line in the log (and indents everything under it). (https://docs.rs/tracing/0.1.25/tracing/span/struct.Span.html#in-asynchronous-code explains why this is necessary)

The in_current_span is there for the same reason as the other call to it.

SergioBenitez · 2021-03-17T02:03:22Z

core/lib/src/server.rs

-    pub(crate) async fn handle_error<'s, 'r: 's>(
+    pub(crate) fn handle_error<'s, 'r: 's>(


Why this change? It seems unnecessary? The code also got harder to read.

In general, these tail instrument calls are hard to follow.

This could alternatively remain an async fn and use the #[instrument] attribute, like:

#[tracing::instrument( level = "warn", skip(self, status, req), fields(message = %format_args!("Responding with {} catcher.", Paint::red(&status)), )] pub(crate) async fn handle_error<'s, 'r: 's>( // ...

core/lib/src/server.rs

SergioBenitez · 2021-03-17T02:04:29Z

core/lib/src/server.rs

            }
        });

-        // NOTE: `hyper` uses `tokio::spawn()` as the default executor.
+        #[derive(Clone)]
+        struct InCurrentSpanExecutor;


Why is this here? Isn't this what .instrument() and .in_current_span() are for?

This is added so that hyper's calls to tokio::spawn will "inherit" the active spans (e.g. the current connection, request, etc.), instead of being logged at the root level.

jebrosen · 2021-03-20T20:23:45Z

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 · 2021-04-05T21:26:49Z

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 · 2021-04-05T21:33:01Z

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

'tracing' is now used for all messages and for Rocket's default logger. Co-authored-by: Eliza Weisman <eliza@buoyant.io> Co-authored-by: Jeb Rosen <jeb@jebrosen.com>

…fig fields unpainted

oren0e · 2022-01-06T10:35:13Z

Hi, any news about when should we expect the move to tracing to be completed? I was just trying to do something related in #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 · 2022-08-12T03:46:53Z

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 · 2023-03-31T15:30:42Z

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 · 2023-03-31T18:07:46Z

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

oren0e · 2023-03-31T18:17:29Z

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

SergioBenitez · 2023-03-31T18:43:50Z

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

oren0e · 2023-03-31T22:18:09Z

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

SergioBenitez · 2023-03-31T22:25:18Z

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

wrenix · 2023-05-20T14:04:23Z

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

maybe i would like to take a look

oren0e · 2023-05-20T14:08:38Z

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.

wrenix · 2023-05-20T14:15:45Z

contrib/lib/src/databases/connection.rs

@@ -62,8 +63,8 @@ async fn run_blocking<F, R>(job: F) -> R

 macro_rules! dberr {
    ($msg:literal, $db_name:expr, $efmt:literal, $error:expr, $rocket:expr) => ({
-        rocket::error!(concat!("database ", $msg, " error for pool named `{}`"), $db_name);
-        error_!($efmt, $error);
+        error!(concat!("database ", $msg, " error for pool named `{}`"), $db_name);


please just one log per message / error + please keep logmessage clean from values (it is easier to indexing, search and anonymize in log systems, if all values are in defined files):

Suggested change

error!(concat!("database ", $msg, " error for pool named `{}`"), $db_name);

error!(

database.name = $msg,

database.pool = $db_name,

error = $error,

$efmt

);

jebrosen requested a review from SergioBenitez March 15, 2021 16:51

SergioBenitez mentioned this pull request Mar 17, 2021

Adopt Tracing #1410

Closed

9 tasks

SergioBenitez requested changes Mar 17, 2021

View reviewed changes

jebrosen and others added 3 commits April 15, 2021 21:50

Use 'tracing' library instead of 'log'.

658e207

'tracing' is now used for all messages and for Rocket's default logger. Co-authored-by: Eliza Weisman <eliza@buoyant.io> Co-authored-by: Jeb Rosen <jeb@jebrosen.com>

change: log all field values default+bold by default, and log all con…

b1ab8c1

…fig fields unpainted

change: use stringify! in a few places in codegen

f2a7e25

jebrosen force-pushed the tracing-rebase-202103 branch from 9b822d8 to f2a7e25 Compare April 16, 2021 05:00

fix examples

41ffa45

SergioBenitez mentioned this pull request May 26, 2021

Improve Logging: Migrate to tracing #21

Open

SergioBenitez marked this pull request as draft June 30, 2021 21:16

somehowchris mentioned this pull request Jan 8, 2022

Questions & Suggestions somehowchris/rocket-tracing-fairing-example#3

Open

kvinwang mentioned this pull request Mar 14, 2023

pruntime: Structured logging with tracing Phala-Network/phala-blockchain#1199

Merged

SergioBenitez closed this Mar 31, 2023

wrenix reviewed May 20, 2023

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use 'tracing' library instead of 'log'. #1579

Use 'tracing' library instead of 'log'. #1579

jebrosen commented Mar 15, 2021 •

edited

SergioBenitez left a comment •

edited

SergioBenitez Mar 17, 2021

jebrosen Apr 5, 2021

SergioBenitez Mar 17, 2021

jebrosen Apr 5, 2021

SergioBenitez Mar 17, 2021

jebrosen Apr 5, 2021 •

edited

SergioBenitez Mar 17, 2021

hawkw Apr 5, 2021

SergioBenitez Mar 17, 2021

jebrosen Apr 5, 2021

jebrosen commented Mar 20, 2021

hawkw commented Apr 5, 2021

hawkw commented Apr 5, 2021

oren0e commented Jan 6, 2022

SohumB commented Aug 12, 2022

SergioBenitez commented Mar 31, 2023

SergioBenitez commented Mar 31, 2023

oren0e commented Mar 31, 2023

SergioBenitez commented Mar 31, 2023

oren0e commented Mar 31, 2023 •

edited

SergioBenitez commented Mar 31, 2023

wrenix commented May 20, 2023

oren0e commented May 20, 2023 •

edited

wrenix May 20, 2023

		pub(crate) async fn handle_error<'s, 'r: 's>(
		pub(crate) fn handle_error<'s, 'r: 's>(

-        error!(concat!("database ", $msg, " error for pool named `{}`"), $db_name);
+        error!(
+            database.name = $msg,
+            database.pool = $db_name,
+            error = $error,
+            $efmt
+        );

Use 'tracing' library instead of 'log'. #1579

Use 'tracing' library instead of 'log'. #1579

Conversation

jebrosen commented Mar 15, 2021 • edited

SergioBenitez left a comment • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jebrosen Apr 5, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jebrosen commented Mar 20, 2021

hawkw commented Apr 5, 2021

hawkw commented Apr 5, 2021

oren0e commented Jan 6, 2022

SohumB commented Aug 12, 2022

SergioBenitez commented Mar 31, 2023

SergioBenitez commented Mar 31, 2023

oren0e commented Mar 31, 2023

SergioBenitez commented Mar 31, 2023

oren0e commented Mar 31, 2023 • edited

SergioBenitez commented Mar 31, 2023

wrenix commented May 20, 2023

oren0e commented May 20, 2023 • edited

Choose a reason for hiding this comment

jebrosen commented Mar 15, 2021 •

edited

SergioBenitez left a comment •

edited

jebrosen Apr 5, 2021 •

edited

oren0e commented Mar 31, 2023 •

edited

oren0e commented May 20, 2023 •

edited