How to enrich Jaeger opentracing data with the application logs (produced by slf4j) for Spring Boot?

Question

There is an existing Spring Boot app which is using SLF4J logger. I decided to add the support of distributed tracing via standard opentracing API with Jaeger as the tracer. It is really amazing how easy the initial setup is - all that is required is just adding two dependencies to the pom.xml:

    <dependency>
        <groupId>io.opentracing.contrib</groupId>
        <artifactId>opentracing-spring-web-autoconfigure</artifactId>
        <version>${io.opentracing.version}</version>
    </dependency>

    <dependency>
        <groupId>io.jaegertracing</groupId>
        <artifactId>jaeger-core</artifactId>
        <version>${jaegerVersion}</version>
    </dependency>

and providing the Tracer bean with the configuration:

@Bean
public io.opentracing.Tracer getTracer() throws ConfigurationException {
    return new new io.jaegertracing.Tracer.Builder("my-spring-boot-app").build();
}

All works like a charm - app requests are processed by Jaeger and spans are created:

However, in the span Logs there are only preHandle & afterCompletion events with info about the class / method that were called during request execution (no logs produced by slf4j logger are collected) :

The question is if it is possible to configure the Tracer to pickup the logs produced by the app logger (slf4j in my case) so that all the application logs done via: LOG.info / LOG.warn / LOG.error etc. would be also reflected in Jaeger

NOTE: I have figured out how to log to span manually via opentracing API e.g.:

Scope scope = tracer.scopeManager().active();
if (scope != null) {
    scope.span().log("...");
}

And do some manual manipulations with the ERROR tag for exception processing in filters e.g.

} catch(Exception ex) {
    Tags.ERROR.set(span, true);
    span.log(Map.of(Fields.EVENT, "error", Fields.ERROR_OBJECT, ex, Fields.MESSAGE, ex.getMessage()));
    throw ex
}

But, I'm still wondering if it is possible to configure the tracer to pickup the application logs automatically:

• LOG.info -> tracer adds new log to the active span
• LOG.error -> tracer adds new log to the active span plus adds ERROR tag

UPDATE: I was able to add the application logs to the tracer by adding wrapper for the logger e.g.

public void error(String message, Exception e) {
    Scope scope = tracer.scopeManager().active();
    if (scope != null) {
        Span span = scope.span();
        Tags.ERROR.set(span, true);
        span.log(Map.of(Fields.EVENT, "error", Fields.ERROR_OBJECT, e, Fields.MESSAGE, e.getMessage()));

    }
    LOG.error(message, e);
}

However, so far I was not able to find opentracing configuration options that would allow to add the application logs to the tracer automatically by default. Basically, it seems that it is expected that dev would add extra logs to tracer programmatically if needed. Also, after investigating tracing more it appeared to be that normally logging and tracing are handled separately and adding all the application logs to the tracer is not a good idea (tracer should mainly include sample data and tags for request identification)

• https://github.com/openzipkin/zipkin/issues/1453
• https://peter.bourgon.org/blog/2016/02/07/logging-v-instrumentation.html

Answer 1

As it was already noted, it is, in general, bad idea to put all the logs to the Jaeger traces in any other than development environments - it might overwelm Jaeger. Also as was answered in the most relevant answer here, opentracing-spring-cloud-core library provides this ability. It is controlled by parameter opentracing.spring.cloud.log.enabled

Look at io/opentracing/contrib/spring/cloud/log/LoggingAutoConfiguration.java

This bean adds SpanLogsAppender to the root logger, which will add logs to the active span. This would propagate to all the others loggers by default unless some of the loggers have additivity attribute set to false.

In my application all the loggers in com.mycompany.myapp have additivity false, so I had to create workaround for that.

My workaround was to run similar logic with adding SpanLogsAppender for the my app's logger "com.mycompany.myapp" which will be parent for all classes in that package:

package com.mycompany.myapp.config;

import ch.qos.logback.classic.Logger;
import io.opentracing.Tracer;
import io.opentracing.contrib.spring.cloud.log.SpanLogsAppender;
import io.opentracing.contrib.spring.tracer.configuration.TracerAutoConfiguration;
import org.slf4j.LoggerFactory;
import org.springframework.boot.autoconfigure.AutoConfigureAfter;
import org.springframework.boot.autoconfigure.condition.ConditionalOnClass;
import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty;
import org.springframework.context.annotation.Configuration;


@Configuration
@AutoConfigureAfter(TracerAutoConfiguration.class)
@ConditionalOnClass(ch.qos.logback.classic.Logger.class)
@ConditionalOnProperty(name = "opentracing.spring.cloud.log.enabled", havingValue = "true", matchIfMissing = true)
public class MyAppLoggingAutoConfiguration {

    public MyAppLoggingAutoConfiguration(final Tracer tracer) {
        SpanLogsAppender spanLogsAppender = new SpanLogsAppender(tracer);
        spanLogsAppender.start();
        Logger rootLogger = (Logger)LoggerFactory.getLogger("com.mycompany.myapp");
        rootLogger.addAppender(spanLogsAppender);
    }
}

This way all the loggers created for classes which resides on any depth in the package com.mycompany.myapp will get that additional SpanLogsAppender which will put logs to the current span.

Answer 2

https://github.com/opentracing-contrib/java-spring-cloud project automatically sends standard logging to the active span. Just add the following dependency to your pom.xml

<dependency>
   <groupId>io.opentracing.contrib</groupId>
   <artifactId>opentracing-spring-cloud-starter</artifactId>
</dependency>

Or use this https://github.com/opentracing-contrib/java-spring-cloud/tree/master/instrument-starters/opentracing-spring-cloud-core starter if you want only logging integration.

Answer 3

Here is what I did to make jdbc related logs from Logback (Slf4j) write into Jaeger server:

Beginning with Logback config (logback-spring.xml):

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<springProperty scope="context" name="consoleAppender" source="logging.console.enabled" defaultValue="false"/>
<property name="ENV" value="${SPRING_PROFILES_ACTIVE:-dev}"/>

<include resource="org/springframework/boot/logging/logback/console-appender.xml"/>

<jmxConfigurator/>

<appender name="JSON_CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LogstashEncoder">
        <includeMdc>true</includeMdc>
        <customFields>{"log_type":"application","appname":"products-rs-load", "environment": "${ENV}"}
        </customFields>
    </encoder>
</appender>
<appender name="myAppender" class="com.test.MyAppender">
</appender>
<root level="DEBUG">
    <appender-ref ref="myAppender"/>
</root>
<logger name="org.springframework.boot" level="INFO"/>
<logger name="p6spy" additivity="false" level="ALL">
    <appender-ref ref="myAppender" />
</logger>
</configuration>

Here is my appender:

import ch.qos.logback.core.AppenderBase;
public class MyAppender extends AppenderBase {

@Override
protected void append(Object eventObject) {
    LoggingEvent event = (LoggingEvent) eventObject;

    final String loggerName = event.getLoggerName();

    // only DB related operations have to be traced:
    if (!("p6spy".equals(loggerName))) {
        return;
    }
    /// Tracer config is straight forward
    Span sp = TracingUtils.buildActiveChildSpan(loggerName, null);

    if (Level.ERROR.equals(event.getLevel())) {
        TracingUtils.setErrorTag(sp);
    }
    Map<String, String> fields = new HashMap<String, String>();
    fields.put("level", event.getLevel().toString());
    fields.put("logger", loggerName);
    fields.put("content", event.getFormattedMessage());
    sp.log(fields);

    sp.finish();
  }
}