Maybe it's basic, but still, sometimes some suboptimal usage of logger can be seen. There also is/was a notion that Java applications tend to overuse logging. That may or not be true, but using the logger properly should have minimal performance implications on the application. This one is to give you few recommendations for logging things in Java, based on my experience. Feel free to disagree in comments.

1. Log when it makes sense

Yes, do it when it makes sense. So log when you may benefit from it, and not because you have to. When it makes sense, in my opinion:

  • Public methods in the service layer of the application, where the magic happens, to make sure the service layer is called properly by other layers. You probably want DEBUG log level for this.
  • When a decision is made, because it's useful to know when/if the execution branches according to some condition. The log level could be TRACE, unless it's important.
  • Inside a crazy function implementing an equally crazy algorithm to check some (crazy) intermediate values. TRACE in most cases.
  • When an exception occurs and you intend to handle it or handle by ignoring it. According to perceived severity - ERROR or WARN. You might want to use the latter for cases when the exception is relatively common, recoverable and doesn't impact the execution much.

The last one deserves a mention of a well-known anti-pattern. In most cases you don't want to log-throw:

try {
    // something, something
} catch(SomeException e) {
    LOGGER.debug("Exception occurred when...", e);
    throw new OrRethrowTheSameException();
}

...or you'll end-up having multiple stack traces in the logs referring to the same problem, causing clutter. Log only the 'top-level' exceptions.

Once you agree what makes sense to you, try to keep it consistent across the application, but don't hold on to it regardless. Whenever it stops making sense to you, just change the rules.

2. Log so you can make sense out of logs

In general:

  • Use meaningful log messages with enough information. When you log the fact the method was called, log the most important parameters it was called with as well.
  • Avoid unnecessary clutter. When a parameter is a String that can be looong - just cut it down so it's visible it's not null and still readable.
  • Be careful not to log any sensitive information - you don't want to have passwords/keys flying in the logs, as you don't know what happens with them.
  • When logging exceptions, log the exception object too, so you can see it's type, message and a stack trace.

3. Use SLF4J

Using SLF4J is de facto standard. It's an abstraction over different logging frameworks like Log4j. Besides from the fact that having an abstraction allows you to switch logging frameworks, which surely isn't something you do on daily basis, it's just a nice API to use :) Spring Boot uses SLF4J with Logback, so no special configuration is needed, you get it out of the box. The feat of using Logback is that it's using SLF4J as it's API, so no separate artifacts for SLF4J are needed. To use Logback in non-Spring Boot apps, put this into pom.xml:

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.1.2</version>
</dependency>

Then put a basic configuration in the root of classpath in a logback.xml file:

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  </appender>
  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

This logs everything with DEBUG log level to the console.

If you are using some libraries in the application that make use of other logging APIs, the log messages might appear to ignore any Logback settings. For that occasion SLF4J provides bridges. These are modules that implement that other APIs, but passes the messages to SLF4J instead, and in turn they are handled by Logback which implements SLF4J. Refer to the documentation on bridging legacy APIs to see what APIs are supported.

The general strategy to use them involves:

  • adding relevant bridge to pom.xml (Spring Boot adds most of them by default)
  • excluding the legacy API from the artifact that uses them by using Maven's <exclusions> tag

4. Set the log levels appropriately

For most of the time you don't want to see log messages from libraries you use (e.g. Spring), while you want to see messages coming from your code. So that's what settings log levels is for, and they can be set per-package.

For Spring Boot apps you can forget about the logback.xml, and set your log levels in application.properties, for example:

logging.level.eu.kielczewski: DEBUG
logging.level: WARN

For non Spring Boot apps, having this in logback.xml:

<configuration>
<logger name="eu.kielczewski" additivity="false" level="TRACE">
    <appender-ref ref="stdout"/>
</logger>
<root level="WARN">
    <appender-ref ref="stdout"/>
</root>

....sets the log level for eu.kielczewski package to TRACE, and WARN for everything else.

4. Initialize the logger once

You really want the logger for a class to be initialized only once, and not every time a method is called, so just make a private static final class property out of it.

public class SomeClass {
    private static final Logger LOGGER = LoggerFactory.getLogger(SomeClass.class);

    public void someMethod() {
        LOGGER.debug("Executing some method");
    }
}

There are different conventions when it comes to calling the property LOGGER (upper case) or logger (lower case) with a debate whether the Logger is immutable or not. Again, use what it makes sense to you (or complies with company policy). I, for myself, like uppercase because it's more visible.

So to illustrate the above, just don't:

