Utilizing logging properly is one of the quickest ways to diagnose and debug issues locally or in production. It's not uncommon to find developers or even entire teams / organizations who blatantly ignore or misuse such a fundamental feature. Interactive debuggers are incredibly powerful but can also be very time consuming. Ever try step through debugging a HTTP request that follows several redirects? You better have very solid concentration and a lot of time on your hands to inspect each and every header. Or you can just edit one line in your logging file of choice and make sure logging middleware is enabled on your HTTP client and get the full request / response chain with all redirects dumped to your logging file.

SLF4J

SLF4J is a set of common logging interfaces that has been widely adopted by the Java community and is used by most third party libraries. If by chance it is not used you can always find a bridge implementation to help. Two main implementations are Logback and Log4j. Use whatever you are more comfortable with, we will primarily be using Logback.

Enter Logback

The simplest and most common way to configure logback is through the logback.xml configuration file. By default logback checks the classpath for the following resources logback.groovy, logback-test.xml, and logback.xml (more configuration options). Your configuration should only be stored in projects that execute. Putting a logback.xml file in a thrid party library can cause issues with all library conusmers logging configuration.

Simple logback.xml Configuration

A simple logback.xml file we will be using for our examples.

<!-- turn debug=true on for logback-test.xml to help debug logging configurations. -->
<configuration debug="false"> 

  <!--
  We prefer logging to console instead of a File. Its very easy
  to pipe console output to a file and most organizations already
  have a log rotation setup in place. It can also be faster to use this
  approach vs using a FileAppender directly
  -->
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 
    <!-- encoders are  by default assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder -->
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <!--
  Async appenders can drastically speed up logging as well as your application's
  response time but with some potential drawbacks. Read more at.
  https://logback.qos.ch/manual/appenders.html#AsyncAppender
  http://blog.takipi.com/how-to-instantly-improve-your-java-logging-with-7-logback-tweaks/
  
  Always be sure to test different configurations for yourself. Every
  application has different requirements.
   -->
  <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="STDOUT" />
    <queueSize>1000</queueSize>
  </appender>

  <!--
  We prefer a default setting of WARN and turn on logging explicitly for
  any packages we care about. INFO is also a good choice. Going lower than INFO
  may log sensitive data such as passwords or api tokens via HTTP or networking
  libraries. Remember these defaults impact third party libraries as well.
  
  Often times the cost of logging is overlooked. Try a simple benchmark of
  logging in a tight loop a few million iterations vs not logging and see the difference.
  There are a few ways you can change logging levels on the fly in a running app.
  This could be a better solution than over logging.
  -->
  <root level="WARN">
    <!--
    If you want async logging just use ref="ASYNC" instead.
    We will favor synchronous logging for simplicity. -->
    <appender-ref ref="STDOUT" />
  </root>
  
  <!-- Turn on debug logging for our HikariCP connection pool. -->
  <logger name="com.zaxxer.hikari" level="DEBUG" />
  
  <!-- Turn on debug logging for all loggers under com.stubbornjava -->
  <logger name="com.stubbornjava" level="DEBUG" />
  
  <!--
  Assume we have a com.stubbornjava.secrets.MySecretPasswordClass.Java class.
  This line will disable debug logging for only this class and set it to warn
  so we don't log sensitive data. This is something we may want turned on in
  our logback-test.xml file for local debugging but not in our production
  configuration file.
  -->
  <logger name="com.stubbornjava.secrets.MySecretPasswordClass" level="WARN" />

</configuration>

Simple logback-test.xml Configuration for Local Development

A common use case is to keep src/main/resources/logback.xml as the projects production logging configuration. You can also use src/test/resources/logback-test.xml for local configuration. The logback-test.xml file will be read first and override the main config file locally. If you keep the logback-test.xml file ignored from source control each developer can keep their own local configurations.

What if I need more configurations?

Logback gives you some additional options for passing in the configurations. Let's say we have a single Jar that has many main methods inside of it. Maybe one or more services and potentially some mains that are run as cron jobs. In this case src/main/resources/logback.xml works for our services but we want a different config file for the cron jobs. Simply make a src/main/resources/cron-logback.xml and when you start the java process add the system property flag -Dlogback.configurationFile=logback-crons.xml. This will force logback to use that specific file instead of the default.

Usage

public class LogbackExamples {
    /*
     *  Loggers are thread safe so it is okay to make them static.
     *  Sometimes you may want to pass instances though, it's up to you.
     */
    private static final Logger logger = LoggerFactory.getLogger(LogbackExamples.class);
    private static final Logger secretLogger = LoggerFactory.getLogger("com.stubbornjava.secrets.MySecretPasswordClass");

    public static void main(String[] args) {

        logger.trace("TRACE");
        logger.info("INFO");
        logger.debug("DEBUG");
        logger.warn("WARN");
        logger.error("ERROR");

        secretLogger.trace("TRACE");
        secretLogger.info("INFO");
        secretLogger.debug("DEBUG");
        secretLogger.warn("WARN");
        secretLogger.error("ERROR");
    }
}
2017-02-05 12:05:06.488 [main] INFO  c.s.examples.logback.LogbackExamples - INFO
2017-02-05 12:05:06.492 [main] DEBUG c.s.examples.logback.LogbackExamples - DEBUG
2017-02-05 12:05:06.492 [main] WARN  c.s.examples.logback.LogbackExamples - WARN
2017-02-05 12:05:06.492 [main] ERROR c.s.examples.logback.LogbackExamples - ERROR
2017-02-05 12:05:06.492 [main] WARN  c.s.secrets.MySecretPasswordClass - WARN
2017-02-05 12:05:06.492 [main] ERROR c.s.secrets.MySecretPasswordClass - ERROR

Notice how neither logger logged at Trace level and MySecretPasswordClass only traced Warn and above.

Monitoring

Often times even with proper logging your application can be spewing errors / exceptions in production and no one will notice for extended periods of time. Utilizing Dropwizard Metrics SLF4J Instrumented Appender you can easiy set up graphs or alerts on warn / error rates.