Debugging: Errors, Stack Traces, the Debugger and Logging

Every programmer spends a large share of their time looking at code that does not do what they expected. The difference between a beginner and an experienced developer is rarely that the experienced one writes fewer bugs. It is that they find bugs systematically: they gather evidence, narrow the search, and fix the cause instead of the symptom.

The earlier articles showed you error messages and exceptions. This one gives you a method, and the tools to follow it.

• A debugging method that works on any bug.
• How to read compiler errors and stack traces, including Caused by chains.
• How to use a debugger effectively.
• How to log well, and the difference between print debugging and logging.
• Which tools to use for hangs, memory problems and slowness.

When a program misbehaves, resist the urge to change things. Change one thing at a time, and always know why. A reliable process:

1. Reproduce it. If you cannot make the bug happen on demand, you cannot know whether you fixed it. Write down the exact inputs and steps.
2. Shrink it. Remove everything that is not needed to trigger the bug, until the smallest possible example remains. Often the cause becomes visible during the shrinking.
3. Read the evidence. Read the error message and stack trace completely. Note what you expected and what actually happened.
4. Form a hypothesis. "The list is empty when process is called, because the loader failed silently." A good hypothesis can be proven wrong.
5. Test the hypothesis with the cheapest experiment: a log line, a breakpoint, a small test, an assertion. Observe, do not assume.
6. Fix the cause, not the symptom. If you wrap a NullPointerException in a try/catch without asking why the value was null, you have hidden the bug.
7. Verify that the original problem is gone and that nothing else broke.
8. Prevent a return. Add a test that fails without your fix and passes with it (article 25).

Some techniques that help:

• Binary search the problem. If a result is wrong at the end of ten steps, check the state after step five. Correct there? Then the bug is in the second half. Repeat.
• Explain it aloud ("rubber duck debugging"). Putting the problem into words often reveals the assumption that is wrong.
• Question your assumptions. What are you sure is true? Verify it. Many long debugging sessions end with "the input was not what I thought".
• Check what changed. If it worked yesterday, version control (article 24) can show the differences, and git bisect can find the commit that introduced the bug.

Compiler messages are precise, and beginners often ignore the first line, which is the useful one. The commonest messages:

Fix errors from the top: one early mistake can cause a cascade of later messages that disappear when it is fixed.

When an exception is not handled, Java prints a stack trace: the call stack at the moment the exception was created (article 18). Here is a program with several layers and a wrapped cause, so you can see every part.

// File: Main.javaimport java.io.IOException;public class Main {    static class ConfigException extends RuntimeException {        ConfigException(String message, Throwable cause) {            super(message, cause);        }    }    static String readFile(String name) throws IOException {        throw new IOException("cannot read " + name);          // the root cause    }    static String loadConfig(String name) {        try {            return readFile(name);        } catch (IOException e) {            throw new ConfigException("configuration could not be loaded", e);        }    }    static void startUp() {        String config = loadConfig("app.properties");        System.out.println(config);    }    public static void main(String[] args) {        try {            startUp();        } catch (ConfigException e) {            e.printStackTrace(System.out);        }    }}

Main$ConfigException: configuration could not be loaded	at Main.loadConfig(Main.java:19)	at Main.startUp(Main.java:24)	at Main.main(Main.java:30)Caused by: java.io.IOException: cannot read app.properties	at Main.readFile(Main.java:12)	at Main.loadConfig(Main.java:17)	... 2 more

How to read it, from the top:

1. The first line is the headline: the exception class and its message (Main$ConfigException: configuration could not be loaded). Read this first, every time.
2. The lines starting with at are the call stack, most recent call first. Each line is class.method(file:line). The top frame is where the exception was created. The ones below are the callers, going back to main. Start from the top and find the first frame that is your own code, because frames from libraries are usually not where the bug is.
3. Caused by: introduces the underlying exception that was passed as the cause when this one was wrapped (article 10). The root cause is the last Caused by in the chain, and it is often the most informative: here, IOException: cannot read app.properties. This is why you should always pass the cause when you wrap an exception.
4. ... 2 more means the remaining frames are identical to the ones already shown above for the enclosing exception, so they are not repeated.

Common exceptions, and what they usually mean:

The hardest bugs produce no error at all. Here is a binary search with a subtle mistake. It does not crash. It loops. We cannot run an endless loop in a demonstration, so the version below includes a step counter as a debugging guard, and prints the state of each step: the oldest and simplest debugging tool, print debugging.

