tracing::instrument not logging

[soerenmeier]

I thought that
#[tracing::instrument(level = "debug", skip(self))]
would always make a log entry of the arguments, but it doesn't.
I found out that if I add ret to the instrument "call" I get a log entry.

Am I doing something wrong or is that intended?

Background

I'm implementing a tonic service which the return value is an empty struct so i emitted the ret from the instrument call, since it doesn't bring any value to the log entry.

[davidbarsky]

The behavior of logging here depends on what subscriber you're using. If you're using tracing-subscriber, it will by default only log when an event occurs. If you'd like to change this behavior, try using https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/struct.Layer.html#method.with_span_events.

[hawkw]

To expand a little bit on @davidbarsky's answer, the #[instrument] attribute creates and enters a span. It does not produce an event by default. The default configuration for tracing-subscriber's [fmt module][fmt] emits a log line whenever an event occurs. It does not emit a log line when spans are created or entered by default, but data from the current spans is used as context when printing log lines for events.

When you add the ret and/or err arguments to the #[instrument] attribute, you are telling #[instrument] to also emit an event in the span it generates, when the function returns. A log line is then emitted by the fmt subscriber for those events.

As David mentioned, you can also use fmt::SubscriberBuilder::with_span_events to configure the fmt subscriber to emit a log line when spans are created and/or entered; this behavior is not the default, but it can be enabled if desired.

Hope that helps!

[soerenmeier]

Thanks for the answers, that makes sense.

I think instrument is not what I'm really looking for, probably just simple trace! and error!. I want to log a trace with the arguments and the return type Result::Ok if it does not return an empty struct. If the return type is Result::Err I want to log an error. Am I correct that this is not possible with #[instrument]?

Another question, when using span since you need to provide a level I assume the span will only be created when that level is enabled. So if I use different event macros like warn! or trace! I should select the highest level for the span (in this case warn) if I want to have the span information in the event, right?

[davidbarsky]

I think instrument is not what I'm really looking for, probably just simple trace! and error!. I want to log a trace with the arguments and the return type Result::Ok if it does not return an empty struct. If the return type is Result::Err I want to log an error. Am I correct that this is not possible with #[instrument]?

Creating event whose level that diverges with the return type is not currently supported, but I'm not opposed to discussing an approach for this in a dedicated issue. My current concern is that #[instrument] does a lot, and I'd like to expose this functionality in a way that's not overwhelming and scales gracefully. Here's a bad syntax that should be bikeshed if we want to add additional features such as this:

#[instrument(skip(self), ret(Display, level = Level::TRACE), err(Debug, level = level::ERROR))]
fn foo(&self) -> Result<(), Error> {
    unimplemented!()
}

If this is something that you're interested in, I can open a design issue for this to discuss this further.

So if I use different event macros like warn! or trace! I should select the highest level for the span (in this case warn) if I want to have the span information in the event, right?

If your application-wide filter is set to warn, yes, then you could set the span level at the at the threshold (e.g., warn) to include the span. As an alternative, you can use use filter_fn to construct a filter like metadata.level() <= &Level::WARN || metadata.is_span(), which will enable events at WARN or EVENT and all spans, which might get closer to the semantics you're looking for.

[soerenmeier]

Yeah, I'm interested in that. Maybe even another argument enter like ret which just emits an event when the function body is entered.