Instrument(ret) print error when function return Err

[simon-fu]

Bug Report

Version

cargo tree | grep tracing
│ │ │ └── tracing v0.1.35
│ │ │ ├── tracing-attributes v0.1.20 (proc-macro)
│ │ │ └── tracing-core v0.1.28
│ │ ├── tracing v0.1.35 ()
│ │ └── tracing v0.1.35 ()
│ │ ├── tracing v0.1.35 ()
│ │ └── tracing-futures v0.2.5
│ │ └── tracing v0.1.35 ()
│ ├── tracing v0.1.35 ()
│ ├── tracing-appender v0.1.2
│ │ └── tracing-subscriber v0.2.24
│ │ ├── tracing v0.1.35 ()
│ │ ├── tracing-core v0.1.28 ()
│ │ ├── tracing-log v0.1.2
│ │ │ └── tracing-core v0.1.28 ()
│ │ └── tracing-serde v0.1.3
│ │ └── tracing-core v0.1.28 ()
│ └── tracing-subscriber v0.2.24 ()
│ ├── tracing v0.1.35 ()
│ └── tracing v0.1.35 ()
├── tracing v0.1.35 ()
├── tracing-appender v0.1.2 ()
├── tracing-subscriber v0.2.24 (*)

Platform

Darwin Kernel Version 21.5.0: Tue Apr 26 21:08:29 PDT 2022; root:xnu-8020.121.3~4/RELEASE_ARM64_T8101 arm64

Description

#[tracing::instrument(level="debug", ret, skip_all)]
pub async fn async_return_ok() -> Result<()> {
Ok(())
}

#[tracing::instrument(level="debug", ret, skip_all)]
pub fn sync_return_ok() -> Result<()> {
Ok(())
}

#[tracing::instrument(level="debug", ret, skip_all)]
pub async fn async_return_err() -> Result<()> {
anyhow::bail!("err")
}

#[tracing::instrument(level="debug", ret, skip_all)]
pub fn sync_return_err() -> Result<()> {
anyhow::bail!("err")
}

#[tokio::test]
async fn test_instrument() -> Result<()> {
tracing_subscriber::fmt().with_max_level(tracing::Level::DEBUG).init();
let _r = async_return_ok().await;
let _r = async_return_err().await;
let _r = sync_return_ok();
let _r = sync_return_err();
Ok(())
}

[simon-fu]

from https://docs.rs/tracing/latest/tracing/attr.instrument.html
Note: if the function returns a Result<T, E>, ret will record returned values if and only if the function returns Result::Ok.

[davidbarsky]

I'm guessing that the issue you're reporting is that you're not seeing any instrumentation of the return value. Is that correct? I believe that skip_all is forcing return values to not be recorded. If you're to remove skip_all, you should the recorded return values.

[hawkw]

You can use #[instrument(err)] to log an event when an instrumented function returns Err. From the documentation:

If the function returns a Result<T, E> and E implements std::fmt::Display, you can add
err or err(Display) to emit error events when the function returns Err:

#[instrument(err)]
fn my_function(arg: usize) -> Result<(), std::io::Error> {
    Ok(())
}

By default, error values will be recorded using their std::fmt::Display implementations.
If an error implements std::fmt::Debug, it can be recorded using its Debug implementation
instead, by writing err(Debug):

#[instrument(err(Debug))]
fn my_function(arg: usize) -> Result<(), std::io::Error> {
    Ok(())
}

The ret and err arguments can be combined in order to record an event if a
function returns Result::Ok or Result::Err:

#[instrument(err, ret)]
fn my_function(arg: usize) -> Result<(), std::io::Error> {
    Ok(())
}

[simon-fu]

According to https://docs.rs/tracing/latest/tracing/attr.instrument.html,

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

sync_return_err return Err and is supposed to print nothing，but it does print:

Jul 13 09:38:44.138 DEBUG sync_return_err: ctest return=Err("err")

Here is the more concise code snippet

#[tracing::instrument(level="debug", ret)]
pub fn sync_return_err() -> Result<(), &'static str> {
    Err("err")
}

#[tokio::test]
async fn test_instrument() -> Result<()> {
    tracing_subscriber::fmt().with_max_level(tracing::Level::DEBUG).init();
    let _r = sync_return_err();
    Ok(())
}

[limo520]

I happen to meet this too. The following code

#[tracing::instrument(ret)]
pub fn sync_return_ok() -> Result<i32, ()> {
    Ok(42)
}

#[tokio::test]
async fn test_instrument(){
    tracing_subscriber::fmt().with_max_level(tracing::Level::TRACE).init();
    let _r = sync_return_ok();
}

is supposed to print something like this

2024-04-16T16:32:35.857383Z  INFO sync_return_ok: tracingdemo: return=42

but it does print:

2024-04-16T16:32:35.857383Z  INFO sync_return_ok: tracingdemo: return=Ok(42)

I found out that if I combine err and ret, it works as expected

#[tracing::instrument(err,ret)]
pub fn sync_return_ok() -> Result<i32, i32> {
    Ok(63)
}
#[tracing::instrument(err,ret)]
pub fn sync_return_err() -> Result<i32, i32> {
    Err(42)
}

#[tokio::test]
async fn test_instrument(){
    tracing_subscriber::fmt().with_max_level(tracing::Level::TRACE).init();
    let _ = sync_return_ok();
    let _ = sync_return_err();
}

This prints

2024-04-16T16:39:26.869427Z  INFO sync_return_ok: tracingdemo: return=63
2024-04-16T16:39:26.869518Z ERROR sync_return_err: tracingdemo: error=42