Debug Your Java Applications

Logging Instead of Printing

Have you ever been in a place where you were expected to be quiet, like a library or the theater, and heard that one person who had to talk out loud and ruin it for everyone? Print statements are a little like this. The things you  System.out.println  are visible to the person or script which started your program and sent to the console running it. 

Generally, you want any output from the running application to be about the goal of the application, and it’s overall success or failure. It should be meaningful to the people who run that application or monitor its output.

If someone on my team starts using  System.out.println() to display esoteric and technical details about one class deep inside the code, I suddenly have this loud developer screaming out of my application, and I have no idea where it comes from.  

System.out.println()  does one thing. It prints the value you give it to the console. It does not tell me where that value was printed from or when it was printed. It just prints it. If you want your program to display meaningful output, do not litter its console with anything more than you need to communicate. For instance, our original Dragon Saddle Size Guesser only needed to communicate the estimate it had calculated. It's a good thing we debugged it and didn't litter it with print statements.

Debugging, that’s why! You saw how to use the debugger earlier in this course. It involves running a version of your application and controlling its flow with a debugging tool.

Many developers seem to modify their code with  System.out.println()  statements that show variables and mark what the app is doing with arbitrary lines of text. We’ve all done this, including me.  😳

It’s something you do with a cringe because you know you’re risking leaving a loud noise in your code while responding to the latest emergency. If doing this was based on nothing but a hope that you will find and fix a serious issue through the magical luck of the universe, please take the time to use a debugger.🎱

Although  System.out.println() is rarely fruitful, it is incredibly useful to be able to see what your application was doing when a bug occurred in production. 🔎 Such insight can provide clues to help formulate theories through a better understanding of what was going on inside the application when it failed. For instance, seeing a disk-space error printed out by your application before an  IOException might give you a clue that there was a space issue at the time.

The problem with  System.out.println()  statements is that they can often be forgotten inside the codebase. If they are left, you will have to endure the screams of a dear deeply hidden class for eternity. Or at least until you duct tape its mouth with a logger. 🤐

Loggers are libraries that help you safely create a running report, or log, of what your application is doing directly from your code. Like print statements, you can log anything, and are encouraged to use well-formed sentences to ensure your log lines are readable. Unlike print statements, log lines are printed together with details of when they were printed, the location in the code they were printed from, and details of the process and thread pool printing them. This can help you figure out what other things went wrong during the same time and even within the same thread. 🔎

Further, log lines can be hushed or turned back on using configuration. A logger provides logging methods that print out the provided text and associate it with a level of importance, which is a log level. 

Here's a quick rule of thumb to understand the differences:

• JConsole and JMX excel at reporting on metrics at the current moment in time. What's going on right now?! There are attributes you've thought of upfront, which continuously change. Use these to inspect selected health metrics such as the number of errors per minute from which can help you make a diagnosis about how well your application is doing its job. You might choose to also store some of these metrics for deeper insights over time.

•  VisualVM is also great for observing what's going on at this moment. It allows you to view metrics on how well it's performing and using memory in real-time. You can use it to profile how fast your code is going. Since it can slow your application down, avoid using it in production.

• Logs are like print statements, things we generally persist or save to a file or log aggregator. These allow you to report and inspect what your application is doing at the current point in time as well as review what it did previously. This can be useful when investigating a persistent issue. 

Logs can be as chatty and coherent as you'd like, using plain language. They can also be structured and concise if that's easier for you to use them. Essentially, they enable you to capture any sort of information which you think will give you insights into your application. Logs can even help you figure out new metrics that you should be catching. If you find yourself logging something that is effectively a metric, then capture it as one.

In practice, you'll find yourself logging more than publishing new metrics. You should always add useful logging to your application, where you feel that it can help you understand the flow of execution and diagnose an issue faster. For instance, logging a stack trace for all unchecked RuntimeExceptions will give you an immediate place to look if your application doesn't guard against this!

There are a lot of loggers in Java, and there's no right one to use. The JDK comes with the java.util.logging (or JUL). This has its own log levels. Other extremely popular logging frameworks include Logback and Log4j2 (Note the two at the end).

