Don't forward empty span messages to log #607
Comments
The problem is that it's really hard to present the contextual data that spans represent to If that's not the case, I'm certainly open to revisiting or removing them, although we should probably make sure that there aren't other users of the Ideally, I think we would want to have a better way of tracking span contexts & presenting that information to
I'm definitely open to changing that so that span creation is only logged when there are fields, especially if we remove some of the other span-related logs! |
I can see where you're coming from and that makes some sense, but I'd argue that if a user wants that contextual data, they should switch their output to a |
Sure, this is probably true...at the time, when I was writing the
This is true in the case of a library that previously used Here's a thought: what if the span enter/exit/close What do you think? |
|
Interesting idea, I like the sound of that, it would work well for my own use-case at least. |
|
Okay, I'll see if anyone else using the log integration has an opinion, and then we can make that change pretty easily. As a side note, @sagebind, thanks for the thoughtful discussion on this! I appreciate it! |
The more I think about it, the more I like this approach. It can also be a way of tackling/validating two independent issues—this proposed behavioral change and moving Hyper/h2 to I think this also has the nice side effect of (maybe!) driving more attention to the customizability of targets in |
|
I second that. log backends like flexilogger let you set different log levels per target. Also it can even just be grepped out. |
## Motivation Currently, the `tracing` crate's "log" feature always logs span lifecycle (creation/enter/exit/close) events, even when the span has no fields. This can be quite noisy. Since the enter, exit, and close logs don't include the span's fields, it doesn't add that much additional context to the surrounding log records. ## Solution In order to continue recording this data while improving the signal-to-noise ratio of `tracing`-generated logs, this commit changes the log integration to log span lifecycle events under a separate target, "tracing::span". This way, log users can opt in to this data when it is desired, but logs are generally much less noisy. Span creation is still logged to the default target when the span has fields, as this often provides useful information, but is sent to the "tracing-span" target when there are no fields. Fixes #607
## Motivation Currently, the `tracing` crate's "log" feature always logs span lifecycle (creation/enter/exit/close) events, even when the span has no fields. This can be quite noisy. Since the enter, exit, and close logs don't include the span's fields, it doesn't add that much additional context to the surrounding log records. Additionally, when using `tracing` with the `log-always` feature and a subscriber is active, the IDs of enabled spans are available, but not included in the span lifecycle `log` records. These could be used to enable tracking individual span's lifecycles via these log records, but this is not currently possible. ## Solution In order to continue recording this data while improving the signal-to-noise ratio of `tracing`-generated logs, this branch changes the log integration to log span lifecycle events under a separate target, "tracing::span". This way, log users can opt in to this data when it is desired, but logs are generally much less noisy. Span creation is still logged to the default target when the span has fields, as this often provides useful information, but is sent to the "tracing-span" target when there are no fields. This branch also updates the `log` integration so that when a span is enabled by a subscriber, and `log` integration is enabled, that span's `log` records will include its ID. Now, when multiple spans with the same name are in the logs, we have a rudimentary ability to correlate those span's lifecycle events, without introducing so much complexity that just using a `tracing` subscriber would be a better solution. For example, when a subscriber is assigning IDs to spans, the logs look like this: ``` ERROR log_with_trace foo=5 ERROR log_with_trace foo=42 ERROR log_with_trace foo=39 WARN log_with_trace hello world; INFO log_with_trace hello world; thingy=42 other_thingy=666 TRACE tracing::span ++ foo; span=1 TRACE tracing::span -> foo; span=1 TRACE log_with_trace hello san francisco; foo=3 bar=4 TRACE tracing::span <- foo; span=1 TRACE tracing::span -- foo; span=1 TRACE log_with_trace ++ foo; bar=3 baz=false; span=2 TRACE tracing::span -- foo; span=2 TRACE log_with_trace hello world foo=1 bar=2 ``` Finally, I've added a new section to the `tracing` crate's documentation to provide details on using the `log` integration features. Fixes #607 Signed-off-by: Eliza Weisman <eliza@buoyant.io>
I am currently experimenting with migrating my library Isahc from the
logcrate totracingin order to get better per-request tracing, but the migration is not as seamless as I was hoping for (though I mostly like what I see). One large problem is how thelogfeature on thetracingcrate handles entering and exiting spans; as alibrary author, I want to maintain the ability to output quality logs via thelogabstraction for users using that crate, while also delivering additional value for users oftracing.Unfortunately, migrating to
tracingreduces the "quality" of logs emitted through thelogabstraction because it is filled with a lot of mostly empty messages indicating when spans are entered, exited, and closed:(Here the logger implementation is
env_logger, but a user could use any implementation. Also keep in mind that this just from an experimental branch.)In the context of a tracing subscriber, this structured information is of course quite valuable and can be presented in very useful ways. But in the context of a
loglogger, these logs seem pretty spammy and useless; since the fields of the span are not included on enter/exit, the only value that might come from this is the timestamps, but even that seems like a stretch to me.My gut reaction to this behavior was that maybe all of my non-public methods should be using
Trace-level spans so that users wouldn't get this spam unless they set their log level totrace. I often recommend to users to send me snippets of theirtracelogs whenever they think they are encountering a bug, but even then these log lines seem like they still would be just noise and not helpful.I do see that the
#[instrument]attribute optionally takes alevel, but if spans should betraceeverywhere except public methods, why isinfothe default level?A similar problem is the logs when spans are created. Emitting a log when a span is created can be quite useful, except when it has no fields; in that case maybe spans with no fields should not be logged.
Ultimately I'm looking to benefit from tracing's more structured approach for both me when debugging concurrent behaviors and for users making use of tracing in their apps, but without giving existing
logusers the short shrift. I might be usingtracingwrong or have the wrong expectations here and I just need to do some more learning first. Maybe there's a good reason for this behavior that I'm not grasping?The text was updated successfully, but these errors were encountered: