Thoughts on supporting tracing as alternative logging framework?

[isaacdavis]

Hi all!

We at Fastly have run into an interesting quandary:

• We really want to use dropshot for REST-serving
• We really want to use tracing for logging in our ecosystem
• The existing shim for coupling slog-based libraries to a tracing-based environment discards all key-value pairs from the slog Record when performing the conversion, which makes it useless to us!
  • I've looked into fixing this, and have determined that it's impossible to preserve key-value pairs in a useful way without making breaking changes to slog itself.

I am happy to further explain any of the points above.

Anyway:

Would you all be open to an attempt to add tracing as an alternative logging framework? Do you all reckon it's feasible to support two logging libraries at once, knowing the dropshot codebase better than I?

I'd imagine this would involve adding a wrapper interface to be used internally to dispatch logs to whatever framework is active, as well some expansion of ConfigLogging to allow users to choose slog or tracing. I can see lots of ways this could get too complicated, but would you be open to an attempt?

[smklein]

Hey @isaacdavis , thanks for bringing this up! I'll also let @ahl and @davepacheco chime in, but here are my first thoughts, for whatever they're worth:

I think the idea to internally dispatch logs to one framework or the other seems reasonable, but I'm not sure I love the idea of making this a dynamic runtime flag (this means consumers will need to depend on both slog and tracing in all cases). This "choose your dependencies" behavior seems like it might be a better fit for a feature flag. This way, callers can opt into whichever flavor they want, and discard the alternative from a binary-size perspective.

If we do this, then all the calls to info, debug, warn, and trace can be redirected to one of the appropriate backends. Additionally, dropshot is currently constructing logs (see: calls to log.new) which would need to be replaced with code that could multiplex to a tracing equivalent.

I do think this might require some code to intercept the keys (which would have been provided to slog) and instead provide them to one of the two backends as appropriate, but if you think this is an easier approach then parsing them out of the slog KV object then that seems like it would be the way to go.

TL;DR: I'm personally open to the attempt; logging is an auxiliary aspect to dropshot, and making the library more usable in more environments seems like a net win.

[davepacheco]

Hey @isaacdavis! I'm glad to see y'all are having a good experience with dropshot.

Stepping back: I think my goals for dropshot logging are:

• constraint: machine-parseable log messages
• constraint: code paths that log messages can include whatever key-value pairs they want in the message
• constraint: the pattern needs to be composeable so that:
  • the dropshot consumer can use the same mechanism (and use it for other subcomponents too)
  • the dropshot consumer can specify key-value pairs that show up in all of dropshot's log messages
  • the dropshot consumers can use a single log destination for messages from all these components
• constraint? it should be possible to configure the system to never drop messages (blocking instead on overload)
• constraint: it should be possible to log to a file
• very nice-to-have: runtime flexibility about exactly what happens when a log message (or "event", more generally) is generated. This is getting into the weeds, but one dream is to be able to configure at runtime whether we emit the log message to a file, send it to an aggregating service, fire a DTrace probe, or bump a counter, and how much of the event details are aggregated immediately in situ. (Concretely, you could imagine a "request completed" event with a ton of different fields, most of which make it into the log message, but maybe 1-2 are used in the counter. And that could be configurable at runtime.) I don't expect we'd do much of this any time soon but it'd be nice not to have to revisit all the event sites if we did decide to implement these features.
• very nice-to-have: be able to send messages to something that consumes OpenTracing data or some other ecosystem of tools for searching and visualizing this data
• nice-to-have: uses a widely-available mechanism for easy integration with components we didn't build

Now we're where we are because slog + bunyan + slog-dtrace ticked most of these boxes when we did this back in early 2020. But I haven't been following the space since then. What has you all excited about tracing? Should we be looking at that instead? Can tracing piggy-back on the existing slog macros?

I'm also curious why it's impossible to adapt the existing slog-tracing shim, since it seems like slog is built to be extended in exactly this way (which was part of the appeal).

If the most promising answer is (as I suspect) to somehow support both, I'm really curious what that would look like. Maybe a cheap first step would be to write a separate dummy library crate that supports both, with two consumers (one that uses each backend)?

