CODEWITHSUNDEEP
spring-bootzipkinspring-cloud-sleuth
user3105453
user3105453

Reputation: 1981

Add Spring Boot Profile to Sleuth/Zipkin logs

I'm using these dependencies:

compile 'org.springframework.cloud:spring-cloud-starter-zipkin'
compile 'org.springframework.cloud:spring-cloud-starter-sleuth'
compile 'org.springframework.cloud:spring-cloud-sleuth-zipkin'

Is there a possibility to add the current active profile(s) to each log line? This would make it possible to filter logs based on the profiles in Splunk/ELK/...

So instead of 

2017-03-13 13:38:30.465  INFO [app,,,] 19220 --- [           main] com.company.app.Application    : Started Application in 20.682 seconds (JVM running for 22.166)

it should log 

2017-03-13 13:38:30.465  INFO [app,,,] [dev] 19220 --- [           main] com.company.app.Application    : Started Application in 20.682 seconds (JVM running for 22.166)

EDIT: Based on Marcin's answer, I implemented it as follows:

application.yml

logging:
  pattern:
    level: "%X{profiles} %5p"

ProfileLogger.java

public class ProfileLogger implements SpanLogger {

    private final Environment environment;
    private final Logger log;
    private final Pattern nameSkipPattern;

    @Autowired
    public ProfileLogger(String nameSkipPattern, final Environment environment) {
        this.nameSkipPattern = Pattern.compile(nameSkipPattern);
        this.environment = environment;
        this.log = org.slf4j.LoggerFactory.getLogger(this.getClass());
    }

    private void setProfiles() {
        MDC.put("profiles", Arrays.toString(environment.getActiveProfiles()));
    }

    @Override
    public void logStartedSpan(Span parent, Span span) {
        setProfiles();
        ...
    }
    ... // (as https://github.com/spring-cloud/spring-cloud-sleuth/blob/master/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jSpanLogger.java)
}

LogConfig.java

@Configuration
public class LogConfig {

    private final Environment environment;

    @Autowired
    public LogConfig(final Environment environment) {
        this.environment = environment;
    }

    @Bean
    SpanLogger getLogger() {
        return new ProfileLogger("", environment);
    }
}

This prints logs like the following:

2017-03-13 14:47:02.796   INFO 22481 --- [           main] com.company.app.Application    : Started Application in 16.115 seconds (JVM running for 16.792)
2017-03-13 14:47:32.684 [localhost, swagger] TRACE 22481 --- [pool-2-thread-1] c.c.app.config.ProfileLogger    : Starting span: [Trace: bfcdd2ce866efbff, Span: bfcdd2ce866efbff, Parent: null, exportable:true]

This is already good but not completely what I'm looking for yet. I'd like to add the profile from the beginning -> even the "Started Application" should contain the profile - if possible. Secondly, I'd like to move the profiles between INFO and 22481.

One more question came up during implementation: In the linked implementation there is this statement:

if (this.log.isTraceEnabled()) {
    this.log.trace(text, span);
}

does that mean you only send traces if log-level is set to TRACE? If so, how could I improve logging to stdout with that approach (given a log-level of debug/info/warn)? I think the log-pattern is overriden by Sleuth/Zipkin upon importing the dependencies and thus, local logging looks the same as tracing. Eventually I'm interested in having the profile displayed in local stdout as well as in Zipkin.

EDIT 2: With the help of Marcin, I have changed the pattern by introducing a resources/logback-spring.xml file containing these lines:

<springProperty scope="context" name="activeSpringProfiles" source="spring.profiles.active"/>
<!-- Example for logging into the build folder of your project -->
<property name="LOG_FILE" value="${BUILD_FOLDER:-build}/${activeSpringProfiles:-}"/>​

<!-- You can override this to have a custom pattern -->
<property name="CONSOLE_LOG_PATTERN"
value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) [${activeSpringProfiles:-}] %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>

Note that you have to add a bootstrap.yml file too in order to have the application name correctly displayed. Without a bootstrap.yml file, the above log-pattern just prints "bootstrap" as application name.

The bootstrap.yml just contains 

spring:
  application:
    name: app

in my case. Everything else is configured in application-[profile].yml

Now everything works as desired:

2017-03-13 15:58:21.291  INFO [app,,,] [localhost,swagger] 27519 --- [           main] com.company.app.keyserver.Application    : Started Application in 17.565 seconds (JVM running for 18.232)

Upvotes: 2

Views: 4186

Answers (1)

Marcin Grzejszczak
Marcin Grzejszczak

Reputation: 11179

Of course - you have to just provide your own logging format (e.g. via logging.pattern.level - check https://docs.spring.io/spring-boot/docs/current/reference/html/boot-features-logging.html for more info). Then you have to register your own SpanLogger bean implementation where you will take care of adding the value of a spring profile via MDC (you can take a look at this as an example https://github.com/spring-cloud/spring-cloud-sleuth/blob/master/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jSpanLogger.java )

UPDATE:

There's another solution for more complex approach that seems much easier than rewriting Sleuth classes. You can try the logback-spring.xml way like here - https://github.com/spring-cloud-samples/sleuth-documentation-apps/blob/master/service1/src/main/resources/logback-spring.xml#L5-L11 . I'm resolving the application name there so maybe you could do the same with active profiles and won't need to write any code?

Upvotes: 3

Related Questions