Logfmt should show the current span

[NickLarsenNZ]

Is your feature request related to a problem? Please describe.

I am unable to see the span that the log/event was emitted from within.

Describe the solution you'd like

I would like tracing_logfmt to show the span that the log event occurred in (I guess in the target field.

Describe alternatives you've considered

Switching back to tracing_subscriber::fmt, but then I lose the logfmt style which is useful for parsing in Grafana Loki.

Additional context

use std::{env, thread, time::Duration};
use tracing::{dispatcher, Dispatch};
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::{fmt, EnvFilter, Registry};

const INTERVAL_VAR: &str = "INTERVAL";
const DEFAULT_INTERVAL: &str = "10";

fn main() -> anyhow::Result<()> {
    let env_filter =
        EnvFilter::try_from_env("LOG_LEVEL").unwrap_or_else(|_| EnvFilter::new("INFO"));

    let subscriber = Registry::default()
        .with(tracing_logfmt::layer())
        .with(fmt::layer())
        .with(env_filter);

    dispatcher::set_global_default(Dispatch::new(subscriber))?;

    let interval = env::var(INTERVAL_VAR)
    .unwrap_or_else(|_| {
        tracing::info!("environment variable {INTERVAL_VAR} is not set, defaulting to an interval of {DEFAULT_INTERVAL} seconds.");
        DEFAULT_INTERVAL.to_owned()
    })
    .parse::<u64>()?;

    loop {
        tracing::trace_span!("sleep_loop", interval).in_scope(|| {
            tracing::info!("sleeping");
            thread::sleep(Duration::from_secs(interval));
        });
    }
}

I can see the current span (sleep_loop) via the fmt subscriber, but not via the tracing_logfmt subscriber:

[fredr]

Thanks for opening this issue, it's definitely something we should add. Just not sure how it should be displayed for nested spans 🤔, maybe a span field, and a span path, or something.

I'm currently away on vacation, but will be back next week, I'll have a look at it then.

[fredr]

Released as 0.2.0 🚀
Let me know if there is any issues

[NickLarsenNZ]

I have upgraded and tried again, but I don't see it. Is there additional config needed, or is my use of an async runtime causing a problem?

[dependencies]
tracing-logfmt = "0.2.0"

    tracing::trace_span!("sleep_loop")
        .in_scope(|| async {
            tracing::info!("sleeping");
            interval.tick().await;
        })
        .await;

The target shows the app, rather than my scope named sleep_loop:

ts=2022-09-27T13:50:05.110128Z level=info target=emitter message=sleeping

[NickLarsenNZ]

It appears to be a problem when using async (which from memory, the tracing crate mentions some caveats there).

If I change it to (sync):

    tracing::trace_span!("sleep_loop").in_scope(|| {
        tracing::info!("sleeping");
    });

I see the right context in the logs:

ts=2022-09-27T13:56:34.448547Z level=info target=emitter span=sleep_loop span_path=sleep_loop message=sleeping

So I don't think this is a problem with the tracing-logfmt crate. I'll post back if I find anything.

[NickLarsenNZ]

Ah yes, here's the caveat about async spans: https://github.com/tokio-rs/tracing/blob/968dd0d0ee0ee1e55061c72a7572c0541d54775e/tracing/README.md#in-asynchronous-code

This works as expected:

    // contrived async + sleep
    async {
        tracing::info!("sleeping");
        interval.tick().await;
    }
    .instrument(tracing::info_span!("sleep_loop"))
    .await;

ts=2022-09-27T14:02:55.7186Z level=info target=emitter span=sleep_loop span_path=sleep_loop message=sleeping

[fredr]

Nice find, that is a bit hard to spot 😬