Tutorial: Correct SLF4J logging usage and how to check it

SLF4J is a very popular logging facade but, like all libraries we use, there is a chance that we use it in a wrong or at least in a not optimal way.

In this tutorial we will list common logging errors and how we can detect them using FindBugs. We will also mention PMD and Sonar Squid checks when relevant.

We will use two external FindBugs plugins which add logging detectors to FindBugs.

The first one is a SLF4J only plugin by Kengo Toda which contains SLF4J detectors only.

The second plugin is the popular FB Contrib which contains, among many others, some logging detectors.

For how to use FindBugs plugins, please refer to the following posts:

Note: in all examples we will assume the following imports:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

1. Logger definition

Wrong way:

W1a. Logger log = LoggerFactory.getLogger(MyClass.class);
W1b. private Logger logger = LoggerFactory.getLogger(MyClass.class);
W1c. static Logger LOGGER = LoggerFactory.getLogger(AnotherClass.class);

Correct way:

C1a. private static final Logger LOGGER = LoggerFactory.getLogger(MyClass.class);
C1b. private final Logger logger = LoggerFactory.getLogger(getClass());

General rule: the logger should be final and private because there are no reasons to share it with other classes or to re-assign it.

On the contrary there is no general agreement if the logger should be static or not. SLF4J plugin favors non static version (C1b) while PMD (“LoggerIsNotStaticFinal” rule) and Sonar (squid rule S1312) prefer a static logger (C1a) so both options should be considered as valid.

Additional info:

Please note that

  • in the static version (C1a), the logger name is usually in uppercase characters as all constant fields. If not, PMD will report a “VariableNamingConventions” violation.
  • in both cases, the suggested name is “logger/LOGGER” and not “log/LOG” because some naming conventions avoid too short names (less than four characters). Moreover log is the verb, more suited for a method name.
  • the W1c is wrong because we are referring to a class (AnotherClass) which is not the class where the logger is defined. In the 99% of the cases, this is due to a copy & paste from one class to another.

Related FindBugs (SLF4J plugin) checks:

  • SLF4J_LOGGER_SHOULD_BE_PRIVATE
  • SLF4J_LOGGER_SHOULD_BE_NON_STATIC
  • SLF4J_LOGGER_SHOULD_BE_FINAL
  • SLF4J_ILLEGAL_PASSED_CLASS

 

2. Format string

Wrong way:

W2a. LOGGER.info("Obj=" + myObj);
W2b. LOGGER.info(String.format(“Obj=%s”, myObj));

Correct way:

C2. LOGGER.info("Obj={}",myObj);

General rule: the format string (the first argument) should be constant, without any string concatenation. Dynamic contents (the myObj value in the example) should be added using the placeholders (the ‘{}’ ).

Motivation is simple: we should delay logging message creation after the logger has established if the message should be logged or not, depending on the current logging level. If we use string concatenation, message is built any way, regardless the logging level which is a waste of CPU and memory resources.

Related FindBugs (SLF4J plugin) checks:

  • SLF4J_FORMAT_SHOULD_BE_CONST Format should be constant
  • SLF4J_SIGN_ONLY_FORMAT Format string should not contain placeholders only

Related FindBugs (FB Contrib plugin) checks:

  • LO_APPENDED_STRING_IN_FORMAT_STRING Method passes a concatenated string to SLF4J’s format string

 

3. Placeholder arguments

Wrong way:

W3a. LOGGER.info("Obj={}",myObj.getSomeBigField());
W3b. LOGGER.info("Obj={}",myObj.toString());
W3c. LOGGER.info("Obj={}",myObj, anotherObj);
W3d. LOGGER.info("Obj={} another={}",myObj);

Correct way:

C3a. LOGGER.info("Obj={}",myObj);
C3b. LOGGER.info("Obj={}",myObj.log());

General rule: the placeholder should be an object (C3a), not a method return value (W3a) in order to post-pone its evaluation after logging level analysis (see previous paragraph). In W3a example, the mehod getSomeBigField() will be always called, regardless the logging level. For the same reason, we should avoid W3b which is semantically equivalent to C3a but it always incurs in the toString() method invocation.

Solutions W3c and W3d are wrong because the number of placeholders in the format string does not match the number of placeholders arguments.

Solution C3b could be somehow misleading because it includes a method invocation but it could be useful whenever the myObj contains several fields (for example it is a big JPA entity) but we do not want to log all its contents.

For example, let’s consider the following class:

public class Person {
private String id;
private String name;
private String fullName;
private Date birthDate;
private Object address;
private Map<String, String> attributes;
private List phoneNumbers;

its toString() method will most probably include all fields. Using the solution C3a, all their values will be printed in the log file.

If you do not need all this data, it is useful to define a helper method like the following:

public String log() {
return String.format("Person: id=%s name=%s", this.id, this.name);
}

which prints relevant information only. This solution is also CPU and memory lighter than toString().

What is relevant ? It depends on the application and on the object type. For a JPA entity, I usually include in the log() method the ID field (in order to let me find the record in the DB if I need all columns data) and, may be, one or two important fields.

For no reason, passwords fields and/or sensitive info (phone numbers,…) should be logged. This is an additional reason to not log using toString().

Related FindBugs (SLF4J plugin) checks:

  • SLF4J_PLACE_HOLDER_MISMATCH

 

4. Debug messages

IMPORTANT: rule #4 (see 5 rules article) guide us to use a guarded debug logging

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(“Obj={}”, myObj);
}

Using SLF4J, if the placeholder argument is an object reference (see solutions C3a/C3b), we can use avoid the if in order to keep the code cleaner.

So it is safe to use the following:

LOGGER.debug(“Obj={}”, myObj);

 

5. Exceptions

Proper exceptions logging is an important support for problems analysis but it is easy to neglect its usefulness.

Wrong way:

W5a. catch (SomeException ex) { LOGGER.error(ex);}..
W5b. catch (SomeException ex) { LOGGER.error("Error:" + ex.getMessage());}..

Correct way:

