Include Trace ID and Span ID in formatted logs

[bjchambers]

Feature Request

Motivation

When using tracing to report traces to both a tracing backend such as Grafana Tempo and a logging backend such as Grafana Loki it is possible to link between the two using the span ID and trace ID. See for instance this example: https://grafana.com/blog/2020/11/09/trace-discovery-in-grafana-tempo-using-prometheus-exemplars-loki-2.0-queries-and-more/

However, it doesn't look like it is possible to include the Span ID and Trace ID in the JSON logs produced using tracing-subscriber.

Proposal

This could take a variety of forms -- two thoughts (based on places that I looked):

1. tracing-subscriber could include information to include the trace ID and span ID. This information may not be generally available, so it may not be feasible.
2. tracing-opentelemetry could provide an option that added the span and trace ID as fields to the spans and events passed to the later layers. This would allow the tracing-subscriber to include them in the JSON logs since they would be just be additional fields.

I'm not sure which of these would be the best approach, or if there are other approaches that would be better.

[hawkw]

FWIW, I started prototyping a sketch of an opentelemetry-aware FormatEvent implementation for use with tracing-subscriber's fmt module, but didn't have the time to finish it (as I have no personal need for it right now). if anyone who needs this is interested in finishing that PR, it's here if you want it: https://github.com/tokio-rs/tracing/pull/1304 and I'm happy to provide advice.

A recent tracing-subscriber change (#1696) should also make it possible to simplify the ANSI color handling in that PR significantly...

[kesavkolla]

Has anyone solved this? I am also interested in this as I use Grafana stack Loki and Tempo. I would really love to see the co-relation between logs and trace so that I can visualize things in better way.

[loriopatrick]

@kesavkolla I got it working with Grafana Tempo, I'll push my code later today and share.

[loriopatrick]

@kesavkolla this is some copy pasta but should be enough to get you started, https://gist.github.com/loriopatrick/bd00116562084b1d61f105f31d31afe0

[kesavkolla]

Didn't work :-( couple of things function new_span is not part of Layer trait. There is no method to_hex in TraceId struct. I have fixed them but I didn't get any output on console log.

[cschaible]

Are there some news? The correlation of logs and traces in jaeger would be powerful.
I've tried the code snippet of @loriopatrick but it also didn't work on my machine. The problem is that the code in logging.rs in line 51 doesn't return the SpanBuilder.

extensions.get_mut::<opentelemetry::trace::SpanBuilder>()

I have also looked into #1304 of @hawkw but I couldn't get it to run with the Trace and Span IDs in the logs.

I've tried many things the last days and the only logging (but not so nice) solution was the usage of the stdout tracer. But then I didn't have the traces in jaeger:

let tracer = opentelemetry::sdk::export::trace::stdout::new_pipeline().install_simple();

It would be awesome if some experienced could help to get it to work. I guess it's just a small thing but I just couldn't figure it out. I'm not searching for a perfect solution, I just want to have the TraceID and SpanID in the json formatted log messages.

I've prepared a small sample application you can use to try it, to not have the effort to bootstrap a sample application. You can just start jaeger with the script and run the application.

Thanks in Advance!

[loriopatrick]

@cschaible I haven't looked into this myself but there appears to be a tracing-loki crate now: https://crates.io/crates/tracing-loki. You might be able to utilize that or fork it for you purposes.

[cschaible]

Thank you for the fast reply @loriopatrick! However, I'm not really interested in a specific solution for Grafana / Tempo / Loki. I'm interested in a generic one that logs the Trace/Span-IDs on stdout to be collected with any kind of solution in Kubernetes.

[lswith]

One issue I've been thinking about is around this piece of functionality.

When our team uses the tracing_subscriber::fmt it prints out all of the span's metadata, and context alongside the actual span events. This means that the logs become very, very verbose. In reality, we only need the timestamp, traceId and spanId to be printed alongside the event and its fields, as the rest of the context is already captured in the opentelemetry traces.