// File: Main.javapublic class Main {    static int buggySearch(int[] sorted, int target, int maxSteps) {        int low = 0;        int high = sorted.length - 1;        int steps = 0;        while (low <= high && steps < maxSteps) {            int mid = (low + high) / 2;            System.out.println("step " + steps + ": low=" + low + " high=" + high + " mid=" + mid                    + " value=" + sorted[mid]);            if (sorted[mid] == target) {                return mid;            }            if (sorted[mid] < target) {                low = mid;                 // the suspected bug            } else {                high = mid - 1;            }            steps++;        }        return -1;    }    static int fixedSearch(int[] sorted, int target) {        int low = 0;        int high = sorted.length - 1;        while (low <= high) {            int mid = (low + high) >>> 1;            if (sorted[mid] == target) {                return mid;            }            if (sorted[mid] < target) {                low = mid + 1;            } else {                high = mid - 1;            }        }        return -1;    }    public static void main(String[] args) {        int[] data = {2, 4, 6, 8, 10};        System.out.println("result: " + buggySearch(data, 10, 6));        System.out.println("fixed: " + fixedSearch(data, 10) + " " + fixedSearch(data, 5));    }}

step 0: low=0 high=4 mid=2 value=6step 1: low=2 high=4 mid=3 value=8step 2: low=3 high=4 mid=3 value=8step 3: low=3 high=4 mid=3 value=8step 4: low=3 high=4 mid=3 value=8step 5: low=3 high=4 mid=3 value=8result: -1fixed: 4 -1

The printed states tell the story in seconds. From step 2 onward, low is 3, high is 4, mid is 3, and the values never change: the search is stuck. When the value at mid is too small, the code sets low = mid, but mid was already examined and rejected, so the range does not shrink. The fix is low = mid + 1. This is the method in action: reproduce (the input {2,4,6,8,10} and target 10), shrink, observe, form the hypothesis ("the range stops shrinking"), and then fix the cause. After the fix, add a test with the boundary cases: first element, last element, absent values and an empty array.

(In fixedSearch, (low + high) >>> 1 avoids a rarely met overflow bug in (low + high) / 2 when the sum of two large int values exceeds the int range, which is the overflow behaviour from article 2.)

Print statements work, and they have costs: you must edit and recompile for each question, remove them later, and you only see what you decided to print in advance. A debugger lets you pause a running program and look at everything. Every Java IDE (IntelliJ IDEA, Eclipse, VS Code with the Java extensions) has one, and the JDK ships a command-line debugger called jdb.

For the binary search above, a session in an IDE would go like this:

1. Put a breakpoint on the line int mid = ... inside the loop.
2. Start the program in debug mode. It stops at the first iteration. Look at the variables view: low = 0, high = 4.
3. Resume repeatedly, and watch low, high and mid at each stop. Your hypothesis says the range stops shrinking, and you can see low stuck at 3.
4. Add a watch for sorted[mid] < target, and see it is true each time while low does not change.
5. Step over the if and observe the line low = mid setting low to the value it already had.

You have seen the cause instead of guessing it. A few habits make a debugger far more effective:

• Form a question before you step: "I expect total to be 15 here." Then check it. Stepping aimlessly wastes time.
• Use the call stack view when you stop in a method with a surprising argument: click the caller's frame to see where the bad value came from.
• Do not step through library code. Use step over for framework and library calls, and step into only your own code.
• Debugging concurrent code changes its timing, because pausing a thread changes the interleaving. A bug that vanishes under the debugger is a hint that the problem is a race.

Remote debugging lets an IDE attach to a JVM running elsewhere (a container, a server) when started with the right JVM option, and is invaluable and dangerous: never leave it enabled on a production system exposed to a network.

Print debugging is for you, now. Logging is for whoever runs your program later, possibly at three in the morning, in a place where you cannot attach a debugger. A logging framework is far better than System.out.println because it adds:

• Levels, so you can switch detail on and off without changing code.
• Context: timestamp, thread, logger name.
• Destinations: console, files, and log collection systems.
• Configuration at runtime, with no recompilation.
• Performance: messages below the active level are cheap to skip.

