Is structured logging à la slog supported?

[dvtomas]

Years ago, before tracing was incepted, I started logging with slog. Overall, I'm more or less happy, but now tracing seems to have gained a lot of traction, features are constantly being added, while slog seems to be stalling.

One crucial thing I really like about slog is that Logger is not global, but local to specific components of the application. Logger instances form a hierarchy.

For example, I have a BinaryTransport type that can connect to RS232, TCP, UDP. It contains it's own Logger instance, that was at instantiation time provided with a field identifying the peer of the communication (RS232 port, TCP host, ..). In the BinaryTransport I use it as

debug!(&self.log, "Read bytes: ...")

and in the log output I automatically see something like DEBG Read bytes: ..., peer: 192.168.1.10:10000.

Going one level up, I have a Device that contains the instance of the binary transport. It also contains it's own Logger created with a field identifying the device. So, I can do

debug!(&self.log, "Read device ident: {}", ident)

and get DEBG Read device ident: 123, device: FooDevice in the log output.

The device typically uses a binary transport as a means of communication. It is created as following:

impl Device {
   pub fn new(log: &Logger, ...) -> Self {
     let log = log.new(o!("device" => "FooDevice")),
     Device {
       transport: BinaryTransport::rs232(&log, ...),
       log,
       ...
    }
  }
}

impl BinaryTransport {
   pub fn rs232(log: &Logger, ...) -> Rs232 {
     let log = log.new(o!("port" => port)),
     Rs232 {
       log,
       ...
    }
  }
}

The best part of such an approach is that the Logger in Rs232 now contains both field port and device. That means that now debug!(&rs232.log, "Read bytes: ...") will yield DEBG Read bytes: ..., peer: 192.168.1.10:10000, device: FooDevice.

Thus, I see all the structural context in each log message. I can configure filtering based on communication peer, or on the device, or some combination of both.

The setup of the logging configuration is probably slightly more complicated than usual, but the great advantage is that the hierarchy of loggers respects the structural configuration, not the call-stack configuration. Also, it is very clear in the code what particular logger each component uses.

I wonder if this is something tracing has taken a stance on? Is something like this possible (or even idiomatic) in tracing? Or can the same result be achieved with other tracing approach?

[davidbarsky]

Thanks for asking this question and providing examples showing what you're looking for. tracing does support structured logging, but it instead of creating nested loggers like slog does, tracing prefers to achieve this through spans, which often, but not always, correspond to a unit of work. Here's a direct translation as to how I'd rewrite the example you provided using tracing:

impl Device {
   pub fn new(...) -> Self {
     let _span = span!(Level::INFO, "device", name = "FooDevice").entered();
     
     Device {
       transport: BinaryTransport::rs232(...),
       ...
    }
  }
}

impl BinaryTransport {
   pub fn rs232(...) -> Rs232 {
     let _span = span!(Level::INFO, "transport", name = "rs232", port = %port).entered();
     Rs232 {
       ...
    }
  }
}

This will result in any logging statements (info!, warn!, etc.) to include the contextual key/value pairs defined on spans if you're using tracing_subscriber::fmt::{Layer, Subscriber} which is the closest analogue to a traditional logger. Other layers/subscribers might have different behavior.

[hawkw]

The setup of the logging configuration is probably slightly more complicated than usual, but the great advantage is that the hierarchy of loggers respects the structural configuration, not the call-stack configuration. Also, it is very clear in the code what particular logger each component uses.

It's certainly possible to replicate slog-style explicit context passing via a struct field or parameter. You can do this by passing around tracing::Span instances, and passing them as the parent of your spans or events explicitly. For example, to replicate your example in tracing, you could write:

impl Device {
   pub fn new(span: &tracing::Span, ...) -> Self {
     let span = tracing::info_span!(parent: &span, "device", name = "FooDevice");
     Device {
       transport: BinaryTransport::rs232(&span, ...),
       span,
       ...
    }
  }
}

impl BinaryTransport {
   pub fn rs232(span: &tracing::Span, ...) -> Rs232 {
     let span = tracing::debug_span!(parent: &span, "transport", name = "rs232", ?port);
     Rs232 {
       span,
       ...
    }
  }
}

