Traceid and spanid is added to logs as empty in spring boot with log4j2.xml

[sulthans]

Hi,

Below are the config i have done for my application, trace and span id generated also traceparent added in kafka message header as - 00-9e94c3668945e351de9bcce36fa50b77-6cf5599c9aa1bb9e-01

pom.xml

<dependency>
            <groupId>io.opentelemetry.instrumentation</groupId>
            <artifactId>opentelemetry-spring-boot-starter</artifactId>
            <version>2.6.0</version>
        </dependency>
        <dependency>
            <groupId>io.opentelemetry.instrumentation</groupId>
            <artifactId>opentelemetry-log4j-appender-2.17</artifactId>
            <version>2.6.0-alpha</version>
            <scope>runtime</scope>
        </dependency>
        <!--<dependency>
            <groupId>io.opentelemetry.instrumentation</groupId>
            <artifactId>opentelemetry-logback-mdc-1.0</artifactId>
            <version>2.6.0-alpha</version>
        </dependency>-->
        <!--<dependency>
            <groupId>io.opentelemetry.instrumentation</groupId>
            <artifactId>opentelemetry-log4j-context-data-2.17-autoconfigure</artifactId>
            <version>2.6.0-alpha</version>
            <scope>runtime</scope>
        </dependency>-->
        <dependency>
            <groupId>org.springframework.kafka</groupId>
            <artifactId>spring-kafka</artifactId>
        </dependency>
        <dependency>
            <groupId>io.opentelemetry</groupId>
            <artifactId>opentelemetry-api</artifactId>
            <version>1.41.0</version>
        </dependency>
        <dependency>
            <groupId>io.opentelemetry</groupId>
            <artifactId>opentelemetry-sdk-extension-autoconfigure</artifactId>
        </dependency>

log4j2.xml

<Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout
                    pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} trace_id: %X{trace_id} span_id: %X{span_id} trace_flags: %X{trace_flags} - %msg%n"/>
            <LogstashLayout
                    dateTimeFormatPattern="yyyy-MM-dd'T'HH:mm:ss.SSSZZZ"
                    templateUri="classpath:log4j2/LogstashJsonLayout.json"
                    stackTraceEnabled="true" prettyPrintEnabled="false"/>
        </Console>
        <OpenTelemetry name="OpenTelemetryAppender"/>
    </Appenders>
    <Loggers>
        <Logger name="org.apache.kafka.*" level="ERROR" />
        <Root level="INFO">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="OpenTelemetryAppender" level="All"/>
        </Root>
    </Loggers>```


Logs generated : 

2024-09-23T15:03:59.466+05:30 trace_id= span_id= trace_flags= INFO 57396 --- [otel_demo] [nio-8080-exec-1] o.a.k.c.t.i.KafkaMetricsCollector : initializing Kafka metrics collector
2024-09-23T09:33:59.466Z INFO 'initializing Kafka metrics collector' : 9e94c3668945e351de9bcce36fa50b77 0a153e372d34851d [scopeInfo: org.apache.kafka.common.telemetry.internals.KafkaMetricsCollector:] {}
2024-09-23T15:03:59.520+05:30 trace_id= span_id= trace_flags= INFO 57396 --- [otel_demo] [nio-8080-exec-1] o.a.k.clients.producer.KafkaProducer : [Producer clientId=otel_demo-producer-1] Instantiated an idempotent producer.
2024-09-23T09:33:59.52Z INFO '[Producer clientId=otel_demo-producer-1] Instantiated an idempotent producer.' : 9e94c3668945e351de9bcce36fa50b77 0a153e372d34851d [scopeInfo: org.apache.kafka.clients.producer.KafkaProducer:] {}
2024-09-23T15:03:59.547+05:30 trace_id= span_id= trace_flags= INFO 57396 --- [otel_demo] [nio-8080-exec-1] o.a.kafka.common.utils.AppInfoParser : Kafka version: 3.7.1
2024-09-23T09:33:59.547Z INFO 'Kafka version: 3.7.1' : 9e94c3668945e351de9bcce36fa50b77 0a153e372d34851d [scopeInfo: org.apache.kafka.common.utils.AppInfoParser:] {}
2024-09-23T15:03:59.547+05:30 trace_id= span_id= trace_flags= INFO 57396 --- [otel_demo] [nio-8080-exec-1] o.a.kafka.common.utils.AppInfoParser : Kafka commitId: e2494e6ffb89f828
2024-09-23T09:33:59.547Z INFO 'Kafka commitId: e2494e6ffb89f828' : 9e94c3668945e351de9bcce36fa50b77 0a153e372d34851d [scopeInfo: org.apache.kafka.common.utils.AppInfoParser:] {}
2024-09-23T15:03:59.547+05:30 trace_id= span_id= trace_flags= INFO 57396 --- [otel_demo] [nio-8080-exec-1] o.a.kafka.common.utils.AppInfoParser : Kafka startTimeMs: 1727084039545
2024-09-23T09:33:59.547Z INFO 'Kafka startTimeMs: 1727084039545' : 9e94c3668945e351de9bcce36fa50b77 0a153e372d34851d [scopeInfo: org.apache.kafka.common.utils.AppInfoParser:] {}
2024-09-23T15:03:59.724+05:30 trace_id= span_id= trace_flags= INFO 57396 --- [otel_demo] [demo-producer-1] org.apache.kafka.clients.Metadata : [Producer clientId=otel_demo-producer-1] Cluster ID: lT2QuuCARkKuBzZfw2ueKQ
2024-09-23T09:33:59.724Z INFO '[Producer clientId=otel_demo-producer-1] Cluster ID: lT2QuuCARkKuBzZfw2ueKQ' : 00000000000000000000000000000000 0000000000000000 [scopeInfo: org.apache.kafka.clients.Metadata:] {}
2024-09-23T15:03:59.725+05:30 trace_id= span_id= trace_flags= INFO 57396 --- [otel_demo] [demo-producer-1] o.a.k.c.p.internals.TransactionManager : [Producer clientId=otel_demo-producer-1] ProducerId set to 29 with epoch 0```