I think the bottom line is: we're definitely open to seeing what this looks like. I'm less excited if it means changing every use of all the slog macros and using some different pattern, but again, open to seeing what that looks like. And part of my reluctance is that slog is already supposed to be general enough that it seems like this shouldn't be necessary, so understanding that better would probably help me get over that.

Thanks again.

[isaacdavis]

Hi @davepacheco and @smklein! Thanks for your thoughtful answers to my inquiry.

I set out to do my due diligence in answering all your questions, and in the process discovered some things that have me questioning whether tracing is the right choice for my team at all.

A detailed response is below; here's the main concern:

Tracing's pattern of routing logs to an implicit global or thread-local "subscriber" doesn't give the maintainer enough control of what information gets logged where. Workarounds, if possible, are convoluted. Slog's pattern of passing around explicit Logger structs provides this level of control easily.

And now, the full write-up:

Good things

What has you all excited about tracing? Should we be looking at that instead?

We are still digging into its features, but the main thing that has stood out to us so far is the instrument attribute macro. This gives us a lot of what we want (logging function arguments/entry and exit points) without much boilerplate. This goes hand-in-hand with tracing's "span" construct, which we've found useful for human readability (though including request ids accomplishes much of the same). So far, we've found parity with slog in all the other features we've tried to use.

I will candidly admit that we're also motivated by this message, especially since it's the first thing in the slog README! It looks like tracing
development is much more active than slog right now. I am not a fan of constantly switching libraries in an effort to chase the latest and greatest thing, but given that our codebase is new and we're able to choose libraries without having to pay down too much debt, tracing has our attention.

constraint: machine-parseable log messages

With tracing_bunyan_formatter, tracing can output log lines as bunyan-compatible json, e.g.:

{"v":0,"name":"foo","msg":"service starting","level":30,"hostname":"tele","pid":1430462,"time":"2022-12-13T22:09:48.853812462Z","target":"foo","line":107,"file":"src/main.rs"}

constraint: code paths that log messages can include whatever key-value pairs they want in the message

Tracing has the same key/value construct as slog.

the dropshot consumer can use the same mechanism (and use it for other subcomponents too)

Tracing supports this.

the dropshot consumers can use a single log destination for messages from all these components

Tracing can do this with its "default subscriber" construct.

constraint: it should be possible to log to a file

Tracing supports this via the tracing_appender crate.

very nice-to-have: be able to send messages to something that consumes OpenTracing data or some other ecosystem of tools for searching and visualizing this data

There are crates for sending tracing data to OpenTelemetry and Honeycomb.

nice-to-have: uses a widely-available mechanism for easy integration with components we didn't build

Could you please explain what you have in mind here?

Annoying, but do-able things

Can tracing piggy-back on the existing slog macros?
I'm less excited if it means changing every use of all the slog macros and using some different pattern

The macro syntax is slightly different but broadly equivalent. This means that we'd have to write some wrappers and do compile-time dispatching to the correct macro, as @smklein suggests.

very nice-to-have: runtime flexibility about exactly what happens when a log message (or "event", more generally) is generated. This is getting into the weeds, but one dream is to be able to configure at runtime whether we emit the log message to a file, send it to an aggregating service, fire a DTrace probe, or bump a counter, and how much of the event details are aggregated immediately in situ. (Concretely, you could imagine a "request completed" event with a ton of different fields, most of which make it into the log message, but maybe 1-2 are used in the counter. And that could be configurable at runtime.) I don't expect we'd do much of this any time soon but it'd be nice not to have to revisit all the event sites if we did decide to implement these features.

I believe tracing supports this via its "Layer" construct -- it looks like layers can be conditionally activated.

Note that someone (me?) would have to write a "tracing-dtrace" crate from scratch, similar to slog-dtrace.

constraint? it should be possible to configure the system to never drop messages (blocking instead on overload)

I'm not sure if this exists! In the worst case, we could write our own tracing Layer with this behavior.

Bad things

