Spring Boot Starter : Chapter 3, logger and process unique id

TSBS Project repository and archives

As a shortcut, TSBS stands for Tooling Spring Boot Starter until I find a better name.

You can find TSBS sources at GitHub project page and this chapter archive under its own tag Chapter 3 archive

See Chapter 1 introduction to read more about this project.

Objectives

In this chapter, we will set up some logging features using MDC. MDC (Mapped Diagnostic Context) provides an interface to dynamically set values in each thread, which is useful to follow a process from its beginning towards its end, without taking care of passing anything specific though called methods. This is quite handy when multiple concurrent requests are served during the same time frame, and when you need to analyse the logs.

We’ll also use MDC to set a unique id to each Controller method start, in order to follow processing across the whole application.

Check previous chapter if you missed it !

MonitoringService

MonitoringService defines a few methods to control monitoring through MDC :

start(processName) : To be called when a new process is started. Creates a unique processId and log process start.
end() : To be called when a process is finished.

package net.kprod.tooling.spring.starter.service.impl;

//imports

/** {@inheritDoc} */
@Service
public class MonitoringServiceImpl implements MonitoringService {
    public static final String MONITORING_PROCESS_NAME = "_processName";
    public static final String MONITORING_PROCESS_ID = "_processId";
    public static final String MONITORING_PROCESS_ID_SHORT = "_processIdShort";
    private Logger LOG = LoggerFactory.getLogger(MonitoringService.class);

    protected final static int LOG_DATA_ID_LENGTH = 36;
    protected final static int LOG_DATA_ID_SHORT_LENGTH = 12;
    protected final static int LOG_DATA_ID_SHORT_DIFF = LOG_DATA_ID_LENGTH - LOG_DATA_ID_SHORT_LENGTH;

    // start process monitoring
    @Override
    public String start(String processName) {
        MDC.clear();
        //processId is a ramdom UUID
        String processId = UUID.randomUUID().toString();

        MDC.put(MONITORING_PROCESS_NAME, processName);
        MDC.put(MONITORING_PROCESS_ID, processId);
        //Short version of processId (split after the last UUID dash)
        MDC.put(MONITORING_PROCESS_ID_SHORT, this.getShortLogDataId(processId));

        LOG.info("Start monitoring processName [{}] id [{}]",
                processName,
                processId);

        return processId;
    }

    // mark process as finished
    @Override
    public void end() {
        LOG.info("End monitoring processName [{}] id [{}]",
                this.getProcessName(),
                this.getProcessId());

        //clear MDC context
        MDC.clear();
    }

    //get processId from MDC
    private String getProcessId() {
        return MDC.get(MONITORING_PROCESS_ID);
    }

    //get processName from MDC
    private String getProcessName() {
        return MDC.get(MONITORING_PROCESS_NAME);
    }

    //shortening processId UUID
    private String getShortLogDataId(String logDataId) {
        if(logDataId == null || logDataId.length() < LOG_DATA_ID_SHORT_DIFF) {
            return logDataId;
        }
        return logDataId.substring(LOG_DATA_ID_SHORT_DIFF);
    }
}

Set Up logback

We configure log pattern using logback.xml from src/resources/.

Using %X flags, we’re able to display MDC context variables in each log entry.

PatternLayout also supports coloring, as in %clr([%X{_processIdShort}]){red}, processIdShort may be displayed in red color.

To display essential monitoring data in our logs, we set the following variables in our custom pattern

%clr([%X{_processIdShort}]){red} : the short version of the processId, in red color
%clr([%X{_processName}]){red}" : the process name

processIdShort might be random enough to avoid colliding in our logs with a daily rotation.

logback mdc configuration

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
    <conversionRule conversionWord="wex" converterClass="org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter" />
    <conversionRule conversionWord="wEx" converterClass="org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter" />

    <!-- This variable defines the MDC pattern -->
    <variable scope="context" name="mdcPattern" value="%clr([%X{_processIdShort}]){red} %clr([%X{_processName}]){red}"/>

    <!-- This defines console appender -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                <!-- mdcPattern variable is integrated to main pattern -->
                ${CONSOLE_LOG_PATTERN:-%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} ${mdcPattern} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}
            </Pattern>
        </layout>
    </appender>

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

