Logging is sometimes one of the things on which too little attention is spent, but when production errors start to arrive you’ll sure want to have the maximum amount of information you want. Most logging implementations in Java will give you the time, the name of the class (or to be more precise, the name of the logger), the name of the thread, and a message and this is actually the best a logging implementation can do by default.
Sometimes it’s interesting to add extra information to every message you log, like for example the id of the user or the tenant’s id (in case of a multi-tenancy application). It would be stupid to manually append it to each log-message because it’s boring and error prone (and you can’t reliably parse it for use in an ELK-stack). To automate this we can use Logback’s (SLF4J) ‘Mapped Diagnostic Context’. Everything you put in the MDC can be used in the log pattern and it’s comparable to a ThreadLocal (each incoming REST request will have different values).
For example:
MDC.put("userId", SecurityUtil.getUserId() == null ? "-1" : SecurityUtil.getUserId().toString());
would put the userId in the MDC and it can then be added to the log message using
%mdc{userId:--2}
The :–2 refers to the default value of -2 which will be logged in case the MDC is empty. I’ll explain later when this happens.
Filling in the MDC
What we want to achieve is that on every REST request, the current user id and the tenant is stored in the MDC and that this information is logged. A Spring FilterRegistrationBean will register a custom servlet Filter (javax.servlet.Filter) which will be triggered on each request and it will set the values in the MDC.
It’s important to note that Spring executes all filters in a certain order and the MDC filter should be executed after the security filter (otherwise we can’t have the user id because the security hasn’t yet extracted this information from the request).
By default (in older versions of Spring) the Spring security filter runs quite late in the chain so it’s best to force it to run a bit earlier by putting this in your application.properties file. This is optional but the default value might change in the future and you want to be sure that when this happens, it still runs in an earlier stage.
security.filter-order=0
The filter registration bean looks like this:
@Component
public class LogbackDiagnosticContext extends FilterRegistrationBean {
public LogbackDiagnosticContext() {
super(new MDCContextFilter());
addUrlPatterns("/*");
setOrder(Integer.MAX_VALUE);
}
public static class MDCContextFilter implements Filter {
/**
* {@inheritDoc}
*/
@Override
public void init(FilterConfig
filterConfig) throws ServletException {
// NOOP
}
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
MDC.put("userId", SecurityUtil.getUserId() == null ? "-1" : SecurityUtil.getUserId().toString());
MDC.put("tenant", StringUtils.isBlank(CurrentContext.getTenant()) ? "none" : CurrentContext.getTenant());
filterChain.doFilter(servletRequest, servletResponse);
}
/**
* {@inheritDoc}
*/
@Override
public void destroy() {
// NOOP
}
}
}
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/application.log}"/>
<property name="CONSOLE_LOG_PATTERN" value="%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} %clr([%mdc{userId:--2}] [%-10.10mdc{tenant:-null}]){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
<property name="FILE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : [%mdc{userId:--2}] [%-10.10mdc{tenant:-null}] %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
<include resource="org/springframework/boot/logging/logback/console-appender.xml" />
<include resource="org/springframework/boot/logging/logback/file-appender.xml" />
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
</root>
<logger name="org.springframework" level="INFO"/>
<logger name="be.pw999" level="INFO"/>
</configuration>
This pattern will result in a log message like this (given that the tenant is junit and the userId is 123456789):
2017-05-06 17:42:11.410 INFO --- [ main] be.pw999.secretproject.base.LogTest : [12345679] [junit ] INFO
2017-05-06 17:42:11.440 WARN --- [ main] be.pw999.secretproject.base.LogTest : [12345679] [junit ] WARNING
2017-05-06 17:42:11.441 ERROR --- [ main] be.pw999.secretproject.base.LogTest : [12345679] [junit ] ERRORRRR
As previously said, it’s possible that the MDC is empty. This can happen in a couple of cases:
- A message is being logged before the custom filter was executed. You can make it run earlier in the chain by passing a smaller number to setOrder(int).
- A message is being logged for something else than a REST call. Since this is a servlet filter, it won’t work for stuff like JMS messages or Spring Batch
- A message is called from an asynchronous thread (eg. using @Async)
Parsing the log message using Grok
Here’s a little bonus for you. Our log message are captured using Filebeat and sent to Logstash before being stored into ElasticSearch (classic ELK stack). Logstash will parse the log-message and convert them so that we can search on the tenant and userId using Kibana. For this we use the following grok-pattern:
filter {
if [type] == "logback" {
grok {
patterns_dir => "/etc/logstash/grok/patterns"
# Do multiline matching with (?m) as the above mutliline filter may add newlines to the log messages.
match => [ "message", "^%{LOGBACK_TIMESTAMP:logtime}%{SPACE}%{LOGLEVEL:loglevel}%{SPACE}%{NUMBER:pid}%{SPACE}---%{SPACE}%{SYSLOG5424SD:thread}%{SPACE}%{JAVACLASSSPRING:javaclass}%{SPACE}:%{SPACE}\[%{USERID:userId}\]%{SPACE}\[%{TENANT:tenant}\]%{SPACE}%{GREEDYDATA:logmessage}"]
}
mutate {
convert => [ "pid", "integer"]
convert => [ "userId", "integer" ]
}
date {
match => [ "logtime" , "yyyy-MM-dd HH:mm:ss.SSS" ]
timezone => "Europe/Brussels"
add_tag => [ "dateparsed" ]
}
}
}
and these are the extra regex patterns used in the grok parser
JAVACLASSSPRING (?:[\.]?[\[\]/a-zA-Z0-9-]+\.)*[\[\]/A-Za-z0-9$]+
MSEC (\d{3})
LOGBACK_TIMESTAMP %{YEAR}-%{MONTHNUM}-%{MONTHDAY}%{SPACE}%{HOUR}:%{MINUTE}:%{SECOND}.%{MSEC}
USERID [\-0-9]*
TENANT [a-zA-Z0-9 ]+
P_W999