No MDC Log Information in @SqsListener in Java Agent Auto Instrumentation

[fabiolnh]

Describe the bug

I have two services:

Service A: SNS Sender (Using SDK v2 AWS), Spring Boot 2, Java 17, Agent Version 1.30.0 Service B: SQS Listener, Spring Boot 3, Java 17, Agent Version 1.30.0

Docker-compose:

• Localstack (free version) (image: localstack/localstack)
• Jaeger (image: jaegertracing/all-in-one:latest)
• Service A
• Service B

The structure:

Service A -> SNS -> SQS -> Service B

Dockerfile Service A:

FROM amazoncorretto:17-alpine-jdk
WORKDIR /home/app
RUN apk add --no-cache wget
ARG JAR_FILE=build/libs/scheduler-0.0.1-SNAPSHOT.jar
COPY ${JAR_FILE} app.jar
COPY opentelemetry-javaagent.jar opentelemetry-javaagent.jar
ENTRYPOINT ["java", \ \
            "-javaagent:/home/app/opentelemetry-javaagent.jar", \
            "-Dotel.resource.attributes=service.name=scheduler", \
            "-Dotel.traces.exporter=jaeger", \
            "-Dotel.exporter.jaeger.endpoint=http://jaeger:14250", \
            "-Dotel.metrics.exporter=none", \
             "-Dotel.instrumentation.aws-sdk.experimental-span-attributes=true", \
             "-Dotel.instrumentation.aws-sdk.experimental-use-propagator-for-messaging=true", \
            "-Dotel.traces.sampler=always_on", \
            "-jar", "/home/app/app.jar"]
EXPOSE 8080

Service B:

FROM amazoncorretto:17-alpine-jdk
WORKDIR /home/app
ARG JAR_FILE=build/libs/demo-0.0.1-SNAPSHOT.jar
COPY ${JAR_FILE} app.jar
COPY opentelemetry-javaagent.jar opentelemetry-javaagent.jar
ENTRYPOINT ["java", \
            "-javaagent:/home/app/opentelemetry-javaagent.jar", \
            "-Dotel.resource.attributes=service.name=demo", \
            "-Dotel.traces.exporter=jaeger", \
            "-Dotel.exporter.jaeger.endpoint=http://jaeger:14250", \
            "-Dotel.metrics.exporter=none", \
             "-Dotel.instrumentation.aws-sdk.experimental-span-attributes=true", \
             "-Dotel.instrumentation.aws-sdk.experimental-use-propagator-for-messaging=true", \
            "-Dotel.traces.sampler=always_on", \
            "-Dotel.javaagent.debug=true", \
            "-jar", "/home/app/app.jar"]
EXPOSE 8081

I tested 3 endpoints:

1) Rest (Working) 2) GRPC (Working) 3) SNS/SQS (Tracing Between Services appears in Jaeger, however, the MDC Log (trace_id and span_id) is empty in Service B (using @SqsConsumer), So I cannot log the trace, which is pretty important)

I tried to implement Manual Instrumentation, importing the libs into the Service B (Micrometer and Open Telemetry), but it does not work, too. (It works with Rest and GRPC, but with SQS does not)

It seems to be something related with Asynchronous communication.

Is there an issue? Or I am doing something wrong? I would appreciate a help.

Libs that I am using in Service B:

plugins {
    id 'java'
    id 'org.springframework.boot' version '3.1.4'
    id 'io.spring.dependency-management' version '1.1.3'
}

dependencies {
implementation 'org.springframework.boot:spring-boot-starter-web'

implementation 'io.awspring.cloud:spring-cloud-aws-dependencies:3.0.2'
implementation 'io.awspring.cloud:spring-cloud-aws-starter:3.0.2'
implementation 'io.awspring.cloud:spring-cloud-aws-starter-sqs:3.0.2'

implementation 'org.springframework.boot:spring-boot-starter-log4j2'
}

configurations {
    all {
        exclude group: 'org.springframework.boot', module: 'spring-boot-starter-logging'
    }
}

Class SqsConsumer in Service B:

import io.awspring.cloud.sqs.annotation.SqsListener;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
public class SqsConsumer {

  Logger logger = LoggerFactory.getLogger(SqsConsumer.class);

  @SqsListener(value = "${aws.sqs.queue.name}")
  public void receiveMessage(String payload) {
    logger.info("teste sqs: " + payload);
    }
}

log4j2.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} [trace_id='%mdc{trace_Id}'] [span_id='%mdc{span_id}'] - %msg %n" />
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console" />
        </Root>
    </Loggers>
</Configuration>

Steps to reproduce

Create 2 Services With Java and SpringBoot using the following components:

Service A: SNS Sender (Using SDK v2 AWS), Spring Boot 2, Java 17, Agent Version 1.30.0 Service B: SQS Listener, Spring Boot 3, Java 17, Agent Version 1.30.0

Implement Log4j with the following layout:

<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} [trace_id='%mdc{trace_Id}'] [span_id='%mdc{span_id}'] - %msg %n" />

Try to communicate through SNS/SQS between them and check the Log

Trace_id and span_id are empty.

Expected behavior

It should show the trace_id and the span_id on the log

Actual behavior

Log in Service B is shown this way:

19:39:03.503 [io.awspring.cloud.sqs.sqsListenerEndpointContainer#0-1] INFO  com.example.demo.sqs.SqsConsumer [trace_id=''] [span_id=''] - teste sqs: {"Type": "Notification", "MessageId": "392b92b0-3ac9-4deb-9dca-10cba7187181", "TopicArn": "arn:aws:sns:sa-east-1:000000000000:scheduler_connection_refresh-tf", "Message": "{ \"connectionId\": \"63f15eff-7ea0-4401-932c-13e556bde0b4\" }", "Timestamp": "2023-09-28T19:39:03.287Z", "SignatureVersion": "1", "Signature": "EXAMPLEpH+..", "SigningCertURL": "https://sns.sa-east-1.amazonaws.com/SimpleNotificationService-0000000000000000000000.pem", "UnsubscribeURL": "http://localhost:4566/?Action=Unsubscribe&SubscriptionArn=arn:aws:sns:sa-east-1:000000000000:scheduler_connection_refresh-tf:623845af-7a67-4e72-ae99-b6a709617dcf", "MessageAttributes": {"traceparent": {"Type": "String", "Value": "00-841d970aef4c98faca6c7223133e3df2-04d4c8cd4a07af6f-01"}}

Javaagent or library instrumentation version

1.30.0

Environment

JDK: 17 OS: MacOS (however, I am running through both servers through Docker)

Additional context

I think there are no more information to provide. If there is some question, please, ask to me that I will be glad to answer. Thank you all.

[fabiohenriqueszup]

More information: all the tests are locally, using localstack (free)

[laurit]

Same as https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/4788 For this to work instrumentation for spring SqsListener is needed. Also note that the free version of localstack does not propagate AWSTraceHeader message system attribute that is, by default, used to propagate the trace through sqs. For trace propagation on localstack -Dotel.instrumentation.aws-sdk.experimental-use-propagator-for-messaging=true could help, but it won't help with having the trace available in SqsListener.