I'm also curious why it's impossible to adapt the existing slog-tracing shim, since it seems like slog is built to be extended in exactly this way (which was part of the appeal).

slog-tracing is implemented as a drain that converts each slog Record to a tracing Event. The key-value pairs attached to the slog Record are exposed only as an instance of the slog::KV trait, which is mostly opaque -- there's no way to e.g. iterate over each field and convert it to its equivalent type in tracing.

So, slog-tracing just drops the key-value pairs on the floor. Note that in the relevant function, record.kv() is never called.

Fixing this would require upstreaming a change to slog that introduces an iterator for the KV trait. I'm worried that this wouldn't be well-received, since it would require other implementors of the KV trait to make changes if they wanted to upgrade to a new version of slog. I'll float the idea on the slog repo and see what they say.

the dropshot consumer can specify key-value pairs that show up in all of dropshot's log messages

This may be possible, but I think it's going to be surprisingly convoluted. The reason is that tracing doesn't have Logger objects to pass around, instead routing messages to an implicit global or thread-local logger. The "span" construct is sort of a substitute, but spans are not shared among threads.
So, we'd have to:

• pass a set of the desired global k/v pairs around between tokio tasks
• when each task is entered, create a new span that records the global k/v set
  • do this using the #[instrument] function attribute, so the span is
    async-safe. This is annoying.

This gives me a new appreciation for the control gained by passing around log objects explicitly.

Next steps

So, where does this leave me, and us?

The lack of control imposed by the lack of Logger objects is a real bummer that I hadn't fully comprehended before. My team is going to discuss just using slog for everything because of this.

If my team decides we still want to push for tracing, I'll see if I can get an iterator method added to the slog KV trait so I can just use the slog-tracing shim. This seams like the least work at this point. I'll keep you all updated on how this goes.

If that doesn't work out, I may push for getting dropshot to support tracing. Based on what I've laid out, are you all still amenable to me taking this on, or are there hard dealbreakers here?

If the most promising answer is (as I suspect) to somehow support both, I'm really curious what that would look like. Maybe a cheap first step would be to write a separate dummy library crate that supports both, with two consumers (one that uses each backend)?

I think this is a really good idea! This is how I will start, if we do go down this path.

[davepacheco]

Thanks for the thoughtful response. That all makes sense. I too prefer to the explicit passing of hierarchical loggers around, though I'm also open to being talked out of that I suppose.

That slog work sounds useful. I believe @bnaecker ran into a similar problem (not being able to iterate the key-value pairs) in building slog-dtrace.

nice-to-have: uses a widely-available mechanism for easy integration with components we didn't build

Could you please explain what you have in mind here?

Sorry, that was just an awkward way to say the obvious nice-to-have that there's value in using something popular if it means we can easily incorporate the logs already emitted by other crates.

If that doesn't work out, I may push for getting dropshot to support tracing. Based on what I've laid out, are you all still amenable to me taking this on, or are there hard dealbreakers here?

I'm still amenable to seeing what that looks like, yeah.

[luodanping]

您好，      您的邮件我已收到，我将尽快回复您。

[steveklabnik]

To return to this question a few years later, tracing has basically become the de-facto standard in the Rust world. Slog's README has "You might consider using tracing instead" at the top of its README.

Is there any interest in moving these days? I haven't investigated how much work this would be, at all, but wanted to leave a comment before I forgot.

[hawkw]

FWIW, as the putative maintainer of tracing, I'd be happy to either work on or offer advice for a potential effort to add tracing support in Dropshot...

[jclulow]

Does tracing support (an analogue of) the dynamic-keys mode of slog?

I'm trying to find time to land this change, which will depend on it: main...x-forwarded-for

[davepacheco]

I think the state remains what I posted above: those are still our goals, and I think we'd be open to alternatives, but someone would have to do the legwork to figure out what we'd gain and what's involved. @isaacdavis spent some time on this (above) and seemed to find it not that great a fit. It's possible I misunderstood or that things have changed in the meantime.

[steveklabnik]

I didn't realize this until very recently, but you can also Just Use Tracing. It's not ideal, in that you get mixed logs:

