open-telemetry / opentelemetry-java-instrumentation

OpenTelemetry auto-instrumentation and instrumentation libraries for Java
https://opentelemetry.io
Apache License 2.0
1.88k stars 823 forks source link

SQS trace ids are not added to MDC #8829

Closed ASarco closed 1 year ago

ASarco commented 1 year ago

Describe the bug I have an app that uses the OTEL agent, v1.27.0 This is a SpringBoot 2.7.x app, using WebMVC , Spring Cloud AWS 2.4.4, with AWS SDK 1.12.x When I send a request to an endpoint, I can see in the logs (logback) the trace and span Ids. However, when an SQS message is received, the trace and span Ids are empty.

Steps to reproduce I have included opentelemetry-logback-mdc-1.0 in the classpath, and configured an appender in logback.xml

<appender name="OTEL" class="io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender">
        <appender-ref ref="CONSOLE"/>
</appender>

(although I'm not sure if this is really necessary, or I can use any other appender?)

What did you expect to see? For a rest request, the logs show the trace and span Ids perfectly:

2023-06-29 10:50:10.636 trace=ac8c2a211e0d0543fd4346e221dc97c7 span=7f74e0f1623861a0 flags=01  INFO 11840 --- [nio-9331-exec-2] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-06-29 10:50:10.649 trace=ac8c2a211e0d0543fd4346e221dc97c7 span=7f74e0f1623861a0 flags=01  INFO 11840 --- [nio-9331-exec-2] c.i.p.filters.HttpRequestLoggingFilter   : http.request
2023-06-29 10:50:10.716 trace=ac8c2a211e0d0543fd4346e221dc97c7 span=5f8b20b89bd940d2 flags=01  INFO 11840 --- [nio-9331-exec-2] c.i.p.controller.PipelineController      : Received get pipeline state request for pipelineKeys: [1234, 2345], to: null
2023-06-29 10:50:10.753 trace=ac8c2a211e0d0543fd4346e221dc97c7 span=7f74e0f1623861a0 flags=01  INFO 11840 --- [nio-9331-exec-2] c.i.p.filters.HttpRequestLoggingFilter   : http.response

What did you see instead? When an SQS message is received, the log doesn't includes the trace and span ids:

2023-06-29 10:45:22.383 trace= span= flags=  INFO 11840 --- [enerContainer-2] c.i.p.listener.ResourceEventListener     : Message received: {"version":"0","id":"20b47cf3-3cda-0e6d-c3e3-4d37b296f12c","detail-type":"MediaLive

What version are you using? [otel.javaagent 2023-06-29 10:45:02:307 +0100] [main] INFO io.opentelemetry.javaagent.tooling.VersionLogger - opentelemetry-javaagent - version: 1.27.0

Environment Compiler: Correto 17.0.7 OS: Windows 10

Additional context Maybe I'm doing something wrong, or something I'm using is not compatible, so I'd appreciate some help.

laurit commented 1 year ago

Firstly when using java agent you shouldn't need to include opentelemetry-logback-mdc-1.0 and configure it manually, it should work automatically. My guess is that for this to work as you expect Spring Cloud AWS instrumentation is needed.

ASarco commented 1 year ago

Firstly when using java agent you shouldn't need to include opentelemetry-logback-mdc-1.0 and configure it manually, it should work automatically. My guess is that for this to work as you expect Spring Cloud AWS instrumentation is needed.

Thanks for your answer. But if Spring Cloud AWS uses AWS SDK in the end, shouldn't still work?

laurit commented 1 year ago

Thanks for your answer. But if Spring Cloud AWS uses AWS SDK in the end, shouldn't still work?

That is a good question. Basically it boils down to the api that is exposed by the framework. For messaging instrumentation we like apis that are based on listeners. When a message is received a user method is called to process the message, we can instrument it so that message processing starts on entry to that method and ends on exit. We can nicely capture the message processing and set the traceid/spanid for that operation. With aws sdk you call client.receiveMessage(...) and get a message back. We don't like that kind of apis because there is no visibility what is going to happen with the message next. We can't use the context from the receive operation for subsequent operations because we can't tell when or whether the processing ends.

github-actions[bot] commented 1 year ago

This has been automatically marked as stale because it has been marked as needing author feedback and has not had any activity for 7 days. It will be closed automatically if there is no response from the author within 7 additional days from this comment.