Issues with Log4j MDC injections #3074

pwfarwell · 2021-05-24T14:31:38Z

pwfarwell
May 24, 2021

In our application, traceIds and spanIds don't consistently appear in our Log4j logs.
We are wondering if our client code will need to inject traceIds/spanIds into the MDC context manually. My understanding is that otel will manage the MDC context itself (regardless of whether the client is instrumented manually or automatically).

We are using otel 1.1 with manual instrumentation. I have the logging.pattern in my application.properties.

I have a simple SpringBoot app to demonstrate the problem. In the demo, I create a new span inside a new thread. I don't see any traceIds injected into the logs.
I am attaching the source code.

Code snippet:

  static class WorkerThread extends Thread {
    
    private Tracer tracer;
    
    private static final Logger WORK_LOGGER = LoggerFactory.getLogger(WorkerThread.class);
    
    WorkerThread(Tracer tracer) {
      this.tracer = tracer;
    }
    
      public void run() {
          int i = 0;
          while (true) {
            WORK_LOGGER.info(this.getName() + ": Worker Thread is running..." + i++);         
            Span span = tracer.spanBuilder("my span").startSpan();
            
            try (Scope scope = span.makeCurrent()) {              
              WORK_LOGGER.info("Inside span, traceId: {}, spanId: {}", span.getSpanContext().getTraceId(), span.getSpanContext().getSpanId());
            } catch (Throwable t) {
                t.printStackTrace();
            } finally {
                span.end(); // closing the scope does not end the span, this has to be done manually
            }
          }
      }
  }

Logs:

2021-05-24 09:32:41 - c.e.s.Application$WorkerThread - Thread-1: Worker Thread is running...4 trace_id= span_id= trace_flags= 
2021-05-24 09:32:41 - c.e.s.Application$WorkerThread - Inside span, traceId: a86d15a0fad919c33ba1dfcc5ffbfde4, spanId: c2c01aa1d2380142 trace_id= span_id= trace_flags=

I see the new traceId/spanId have been created, but they aren't injected into the logs (even during the current scope of the span).

Here are the dependencies in my maven pom.xml:

  <dependencyManagement>
    <dependencies>
      <dependency>
        <groupId>io.opentelemetry</groupId>
        <artifactId>opentelemetry-bom</artifactId>
        <version>1.1.0</version>
        <type>pom</type>
        <scope>import</scope>
      </dependency>
    </dependencies>
  </dependencyManagement> 
  
  <dependencies>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-web</artifactId>
    </dependency>

    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-test</artifactId>
      <scope>test</scope>
    </dependency>
    
    <dependency>
      <groupId>io.opentelemetry</groupId>
      <artifactId>opentelemetry-api</artifactId>
    </dependency>
        <dependency>
            <groupId>io.opentelemetry</groupId>
            <artifactId>opentelemetry-sdk</artifactId>
        </dependency>
    <dependency>
        <groupId>io.opentelemetry</groupId>
        <artifactId>opentelemetry-exporter-otlp</artifactId>
    </dependency>
    <dependency>
        <groupId>io.opentelemetry</groupId>
        <artifactId>opentelemetry-sdk-common</artifactId>
    </dependency>
    <dependency>
      <groupId>io.opentelemetry.instrumentation</groupId>
      <artifactId>opentelemetry-log4j-2.13.2</artifactId>
      <version>0.17.0-alpha</version>
      <scope>runtime</scope>
    </dependency>   
    
        <dependency>
            <groupId>io.grpc</groupId>
            <artifactId>grpc-protobuf</artifactId>
            <version>1.37.0</version>
        </dependency>
        <dependency>
            <groupId>io.grpc</groupId>
            <artifactId>grpc-netty-shaded</artifactId>
            <version>1.37.0</version>
        </dependency>   
  </dependencies>

opentel-springboot-demo.zip

Answered by jkwatson

May 24, 2021

Hi @pwfarwell .

The issue here is that spring boot, by default, is using logback as the logging implementation, not log4j2. If you want to have the logging implementation be log4j2, you'll need to tweak your pom a bit:

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-web</artifactId>
			<exclusions>
				<exclusion>
					<groupId>org.springframework.boot</groupId>
					<artifactId>spring-boot-starter-logging</artifactId>
				</exclusion>
			</exclusions>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-log4j2</artifactId>
		</dependency>

I tried this locally, and it worked fine.

