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

4

11

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:

enter image description here

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) :

enter image description here

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)

Unisexual answered 14/6, 2018 at 10:37 Comment(0)
B
7

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.

Barm answered 22/6, 2018 at 9:38 Comment(0)
S
2

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();
  }
}
Seclusive answered 11/11, 2019 at 8:48 Comment(0)
K
2

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.

Kef answered 22/7, 2021 at 1:49 Comment(0)
L
0

Then I use opentracing-spring-jaeger-cloud-starter

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

I got just one line in console with current trace and span i.j.internal.reporters.LoggingReporter : Span reported: f1a264bbe2c7eae9:f1a264bbe2c7eae9:0:1 - my_method

2019-05-20 16:07:59.549 DEBUG 24428 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [632103eb] HTTP POST "/api"
2019-05-20 16:07:59.552 DEBUG 24428 --- [ctor-http-nio-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [632103eb] Mapped to public reactor.core.publisher.Mono<org.springframework.http.ResponseEntity<model.Response>> service.controller.method(model.Request)
2019-05-20 16:07:59.559 DEBUG 24428 --- [ctor-http-nio-2] .s.w.r.r.m.a.RequestBodyArgumentResolver : [632103eb] Content-Type:application/json
2019-05-20 16:08:01.450  INFO 24428 --- [ctor-http-nio-2] i.j.internal.reporters.LoggingReporter   : Span reported: f1a264bbe2c7eae9:f1a264bbe2c7eae9:0:1 - method
2019-05-20 16:08:01.450 DEBUG 24428 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [632103eb] Completed 200 OK

Then I use spring-cloud-starter-sleuth

<dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>

I got the Trace and Spans like [my-service,90e1114e35c897d6,90e1114e35c897d6,false] in each line and it's helpfull for filebeat in ELK

2019-05-20 16:15:38.646 DEBUG [my-service,,,] 12548 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [3e578505] HTTP POST "/api"
2019-05-20 16:15:38.662 DEBUG [my-service,,,] 12548 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Received a request to uri [/api]
2019-05-20 16:15:38.667 DEBUG [my-service,,,] 12548 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Handled receive of span NoopSpan(90e1114e35c897d6/90e1114e35c897d6)
2019-05-20 16:15:38.713 DEBUG [my-service,90e1114e35c897d6,90e1114e35c897d6,false] 12548 --- [ctor-http-nio-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [3e578505] Mapped to public reactor.core.publisher.Mono<org.springframework.http.ResponseEntity<model.Response>> service.controller.method(model.Request)
2019-05-20 16:15:38.727 DEBUG [my-service,90e1114e35c897d6,90e1114e35c897d6,false] 12548 --- [ctor-http-nio-2] .s.w.r.r.m.a.RequestBodyArgumentResolver : [3e578505] Content-Type:application/json
2019-05-20 16:15:39.956 DEBUG [my-service,90e1114e35c897d6,90e1114e35c897d6,false] 12548 --- [gine-1-thread-1] .s.w.r.r.m.a.ResponseEntityResultHandler : Using 'application/json;charset=UTF-8' given [*/*] and supported [application/json;charset=UTF-8, application/*+json;charset=UTF-8, text/event-stream]
2019-05-20 16:15:40.009 DEBUG [my-service,90e1114e35c897d6,90e1114e35c897d6,false] 12548 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Adding a method tag with value [method] to a span NoopSpan(90e1114e35c897d6/90e1114e35c897d6)
2019-05-20 16:15:40.009 DEBUG [my-service,90e1114e35c897d6,90e1114e35c897d6,false] 12548 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Adding a class tag with value [Controller] to a span NoopSpan(90e1114e35c897d6/90e1114e35c897d6)
2019-05-20 16:15:40.010 DEBUG [my-service,90e1114e35c897d6,90e1114e35c897d6,false] 12548 --- [ctor-http-nio-2] o.s.c.s.instrument.web.TraceWebFilter    : Handled send of NoopSpan(90e1114e35c897d6/90e1114e35c897d6)
2019-05-20 16:15:40.021 DEBUG [my-service,90e1114e35c897d6,90e1114e35c897d6,false] 12548 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [3e578505] Completed 200 OK

How could I get the same log in console using opentracing-spring-jaeger-cloud-starter ?

my opentracing config

opentracing:
  jaeger:
    enabled: true
    enable-b3-propagation: true
    log-spans: true
    const-sampler:
      decision: true
    http-sender:
      url: http://jaeger-collector:14268/api/traces

Lamentation answered 20/5, 2019 at 13:39 Comment(2)
A part of answer I've found in #53323400Lamentation
I also have a similar type of question (https://mcmap.net/q/1018567/-trace-id-is-not-shown-on-controller-level-log-spring-boot-jaeger-configuration @petr If you find answer than please help meTapping

© 2022 - 2024 — McMap. All rights reserved.