Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Feature]: opentelemetry-appender-tracing should respect information inside tracing::Span #1378

Open
0xForerunner opened this issue Nov 16, 2023 · 36 comments · May be fixed by #2438
Open

[Feature]: opentelemetry-appender-tracing should respect information inside tracing::Span #1378

0xForerunner opened this issue Nov 16, 2023 · 36 comments · May be fixed by #2438
Assignees
Labels
A-log Area: Issues related to logs enhancement New feature or request triage:todo Needs to be traiged.

Comments

@0xForerunner
Copy link

0xForerunner commented Nov 16, 2023

It's great to be able to correlate logs with traces as is possible with the Grafana Tempo+Loki combo. This could be some sort of configuration option likely.

@0xForerunner 0xForerunner added enhancement New feature or request triage:todo Needs to be traiged. labels Nov 16, 2023
@cijothomas
Copy link
Member

The logs should be correlated automatically.. Are you not seeing that behavior?

@cijothomas cijothomas added the A-log Area: Issues related to logs label Nov 16, 2023
@lalitb
Copy link
Member

lalitb commented Nov 16, 2023

Yes - this should be correlated automatically, as long as the application is instrumented using opentelemetry tracing (either through tracing-opentelemetry or directly using opentelemetry tracing api). Not if it is using any other (non-otel) tracing subscriber.

@0xForerunner
Copy link
Author

0xForerunner commented Nov 16, 2023

Screenshot 2023-11-16 at 9 24 20 AM This is the information I'm getting in loki, with no trace_id information.

Logs are being generated with this code

        let logs = opentelemetry_otlp::new_pipeline()
            .logging()
            .with_exporter(opentelemetry_otlp::new_exporter().http())
            .with_log_config(
                opentelemetry_sdk::logs::config().with_resource(Resource::new(vec![
                    KeyValue::new("service.name", "liquidation-bot-rs"),
                ])),
            )
            .install_batch(opentelemetry_sdk::runtime::Tokio)?;

        let logging = OpenTelemetryTracingBridge::new(&logs.provider().unwrap())
            .with_filter(EnvFilter::from_default_env());
        
        subscriber = Registry::default()
            .with(stdout)
            .with(logging)
            .with(paper_trail)
            .with(metrics)
            .with(tracing)

@0xForerunner
Copy link
Author

Yes - this should be correlated automatically, as long as the application is instrumented using opentelemetry tracing (either through tracing-opentelemetry or directly using opentelemetry tracing api). Not if it is using any other (non-otel) tracing subscriber.

I can confirm things are properly instrumented with tracing-opentelemetry. The log in the screenshot above is inside a function with #[instrument] and I am correctly seeing traces and events.

@cijothomas
Copy link
Member

Can you use stdout exporter and share the output? We just want to confirm if this issue is with OTLP or Loki itself.

@cijothomas
Copy link
Member

Can you use stdout exporter and share the output? We just want to confirm if this issue is with OTLP or Loki itself.

Or just the log output from otel collector

@0xForerunner
Copy link
Author

0xForerunner commented Nov 16, 2023

Can you use stdout exporter and share the output? We just want to confirm if this issue is with OTLP or Loki itself.

This code somehow results in no output...

        let exporter = opentelemetry_stdout::LogExporter::default();
        let logs = LoggerProvider::builder()
            .with_simple_exporter(exporter)
            .build();
        let logging = OpenTelemetryTracingBridge::new(&logs);

@0xForerunner
Copy link
Author

collector logs are scarce

otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.702Z info    [email protected]/telemetry.go:84 Setting up own telemetry...
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.702Z info    [email protected]/telemetry.go:201        Serving Prometheus metrics      {"address": ":8888", "level": "Basic"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.703Z info    [email protected]/exporter.go:41     using the new Loki exporter     {"kind": "exporter", "data_type": "logs", "name": "loki"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.707Z info    [email protected]/service.go:143  Starting otelcol-contrib...     {"Version": "0.88.0", "NumCPU": 8}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:33     Starting extensions...
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:36     Extension is starting...        {"kind": "extension", "name": "basicauth/server"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:43     Extension started.      {"kind": "extension", "name": "basicauth/server"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:36     Extension is starting...        {"kind": "extension", "name": "basicauth/traces"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:43     Extension started.      {"kind": "extension", "name": "basicauth/traces"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:36     Extension is starting...        {"kind": "extension", "name": "basicauth/metrics"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:43     Extension started.      {"kind": "extension", "name": "basicauth/metrics"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:36     Extension is starting...        {"kind": "extension", "name": "basicauth/logs"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.708Z info    extensions/extensions.go:43     Extension started.      {"kind": "extension", "name": "basicauth/logs"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.709Z warn    [email protected]/warning.go:40  Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks        {"kind": "receiver", "name": "otlp", "data_type": "metrics", "documentation": "https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.709Z info    [email protected]/otlp.go:101        Starting HTTP server    {"kind": "receiver", "name": "otlp", "data_type": "metrics", "endpoint": "0.0.0.0:4318"}
[otel-collector] [2023-11-16 07:19:57] 2023-11-16T07:19:57.710Z info    [email protected]/

@0xForerunner
Copy link
Author

Can you use stdout exporter and share the output? We just want to confirm if this issue is with OTLP or Loki itself.

This code somehow results in no output...

        let exporter = opentelemetry_stdout::LogExporter::default();
        let logs = LoggerProvider::builder()
            .with_simple_exporter(exporter)
            .build();
        let logging = OpenTelemetryTracingBridge::new(&logs);

Do you know what's going on here? Something about that is blocking all output on the tracing subscriber.

@cijothomas
Copy link
Member

collector logs are scarce

I should have been more precise, apologies. You need "logging" exporter in collector to see the actual data it receives.
https://github.com/open-telemetry/opentelemetry-rust/blob/main/opentelemetry-otlp/examples/basic-otlp/otel-collector-config.yaml#L14

@cijothomas
Copy link
Member

Can you use stdout exporter and share the output? We just want to confirm if this issue is with OTLP or Loki itself.

This code somehow results in no output...

        let exporter = opentelemetry_stdout::LogExporter::default();
        let logs = LoggerProvider::builder()
            .with_simple_exporter(exporter)
            .build();
        let logging = OpenTelemetryTracingBridge::new(&logs);

Do you know what's going on here? Something about that is blocking all output on the tracing subscriber.

Start with the example from the repo. That should work as-is. And you can tweak it to match your setup.
https://github.com/open-telemetry/opentelemetry-rust/blob/main/opentelemetry-appender-tracing/examples/basic.rs

@0xForerunner
Copy link
Author

debug logs

2023-11-16T18:21:31.684Z        info    [email protected]/telemetry.go:84 Setting up own telemetry...
2023-11-16T18:21:31.685Z        info    [email protected]/telemetry.go:201        Serving Prometheus metrics      {"address": ":8888", "level": "Basic"}
2023-11-16T18:21:31.685Z        info    [email protected]/exporter.go:275        Deprecated component. Will be removed in future releases.       {"kind": "exporter", "data_type": "logs", "name": "logging"}
2023-11-16T18:21:31.685Z        warn    common/factory.go:68    'loglevel' option is deprecated in favor of 'verbosity'. Set 'verbosity' to equivalent value to preserve behavior.      {"kind": "exporter", "data_type": "logs", "name": "logging", "loglevel": "debug", "equivalent verbosity level": "Detailed"}
2023-11-16T18:21:31.685Z        info    [email protected]/service.go:143  Starting otelcol-contrib...     {"Version": "0.88.0", "NumCPU": 10}
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:33     Starting extensions...
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:36     Extension is starting...        {"kind": "extension", "name": "basicauth/logs"}
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:43     Extension started.      {"kind": "extension", "name": "basicauth/logs"}
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:36     Extension is starting...        {"kind": "extension", "name": "basicauth/server"}
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:43     Extension started.      {"kind": "extension", "name": "basicauth/server"}
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:36     Extension is starting...        {"kind": "extension", "name": "basicauth/traces"}
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:43     Extension started.      {"kind": "extension", "name": "basicauth/traces"}
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:36     Extension is starting...        {"kind": "extension", "name": "basicauth/metrics"}
2023-11-16T18:21:31.685Z        info    extensions/extensions.go:43     Extension started.      {"kind": "extension", "name": "basicauth/metrics"}
2023-11-16T18:21:31.686Z        warn    [email protected]/warning.go:40  Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks        {"kind": "receiver", "name": "otlp", "data_type": "metrics", "documentation": "https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks"}
2023-11-16T18:21:31.686Z        info    [email protected]/otlp.go:101        Starting HTTP server    {"kind": "receiver", "name": "otlp", "data_type": "metrics", "endpoint": "0.0.0.0:4318"}
2023-11-16T18:21:31.686Z        info    [email protected]/service.go:169  Everything is ready. Begin running and processing data.
2023-11-16T18:21:37.557Z        info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "logging", "resource logs": 1, "log records": 1}
2023-11-16T18:21:37.558Z        info    ResourceLog #0
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(liquidation-bot-rs)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope opentelemetry-appender-tracing 0.2.0
LogRecord #0
ObservedTimestamp: 2023-11-16 18:21:37.443094 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: DEBUG
SeverityNumber: Debug(5)
Body: Str(Initializing client with url: wss://testnet.tm.injective.network/websocket)
Trace ID: 
Span ID: 
Flags: 0
        {"kind": "exporter", "data_type": "logs", "name": "logging"}
2023-11-16T18:21:38.573Z        info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "logging", "resource logs": 5, "log records": 5}
2023-11-16T18:21:38.574Z        info    ResourceLog #0
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(liquidation-bot-rs)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope opentelemetry-appender-tracing 0.2.0
LogRecord #0
ObservedTimestamp: 2023-11-16 18:21:38.154245 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: TRACE
SeverityNumber: Trace(1)
Body: Str(syncing data)
Trace ID: 
Span ID: 
Flags: 0
ResourceLog #1
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(liquidation-bot-rs)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope opentelemetry-appender-tracing 0.2.0
LogRecord #0
ObservedTimestamp: 2023-11-16 18:21:38.261633 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: TRACE
SeverityNumber: Trace(1)
Body: Str(syncing markets)
Attributes:
     -> height: Str(18494177)
Trace ID: 
Span ID: 
Flags: 0
ResourceLog #2
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(liquidation-bot-rs)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope opentelemetry-appender-tracing 0.2.0
LogRecord #0
ObservedTimestamp: 2023-11-16 18:21:38.261741 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: TRACE
SeverityNumber: Trace(1)
Body: Str(syncing collaterals)
Attributes:
     -> height: Str(18494177)
Trace ID: 
Span ID: 
Flags: 0
ResourceLog #3
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(liquidation-bot-rs)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope opentelemetry-appender-tracing 0.2.0
LogRecord #0
ObservedTimestamp: 2023-11-16 18:21:38.261778 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: TRACE
SeverityNumber: Trace(1)
Body: Str(syncing oracle asset details)
Attributes:
     -> height: Str(18494177)
Trace ID: 
Span ID: 
Flags: 0
ResourceLog #4
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(liquidation-bot-rs)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope opentelemetry-appender-tracing 0.2.0
LogRecord #0
ObservedTimestamp: 2023-11-16 18:21:38.370362 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: TRACE
SeverityNumber: Trace(1)
Body: Str(syncing markets)
Attributes:
     -> height: Str(18494178)
Trace ID: 
Span ID: 
Flags: 0
        {"kind": "exporter", "data_type": "logs", "name": "logging"}

@0xForerunner
Copy link
Author

Looks like the trace ids are being omitted.

@cijothomas
Copy link
Member

Follow this example as-is https://github.com/open-telemetry/opentelemetry-rust/blob/main/opentelemetry-otlp/examples/basic-otlp/README.md#manual

You should see logs correctly correlated to traces https://github.com/open-telemetry/opentelemetry-rust/blob/main/opentelemetry-otlp/examples/basic-otlp/src/main.rs#L126

@ewoolsey Could you start with the above example (which we know is working as expected), and progressively make changes to it to match your setup? That'll help us identify root-cause quickly.

@0xForerunner
Copy link
Author

Follow this example as-is https://github.com/open-telemetry/opentelemetry-rust/blob/main/opentelemetry-otlp/examples/basic-otlp/README.md#manual
You should see logs correctly correlated to traces https://github.com/open-telemetry/opentelemetry-rust/blob/main/opentelemetry-otlp/examples/basic-otlp/src/main.rs#L126

@ewoolsey Could you start with the above example (which we know is working as expected), and progressively make changes to it to match your setup? That'll help us identify root-cause quickly.

I just did, and that example doesn't emit a trace_id either, even when inside a span.

code

use opentelemetry::KeyValue;
use opentelemetry_appender_tracing::layer;
use opentelemetry_sdk::{
    logs::{Config, LoggerProvider},
    Resource,
};
use tracing::{error, span};
use tracing_core::Level;
use tracing_subscriber::prelude::*;

fn main() {
    let exporter = opentelemetry_stdout::LogExporter::default();
    let provider: LoggerProvider = LoggerProvider::builder()
        .with_config(
            Config::default().with_resource(Resource::new(vec![KeyValue::new(
                "service.name",
                "log-appender-tracing-example",
            )])),
        )
        .with_simple_exporter(exporter)
        .build();
    let layer = layer::OpenTelemetryTracingBridge::new(&provider);
    tracing_subscriber::registry().with(layer).init();
    let my_span = span!(Level::TRACE, "my_span");

    // `my_span` exists but has not been entered.

    // Enter `my_span`...
    let _enter = my_span.enter();
    error!(name: "my-event-name", target: "my-system", event_id = 20, user_name = "otel", user_email = "[email protected]");
    drop(provider);
}

output

{"resourceLogs":[{"resource":{"attributes":[{"key":"service.name","value":{"stringValue":"log-appender-tracing-example"}}]},"scopeLogs":[{"scope":{"name":"opentelemetry-appender-tracing","version":"0.2.0"},"logR
ecords":[{"timeUnixNano":null,"time":null,"observedTimeUnixNano":1700160228053182000,"observedTime":"2023-11-16 18:43:48.053","severityNumber":17,"severityText":"ERROR","attributes":[{"key":"name","value":{"stri
ngValue":"my-event-name"}},{"key":"event_id","value":{"intValue":20}},{"key":"user_name","value":{"stringValue":"otel"}},{"key":"user_email","value":{"stringValue":"[email protected]"}}],"droppedAttributesCo
unt":0}]}]}]}

@lalitb
Copy link
Member

lalitb commented Nov 16, 2023

I don't see the tracing-opentelemetry subscriber configured in the above example before emitting spans.

@0xForerunner
Copy link
Author

I don't see the tracing-opentelemetry subscriber configured in the above example before emitting spans.

ah right I just blindly ran that example since you linked it.

Anyhow, I found the root cause.

This does not emit a trace id

#[instrument]
pub async fn my_func()  {
    trace!("fun log");
}

But this does

#[instrument]
pub async fn my_func() {
    let tracer = opentelemetry::global::tracer("ex.com/basic");
    tracer.in_span("cool span", |_| {
        trace!("fun log");
    });
}

Should #[instrument] not be taking care of this for me?

@cijothomas
Copy link
Member

Should #[instrument] not be taking care of this for me?

That is a question for tracing-opentelemetry repo! It should have worked, but might need additional setups/config, which are better asked in tracing-opentelemetry repo.

@0xForerunner
Copy link
Author

Should #[instrument] not be taking care of this for me?

That is a question for tracing-opentelemetry repo! It should have worked, but might need additional setups/config, which are better asked in tracing-opentelemetry repo.

I can't have been the only person to run into this, seems like a pretty common use case. I suppose I can open up an issue over there.

Thanks so much for your help talking through this! Appreciate your time. I'll mark this issue as closed here.

@0xForerunner
Copy link
Author

Sorry I think I need to reopen this. I'm pretty sure the issue lies with the opentelemetry-appender-tracing crate. Looking at its code, nowhere does it use the LogRecord trace_context field, which I believe is required to make this feature work correctly, no?

@0xForerunner 0xForerunner reopened this Nov 18, 2023
@lalitb lalitb self-assigned this Nov 19, 2023
@lalitb
Copy link
Member

lalitb commented Nov 19, 2023

opentelemetry-appender-tracing expects the parent's trace-context to be stored in the Otel Context , while tracing-opentelemetry manages the parent-child relationship of spans primarily within the tracing context, and it is not translated in OpenTelemetry Context for logs. Will have a look into this further, though not sure where the changes lies.

@0xForerunner
Copy link
Author

opentelemetry-appender-tracing expects the parent's trace-context to be stored in the Otel Context , while tracing-opentelemetry manages the parent-child relationship of spans primarily within the tracing context, and it is not translated in OpenTelemetry Context for logs. Will have a look into this further, though not sure where the changes lies.

Yeah I think that's an accurate description.
I would think that opentelemetry-appender-tracing should be doing the work here but this ecosystem is complicated enough that I won't claim to know how things should work haha.

@0xForerunner 0xForerunner changed the title [Feature]: Support for adding trace_id in opentelemetry-appender-tracing [Feature]: opentelemetry-appender-tracing should respect information inside tracing::Span Nov 21, 2023
@0xForerunner
Copy link
Author

opentelemetry-appender-tracing expects the parent's trace-context to be stored in the Otel Context , while tracing-opentelemetry manages the parent-child relationship of spans primarily within the tracing context, and it is not translated in OpenTelemetry Context for logs. Will have a look into this further, though not sure where the changes lies.

I changed the name of this issue to reflect what I think should be the expected behaviour.

@0xForerunner
Copy link
Author

@lalitb I need to try and get this going for my work, would you be able to help me out with a quick workaround? Within the on_event trait method inside opentelemetry-appender-tracing, how exactly should I be extracting the trace_id from the tracing ctx?. Here's what I have so far but I can't quite figure out the very last step.

impl<'a, S, P, L> Layer<S> for OpenTelemetryTracingBridge<P, L>
where
    for<'lookup> S: tracing_subscriber::registry::LookupSpan<'lookup>,
    S: tracing::Subscriber,
    P: LoggerProvider<Logger = L> + Send + Sync + 'static,
    L: Logger + Send + Sync + 'static,
{
    fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
        let meta = event.metadata();
        let mut log_record: LogRecord = LogRecord::default();
        log_record.severity_number = Some(severity_of_level(meta.level()));
        log_record.severity_text = Some(meta.level().to_string().into());

        if let Some(current_span) = ctx.lookup_current() {
            if let Some(mut otel_data) = current_span.extensions_mut().remove::<OtelData>() {
                log_record.with_context(otel_data.parent_cx);
            }
        }


    ...

@lalitb
Copy link
Member

lalitb commented Nov 22, 2023

@lalitb I need to try and get this going for my work, would you be able to help me out with a quick workaround? Within the on_event trait method inside opentelemetry-appender-tracing, how exactly should I be extracting the trace_id from the tracing ctx?. Here's what I have so far but I can't quite figure out the very last step.

impl<'a, S, P, L> Layer<S> for OpenTelemetryTracingBridge<P, L>
where
    for<'lookup> S: tracing_subscriber::registry::LookupSpan<'lookup>,
    S: tracing::Subscriber,
    P: LoggerProvider<Logger = L> + Send + Sync + 'static,
    L: Logger + Send + Sync + 'static,
{
    fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
        let meta = event.metadata();
        let mut log_record: LogRecord = LogRecord::default();
        log_record.severity_number = Some(severity_of_level(meta.level()));
        log_record.severity_text = Some(meta.level().to_string().into());

        if let Some(current_span) = ctx.lookup_current() {
            if let Some(mut otel_data) = current_span.extensions_mut().remove::<OtelData>() {
                log_record.with_context(otel_data.parent_cx);
            }
        }


    ...

@ewoolsey with_context is defined for LogRecordBuilder, so won't work here. Did you try directly assigning to log_record.trace_context as done in #1394? I believe it should work.

Also, please remember this will call both OpenTelemetryTracingBridge::on_event() and OpenTelemetryLayer::on_event(), so the logs would be exported both as SpanEvent and LogRecord.

@0xForerunner
Copy link
Author

Oh that's amazing I didn't realize a PR was already being worked on! I'm sure that'll be exactly what I need. Thank you!

@ShovelJockey
Copy link

Has there been any progress on this? Even just a workaround? not been able to find any good examples for implementing and have tried 5 or so different possible solutions to no avail.

@nastynaz
Copy link

Is there an accepted way to correlate logs & traces when using tracing_subscriber? As a hack I'm using opentelemetry-appender-tracing along with tracing-opentelemetry to capture both traces and logs which is inefficient. Is there a better way?

If I only use tracing-opentelemetry I get the traces ingested but log events can't set the proper level because they're technically ingested as traces.

If anyone has some working code they can share that correlates log events with traces I'd very much appreciate it.

@cijothomas
Copy link
Member

Ping to #1689

@geekflyer
Copy link

geekflyer commented May 30, 2024

@ewoolsey did you manage to find a workaround for this or forked the library somehow? Would love to piggyback on yours :-D

@jpramosi
Copy link

I also stumbled over this issue and assumed that the tracing instrument macros work with the opentelemetry framework.
So I hacked something together here https://github.com/jpramosi/opentelemetry-rust/.
It seems to work for a few little examples, but dunno if there are any pitfalls or other new issues?
The signoz trace to log correlation and the otel collector logs looks at least promising for traces and logs (metrics not tested):

Before
2024-08-31T22:34:06.906+0200    info    TracesExporter  {"kind": "exporter", "data_type": "traces", "name": "debug", "resource spans": 1, "spans": 3}
2024-08-31T22:34:06.906+0200    info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "debug", "resource logs": 1, "log records": 3}
2024-08-31T22:34:06.906+0200    info    ResourceSpans #0
Resource SchemaURL: 
ScopeSpans #0
ScopeSpans SchemaURL: 
InstrumentationScope tracing-otel 
Span #0
    Trace ID       : d2188c57c5957be20a9e4a6a7c9df71b
    Parent ID      : 0123c525786a9a1a
    ID             : 177f1f237e21c6b6
    Name           : cut_my_apple
    Kind           : Internal
    Start time     : 2024-08-31 20:34:06.811649122 +0000 UTC
    End time       : 2024-08-31 20:34:06.811713755 +0000 UTC
    Status code    : Error
    Status message : 
Attributes:
     -> code.filepath: Str(examples/tracing-otel/src/main.rs)
     -> code.namespace: Str(tracing_otel)
     -> code.lineno: Int(242)
     -> thread.id: Int(1)
     -> thread.name: Str(main)
     -> slices: Str(0)
     -> busy_ns: Int(54413)
     -> idle_ns: Int(15589)
Events:
SpanEvent #0
     -> Name: I cannot cut the apple in 0 slices
     -> Timestamp: 2024-08-31 20:34:06.811682496 +0000 UTC
     -> DroppedAttributesCount: 0
     -> Attributes::
          -> level: Str(ERROR)
          -> target: Str(vendor)
          -> code.filepath: Str(examples/tracing-otel/src/main.rs)
          -> code.namespace: Str(tracing_otel)
          -> code.lineno: Int(245)
Span #1
    Trace ID       : d2188c57c5957be20a9e4a6a7c9df71b
    Parent ID      : 0123c525786a9a1a
    ID             : c1bf6052588483b8
    Name           : cut_my_apple
    Kind           : Internal
    Start time     : 2024-08-31 20:34:06.811747328 +0000 UTC
    End time       : 2024-08-31 20:34:06.811802152 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> code.filepath: Str(examples/tracing-otel/src/main.rs)
     -> code.namespace: Str(tracing_otel)
     -> code.lineno: Int(242)
     -> thread.id: Int(1)
     -> thread.name: Str(main)
     -> slices: Str(4)
     -> busy_ns: Int(45787)
     -> idle_ns: Int(12544)
Events:
SpanEvent #0
     -> Name: I cut the apple in 4 slices
     -> Timestamp: 2024-08-31 20:34:06.811778658 +0000 UTC
     -> DroppedAttributesCount: 0
     -> Attributes::
          -> level: Str(INFO)
          -> target: Str(vendor)
          -> code.filepath: Str(examples/tracing-otel/src/main.rs)
          -> code.namespace: Str(tracing_otel)
          -> code.lineno: Int(248)
Span #2
    Trace ID       : d2188c57c5957be20a9e4a6a7c9df71b
    Parent ID      : 
    ID             : 0123c525786a9a1a
    Name           : my_instumented_fun
    Kind           : Internal
    Start time     : 2024-08-31 20:34:06.811539605 +0000 UTC
    End time       : 2024-08-31 20:34:06.811825226 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> code.filepath: Str(examples/tracing-otel/src/main.rs)
     -> code.namespace: Str(tracing_otel)
     -> code.lineno: Int(253)
     -> thread.id: Int(1)
     -> thread.name: Str(main)
     -> busy_ns: Int(258268)
     -> idle_ns: Int(32131)
Events:
SpanEvent #0
     -> Name: hello from apple vendor. My price is 2.99
     -> Timestamp: 2024-08-31 20:34:06.811611221 +0000 UTC
     -> DroppedAttributesCount: 0
     -> Attributes::
          -> level: Str(INFO)
          -> target: Str(my-target)
          -> code.filepath: Str(examples/tracing-otel/src/main.rs)
          -> code.namespace: Str(tracing_otel)
          -> code.lineno: Int(257)
        {"kind": "exporter", "data_type": "traces", "name": "debug"}
2024-08-31T22:34:06.906+0200    info    ResourceLog #0
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(unknown_service)
     -> telemetry.sdk.language: Str(rust)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(0.24.1)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope vendor 
LogRecord #0
ObservedTimestamp: 2024-08-31 20:34:06.811688186 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: ERROR
SeverityNumber: Error(17)
Body: Str(I cannot cut the apple in 0 slices)
Trace ID: 
Span ID: 
Flags: 0
LogRecord #1
ObservedTimestamp: 2024-08-31 20:34:06.811784358 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(I cut the apple in 4 slices)
Trace ID: 
Span ID: 
Flags: 0
ScopeLogs #1
ScopeLogs SchemaURL: 
InstrumentationScope my-target 
LogRecord #0
ObservedTimestamp: 2024-08-31 20:34:06.81162147 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(hello from apple vendor. My price is 2.99)
Trace ID: 
Span ID: 
Flags: 0
        {"kind": "exporter", "data_type": "logs", "name": "debug"}
After
2024-08-31T22:33:33.443+0200    info    TracesExporter  {"kind": "exporter", "data_type": "traces", "name": "debug", "resource spans": 1, "spans": 3}
2024-08-31T22:33:33.443+0200    info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "debug", "resource logs": 1, "log records": 3}
2024-08-31T22:33:33.443+0200    info    ResourceLog #0
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(unknown_service)
     -> telemetry.sdk.version: Str(0.24.1)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.language: Str(rust)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope vendor 
LogRecord #0
ObservedTimestamp: 2024-08-31 20:33:33.35766749 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: ERROR
SeverityNumber: Error(17)
Body: Str(I cannot cut the apple in 0 slices)
Trace ID: 53f15c1d0c8f63bd3ecb93e7caec8be5
Span ID: b3ad3b3d8362a35a
Flags: 1
LogRecord #1
ObservedTimestamp: 2024-08-31 20:33:33.357764493 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(I cut the apple in 4 slices)
Trace ID: 53f15c1d0c8f63bd3ecb93e7caec8be5
Span ID: 25a2a92ee5635820
Flags: 1
ScopeLogs #1
ScopeLogs SchemaURL: 
InstrumentationScope my-target 
LogRecord #0
ObservedTimestamp: 2024-08-31 20:33:33.357594531 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(hello from apple vendor. My price is 2.99)
Trace ID: 53f15c1d0c8f63bd3ecb93e7caec8be5
Span ID: ebad8823e60c782e
Flags: 1
        {"kind": "exporter", "data_type": "logs", "name": "debug"}
2024-08-31T22:33:33.443+0200    info    ResourceSpans #0
Resource SchemaURL: 
ScopeSpans #0
ScopeSpans SchemaURL: 
InstrumentationScope tracing-otel 
Span #0
    Trace ID       : 53f15c1d0c8f63bd3ecb93e7caec8be5
    Parent ID      : ebad8823e60c782e
    ID             : b3ad3b3d8362a35a
    Name           : cut_my_apple
    Kind           : Internal
    Start time     : 2024-08-31 20:33:33.357621723 +0000 UTC
    End time       : 2024-08-31 20:33:33.357690203 +0000 UTC
    Status code    : Error
    Status message : 
Attributes:
     -> code.filepath: Str(examples/tracing-otel/src/main.rs)
     -> code.namespace: Str(tracing_otel)
     -> code.lineno: Int(242)
     -> thread.id: Int(1)
     -> thread.name: Str(main)
     -> slices: Str(0)
     -> busy_ns: Int(57980)
     -> idle_ns: Int(13566)
Events:
SpanEvent #0
     -> Name: I cannot cut the apple in 0 slices
     -> Timestamp: 2024-08-31 20:33:33.357654936 +0000 UTC
     -> DroppedAttributesCount: 0
     -> Attributes::
          -> level: Str(ERROR)
          -> target: Str(vendor)
          -> code.filepath: Str(examples/tracing-otel/src/main.rs)
          -> code.namespace: Str(tracing_otel)
          -> code.lineno: Int(245)
Span #1
    Trace ID       : 53f15c1d0c8f63bd3ecb93e7caec8be5
    Parent ID      : ebad8823e60c782e
    ID             : 25a2a92ee5635820
    Name           : cut_my_apple
    Kind           : Internal
    Start time     : 2024-08-31 20:33:33.357721482 +0000 UTC
    End time       : 2024-08-31 20:33:33.357781325 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> code.filepath: Str(examples/tracing-otel/src/main.rs)
     -> code.namespace: Str(tracing_otel)
     -> code.lineno: Int(242)
     -> thread.id: Int(1)
     -> thread.name: Str(main)
     -> slices: Str(4)
     -> busy_ns: Int(50976)
     -> idle_ns: Int(11933)
Events:
SpanEvent #0
     -> Name: I cut the apple in 4 slices
     -> Timestamp: 2024-08-31 20:33:33.357752681 +0000 UTC
     -> DroppedAttributesCount: 0
     -> Attributes::
          -> level: Str(INFO)
          -> target: Str(vendor)
          -> code.filepath: Str(examples/tracing-otel/src/main.rs)
          -> code.namespace: Str(tracing_otel)
          -> code.lineno: Int(248)
Span #2
    Trace ID       : 53f15c1d0c8f63bd3ecb93e7caec8be5
    Parent ID      : 
    ID             : ebad8823e60c782e
    Name           : my_instumented_fun
    Kind           : Internal
    Start time     : 2024-08-31 20:33:33.357498189 +0000 UTC
    End time       : 2024-08-31 20:33:33.357801533 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> code.filepath: Str(examples/tracing-otel/src/main.rs)
     -> code.namespace: Str(tracing_otel)
     -> code.lineno: Int(253)
     -> thread.id: Int(1)
     -> thread.name: Str(main)
     -> busy_ns: Int(274100)
     -> idle_ns: Int(34394)
Events:
SpanEvent #0
     -> Name: hello from apple vendor. My price is 2.99
     -> Timestamp: 2024-08-31 20:33:33.357571788 +0000 UTC
     -> DroppedAttributesCount: 0
     -> Attributes::
          -> level: Str(INFO)
          -> target: Str(my-target)
          -> code.filepath: Str(examples/tracing-otel/src/main.rs)
          -> code.namespace: Str(tracing_otel)
          -> code.lineno: Int(257)
        {"kind": "exporter", "data_type": "traces", "name": "debug"}

'LogRecord' got trace and span ids now

If someone would like to test it, append this to the Cargo.toml file:

[dependencies]
# ...
opentelemetry-tracing = { version = "0.25" }

[patch.crates-io]
opentelemetry = { package = "opentelemetry", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry-appender-tracing = { package = "opentelemetry-appender-tracing", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry-http = { package = "opentelemetry-http", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry-otlp = { package = "opentelemetry-otlp", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry_sdk = { package = "opentelemetry_sdk", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry-tracing = { package = "opentelemetry-tracing", git = "https://github.com/jpramosi/opentelemetry-rust.git" }

The fork includes tracing-opentelemetry but was renamed to 'opentelemetry-tracing'. So it needs to be refactored in your code or it doesn't work at all. A working example can be seen here.

@nastynaz
Copy link

nastynaz commented Sep 12, 2024

I also stumbled over this issue and assumed that the tracing instrument macros work with the opentelemetry framework. So I hacked something together here https://github.com/jpramosi/opentelemetry-rust/. It seems to work for a few little examples, but dunno if there are any pitfalls or other new issues? The signoz trace to log correlation and the otel collector logs looks at least promising for traces and logs (metrics not tested):

Before
After
'LogRecord' got trace and span ids now

If someone would like to test it, append this to the Cargo.toml file:

[dependencies]
# ...
opentelemetry-tracing = { version = "0.25" }

[patch.crates-io]
opentelemetry = { package = "opentelemetry", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry-appender-tracing = { package = "opentelemetry-appender-tracing", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry-http = { package = "opentelemetry-http", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry-otlp = { package = "opentelemetry-otlp", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry_sdk = { package = "opentelemetry_sdk", git = "https://github.com/jpramosi/opentelemetry-rust.git" }
opentelemetry-tracing = { package = "opentelemetry-tracing", git = "https://github.com/jpramosi/opentelemetry-rust.git" }

The fork includes tracing-opentelemetry but was renamed to 'opentelemetry-tracing'. So it needs to be refactored in your code or it doesn't work at all. A working example can be seen here.

This is amazing! Thank you for making the changes and sharing your code. It's working for me.

I got it working after doing the switch from tracing-opentelemetry to opentelemetry-tracing as you suggested. I also bumped by version of opentelemtry down to 0.24.0 as that's the same as the one you released.

@dylanahsmith
Copy link

@jpramosi have you tried opening a pull request with the set_trace_context and get_mut_trace_context methods you added to the opentelemetry::logs::LogRecord trait in your fork? Since that would allow this to be implemented similar to your fork with only a forked version of the opentelemetry-appender-tracing crate.

After that, the next question would be how to avoid cargo trying to use the crates.io version of opentelemetry crates in the workspace, which conflict the with workspace path referenced versions of them. I tried working around that with dependency overrides

[patch.crates-io]
opentelemetry = { path = "opentelemetry" }
opentelemetry_sdk = { path = "opentelemetry-sdk" }

but that didn't seem to work. I haven't had a chance to dig into why that is the case, but it seems like that should be the solution.

There is also the question of whether this is something that should just be implemented in tracing-opentelemetry as an additional feature. Not only would that avoid this workspace circular dependency issue, but it seems like these are naturally coupled and thus simpler to maintain together. It would also avoid confusion from users expecting a library like that to support both tracing and logging (tokio-rs/tracing-opentelemetry#76). Any extraction of this code would similarly depend on the opentelemetry::logs::LogRecord trait changes.

@jpramosi
Copy link

@jpramosi have you tried opening a pull request with the set_trace_context and get_mut_trace_context methods you added to the opentelemetry::logs::LogRecord trait in your fork? Since that would allow this to be implemented similar to your fork with only a forked version of the opentelemetry-appender-tracing crate.

The fork has probably already been reviewed by the maintainers. I guess the team is following another similar idea, or the changes in my repository don't fit well with the current state of the project. Since I have not received direct feedback from the members, I believe the changes are undesirable.

After that, the next question would be how to avoid cargo trying to use the crates.io version of opentelemetry crates in the workspace

Maybe cargo tree could help here.

@dylanahsmith
Copy link

dylanahsmith commented Dec 13, 2024

Full dependency override needed is

[patch.crates-io]
opentelemetry = { path = "opentelemetry" }
opentelemetry_sdk = { path = "opentelemetry-sdk" }
opentelemetry-stdout = { path = "opentelemetry-stdout" }

which I had tried, but got confused by an unrelated version conflict when trying it on an old branch (for #1394), but seems to work on main.

The full fork isn't going to be desirable, since
Lack of approval isn't necessarily indicative of the changes being undesirable.

The fork includes tracing-opentelemetry but was renamed to 'opentelemetry-tracing'. So it needs to be refactored in your code or it doesn't work at all.

Changes like that are certainly going to be undesirable and a signal that you aren't necessarily trying to get the changes upstream. A pull request would be their preferred way of receiving proposed changes, which would make it easier for them to comment on what part of the code might need before the changes could be merged. A pull request will also trigger their bot that asks for a CLA to be signed, which also seems to be a prerequisite before they merge code, which would probably interfere with me basing work off yours if you haven't signed the CLA. A pull request is also a signal that the code is in fact ready for review, especially if CI is passing.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-log Area: Issues related to logs enhancement New feature or request triage:todo Needs to be traiged.
Projects
None yet
8 participants