A…

View full answer

jkwatson · 2021-05-24T15:40:38Z

jkwatson
May 24, 2021
Collaborator

Hi @pwfarwell .

The issue here is that spring boot, by default, is using logback as the logging implementation, not log4j2. If you want to have the logging implementation be log4j2, you'll need to tweak your pom a bit:

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-web</artifactId>
			<exclusions>
				<exclusion>
					<groupId>org.springframework.boot</groupId>
					<artifactId>spring-boot-starter-logging</artifactId>
				</exclusion>
			</exclusions>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-log4j2</artifactId>
		</dependency>

I tried this locally, and it worked fine.

Also, I recommend keeping your opentelemetry versions in sync:

    <dependency>
      <groupId>io.opentelemetry.instrumentation</groupId>
      <artifactId>opentelemetry-log4j-2.13.2</artifactId>
      <version>1.1.0-alpha</version>
      <scope>runtime</scope>
    </dependency>

6 replies

pwfarwell May 24, 2021
Author

@jkwatson I added your tweak to my pom file, but with the same result. The traceId doesn't get injected into the MDC context.

It's a very simple code example, but there must be something else missing in my runtime env.
I am running it with Java 1.8.0_201. Could that be the issue?

Also I see an error about not having a collector running. I expect to see that error, as my intention is only to test the integration with Log4j.
Could the lack of a running collector prevent the traceIds from getting injected?

2021-05-24 12:23:30 - c.e.s.Application$WorkerThread - Inside span, traceId: 10dd24b566a292b21f4063df7bdb0109, spanId: 382da01ed83f07c7 trace_id= span_id= trace_flags= 
2021-05-24 12:23:30 - i.o.e.o.trace.OtlpGrpcSpanExporter - Failed to export spans. Server is UNAVAILABLE. Make sure your collector is running and reachable from this network. Full error message:UNAVAILABLE: io exception trace_id= span_id= trace_flags=

pwfarwell May 24, 2021
Author

btw, the maven dependency tree appears to show that everything is aligned on the 1.1 otel libraries:

