How to send Lombok @Slf4j logs and System.out.println() logs to Open Telemetry through Micrometer

[Giovarco]

Hello people,

My current setup is: a Spring Boot app (version 3.1.5) with Micrometer, sending traces, metrics and (ideally) all logs to an otel/opentelemetry-collector-contrib Docker container.

Everything seems working, except I cannot manage to make the Spring Boot app send logs to the OTEL collector.

As I couldn't find very clear instructions on how to do this, I'm just putting things together, for example from these two and others:
#7723
https://github.com/ff-sdesai/distributed-tracing-spring/blob/ee36dcd78ce9c0b517355642af3c5e0b8b6d67d0/spring-cloud-sleuth-otel-slf4j/src/main/resources/logback.xml#L17

and hope that it works... but it doesn't, therefore I'm here:

application.yml

spring:
  output:
    ansi:
      enabled: always
  (...)
# Micrometer tracing
management:
  tracing:
    sampling:
      probability: 1.0
  otlp:
    tracing:
      endpoint: http://localhost:4318/v1/traces
    metrics:
      export:
        url: http://localhost:4318/v1/metrics
  endpoints:
    web:
      exposure:
        include: "*"
  (...)
logging:
  pattern:
    console: '[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} [%X{traceId}] [%X{spanId}] - %msg%n'
    level: '%5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}]'

logback.xml

<configuration>
  <property name="LOGS" value="./logs"/>

  <appender name="Console"
    class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>
        %black(%d{ISO8601}) %highlight(%-5level) [%blue(%t)] %yellow(%C{1}): trace_id: %X{traceId}
        span_id: %X{spanId} %msg%n%throwable
      </Pattern>
    </layout>
  </appender>

  <appender name="RollingFile"
    class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOGS}/up-user-service.log</file>
    <encoder
      class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
      <Pattern>%d %p %C{1} [%t] %m%n</Pattern>
    </encoder>

    <rollingPolicy
      class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- rollover daily and when the file reaches 10 MegaBytes -->
      <fileNamePattern>${LOGS}/archived/up-user-service-%d{yyyy-MM-dd}.%i.log
      </fileNamePattern>
      <timeBasedFileNamingAndTriggeringPolicy
        class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
        <maxFileSize>10MB</maxFileSize>
      </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
  </appender>

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

  <!-- LOG everything at INFO level -->
  <root level="info">
    <appender-ref ref="RollingFile"/>
    <appender-ref ref="Console"/>
  </root>

  <logger name="com.uplight.upuserservice" level="trace" additivity="false">
    <appender-ref ref="RollingFile"/>
    <appender-ref ref="Console"/>
    <appender-ref ref="OTEL"/>
  </logger>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <!-- encoders are assigned the type
    ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} serviceName: %X{serviceName} requestId: %X{requestId} trace_id: %X{traceId} span_id: %X{spanId} - %msg%n</pattern>
    </encoder>
  </appender>

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

  <root level="INFO">
    <appender-ref ref="STDOUT" />
  </root>

</configuration>

pom.xml

(...)
<dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-actuator</artifactId>
    </dependency>

    <!-- Adds the Tracing API -->
    <dependency>
      <groupId>io.micrometer</groupId>
      <artifactId>micrometer-tracing</artifactId>
    </dependency>

    <!-- Adds the Tracer Implementation -->
    <dependency>
      <groupId>io.micrometer</groupId>
      <artifactId>micrometer-tracing-bridge-otel</artifactId>
    </dependency>

    <!-- Adds an exporter to store the traces -->
    <dependency>
      <groupId>io.opentelemetry</groupId>
      <artifactId>opentelemetry-exporter-otlp</artifactId>
    </dependency>

    <dependency>
      <groupId>io.opentelemetry.instrumentation</groupId>
      <artifactId>opentelemetry-logback-appender-1.0</artifactId>
      <version>2.1.0-alpha</version>
      <scope>runtime</scope>
    </dependency>

    <dependency>
      <groupId>io.opentelemetry</groupId>
      <artifactId>opentelemetry-exporter-otlp-logs</artifactId>
      <version>1.26.0-alpha</version>
    </dependency>

    <dependency>
      <groupId>io.opentelemetry.instrumentation</groupId>
      <artifactId>opentelemetry-logback-1.0</artifactId>
      <version>1.9.2-alpha</version>
      <scope>runtime</scope>
    </dependency>