Set environment variable :

export OTEL_METRICS_EXPORTER=none
export OTEL_LOGS_EXPORTER=none
export OTEL_TRACES_EXPORTER=none

Running application with - jar - java -Dotel.metrics.exporter=none -jar ./target/otel-demo-0.0.1-SNAPSHOT.jar

I have also tried with logback from reference - https://github.com/open-telemetry/opentelemetry-java-instrumentation/tree/main/instrumentation/logback/logback-mdc-1.0/library

still the same.

[laurit]

To have trace and span id available in MDC you must have an active trace. For kafka this means that you need instrumentation that restores context from context propagation header added to a kafka message. Looking at your pom fragment you don't seem to be using a kafka instrumentation so not having trace and span id is expected. Even if you use kafka instrumentation trace and span id will only be available when the context is restored, for example when using https://github.com/open-telemetry/opentelemetry-java-instrumentation/tree/main/instrumentation/spring/spring-kafka-2.7 you could expect to observe the restored context while inside a @KafkaListener annotated method that consumes a single message. You should not expect to have trace/span id available in random log statements inside kafka.

[sulthans]

Thanks @laurit

Span span = tracer.spanBuilder("test-event").startSpan();
        try (Scope scope = span.makeCurrent()) {

      Mono<String> requestBody = request.bodyToMono(String.class);
            
            return requestBody.flatMap(message -> messageService.processMessage(moduleName, message, contentType, 
     traceId)).metrics();
        }
        catch (Throwable t) {
            span.recordException(t);
            throw t;
        }
        finally {
            span.end();
        }

public class MessageService {
    private static final Logger LOGGER = LoggerFactory.getLogger(MessageService.class);

    private final MessageProducer messageProducer;


    @Autowired
    public MessageService(final MessageProducer messageProducer) {
        this.messageProducer = messageProducer;
    }  
   
 public Mono<ServerResponse> processMessage(final String moduleName, final String message,
                                               final String contentType, final String traceId) {
                                               
    String jsonMessage = convertMessageToJson(contentType, message);
    if (StringUtils.isNotBlank(jsonMessage)) {
                log.debug("Destination Kafka  {} ", kafkaTopicName);
                log.debug("Output message  {} ", jsonMessage);
                messageProducer.postMessage(kafkaTopicName, jsonMessage, traceId);
                return ServerResponse.status(HttpStatus.OK).build();
            }
        }
}

i have updated log4j2.xml and logs are having trace and span id. For kafka, in topic the message produced i don't see traceparent not added in header. With the sample project i see the traceparent added message header. We need to add manual code or kafka instrumentation dependency is enough to get tarce?
I am new to otel, could you please provide more details to implement.

[laurit]

We need to add manual code or kafka instrumentation dependency is enough to get tarce?

Adding the dependency is not enough. Unfortunately our spring-kafka instrumentation does not have a readme with instructions yet so you'll have to study the test https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/spring/spring-kafka-2.7/library/src/test/java/io/opentelemetry/instrumentation/spring/kafka/v2_7/SpringKafkaNoReceiveTelemetryTest.java to see how you can use it. Keep in mind that if you are going to use manual instrumentation you may need to add instrumentations for many libraries, e.g. the reactive stuff that you seem to use needs instrumentation to propagate context. It is up to you to figure out which instrumentations you need. Getting started with the java agent may be easier.

[sulthans]

Thank @laurit let me try with kafka instrunmentation

[sulthans]

@laurit I am using Java agent now, trace Id propagating to kafka header and opentelemetry collects and export to jaeger. How
to enable export to a log file and can we define custom data format to be write in that file?

[trask]

hi @sulthans, you can build a Java agent extension and write your own Exporter