[INFO] --- maven-dependency-plugin:3.1.2:tree (default-cli) @ opentel-springboot-demo ---
[INFO] Verbose not supported since maven-dependency-plugin 3.0
[INFO] com.example:opentel-springboot-demo:jar:0.0.1-SNAPSHOT
[INFO] +- org.springframework.boot:spring-boot-starter-web:jar:2.4.2:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter:jar:2.4.2:compile
[INFO] |  |  +- org.springframework.boot:spring-boot:jar:2.4.2:compile
[INFO] |  |  +- org.springframework.boot:spring-boot-autoconfigure:jar:2.4.2:compile
[INFO] |  |  +- org.springframework.boot:spring-boot-starter-logging:jar:2.4.2:compile
[INFO] |  |  |  +- ch.qos.logback:logback-classic:jar:1.2.3:compile
[INFO] |  |  |  |  \- ch.qos.logback:logback-core:jar:1.2.3:compile
[INFO] |  |  |  \- org.apache.logging.log4j:log4j-to-slf4j:jar:2.13.3:compile
[INFO] |  |  +- jakarta.annotation:jakarta.annotation-api:jar:1.3.5:compile
[INFO] |  |  \- org.yaml:snakeyaml:jar:1.27:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-json:jar:2.4.2:compile
[INFO] |  |  +- com.fasterxml.jackson.core:jackson-databind:jar:2.11.4:compile
[INFO] |  |  |  +- com.fasterxml.jackson.core:jackson-annotations:jar:2.11.4:compile
[INFO] |  |  |  \- com.fasterxml.jackson.core:jackson-core:jar:2.11.4:compile
[INFO] |  |  +- com.fasterxml.jackson.datatype:jackson-datatype-jdk8:jar:2.11.4:compile
[INFO] |  |  +- com.fasterxml.jackson.datatype:jackson-datatype-jsr310:jar:2.11.4:compile
[INFO] |  |  \- com.fasterxml.jackson.module:jackson-module-parameter-names:jar:2.11.4:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-tomcat:jar:2.4.2:compile
[INFO] |  |  +- org.apache.tomcat.embed:tomcat-embed-core:jar:9.0.41:compile
[INFO] |  |  +- org.glassfish:jakarta.el:jar:3.0.3:compile
[INFO] |  |  \- org.apache.tomcat.embed:tomcat-embed-websocket:jar:9.0.41:compile
[INFO] |  +- org.springframework:spring-web:jar:5.3.3:compile
[INFO] |  |  \- org.springframework:spring-beans:jar:5.3.3:compile
[INFO] |  \- org.springframework:spring-webmvc:jar:5.3.3:compile
[INFO] |     +- org.springframework:spring-aop:jar:5.3.3:compile
[INFO] |     +- org.springframework:spring-context:jar:5.3.3:compile
[INFO] |     \- org.springframework:spring-expression:jar:5.3.3:compile
[INFO] +- org.springframework.boot:spring-boot-starter-log4j2:jar:2.4.2:compile
[INFO] |  +- org.apache.logging.log4j:log4j-slf4j-impl:jar:2.13.3:compile
[INFO] |  |  +- org.slf4j:slf4j-api:jar:1.7.30:compile
[INFO] |  |  \- org.apache.logging.log4j:log4j-api:jar:2.13.3:compile
[INFO] |  +- org.apache.logging.log4j:log4j-core:jar:2.13.3:compile
[INFO] |  +- org.apache.logging.log4j:log4j-jul:jar:2.13.3:compile
[INFO] |  \- org.slf4j:jul-to-slf4j:jar:1.7.30:compile
[INFO] +- org.springframework.boot:spring-boot-starter-test:jar:2.4.2:test
[INFO] |  +- org.springframework.boot:spring-boot-test:jar:2.4.2:test
[INFO] |  +- org.springframework.boot:spring-boot-test-autoconfigure:jar:2.4.2:test
[INFO] |  +- com.jayway.jsonpath:json-path:jar:2.4.0:test
[INFO] |  |  \- net.minidev:json-smart:jar:2.3:test
[INFO] |  |     \- net.minidev:accessors-smart:jar:1.2:test
[INFO] |  |        \- org.ow2.asm:asm:jar:5.0.4:test
[INFO] |  +- jakarta.xml.bind:jakarta.xml.bind-api:jar:2.3.3:test
[INFO] |  |  \- jakarta.activation:jakarta.activation-api:jar:1.2.2:test
[INFO] |  +- org.assertj:assertj-core:jar:3.18.1:test
[INFO] |  +- org.hamcrest:hamcrest:jar:2.2:test
[INFO] |  +- org.junit.jupiter:junit-jupiter:jar:5.7.0:test
[INFO] |  |  +- org.junit.jupiter:junit-jupiter-api:jar:5.7.0:test
[INFO] |  |  |  +- org.apiguardian:apiguardian-api:jar:1.1.0:test
[INFO] |  |  |  +- org.opentest4j:opentest4j:jar:1.2.0:test
[INFO] |  |  |  \- org.junit.platform:junit-platform-commons:jar:1.7.0:test
[INFO] |  |  +- org.junit.jupiter:junit-jupiter-params:jar:5.7.0:test
[INFO] |  |  \- org.junit.jupiter:junit-jupiter-engine:jar:5.7.0:test
[INFO] |  |     \- org.junit.platform:junit-platform-engine:jar:1.7.0:test
[INFO] |  +- org.mockito:mockito-core:jar:3.6.28:test
[INFO] |  |  +- net.bytebuddy:byte-buddy:jar:1.10.19:test
[INFO] |  |  +- net.bytebuddy:byte-buddy-agent:jar:1.10.19:test
[INFO] |  |  \- org.objenesis:objenesis:jar:3.1:test
[INFO] |  +- org.mockito:mockito-junit-jupiter:jar:3.6.28:test
[INFO] |  +- org.skyscreamer:jsonassert:jar:1.5.0:test
[INFO] |  |  \- com.vaadin.external.google:android-json:jar:0.0.20131108.vaadin1:test
[INFO] |  +- org.springframework:spring-core:jar:5.3.3:compile
[INFO] |  |  \- org.springframework:spring-jcl:jar:5.3.3:compile
[INFO] |  +- org.springframework:spring-test:jar:5.3.3:test
[INFO] |  \- org.xmlunit:xmlunit-core:jar:2.7.0:test
[INFO] +- io.opentelemetry:opentelemetry-api:jar:1.1.0:compile
[INFO] |  \- io.opentelemetry:opentelemetry-context:jar:1.1.0:compile
[INFO] +- io.opentelemetry:opentelemetry-sdk:jar:1.1.0:compile
[INFO] |  \- io.opentelemetry:opentelemetry-sdk-trace:jar:1.1.0:compile
[INFO] |     \- io.opentelemetry:opentelemetry-api-metrics:jar:1.1.0-alpha:runtime
[INFO] +- io.opentelemetry:opentelemetry-exporter-otlp:jar:1.1.0:compile
[INFO] |  \- io.opentelemetry:opentelemetry-exporter-otlp-trace:jar:1.1.0:compile
[INFO] |     +- io.opentelemetry:opentelemetry-exporter-otlp-common:jar:1.1.0:runtime
[INFO] |     |  +- io.opentelemetry:opentelemetry-proto:jar:1.1.0-alpha:runtime
[INFO] |     |  \- io.opentelemetry:opentelemetry-sdk-metrics:jar:1.1.0-alpha:runtime
[INFO] |     \- io.grpc:grpc-stub:jar:1.36.1:runtime
[INFO] +- io.opentelemetry:opentelemetry-sdk-common:jar:1.1.0:compile
[INFO] |  \- io.opentelemetry:opentelemetry-semconv:jar:1.1.0-alpha:runtime
[INFO] +- io.opentelemetry.instrumentation:opentelemetry-log4j-2.13.2:jar:1.1.0-alpha:runtime
[INFO] |  \- io.opentelemetry.instrumentation:opentelemetry-instrumentation-api:jar:1.1.0-alpha:runtime
[INFO] |     \- io.opentelemetry.instrumentation:opentelemetry-instrumentation-api-caching:jar:1.1.0-alpha:runtime
[INFO] +- io.grpc:grpc-protobuf:jar:1.37.0:compile
[INFO] |  +- io.grpc:grpc-api:jar:1.37.0:compile
[INFO] |  |  \- io.grpc:grpc-context:jar:1.37.0:compile
[INFO] |  +- com.google.code.findbugs:jsr305:jar:3.0.2:compile
[INFO] |  +- com.google.protobuf:protobuf-java:jar:3.12.0:compile
[INFO] |  +- com.google.api.grpc:proto-google-common-protos:jar:2.0.1:compile
[INFO] |  +- io.grpc:grpc-protobuf-lite:jar:1.37.0:compile
[INFO] |  +- com.google.guava:guava:jar:30.0-android:runtime
[INFO] |  |  +- com.google.guava:failureaccess:jar:1.0.1:runtime
[INFO] |  |  +- com.google.guava:listenablefuture:jar:9999.0-empty-to-avoid-conflict-with-guava:runtime
[INFO] |  |  +- org.checkerframework:checker-compat-qual:jar:2.5.5:runtime
[INFO] |  |  \- com.google.j2objc:j2objc-annotations:jar:1.3:runtime
[INFO] |  +- com.google.errorprone:error_prone_annotations:jar:2.4.0:runtime
[INFO] |  \- org.codehaus.mojo:animal-sniffer-annotations:jar:1.19:runtime
[INFO] \- io.grpc:grpc-netty-shaded:jar:1.37.0:compile
[INFO]    \- io.grpc:grpc-core:jar:1.37.0:compile (version selected from constraint [1.37.0,1.37.0])
[INFO]       +- com.google.code.gson:gson:jar:2.8.6:runtime
[INFO]       +- com.google.android:annotations:jar:4.1.1.4:runtime
[INFO]       \- io.perfmark:perfmark-api:jar:0.23.0:runtime

