MDC Instrumentation for logback not injecting trace/span ids

[ptabasso2]

Describe the bug

I’m currently trying to get the trace/log correlation working and was experimenting the MDC Instrumentation for logback integration

I’m using Spring Boot with logback and slf4j

I’m not using the java agent. Essentially doing manual instrumentation using the java Otel SDK. I’m using recent versions of spring 3.2 and otel sdk 1.35

Added the dependency to the project and changed the pattern layout of the file appender to add the the placeholders for both trace_id/span_id

But I can’t seem to see the trace_id/span_id values injected into the resulting log events. When debugging it, none of the fields or methods in the OpenTelemetryAppender class get picked.

fyi when using MDC.put() the injection works

Any idea of how I could fix it?

Steps to reproduce

Providing the sample I'm using. sampleapp.tar.gz

It's the one used in the Otel getting started guide.

1. The build.gradle.kts has the dependency included

   implementation("io.opentelemetry.instrumentation:opentelemetry-logback-mdc-1.0:1.32.1-alpha")

Note: I have tried several versions including the latest

dependencies {
    implementation("org.springframework.boot:spring-boot-starter-web")
    implementation("io.opentelemetry:opentelemetry-api:1.35.0")
    implementation("io.opentelemetry:opentelemetry-sdk:1.35.0")
    implementation("io.opentelemetry:opentelemetry-sdk-metrics:1.35.0")
    implementation("io.opentelemetry:opentelemetry-exporter-logging:1.35.0")
    implementation("io.opentelemetry:opentelemetry-semconv:1.23.0-alpha")
    implementation("io.opentelemetry:opentelemetry-sdk-extension-autoconfigure:1.35.0")
    implementation("io.opentelemetry:opentelemetry-sdk-extension-autoconfigure-spi:1.35.0")
    implementation("io.opentelemetry:opentelemetry-exporter-otlp:1.35.0")
    implementation("io.opentelemetry.instrumentation:opentelemetry-logback-mdc-1.0:1.32.1-alpha")
}

2. The application.properties contains the configuration details for logback:

logging.level.root=info
logging.level.org.springframework.web=INFO
logging.file.path=logs
logging.file.name=/var/log/test/simple.log
logging.pattern.file=%d{yyyy-MM-dd HH:mm:ss} %-5level %logger{36} - traceId: %X{trace_id} spanId: %X{span_id} - %msg%n
logging.pattern.console=%d{yyyy-MM-dd HH:mm:ss} %magenta([%thread]) %highlight(%-5level) %yellow(%logger{36}) - %msg%n

3. The logger methods invocation is yet under an active span (In the Controller class)

        try (Scope scope = span.makeCurrent()) {
            if (!rolls.isPresent()) {
                throw new ResponseStatusException(HttpStatus.BAD_REQUEST, "Missing rolls parameter", null);
            }
            List<Integer> result = new Dice(1, 6).rollTheDice(rolls.get());

            if (player.isPresent()) {
                logger.info("{} is rolling the dice: {}", player.get(), result);
            } else {
                logger.info("Anonymous player is rolling the dice: {}", result);
            }
            return result;
        } catch(Throwable t) {
            span.recordException(t);
            throw t;
        } finally {
            span.end();
        }

4. When running the app and curling the endpoint, the resulting log events look like this

curl command used: curl http://localhost:8080/rolldice?rolls=12

...
2024-03-11 14:49:09 INFO  o.s.b.w.s.c.ServletWebServerApplicationContext - traceId:  spanId:  - Root WebApplicationContext: initialization completed in 1494 ms
2024-03-11 14:49:10 INFO  o.s.b.w.e.tomcat.TomcatWebServer - traceId:  spanId:  - Tomcat started on port 8080 (http) with context path ''
2024-03-11 14:49:10 INFO  c.example.springdice.DiceApplication - traceId:  spanId:  - Started DiceApplication in 3.402 seconds (process running for 4.088)
2024-03-11 14:49:15 INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - traceId:  spanId:  - Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-03-11 14:49:15 INFO  o.s.web.servlet.DispatcherServlet - traceId:  spanId:  - Initializing Servlet 'dispatcherServlet'
2024-03-11 14:49:15 INFO  o.s.web.servlet.DispatcherServlet - traceId:  spanId:  - Completed initialization in 1 ms
2024-03-11 14:49:16 INFO  c.example.springdice.RollController - traceId:  spanId:  - Anonymous player is rolling the dice: [6, 6, 5, 4, 2, 3, 3, 2, 4, 2, 2, 5]

5. When debugging the app, none of the OpenTelemetryAppender fields or methods are picked.

Expected behavior

The expected behavior is to see the trace/span ids injected to one of the log records.

Actual behavior

Those values are not present

Javaagent or library instrumentation version

No java agent. Otel SDK 1.35.0 (see dependency list above)

Environment

JDK:

openjdk version "17.0.9" 2023-10-17 LTS
OpenJDK Runtime Environment Zulu17.46+19-CA (build 17.0.9+8-LTS)
OpenJDK 64-Bit Server VM Zulu17.46+19-CA (build 17.0.9+8-LTS, mixed mode, sharing)

OS:

PRETTY_NAME="Ubuntu 23.10"
NAME="Ubuntu"
VERSION_ID="23.10"
VERSION="23.10 (Mantic Minotaur)"
VERSION_CODENAME=mantic
ID=ubuntu
ID_LIKE=debian

gradle

-----------------------------------------------------------
Gradle 8.4
------------------------------------------------------------

Build time:   2023-10-04 20:52:13 UTC
Revision:     e9251e572c9bd1d01e503a0dfdf43aedaeecdc3f

Kotlin:       1.9.10
Groovy:       3.0.17
Ant:          Apache Ant(TM) version 1.10.13 compiled on January 4 2023
JVM:          17.0.9 (Azul Systems, Inc. 17.0.9+8-LTS)
OS:           Linux 6.5.0-1008-gcp amd64

Spring Boot

plugins {
    java
    id("org.springframework.boot") version "3.2.0"
    id("io.spring.dependency-management") version "1.1.4"
}

Additional context

No response

[laurit]

You have not configured the appender that injects trace and span id into the mdc. See https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/logback/logback-mdc-1.0/library/README.md#usage Copy the logback.xml from the readme into your application.

[jeanbisutti]

I’m not using the java agent. Essentially doing manual instrumentation using the java Otel SDK.

You could also use the OpenTelemetry starter. An OpenTelemetry bean will be provided and the Logback OpenTelemetry appender will be automatically added without any configuration.

[ptabasso2]

You have not configured the appender that injects trace and span id into the mdc.

@laurit Wasn't it sufficient by doing this? It's the config from my application.properties file logging.pattern.file=%d{yyyy-MM-dd HH:mm:ss} %-5level %logger{36} - traceId: %X{trace_id} spanId: %X{span_id} - %msg%n The only difference I'm seeing with the link you sent is the trace_flags attribute which was not enabled in my case. I will try with with the logback.xml and will let you know.

@jeanbisutti I will try it as well, thank you

[laurit]

@ptabasso2 the part that sets up the mdc appender is

  <!-- Just wrap your logging appender, for example ConsoleAppender, with OpenTelemetryAppender -->
  <appender name="OTEL" class="io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender">
    <appender-ref ref="CONSOLE"/>
  </appender>

[ptabasso2]

@laurit That did the trick. It is working now. Thanks a lot!