Fortunately, most projects will use SLF4J, the Simple Log Facade for Java, a common API that lets you use any of the above frameworks, but with SLF4J's standard API. That is, you use its methods and classes in one standard way. It handles calling the methods of whatever framework you've already added to your project.

Rather than worrying about JUL's log levels and how they compare to Logback's, you only need to care about using SLF4J's interpretation of each, and their relative importance.

Let's set up our original Dragon Saddle Size Guesser application to use SLF4J's logging API in front of Logback.

First, we need to add the dependencies to the dependency section of our Gradle build file:

    implementation("org.slf4j:slf4j-api:1.7.26'")
    implementation("ch.qos.logback:logback-core:1.2.3")

This adds the current versions of SLF4J API and SLF4 JDK14. The first is the SLF4J API, and the second is SLF4J's integration with JUL, which we call its binding.

We can then add a log line to our DragonSaddleSizeEstimator by adding SLFJ's imports, creating an instance of logger, and using that logger to log.

package com.openclassrooms.debugging.service;


import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
...
@Service
public class DragonSaddleSizeEstimator {

    private static Logger logger = LoggerFactory.getLogger(DragonSaddleSizeEstimator.class);
    ...
    public Double estimateSaddleSizeInCentiMeters(int targetYear) throws Exception {
        logger.info("Calculating an estimate for {}", targetYear)
        double saddleSizeInCm = calculateSaddleSizeFromYear(targetYear);

        // Verify that we have a valid saddle size
        verifier.verify(saddleSizeInCm);

        return saddleSizeInCm;
    }

    ...
}

Let's break this down:

• Line 4: We import SLFJ's logger class, which we'll use to log.

• Line 5: We import SLFJ's LoggerFactory class, which we'll use to create our logger.

• Line 10: We create an instance of a logger by calling LoggerFactory's getLogger(Class clazz) method. Pass this the current class and it uses class and it's package to figure out what log levels  to apply.

• Line 13: Every time some code calls estimateSaddleSizeInCentiMeters(int targetYear), we log the expression "Calculating an estimate for  <the value of the target year>" at infolevel. The logging methods replace each " {} " with the respective argument passed to the logging method. Therefore, targetYear  is evaluated and substituting in.

2019-07-04 21:45:43.054  INFO 11968 --- [nio-9999-exec-2] c.o.d.service.DragonSaddleSizeEstimator  : Calculating an estimate for year 2019

Note how our logger precedes "Calculating an estimate for the year 2019" with:

• A time when this was logged: 2019-07-04 21:45:43.054

• The log level: INFO

• The operating system's process id: 11968

• Thread information: [nio-9999-exec-2]

• Class which logged this line: c.o.d.service.DragonSaddleSizeEstimator 

• The log message: Calculating an estimate for year 2019

We logged our message at INFO level as it doesn't go into too much detail and gives us a gist of what the application is doing. We did this by calling the info(message) method on our logger.

Let's see how they compare, in order of importance:

• Error:  logger.error(message) - Errors are the most important log entry. If you want to know about anything, it's log lines marked as errors. This is generally the least chatty level and is reserved for trouble.  💥

• Warn: logger.warn(message) -Those lines you've determined are warnings are the next most important. If you've asked your code to warn you about something, it should. This can be a little more chatty than errors, but if you warn too much, it will be like the boy who cried wolf; no one will pay attention! ⚠️

• Info: logger.info(message) - Log lines you've specified for informational purposes, or info, are the next down. You might find it interesting for your application to tell you what it's doing without going into much detail. You can provide some useful insights here, but avoid getting too chatty, or your info will turn into noise. At the very least, this might be a line to tell you that it's just processing some data. 

• Debug:logger.debug(message) - These are pretty chatty log lines that attempt to help you debug by debugging calls from method to method and reporting on the value of variables. If you have confidence in your app, these are usually only important when seeking useful diagnostic information. You'd want these to be switched off most of the time, as they are equivalent to the more useful chatty shrieks of print statements.