jkwatson May 24, 2021
Collaborator

I switched your example to use the logging exporter, rather than otlp so I could see the spans on the console as well. I can't imagine that that would make any difference, but it is something I did a little bit differently.

jkwatson May 24, 2021
Collaborator

Here is what I see on the console when I run it:

2021-05-24 10:21:59 - org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/] - Initializing Spring embedded WebApplicationContext trace_id= span_id= trace_flags= 
2021-05-24 10:21:59 - org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 810 ms trace_id= span_id= trace_flags= 
2021-05-24 10:22:00 - org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor - Initializing ExecutorService 'applicationTaskExecutor' trace_id= span_id= trace_flags= 
2021-05-24 10:22:00 - org.springframework.boot.web.embedded.tomcat.TomcatWebServer - Tomcat started on port(s): 8080 (http) with context path '' trace_id= span_id= trace_flags= 
2021-05-24 10:22:00 - com.example.springboot.Application - Started Application in 1.662 seconds (JVM running for 2.446) trace_id= span_id= trace_flags= 
2021-05-24 10:22:03 - com.example.springboot.Application$WorkerThread - Thread-0: Worker Thread is running...1 trace_id= span_id= trace_flags= 
2021-05-24 10:22:03 - com.example.springboot.Application$WorkerThread - Inside span, traceId: 89092192329d7f4375d9343bc210900e, spanId: c1d93c85656f86c0 trace_id=89092192329d7f4375d9343bc210900e span_id=c1d93c85656f86c0 trace_flags=01 
2021-05-24 10:22:03 - io.opentelemetry.exporter.logging.LoggingSpanExporter - 'my span' : 89092192329d7f4375d9343bc210900e c1d93c85656f86c0 INTERNAL [tracer: MyTracer:] {} trace_id= span_id= trace_flags= 
2021-05-24 10:22:08 - com.example.springboot.Application$WorkerThread - Thread-0: Worker Thread is running...2 trace_id= span_id= trace_flags= 
2021-05-24 10:22:08 - com.example.springboot.Application$WorkerThread - Inside span, traceId: d9ac8c69e8ff3ed021b4cbb1cfa7bd8d, spanId: f62bc775790c4716 trace_id=d9ac8c69e8ff3ed021b4cbb1cfa7bd8d span_id=f62bc775790c4716 trace_flags=01 
2021-05-24 10:22:08 - io.opentelemetry.exporter.logging.LoggingSpanExporter - 'my span' : d9ac8c69e8ff3ed021b4cbb1cfa7bd8d f62bc775790c4716 INTERNAL [tracer: MyTracer:] {} trace_id= span_id= trace_flags= 
2021-05-24 10:22:13 - com.example.springboot.Application$WorkerThread - Thread-0: Worker Thread is running...3 trace_id= span_id= trace_flags= 
2021-05-24 10:22:13 - com.example.springboot.Application$WorkerThread - Inside span, traceId: 08098fb0acf57697d96324ea93bd4975, spanId: 5e03c77133b52916 trace_id=08098fb0acf57697d96324ea93bd4975 span_id=5e03c77133b52916 trace_flags=01 
2021-05-24 10:22:13 - io.opentelemetry.exporter.logging.LoggingSpanExporter - 'my span' : 08098fb0acf57697d96324ea93bd4975 5e03c77133b52916 INTERNAL [tracer: MyTracer:] {} trace_id= span_id= trace_flags= 
2021-05-24 10:22:14 - org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor - Shutting down ExecutorService 'applicationTaskExecutor' trace_id= span_id= trace_flags=

