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.

SLF4J Basic Logging Example

/*
 *  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 logLevels() {
    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.

SLF4J Message Formatter Example

SLF4J offers some basic string formatting for convenience as well as a minor performance gain. A log message can start with a format followed by var args of Object to be passed into the message format. This also helps prevent unnecessary string concatenation for log messages that are not being hit. 
public static void logFormat() {
    logger.info("Hello {}", "world");

    for (int i = 0; i < 5; i++) {
        logger.info("Hello {} i={}", "world", i);
    }
}

2017-11-14 23:49:25.152 [main] INFO  c.s.examples.logback.LogbackExamples - Hello world
2017-11-14 23:49:25.156 [main] INFO  c.s.examples.logback.LogbackExamples - Hello world i=0
2017-11-14 23:49:25.156 [main] INFO  c.s.examples.logback.LogbackExamples - Hello world i=1
2017-11-14 23:49:25.156 [main] INFO  c.s.examples.logback.LogbackExamples - Hello world i=2
2017-11-14 23:49:25.157 [main] INFO  c.s.examples.logback.LogbackExamples - Hello world i=3
2017-11-14 23:49:25.157 [main] INFO  c.s.examples.logback.LogbackExamples - Hello world i=4

SLF4J Conditional Logging Example

Message formats give us the performance gain of no unnecessary string concatenation but what if we have very verbose logging? SLF4J allows you to check if a log level is enabled. Wrap this check in an if statement and you can now add very verbose logging that will not hinder performance more than a single conditional check if the logger is disabled. 
public static void conditionalLogging() {

    if (logger.isInfoEnabled()) {
        Object expensiveCall = null;
        logger.info("Logger expensive call {}", expensiveCall);
    }

    if (secretLogger.isInfoEnabled()) {
        Object expensiveCall = null;
        logger.info("Secret expensive call {}", expensiveCall);
    }
}

2017-11-14 23:49:25.157 [main] INFO  c.s.examples.logback.LogbackExamples - Logger expensive call null

SLF4J Exception Logging Example

Pretty much every method signature in SLF4J allows you to pass in a Throwable as a final parameter which will print out the stack trace and message along with your standard logging message. Remember to always add useful information to the logs. If an error occurred log the input or bad output, maybe some ids involved. 
public static void logException() {
    try {
        throw new RuntimeException("What happened?");
    } catch (Exception ex) {
        logger.warn("Something bad happened", ex);
        logger.warn("Something bad happened with id: {}", 1, ex);
    }
}

2017-11-14 23:49:25.161 [main] WARN  c.s.examples.logback.LogbackExamples - Something bad happened
java.lang.RuntimeException: What happened?
	at com.stubbornjava.examples.logback.LogbackExamples.logException(LogbackExamples.java:60)
	at com.stubbornjava.examples.logback.LogbackExamples.main(LogbackExamples.java:72)
2017-11-14 23:49:25.162 [main] WARN  c.s.examples.logback.LogbackExamples - Something bad happened with id: 1
java.lang.RuntimeException: What happened?
	at com.stubbornjava.examples.logback.LogbackExamples.logException(LogbackExamples.java:60)
	at com.stubbornjava.examples.logback.LogbackExamples.main(LogbackExamples.java:72)

Third Party Logging

One of the biggest benefits of a logging library like SLF4J is that it is widely used across third party apis. Although step through debugging is a great tool it can also be significantly more time consuming than simple debug logging for many use cases. Look at the level of detail you can get from OkHttp's Logging.

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.