SLF4J Logging

Photo by Clint Adair on Unsplash

SLF4J Logging

At least 5-10% of the code goes into logging, very crucial to trace back the issues, here are some of my learnings.

The Simple Logging Facade for Java (SLF4J) serves as a simple facade or abstraction for various logging frameworks (e.g. java.util.logging, logback, log4j) allowing the users to plug in the desired logging framework at deployment time.

How to Declare

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
1.private static final Logger LOGGER = LoggerFactory.getLogger(Test.class)
2.private final Logger logger = LoggerFactory.getLogger(getClass())

The logger should be final & private static or non-static?

1. PMD recommends static (“LoggerIsNotStaticFinal” rule)

2. SIF4 used to recommend a non-static approach but they no longer recommend one over another, this link contains the pro’s and con’s http://www.slf4j.org/faq.html#declared_static

The naming convention of variable LOGGER/logger is a matter of preference — PMD and SONAR recommends LOGGER(uppercase)

If you are using lombok you can get away with just a single annotation `@Slf4j`

How to Log — Parameterized logging

First of all, there shouldn’t be any concatenation operation

Use SLF4J expressions, this will delay the construction of the message until it is necessary.

Do:
LOGGER.debug("Some Object={}",obj);
If debug is disabled — the obj toString() method will not be executed and the log message will never be constructed
It is just that you are passing two variables to the debug method.
1. Some Object={}
2. obj
Implementation of debug method takes care of constructing the message only if the debug is enabled.
Dont:
LOGGER.debug("Some Object=" + obj)
Even If debug is disabled  - the message will be constructed.
Here debug method is called with one argument.
`obj.toString()` is evaluated and concatenated.
The message is constructed even before calling the method.

What to Log

In case of exceptions, brief the issue

Always log the stack trace

Say if IOException occurred while reading a file

Do:
LOGGER.error("Error occurred - Unable to read the file {}",absoluteFilePath,ex)
Dont:
LOGGER.error("Error occurred",ex)
LOGGER.error("Error occurred {}",ex.getMessage())

Logging in a single line

As most of the applications are now cloud-based microservices and they write logs to console and magically a log aggregator agent subscribes to the logs and writes it to preferred storage/workspace, mostly database which has text search capabilities, supports queries associated with timestamp(time series DB)

We don't want the aggregator tool to record each line of the stack trace into multiple entries. so make sure to append the logs to a single line in a JSON format.

Example: Logback way of doing the same.

<configuration>
  <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>${CONSOLE_LOG_PATTERN}</pattern>
      <charset>${CONSOLE_LOG_CHARSET}</charset>
    </encoder>
    <layout class="ch.qos.logback.contrib.json.classic.JsonLayout">
      <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter" />
      <timestampFormat>yyyy-MM-dd' 'HH:mm:ss.SSS</timestampFormat>
      <appendLineSeparator>true</appendLineSeparator>
    </layout>
  </appender>
  <root level="INFO">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Add CorrelationId to identify the related logs

This is a common problem when the multiple apps(microservices) are writing logs to console and aggregators aggregating the logs to a workspace — how to trace back a single transaction across the apps? we need an identifier and we don't want to write code to log the identifier by passing it across the different methods/functions within the app and across the apps.

SLF4J way of doing it. (MDC)

Chapter 8: Mapped Diagnostic Context

Add a filter for example in a spring web application to intercept the input request and add the correlation id to MDC.

public class MDCFilter extends OncePerRequestFilter {

  @Override
  protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
      FilterChain filterChain) throws ServletException, IOException {
    MDC.put("correlationId", UUID.randomUUID().toString());
    try {
      filterChain.doFilter(request, response);
    } finally {
      MDC.remove("correlationId");
    }
  }
}

If the app is some intermediary microservice, use headers to pass the identifier across microservice and in the filter check if the correlationId is available in the request headers, if available add it to MDC, or create a new one as a fallback.

{"timestamp":"2022-01-26 14:31:23.767","level":"WARN","thread":"http-nio-8080-exec-3","mdc":{"correlationId":"577f0224-0970-4ed3-ad9b-7adf4a498c07"},"logger":"org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver","message":"Resolved [c.e.f.GlobalException: Not Authorized]","context":"default"}