The Java built-in logging API (java.util.logging) defines seven levels: SEVERE, WARNING, INFO, CONFIG, FINE, FINER and FINEST, with INFO as the default threshold. The libraries most Java applications use (SLF4J with Logback, which Spring Boot's starters use by default, and Log4j 2) name five that you will see in practice, and Spring Boot's documentation lists them: ERROR, WARN, INFO (the default), DEBUG and TRACE.

The important choice is what to leave at INFO and above, because that is what runs in production. If everything is INFO, the log is noise. If a real failure is only DEBUG, nobody sees it.

// File: Main.javaimport java.util.logging.Formatter;import java.util.logging.Handler;import java.util.logging.Level;import java.util.logging.LogRecord;import java.util.logging.Logger;import java.util.logging.StreamHandler;public class Main {    private static final Logger LOG = Logger.getLogger("demo.orders");    // one logger per class, by name    static Handler consoleHandler() {        StreamHandler handler = new StreamHandler(System.out, new Formatter() {            @Override            public String format(LogRecord record) {                String line = record.getLevel() + ": " + formatMessage(record);                if (record.getThrown() != null) {                    line += " [" + record.getThrown().getClass().getSimpleName() + ": " + record.getThrown().getMessage() + "]";                }                return line + System.lineSeparator();            }        }) {            @Override            public synchronized void publish(LogRecord record) {                super.publish(record);                flush();            }        };        handler.setLevel(Level.ALL);        return handler;    }    static void process(int orderId) {        LOG.fine("entering process for order " + orderId);                // detail: hidden at INFO        LOG.log(Level.INFO, "processing order {0}", orderId);        try {            if (orderId % 2 == 1) {                throw new IllegalStateException("stock unavailable");            }            LOG.info("order " + orderId + " completed");        } catch (IllegalStateException e) {            LOG.log(Level.SEVERE, "order " + orderId + " failed", e);      // the exception is passed, once        }    }    public static void main(String[] args) {        LOG.setUseParentHandlers(false);        LOG.addHandler(consoleHandler());        LOG.setLevel(Level.INFO);        System.out.println("-- level INFO --");        process(1);        process(2);        LOG.setLevel(Level.FINE);                                          // change detail without touching the code        System.out.println("-- level FINE --");        process(2);    }}

-- level INFO --INFO: processing order 1SEVERE: order 1 failed [IllegalStateException: stock unavailable]INFO: processing order 2INFO: order 2 completed-- level FINE --FINE: entering process for order 2INFO: processing order 2INFO: order 2 completed

At level INFO, the fine message was suppressed. After raising the level to FINE, it appears, with no change to the processing code. That is the point of levels. (The standard library's logging API is used here so that the demo needs no extra libraries. Most projects use SLF4J with Logback, as Spring Boot does by default, and its documentation explains that with the starters Logback is used, with routing so that libraries using other logging APIs also work. Spring Boot sets levels with properties such as logging.level.root=warn or logging.level.org.hibernate=error. We will use that in the Spring articles.)

With SLF4J the code looks like this (a fragment, because it needs a dependency that arrives with Maven in the next article):

private static final Logger log = LoggerFactory.getLogger(OrderService.class);log.info("Order {} created for user {}", orderId, userId);     // {} placeholders: cheap if INFO is offlog.error("Could not save order {}", orderId, exception);       // exception LAST: the stack trace is logged

Do:

• Use one logger per class, named after it, so you can turn detail on for one part of the system.
• Include context: identifiers and values that let you find the story (orderId, userId), not just "error occurred".
• Use placeholders ({}) instead of string concatenation so the work is skipped when the level is disabled.
• Log an exception once, at the place where you handle it, with the exception object (not just e.getMessage()) so the stack trace and causes are recorded.
• Make logs searchable. Consistent wording and key=value pairs, or structured (JSON) logging with a correlation id that follows a request across components, make large systems debuggable.
• Keep INFO quiet and meaningful.

Do not:

• Log secrets or personal data: passwords, tokens, card numbers, full request bodies with personal details. Logs are copied, stored for months and read by many people. Debug and trace levels in production make this risk bigger.
• Log and rethrow at every layer (the same exception then appears five times).
• Log inside tight loops at a level that is enabled.
• Swallow exceptions silently, or log only the message of an exception and lose the trace.
• Use System.out.println or e.printStackTrace() in application code. They bypass levels and configuration.

Some problems cannot be seen in one stack trace. The JDK includes diagnostic tools for them. Oracle's troubleshooting documentation recommends jcmd, Java Flight Recorder (JFR) and JDK Mission Control as the main tools.

The first step is always to identify the process with jps, and the second is to collect evidence before restarting the application, because a restart erases the evidence. Take two or three thread dumps a few seconds apart for a hang, since one snapshot may not show the pattern.

Java has an assert statement for checking assumptions that should always be true. It is disabled by default and enabled with the -ea flag, so it costs nothing in production. Use it for internal invariants (conditions that indicate a bug in your own code), never for validating user input or arguments of public methods, because the check disappears when assertions are off.

// File: Main.java// JVM: -eapublic class Main {    static int percentage(int part, int whole) {        assert whole > 0 : "whole must be positive but was " + whole;        return part * 100 / whole;    }    public static void main(String[] args) {        System.out.println(percentage(25, 200));        try {            percentage(1, 0);        } catch (AssertionError e) {            System.out.println("assertion failed: " + e.getMessage());        }    }}

12assertion failed: whole must be positive but was 0

The second line of the program says that it was run with java -ea Main. Without -ea, percentage(1, 0) would divide by zero instead and throw an ArithmeticException, which is a good reminder that the assertion is a debugging aid and not an input check.

• Changing code before understanding the problem.
• Ignoring the first line of an error message, or reading only the bottom of a stack trace.
• Fixing the symptom (catching and hiding the exception) rather than the cause.
• Making several changes at once, so you do not know which helped.
• Debugging without a reproduction.
• Printing with System.out in production code instead of logging.
• Logging secrets, or logging the same error at every layer.
• Restarting a hung service before collecting a thread dump.
• Using assert for input validation.
• Not writing a regression test after the fix.

• Next: Maven: What It Does and How to Use It teaches how builds, dependencies and logging libraries are managed.
• For turning a found bug into a safety net: Testing with JUnit and Mockito.
• For production logging and diagnostics in Spring Boot: Production Practices: Configuration, Logging, Docker and Health Checks.