</configuration>

App test setup

Test Service

FooService is out test Service to demonstrate monitoring across various methods.

Thread#sleep() is used to ease a concurrent execution.

FooService class

@Service
public class FooServiceImpl implements FooService {
    private Logger LOG = LoggerFactory.getLogger(FooService.class);

    // /foo returns bar after 1 sec
    @Override
    public Response foo() throws ServiceException {
        LOG.info("foo method");
        try{
          Thread.sleep(1000);
        } catch (Exception e) {
            LOG.error("sleep have gone wrong");
        }
        return new Response("bar");
    }

    //bar returns baz after 2 secs
    @Override
    public Response bar() throws ServiceException {
        LOG.info("bar method");
        try{
            Thread.sleep(2000);
        } catch (Exception e) {
            LOG.error("sleep have gone wrong");
        }
        return new Response("baz");
    }
}

Test Controller

ControllerRoot is modified as follow, to create 2 endpoints :

ControllerRoot class

// foo endpoint
@RequestMapping(value = "/foo", method = RequestMethod.GET, produces = MediaType.APPLICATION_JSON_VALUE)
public ResponseEntity<Response> foo() throws Exception {
    monitoringService.start(this.getClass().getSimpleName() + "#foo");
    Response response = fooService.foo();
    LOG.info("Response [{}]", response.getMessage());
    monitoringService.end();
    return ResponseEntity.ok(response);
}

// /bar endpoint
@RequestMapping(value = "/bar", method = RequestMethod.GET, produces = MediaType.APPLICATION_JSON_VALUE)
public ResponseEntity<Response> bar() throws Exception {
    monitoringService.start(this.getClass().getSimpleName() + "#bar");
    Response response = fooService.bar();
    LOG.info("Response [{}]", response.getMessage());
    monitoringService.end();
    return ResponseEntity.ok(response);
}

Test Monitoring

Using my browser, I’m requesting quite at the same time /foo and /bar.

The log display lines as expected : We can see that /bar request leads to lines identified as f67ac7c3be7d, while concurrently /foo leads to lines with a 0b67310a2ca6 processId. We can also verify that processId and processName are kept along different class and methods across processing.

Console log

[...] [f67ac7c3be7d] [ControllerRoot#bar] Start monitoring processName [ControllerRoot#bar] id [221a35e7-eda3-4997-bed3-f67ac7c3be7d]
[...] [f67ac7c3be7d] [ControllerRoot#bar] bar method
[...] [0b67310a2ca6] [ControllerRoot#foo] Start monitoring processName [ControllerRoot#foo] id [b1108c00-fa34-433e-819a-0b67310a2ca6]
[...] [0b67310a2ca6] [ControllerRoot#foo] foo method
[...] [f67ac7c3be7d] [ControllerRoot#bar] Response [baz]
[...] [f67ac7c3be7d] [ControllerRoot#bar] End monitoring processName [ControllerRoot#bar] id [221a35e7-eda3-4997-bed3-f67ac7c3be7d]
[...] [0b67310a2ca6] [ControllerRoot#foo] Response [bar]
[...] [0b67310a2ca6] [ControllerRoot#foo] End monitoring processName [ControllerRoot#foo] id [b1108c00-fa34-433e-819a-0b67310a2ca6]

Summary of this chapter

We have created a tooling-spring-boot-starter MonitoringService, which could be used through Spring auto-wiring. MonitoringService allows to control process monitoring and affects a processId to each unique process, and store monitoring process inside MDC context.

Then we customized our log pattern to display some MDC context values at runtime.

We test everything with our tooling-app embed test Application

To be continued…

In chapter 4 we will explore AOP aspects to run monitoring automatically.

All available chapters

chapter 1 : Custom Spring Boot 2 Starter with Spring 5, chapter 1
chapter 2 : Spring Boot Starter : Chapter 2, error handling
chapter 3 : Spring Boot Starter : Chapter 3, logger and process unique id
chapter 4 : Spring Boot Starter : Chapter 4, aspects and async processing