(...)

NOTE: I wondering if this issue is related but not caused by the lack of spanid and traceid in some logs. None of them have them, except for example when I log inside a custom span. This is an example of class trying different features including creating spans:

TestApi.java

@Slf4j
@RestController
class TestApi {

    @Autowired
    private ObservationRegistry observationRegistry;

    @Autowired
    private Tracer tracer;

    @Autowired
    private MeterRegistry meterRegistry;

    @GetMapping("test")
    void test() {
        System.out.println("### MY TEST ###");
        log.info("@@@@@ TEST LOMBOK LOGGER @@@@@");
    }

    @GetMapping("exception")
    void exception() throws Exception {
        throw new Exception("CUSTOM EXCEPTION");
    }

    @GetMapping("custom_span") // WORKS
    void customSpan() throws Exception {
        Observation observation = Observation.createNotStarted("my-custom-operation", this.observationRegistry);
        observation.lowCardinalityKeyValue("my-tag", "my-value");
        observation.observe(() -> {
            System.out.println("### HOW LONG DID IT TAKE? ###");
            log.info("@@@@@ HOW LONG DID IT TAKE? @@@@@");
        });
    }

    // So, what is Baggage? The spec defines a standard HTTP header to propagate the application-defined properties associated with a distributed request.
    @GetMapping("custom_baggage")
    void customBaggage() {
        try (BaggageInScope scope = this.tracer.createBaggageInScope("my-baggage-key", "my-baggage-value")) {
            System.out.println("### IS IT BAGGAGING? ###");
            log.info("@@@@@ IS IT BAGGAGING? @@@@@");
            log.info("Contains the following baggage {}", tracer.getAllBaggage());
        }
    }

    @GetMapping("custom_metric")
    void customMetric() { // TODO: TO BE TESTED WITH A COMPATIBLE METRIC UI
        log.info("CREATING CUSTOM METRIC");
        List<Integer> list = new ArrayList<>();
        meterRegistry.gauge("list.size", Tags.empty(), list.size());
        list.add(1);
        list.add(2);
        list.add(3);
    }
}

config.yaml

receivers:
  otlp:
    protocols:
      grpc:
        endpoint:  0.0.0.0:4317
      http:
        endpoint: 0.0.0.0:4318

processors:

exporters:
  logging:
    loglevel: debug

  jaeger:
    endpoint: jaeger-service:14250
    tls:
      insecure: true

service:
  pipelines:
    traces:
      receivers: [otlp]
      exporters: [logging, jaeger]
    metrics:
      receivers: [otlp]
      exporters: [logging]
    logs:
      receivers: [ otlp ]
      exporters: [logging] 

[trask]

hi @Giovarco! it looks like you are using micrometer-tracing, so I'd recommend asking in that project

[Giovarco]

Hi @trask , doesn't Micrometer use Open Telemetry under the hood? Before using Micrometer, I was using Open Telemetry Agent and I was getting the problem (+ others). Micrometer solved some of them, but the problem with logs persists.

[trask]

If you have problems with the OpenTelemetry Agent or the OpenTelemetry Spring Boot Starter, then we can try to help you in this project, but for Micrometer Tracing you'll probably have better luck asking in that project

[jeanbisutti]

@Giovarco

You problem could be that you have not installed OpenTelemetry into the OpenTelemetry Logback appender: OpenTelemetryAppender.install(openTelemetrySdk);

With the OpenTelemetry starter, you can have the Logback appender configured without any configuration (for example, you don't need to add the opentelemetry-logback-appender-1.0 dependency).

For the OpenTelemetry Java agent, you have an automatic instrumentation for Logback. If you are searching to enable some log attributes with the Java agent, you can look at https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/logback/logback-appender-1.0/javaagent/README.md#settings-for-the-logback-appender-instrumentation