C5. catch (SomeException ex) { LOGGER.error("Read operation failed: id={}", idRecord, ex);}..`

General rules:

  1. Do not remove the stack trace information by using getMessage() (see W5b) and not the complete exception. The stack trace often includes the real cause of the problem which is easily another exception raised by the underlying code. Logging only the message will prevent us to discover the real cause of the problem.
  2. Do show significant (for the human which will analyze the log file) information in the logging message showing a text explaining what we wanted to perform while the exception was raised (not the exception kind or messages like “error”: we know already something bad happened). What we need to know is what we were doing and on which data.

The C5 example tells we were trying to read the record with a specific ID whose value has been written in the log with the message.

Please note that C5 use one placeholder in the format string but there are two additional arguments. This is not an error but a special pattern which is recognized by SLF4J as an exception logging case: the last argument (ex in the C5 example) is considered by SLF4J as a Throwable (exception) so it should be not included in the format string.

Related FindBugs (SLF4J plugin) checks:

  • SLF4J_MANUALLY_PROVIDED_MESSAGE: the message should not be based on Exception getMessage()

Tutorial: using FindBugs with Maven

FindBugs can be executed using Maven in two different modes: as stand-alone command or as part of the Maven site command.

These two modes require different settings in the project pom.xml but they are not incompatible to each other so we can use both of them.

info48
You can find complete Maven project here.

Stand-alone mode

Let’s start with the stand-alone mode which requires the following configuration in the pom.xml:

<build>
    <plugins>       
        <plugin>
            <groupId>org.codehaus.mojo</groupId>
            <artifactId>findbugs-maven-plugin</artifactId>
            <version>3.0.1</version>
        </plugin>
         ... other build plugins ....
    </plugins>
</build>

Please note that the FindBugs plugin definition is inside build – plugins section of the pom file.

Giving the following command:

mvn findbugs:findbugs

FindBugs is run against our project with the following log in the console output:

[INFO] --- findbugs-maven-plugin:3.0.1:findbugs (default-cli) @ CodeQualityGallery ---
[INFO] Fork Value is true
     [java] Warnings generated: 1
[INFO] Done FindBugs Analysis....

warning48
FindBugs analyze the compiled files (*.class). If the project is not compiled or just cleaned, FindBugs will report nothing, without error messages. So take care to build your project before running FindBugs.

A warnings number is reported on the console. Warnings are possible bugs found by the FindBugs detectors.

The warnings details are included in a report created in the file target/findbugsXml.xml which is in XML format and so not really readable.

A better way to examine the warnings is to use the FindBugs native GUI with the command:

mvn findbugs:gui

The FindBugs window shows the bugs on the left, the (read-only) code on the right and the bug explanation below.

FindBugs GUI

You can filter bugs for bug rank from the most critical (“scariest”) to trivial and even, saving project status, comparing project evolution (which means how may bugs has been eliminated/introduced after previous FindBugs check).

warning48All main IDEs (Eclipse, NetBeans, IntelliJ) FindBugs plugins show similar views and they can also let you modify the code so I don’t suggest to use FindBugs native GUI unless you have to create exclusion files (see below) which is easier with the native GUI: select a bug, filter it out and export bug filters.

 

Site mode

Maven site command is used to generate a project “site”, which is a collection of information on the project nicely reported in HTML pages. You can configure which information is included in the site report and, of course, you can add FindBugs analysis results.

Maven site requires a “reporting section” in the pom file.

<reporting>
    <plugins>       
        <plugin>
            <groupId>org.codehaus.mojo</groupId>
            <artifactId>findbugs-maven-plugin</artifactId>
            <version>3.0.1</version>
        </plugin>
         ... other site plugins ....
    </plugins>
</reporting>

Giving the following command (note: clean and install options are in to assure that project is compiled and all tests run):

mvn clean install site

on the console output we will see the following:

.....
[INFO] --- maven-site-plugin:3.3:site (default-site) @ CodeQualityGallery ---
[INFO] configuring report plugin org.apache.maven.plugins:maven-jxr-plugin:2.5
[INFO] configuring report plugin org.apache.maven.plugins:maven-project-info-reports-plugin:2.8
[INFO] configuring report plugin org.codehaus.mojo:findbugs-maven-plugin:3.0.1
[INFO] Fork Value is true
     [java] Warnings generated: 2
[INFO] Done FindBugs Analysis....
[INFO] configuring report plugin org.apache.maven.plugins:maven-pmd-plugin:3.4
[WARNING] No project URL defined - decoration links will not be relativized!
[INFO] Rendering site with org.apache.maven.skins:maven-default-skin:jar:1.0 skin.
[INFO] Skipped "Source Xref" report, file "xref/index.html" already exists for the English version.
[INFO] Generating "Source Xref" report    --- maven-jxr-plugin:2.5
[INFO] Generating "Dependency Convergence" report    --- maven-project-info-reports-plugin:2.8
[INFO] Generating "Dependency Information" report    --- maven-project-info-reports-plugin:2.8
[INFO] Generating "About" report    --- maven-project-info-reports-plugin:2.8
[INFO] Generating "Plugin Management" report    --- maven-project-info-reports-plugin:2.8
[INFO] Generating "Project Plugins" report    --- maven-project-info-reports-plugin:2.8
[INFO] Generating "Project Team" report    --- maven-project-info-reports-plugin:2.8
[INFO] Generating "Project Summary" report    --- maven-project-info-reports-plugin:2.8
[INFO] Generating "FindBugs" report    --- findbugs-maven-plugin:3.0.1
[INFO] Generating "PMD" report    --- maven-pmd-plugin:3.4
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
.....

The “site” is created in the target/site dir. Opening the file target/site/index.html with the browser, we will see something like the following:

2015-06-08bIn the Project Reports section you will find the FindBugs report like the following:

2015-06-08c   The report is interesting because it give us the complete picture of our project in the summary section but also the list of the files which have FindBugs detected issues with all details including the priority (i.e. how dangerous could be the problem).

Configuration options

Regardless the used mode, the FindBugs plugin can be configured to modify and tune its behaviour. All below configurations should be placed in the configuration section of the plugin:

<plugin>
    <groupId>org.codehaus.mojo</groupId>
    <artifactId>findbugs-maven-plugin</artifactId>
    <version>3.0.1</version>
    <configuration>
        .....put here
    </configuration>
</plugin>

warning48
Configurations in the build and reporting sections are independent so we can have two different settings in the two modes, stand-alone and site.

Best practice is to use a light and fast configuration on the standalone mode, in order to run quick checks during development and an high effort, production quality configuration for the site mode.

Let’s examine the most important configuration options:

DEBUG: With <debug>true</debug> option, FindBugs will show what is doing during analysis. Useful to fine tune or checks the settings.

EFFORT: with  <effort>Max</effort> we can increase the time FindBugs is allowed to use to analyze the code. More effort means more accurate analysis but, of course, FindBugs run slower.

EXTERNAL PLUGINS: FindBugs can be extended with additional detectors. See my post on the topic. The  <pluginList>plugin1[, plugin2…]</pluginList> configuration option list the plugins to be used. See the sample project for a real example.

EXCLUSIONS: If you need to disable a detector or to disable the analysis on same classes, an exclude list can be specified with the <excludeFilterFile> path_to_exclude_file </excludeFilterFile> option. File syntax is documented here. An easy way to create this file is by using the FindBugs GUI which has an export filter function. See the sample project for a real example.