#[instrument(ret)] behaviour does not match documentation, also reports errors

[Xiretza]

Bug Report

Version

tracing-attributes v0.1.27 (proc-macro)
tracing-core v0.1.32
tracing-log v0.2.0
tracing-subscriber v0.3.18
tracing v0.1.40

Platform

Arch Linux, kernel 6.8.5-arch1-1

Crates

tracing-attributes

Description

The documentation claims that:

Note: if the function returns a Result<T, E>, ret will record returned values if and only if the function returns Result::Ok.

This is however only the case when the #[instrument] macro is also given the err parameter; otherwise, the return value is printed unconditionally (whether it is Ok or Err). This can also be seen in the implementation, which has a match block when err is specified, but does not have a match block when only ret is specified.

I've been trying to do some code archaeology to find out why it was implemented and documented this way in #1716, but I've come up empty.

Reproducer:

use tracing::instrument;

fn main() {
    tracing_subscriber::fmt().init();

    let _ = make_error();
}

#[instrument(ret)]
fn make_error() -> Result<(), &'static str> {
    Err("error!")
}

$ cargo run --quiet
2024-05-05T21:59:22.720067Z  INFO make_error: repro: return=Err("error!")

[mladedav]

I may be wrong, but I think that without (compile time) reflection, the documented behavior is impossible?

Or rather, the macro can look if the resulting type is named Result, but it cannot know if it really is the Result from std and it cannot tell if something else may be just a type alias or named use like type InfallibleResult<T> = Result<T, Infallible>; or use std::result::Result as StdResult;.

In a similar fashion someone could name their type Result but not have the enum variants the code would expect.

So I think we should just change the docs to remove the note and possibly clarify elsewhere?

[Xiretza]

You're probably right, how about adding something like ret(only_ok) that makes the behaviour opt-in?

[hawkw]

We should probably change the documentation to reflect that this behavior is specific to the err argument. I think that was the intent behind the original documentation.

[Xiretza]

Personally I would still find it useful to have an attribute that logs only successful returns. I don't really care about errors, they bubble up to the top and get logged eventually anyway, but I do care about the calculation result in the good case.

[mladedav]

All that would be needed for this is to support turning off err such as in #[instrument(ret, err(off))]. But maybe there is another way to make the intent clearer.

Alternatively, we could split ret and ok as different fields in the attribute with the latter being counterpart to err and the former logging always all return values. But that would be breaking so not before 0.2 lands.

[Xiretza]

If we're talking about doing breaking changes, how about this concept:

• #[instrument(ret(OPTS))] emits the return value regardless of type
• #[instrument(ret(ok(OPTS)))] emits only Ok return values (fails to compile if return type isn't Result)
• #[instrument(ret(err(OPTS)))] emits only Err return values (fails to compile if return type isn't Result)
• #[instrument(ret(ok(OPTS), err(OPTS)))] emits both Ok and Err return values (fails to compile if return type isn't Result)

Where OPTS is a combination of formatting (Debug or Display, with ret() and ret(ok()) defaulting to the former and ret(err()) to the latter) and level = Level::X as before.

#[instrument(ret(OPTS))] on a Result-returning function would be the same as #[instrument(ret(ok(OPTS), err(OPTS)))].

If this sounds workable, I can get started on an implementation.