public class SomeClass {
    public void someMethod() {
        LoggerFactory.getLogger().debug("Executing some method");
    }
}

5. Make use of placeholders

SLF4J provides allows placeholders to format log messages, so you can:

public void someMethod(String paramA, int paramB) {
    LOGGER.debug("Executing some method with paramA={}, paramB={}", paramA, paramB);
}

The last parameter passed to logger can be an exception, and it will appear in the log with a stack-trace, so this is valid:

try {
    // something, something
} catch(SomeException e) {
    LOGGER.debug("Exception occurred when...", e);
}

Remember to use the placeholders instead of composing the log messages using String utility methods or a concatenation. Doing otherwise has performance implications, imagine:

public void someMethod(String paramA, String paramB) {
    LOGGER.debug("Executing some method with paramA=" + paramA + ", paramB=" + paramB);
}

Those strings get concatenated every time the code is executed, regardless of the current log level, which is bad.

As a rule, you don't want to perform any additional operations associated with calling the logger. You want to benefit from the situation that if the current log level is higher, the impact on performance will be minimal. Although the call itself will still occur, the cost stays small.

6. Pass only primitives/object references to the logger

For the same reason you want to pass only object references/primitive values to the logger. Imagine:

public void someMethod(ComplexObjectA paramA, ComplexObjectB paramB) {
    LOGGER.debug("Executing some method with paramA={}, paramB={}", paramA.toString(), paramB.toString());
}

Doing that would force execution of toString() regardless of the current log level. Passing an object reference allows to execute toString() only when something is going to be actually logged.

7. Use meaningful toString() methods on objects

It's useful to create meaningful toString() methods on objects, so you can just pass the object as a whole to the logger. As a personal preference I find the Guava's MoreObjects.toStringHelper() quite nice to use, for example:

@Override
public String toString() {
    return MoreObjects.toStringHelper(this)
            .add("id", id)
            .add("file", file)
            .add("title", title)
            .add("description", description)
            .add("tags", tags)
            .add("datePublished", datePublished)
            .toString();
}

So now I can pass the object reference to the logger and all object's properties will appear in the log file.

9. Use nice logging formatting for the console

While logging to the console it is important to keep logs readable. What helps is a nice log format. For example, in Spring Boot they use a format that keeps fixed width on things like package or thread names, causing every log message to start from the same column. This also uses colors, if your console supports it. It really helps to make sense out of long logs.

To use the format in your Spring Boot application you don't have to do anything, as it just comes as default. To use it with non-Spring Boot applications you can put it into logback.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="CONSOLE_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} %5p ${PID:- } --- [%15.15t{14}] %-40.40logger{39} : %m%n"/>

    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <Target>System.out</Target>
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>
    <logger name="eu.kielczewski" additivity="false" level="TRACE">
        <appender-ref ref="stdout"/>
    </logger>
    <root level="WARN">
        <appender-ref ref="stdout"/>
    </root>
</configuration>

This won't give you the colors, but looks nicely anyway.

10. Consider logging to JSON

While logging to the console while in development is preferred, logging to the console in the production makes little sense, because no one is going to read what's logged straight from the console. It's better to leave it for the machines to parse and extract any relevant information. Machines like structured data though, and for that reason you should consider logging your logs in JSON format, rather than in a plain text.

To log messages in JSON by Logback, the following module should be present in pom.xml:

<!-- Logstash Logback Encoder -->

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>3.4</version>
</dependency>

And the configuration in logback.xml:

<configuration>
    <property name="PROJECT_ID" value="example"/>
    <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>logs/${PROJECT_ID}.json</File>
        <encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
        <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
            <maxIndex>1</maxIndex>
            <FileNamePattern>logs/${PROJECT_ID}.json.%i</FileNamePattern>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>1MB</MaxFileSize>
        </triggeringPolicy>
    </appender>
    <logger name="eu.kielczewski" additivity="false" level="INFO">
        <appender-ref ref="file"/>
    </logger>
    <root level="WARN">
        <appender-ref ref="file"/>
    </root>
</configuration>

This creates example.json file under logs/. The file is rolled once when it reaches 1MB in size.

The benefit is that it may be read and parsed by a tool like Logstash for further processing. Alternatively, there is also a module to write the log directly to Logstash if that's what you prefer. One way or another, this is better than using regular expressions to parse information out of it.

As an added benefit you can also easily add more information to the log, like whole objects serialized to JSON:

LOGGER.debug(append("object", someObject), "log message");

This site uses cookies. By continuing to browse the site, you are agreeing to our use of cookies. Find out more in Privacy and Cookies Policy.