• Trace:logger.trace(message) - These are our most chatty logs. Use trace when you want to desperately shove print statements between each line of code and print just about every variable ever seen. This is the equivalent of standing in the library and vocalizing every thought that enters your head in an operatic style! 🎤 Unlike print statements, you can turn traces off and back on when you need them. This is a motormouth that goes on and on; so you'll mostly keep it hushed. Only add these to areas of code when necessary. For instance, a production incident where no one has a clue after hours of head hammering; such a situation might justify releasing a version of your code packed with trace logs.

Loggers make different volumes of noise. Depending on your need, you can modify the log levels at which your application reports. For example, you can crank up the volume and observe debug level log messages during a production investigation.

Once you've got lots of logging statements in your code, you can adjust which ones get reported by setting log levels for reporting. These can either be coarse-grained, for the entire application, or fine-grained for log lines by individual classes or specific packages.

Since SLF4J is not a logger itself, so much as a programming interface in front of other logging frameworks, you must use your chosen underlying logging framework's volume control, in the form of the appropriate configuration for your framework of choice.

As you saw in the previous chapter where we configured a logging level for the Spring Boot version of our DragonSaddleSizeApp, we can adjust log levels within a Spring Boot project simply by setting Java properties preceded by logging.level.

One of the default locations where Spring Boot looks for properties is in src/main/resources/application.properties. Let's have a look at the relevant bits of our file:

logging.level.root=ERROR
logging.level.org.springframework.web=INFO
logging.level.com.openclassrooms.debugging=TRACE

Let's work through this:

Line 1: The root logger represents our default across the application. This line will hush any logging across the application, except for calls to   Logger::error.

Line 2: This configures logging for any classes under the org.springframework.web package, allow through any calls to Logger::info,  Logger::warn, and  Logger::error.

Line 3: This configures logging for any classes under the com.openclassrooms.debugging package, such that our logger will log all calls to all the logging methods, including Logger::trace  and  Logger::debug.

Try it Out for Yourself!

Go back to our Dragon Saddle Size Guesser and checkout the branch  java-logging-api:

git checkout  java-logging-api

Adding logging statements to your code is sometimes called instrumenting your code. This is because, with each log line, you are adding a new instrument to observe what your code is doing, like bolting a barometer to the side of a method 🌡️.

Let's instrument the Spring version of our Dragon Saddle Size Guesser together:

Did you notice how we used different log lines at different levels to instrument our code with varying degrees of insight? At debug and trace level we reported in more detail and logged more information about the current value of variables to be able to see any changes, should we ever need to turn trace on.

We also set the properties of a root logger, to set a global minimal log level for our application.

Now that our code has been instrumented, I think it's time to see how it behaves as we crank the volume up and down!

Let's control our log levels and see how it affects our logs:

As you saw, it was easy to turn our logging up to gain deeper insights into our code. We could even target our volume controls at a more specific set of loggers. For instance, by setting logging.level.com.openclassrooms.debugging.service=TRACE we were able to force classes under that package to log at trace level!

As we ramped up our logging to trace, we gradually gained deeper insights into what our application was doing.

You could leave your logging at trace, but there are a few consequences. First, it's no better than print statements. Second, you often want to save your logs so you can see them once your programs have finished. This means they eventually get written to disk. Logging frameworks use appenders to send logs to disks or to other systems, which may, in turn, write to disk. Writing to disk is slow, and although there are ways around it, you don't want logging to become the reason your application slows down. Most importantly, the more unnecessary noise your application makes, the harder it becomes to spot real issues whimpering as occasional log lines among all that noise!

Changing Log Levels Without Restarting Your Application

Let's reconsider the DragonSaddleSize web application from the last chapter. Imagine that you had thousands of users visiting your application every minute - all them dragon riders - and you wanted to get your application to tell you what it was doing. You got it! Logging!

But what do you do if you suddenly need to start logging at the error level when your application was started at the info level? Typically, getting those lines to print out when you need them would require having to rebuild our application and restart it. This gets harder if it's already deployed on a production environment, as you'd need to follow your release process.

Let's look at the code below. The  DragonSaddleSizeController  class executes the  Double handleSaddleSizeRequest(Integer targetYear)  method whenever your web browser requests a new saddle size estimate. This method is all set up to do some reporting. Let's have a look at it:

package com.openclassrooms.debugging.controller;

public class DragonSaddleSizeController {
    // Setup a logger   
    private Logger logger = LoggerFactory.getLogger(DragonSaddleSizeController.class);
    
    ...
    
    /**
     * Called by methods which respond to web requests
     **/
    private Double handleSaddleSizeRequest(Integer targetYear) throws Exception {
        // Calcualte the estimate
        Double saddleSizeEstimate = dragonSaddleSizeEstimator.estimateSaddleSizeInCentiMeters(targetYear);
        String response = saddleSizeReporter.report(targetYear, saddleSizeEstimate);
        
        // log it
        logger.info("Calculated a saddle size:" + response);

        return saddleSizeEstimate;
    }
}

What's going on here?

Line 5: We set up a special object called a logger, which allows us to create a continuously updated report, or log, on what our application is doing.

Line 18: We call logger.info() and pass it a line of text to report into our logs. This method will be called by all the methods in our code which receive a request to calculate an estimate.

That means that whenever you reload  your browser, you should see a new line in your log, which shows the message "Calculated a saddle size."

Unfortunately, the application has a properties file with settings that prevent this log line from being displayed. Our file under  src/main/resources/application.properties  contains the setting:

logging.level.com.openclassrooms.debugging=ERROR

For our application to log, we would need to change that value from ERROR to  INFO to match the  .info()  of our Line 18. 

However, changes to our files could require us to modify it, rebuild our application, and then restart it.

If you were troubleshooting an issue in production, imagine how much extra work that would be if you had to also re-test it and release it into a production environment!

Fortunately, you can use JConsole (or another JMX client) to change the log level while the application is running. As you'll see, one of Spring project's MBeans provides an operation you can perform to change the log level. This is useful when debugging an issue in production, as it lets you start collecting more detailed information about what your application is doing.

Let me show you how:

As you saw, we could target a piece of configuration from our application and change it. In this case, we changed the log level without restarting our application. This can be handy if you’re investigating an issue in production and need to observe something as it is happening, to better understand it.

By all means, please do. To reproduce a production issue, you would probably want to understand how to set up a similar scenario. Using JConsole can help.

It also lets you observe a harder-to-reproduce issue, which only happens in production.

Perhaps you couldn’t manage to recreate this issue locally, as we did in Part 2. Tracking down the cause of faults and failures is as close as software engineers get to being detectives. 🕵️‍♀️ Logs and JMX are just other tools in your sleuthing toolbox.

Things will always go wrong, and the more ways you have to inspect them, the greater your chances of putting together all the pieces and finding the culprit!  

As you saw, setting the property informed us that this is an old version of the code, and we should upgrade. In a more complex situation, you might have to dig deeper and play at being Sherlock again, using the clues in your application, which only appear when you set the log level to debug.

Let's Recap!

• The output of your program should not contain technical debugging noise which has little meaning to those responsible for running your program.

• A logging framework lets you create a continuous report, or log, into which your classes can print.

• Java has several logging frameworks, but SLF4J provides a single API to log to all the major frameworks. Using this makes it easy to change to newer or more powerful logging frameworks without changing your code.

• Logging frameworks use log levels to highlight and filter logging events by their importance. SLF4J's log levels, in order of importance, are error, warn, info, debug, and trace.  

• To reduce noise from your application and ensure that real issues can always come to your attention, try to use conservative log levels like error and warn. 

Going Further With Logging

If you have enjoyed learning about logging, you might want to check out the power of structured log lines. 

Logging gives you the freedom to log arbitrary lines as text; however, another powerful technique, canonical log lines, involves logging lines that have key/values pairs of details collected across your processing steps, for example:start_time=12:14:59.01 end_time=12:14:59.02 rows_processed=200.  Doing so makes it easier to find key information when you're piecing together the evidence around your application's behavior. When combined with log aggregation tools like Elastic Stack or Splunk, it then becomes easy to visualize those well-structured log lines. I used to do this for requests to key services at the BBC!