In functions where you want to log events, you could either explicitly pass the struct's span to the event macros, like this:

impl BinaryTransport {
    fn read_bytes(&self, buf: &mut [u8])  {
        let bytes_read = // ...
       
        // log an event with `self.span` as the parent scope.
        tracing::debug!(parent: &self.span, bytes_read);
    }
}

or by entering those spans on the stack in the scope of functions on your types:

impl BinaryTransport {
    fn read_bytes(&self, buf: &mut [u8])  {
        // enter `self.span` for the duration of this function call.
        let _enter = self.span.enter();

        let bytes_read = // ...

        // log an event (implicitly in the scope of `self.span`, due to the `enter` call) 
        tracing::debug!(bytes_read);
    }
}

Regarding the question about what's considered idiomatic,

I wonder if this is something tracing has taken a stance on? Is something like this possible (or even idiomatic) in tracing? Or can the same result be achieved with other tracing approach?

In general, the tracing idiom is to prefer implicit context passing via span.enter() rather than explicit context passing by manually setting the parents of spans or events, in most cases. However, storing a Span instance in a struct is definitely considered idiomatic when it makes sense to do so.

As to why implicit context passing is generally preferred, there are a few reasons:

• Entering and exiting spans allows thinking about spans as units of time. Because tracing spans have first-class enter and exit operations, the Subscriber is aware of exactly when a particular context was entered, and when it was exited. Depending on the Subscriber that's in use, this allows the subscriber to use that span not just as a context for log lines, but also to record the duration of that span --- for example, the length of the function call for which we entered the span. Some subscribers might use these durations to generate profiling data or visualization of span hierarchy. Of course, if you're using tracing just for logging events, you're not necessarily using this data, but if you prefer entering and exiting spans, the data will be available if you ever want to drop in a Subscriber that does measure span durations.
• **Implicit context passing is more library friendly.**Suppose one of the methods you want to add a log context to calls into a function from a library, and that library also logs events. In the slog model, if you want that context to be added to events logged from within the library code, you would need to pass the slog logger into the library's function call...and that means the library must also be using slog, and must pass that logger into all the functions it calls into, as well. In tracing, the library API doesn't need to accept a tracing::Span for its events to be recorded within the currently entered span when calling into the library. And, when consuming log records from libraries using the log crate, the tracing-log adapter can still add the current span context to tracing events generated from log records, even if the library that logged those records isn't aware of tracing at all.
• In some cases, implicit context passing improves performance. This is purely anecdotal evidence, but I've heard from users who switched from slog to tracing that the transition to tracing resulted in noticeable performance improvements. This is because, when logging occurs in a deeply nested function call, the slog logger must be passed on the stack on every stack frame, even in functions that don't actually log anything themselves, but call into functions that do. In tracing, because the current span is stored in a thread-local rather than on the stack, the current span is only accessed when an event is actually logged, and doesn't have to be pushed onto every stack frame. In some cases, this results in a performance improvement.

Of course, using span!(parent: ...) or event!(parent: ...) isn't necessarily considered a strong anti-pattern; it's okay to do it situationally, when it makes sense. But, in general, we tend to prefer entering spans instead.

Hope that's helpful!

[dvtomas]

Awesome answer, thank you.

One more thing I need to have cleared up: In your example you do a

 let span = tracing::info_span!(parent: &span, "device", name = "FooDevice");

and

tracing::debug!(parent: &self.span, bytes_read);

Does this mean that these two will contain the context from the explicitly specified parent spans only, or will they contain the context from the parent spans and any implicit spans in action as well? Or is it different for the first case and the second?

[hawkw]

A span or event can only have a single parent, so in this case, the explicitly specified parent span will be the only parent.

Whether or not data from other currently-entered spans is displayed alongside the data from the parents of the current span is up to the Subscriber implementation --- it can choose to track other spans that have been entered as part of the current context along with the parent.

But, if you're using tracing-subscriber's fmt module, it will only display the current span and its parents as context for log messages. Most other subscribers will probably have similar behavior, but it's technically implementation-specific. If a subscriber does record both parents and the current stack, they'll probably be displayed as separate dimensions of data, since they represent different things.

[dvtomas]

Thank you so much for your explanation.

[hawkw]

Glad I could help!