In my case I'm mostly using this for debugging locally and not for production stuff, so I don't have to like, figure out how to reconcile shipping both off somewhere permanent together.

But given the ecosystem backing of tracing, you get some nice benefits too: sqlx and hyper have both started producing logs for me automatically now, I didn't even realize they were doing that.

I do suggest using skip for the request context though:

#[tracing::instrument(skip(rqctx))]
pub async fn handler(rqctx: RequestContext<ApiContext>) -> // return type omitted

and then using it as normal, but particularly, in map_err:

    .map_err(|e| {
        tracing::error!(?e, "the foo didn't bar properly");
        HttpError::for_internal_error(e.to_string())
    })?;

stick a

    let subscriber = FmtSubscriber::builder()
        .with_max_level(tracing::Level::DEBUG)
        .finish();

    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");

before you start your server, and you're good to go.

[nshalman]

Hi! I'm not from Oxide or Fastly. I too am interested in using Dropshot with tracing. I have an experimental branch here:
https://github.com/nshalman/dropshot/tree/slog-to-tracing
The key commit is nshalman@69b5adc
The idea is to wire up tracing and have it funnel the logs out to slog so that all the logging remains unified, but newer codebases can start using tracing easily. It's part of my larger work to try to wire up OpenTelemetry (#1201, new code hopefully coming soon!)

Thoughts?

[steveklabnik]

I tried this out, but it's sort of backwards from what I personally want, which is just tracing, not tracing -> slog. That said, it does seem like an easier thing to upstream, given the above comments about slog being desired.

[yawn]

We would also love to be able to use tracing in dropshot (which is fantastic, thanks a lot for open sourcing it!). Essentially what @steveklabnik said: tracing as the log standard is available in a lot of places and it would be extremely convenient to get the same experience with dropshot.

A few questions and thoughts (building on top of the very thoughtful analysis from @isaacdavis and collaborators):

• Would you be open to replace slog fully and replace the log macros with those from tracing to avoid writing a wrapper infrastructure? I am not sure it's worth it to create specific tooling to support a continuous migration effort but e.g. Claude Skills should make it pretty painless to support full or partial (to deal with ongoing development work) migrations ...
• Moving fully to tracing would avoid the issues with the slog-tracing adapter
• I am sure I misunderstand some nuances here but joining a span from a threat is not that complicated* - but I have not looked at the codebase to understand the potential ergonomics at play
• Same regarding nuances for the dropshot-consumer-can-pass-kv-pairs comment: from my understanding this would mean that the kv context from my spans passes into the dropshot logging - this should be implicitly available when using tracing and spans

Let me know if I should create a small demo for these behaviours and thanks again for the work of maintaining dropshot in the open!

*) bind Span::current() outside the new thread and create a guard-bind with let _ = span.enter inside it

Addendum: adding to the comment from @hawkw who kindly offered to give high level guidance - I'd be willing to contribute a couple of days to move to tracing, depending on your thoughts about this direction making sense

[jclulow]

Just to put my oar in on this: I don't care if dropshot grows optional support for tracing, but I have zero interest in having slog removed or even deprecated. It's working well for me in a number of dropshot-based services, and I have no desire to retool everything.

[ahl]

A few questions and thoughts (building on top of the very thoughtful analysis from @isaacdavis and collaborators):

• Would you be open to replace slog fully and replace the log macros with those from tracing to avoid writing a wrapper infrastructure? I am not sure it's worth it to create specific tooling to support a continuous migration effort but e.g. Claude Skills should make it pretty painless to support full or partial (to deal with ongoing development work) migrations ...

Not at this time.

[yawn]

Got it, thank you - I will have look at alternative approaches here. Putting slog behind a default feature to allow replacing it fully through an optional tracing dependency would work for you though?

Very quick update: tracing_slog now does support at least some support for k/v serialization but it does not cover all values, just those present in the specific log statement.

[nshalman]

I had never come across tracing_slog before. Thanks for pointing it out!!

[yawn]

It only covers half the problem IIRC - using kv it will log the kv pairs in the current logger but not the parent ones.