Logging in Java and in general: Best Practices?

Question

Sometimes when I see my logging code I wonder if I am doing it right. There might be no definitive answer to that, but I have the following concerns:

Library Classes

I have several library classes which might log some INFO messages. Fatal Errors are reported as exceptions. Currently I have a static logger instance in my classes with the class name as the logging name. (Log4j's: Logger.getLogger(MyClass.class))

Is this the right way? Maybe the user of this library class doesn't want any messages from my implementation or wants to redirect them to an application specific log. Should I allow the user to set a logger from the "outside world"? How do you handle such cases?

General logs

In some applications my classes might want to write a log message to a specific log not identified by the class' name. (I.e.: HTTP Request log) What is the best way to do such a thing? A lookup service comes to mind...

Answer 1

I'm reviewing log-levels of an application and I'm currently detecting a pattern:

private static final Logger logger = Logger.getLogger(Things.class)

public void bla() {
  logger.debug("Starting " + ...)
  // Do stuff
  ...
  logger.debug("Situational")

  // Algorithms
  for(Thing t : things) {
    logger.trace(...)
  }

  // Breaking happy things
  if(things.isEmpty){
    logger.warn("Things shouldn't be empty!")
  }

  // Catching things
  try {
    ...
  } catch(Exception e) {
    logger.error("Something bad happened")
  }

  logger.info("Completed "+...)
}

A log4j2-file defines a socket-appender, with a fail-over file-appender. And a console-appender. Sometimes I use log4j2 Markers when the situation requires it.

Thought an extra perspective might help.

Answer 2

The following is the guidelines I follow in all my projects to ensure good performance. I have come to form this set of guidelines based on the inputs from various sources in the internet.

As on today, I believe Log4j 2 is by far the best option for logging in Java.

The benchmarks are available here. The practice that I follow to get the best performance is as follows:

1. I avoid using SLF4J at the moment for the following reasons:
   • It has some concurrency issues with Markers which I want to use to manage the logging of SQL statements (Markers not as powerful as slf4j - Refer to the first comment by Ralph Goers)
   • It does not support the Java 8 Lambda which, again, I want to use for better performance (Support the lambda expression in the Logger)
2. Do all regular logging using asynchronous logger for better performance
3. Log error messages in a separate file using synchronous logger because we want to see the error messages as soon as it occurs
4. Do not use location information, such as filename, class name, method name, line number in regular logging because in order to derive those information, the framework takes a snapshot of the stack and walk through it. This impacts the performance. Hence use the location information only in the error log and not in the regular log
5. For the purpose of tracking individual requests handled by separate threads, consider using thread context and random UUID as explained here
6. Since we are logging errors in a separate file, it is very important that we log the context information also in the error log. For e.g. if the application encountered an error while processing a file, print the filename and the file record being processed in the error log file along with the stacktrace
7. Log file should be grep-able and easy to understand. For e.g. if an application processes customer records in multiple files, each log message should be like below:

12:01:00,127 INFO FILE_NAME=file1.txt - Processing starts
12:01:00,127 DEBUG FILE_NAME=file1.txt, CUSTOMER_ID=756
12:01:00,129 INFO FILE_NAME=file1.txt - Processing ends

8. Log all SQL statements using an SQL marker as shown below and use a filter to enable or disable it:

private static final Marker sqlMarker = 
  MarkerManager.getMarker("SQL");

private void method1() {
    logger.debug(sqlMarker, "SELECT * FROM EMPLOYEE");
}

9. Log all parameters using Java 8 Lambdas. This will save the application from formatting message when the given log level is disabled:

int i=5, j=10;
logger.info("Sample output {}, {}", ()->i, ()->j);

10. Do not use String concatenation. Use parameterized message as shown above

11. Use dynamic reloading of logging configuration so that the application automatically reloads the changes in the logging configuration without the need of application restart

12. Do not use printStackTrace() or System.out.println()

13. The application should shut down the logger before exiting:

LogManager.shutdown();

14. Finally, for everybody’s reference, I use the following configuration:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration monitorinterval="300" status="info" strict="true">
    <Properties>
        <Property name="filePath">${env:LOG_ROOT}/SAMPLE</Property>
        <Property name="filename">${env:LOG_ROOT}/SAMPLE/sample
        </Property>
        <property name="logSize">10 MB</property>
    </Properties>
    <Appenders>
        <RollingFile name="RollingFileRegular" fileName="${filename}.log"
            filePattern="${filePath}/sample-%d{yyyy-dd-MM}-%i.log">
            <Filters>
                <MarkerFilter marker="SQL" onMatch="DENY"
                    onMismatch="NEUTRAL" />
            </Filters>
            <PatternLayout>
                <Pattern>%d{HH:mm:ss,SSS} %m%n
                </Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy
                    interval="1" modulate="true" />
                <SizeBasedTriggeringPolicy
                    size="${logSize}" />

            </Policies>
        </RollingFile>
        <RollingFile name="RollingFileError" 
            fileName="${filename}_error.log"
            filePattern="${filePath}/sample_error-%d{yyyy-dd-MM}-%i.log"
            immediateFlush="true">
            <PatternLayout>
                <Pattern>%d{HH:mm:ss,SSS} %p %c{1.}[%L] [%t] %m%n
                </Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy
                    interval="1" modulate="true" />
                <SizeBasedTriggeringPolicy
                    size="${logSize}" />
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <AsyncLogger name="com"
            level="trace">
            <AppenderRef ref="RollingFileRegular"/>
        </AsyncLogger>
        <Root includeLocation="true" level="trace">
            <AppenderRef ref="RollingFileError" level="error" />
        </Root>
    </Loggers>
</Configuration>

15. The required Maven dependencies are here:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.8.1</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.8.1</version>
</dependency>
<dependency>
    <groupId>com.lmax</groupId>
    <artifactId>disruptor</artifactId>
    <version>3.3.6</version>
</dependency>
<!-- (Optional)To be used when working 
with the applications using Log4j 1.x -->
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-1.2-api</artifactId>
    <version>2.8.1</version>
</dependency>