You can see that the logging that happens within the context of an active span does indeed get the spanid/traceid injected into the MDC.

pwfarwell Jun 8, 2021
Author

@jkwatson It works for me now. I think the problem is that I had multiple SLF4J bindings in my maven dependencies. Once I excluded ch.qos.logbac.logback-classic, it started to work. So I think your original hunch was correct about a conflict in logging packages.
Thanks again!

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-web</artifactId>
			<exclusions>

                    . . .
				<exclusion>
					<groupId>ch.qos.logback</groupId>
					<artifactId>logback-classic</artifactId>
				</exclusion>
			</exclusions>
		</dependency>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Issues with Log4j MDC injections #3074

Uh oh!

{{title}}

Uh oh!

Replies: 1 comment 6 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Select a reply

Uh oh!

Issues with Log4j MDC injections #3074

Uh oh!

pwfarwell May 24, 2021

Replies: 1 comment · 6 replies

Uh oh!

jkwatson May 24, 2021 Collaborator

Uh oh!

pwfarwell May 24, 2021 Author

Uh oh!

pwfarwell May 24, 2021 Author

Uh oh!

jkwatson May 24, 2021 Collaborator

Uh oh!

Uh oh!

jkwatson May 24, 2021 Collaborator

Uh oh!

Uh oh!

pwfarwell Jun 8, 2021 Author

pwfarwell
May 24, 2021

Replies: 1 comment 6 replies

jkwatson
May 24, 2021
Collaborator

pwfarwell May 24, 2021
Author

pwfarwell May 24, 2021
Author

jkwatson May 24, 2021
Collaborator

jkwatson May 24, 2021
Collaborator

pwfarwell Jun 8, 2021
Author