Debugging techniques and logging

Debugging techniques are the ways to learn why a program does what it does. The first step is always to reproduce the failure. Then either watch it happen with a debugger, which pauses a running JVM at breakpoints, or read what the program recorded about itself in its logs. A breakpoint can stop on a line, but also only when a condition holds, when an exception is thrown or when a field changes. Logging records events while the program runs, at levels from TRACE to ERROR, so that someone can understand a failure where no debugger can be attached, such as in production. Java has a logging API of its own, System.Logger, which writes through java.util.logging unless a library supplies another backend. Use the debugger when you can reproduce a bug, and logs for everything you cannot. A log never contains passwords, tokens or personal data.

This lesson builds on the first debugging lesson, which set line breakpoints and stepped through code in an IDE and in jdb, and runs everything on Eclipse Temurin 25.0.4.1.

A debugger or logs

The two meet in the middle. A good log line, added while debugging, keeps answering the same question after the bug is fixed. Both debugging techniques and logging work best with a precise question, such as “which order made the total negative?”, rather than “what is wrong?”.

Breakpoints beyond the line, by name

• A conditional breakpoint carries a condition, such as amount < 0, and pauses only on the passes where it holds, so a loop of 10,000 rounds shows you the one that matters.
• An exception breakpoint stops where an exception is thrown, before any catch or stack unwinding hides where it came from; jdb calls it catch.
• A watchpoint stops when a field is read or changed, which finds the line that changed it; jdb calls it watch.
• A logpoint in an IDE prints a message when the line runs and does not stop at all.
• Remote debugging attaches a debugger to a JVM started with the JDWP agent, -agentlib:jdwp=…, for example on a test server.
• A thread dump, from jcmd <pid> Thread.print, shows every thread’s stack at one moment without stopping the program.

Here is a bug hunt with a conditional breakpoint, step by step. A report of 10,000 orders shows a total that is 54,921 paise lower than it should be. A line breakpoint on total += amount would stop 10,000 times. Ask what a wrong total needs: an amount that cannot be right. So set the breakpoint’s condition to amount < 0, run, and the program stops once, with i telling you which order it was. From there, step back to where amount was computed, and the cause is on the screen. If no condition comes to mind, an exception breakpoint or a watchpoint on the suspicious field usually narrows the search the same way.

Logging with System.Logger and java.util.logging

package com.example.payments;

import java.lang.System.Logger;
import java.lang.System.Logger.Level;

/// Settles one day of a shop's UPI payments and logs what it does, at every level that System.Logger has.
public class Settlement {
    private static final Logger LOG = System.getLogger(Settlement.class.getName());

    public static void main(String[] args) {
        long[] payments = {49_900, 125_000, 9_900, 310_000};
        long total = 0;
        for (long paise : payments) {
            LOG.log(Level.TRACE, () -> "adding a payment of " + paise + " paise");
            total += paise;
        }
        LOG.log(Level.DEBUG, "total of {0} payments: {1} paise", payments.length, total);
        LOG.log(Level.INFO, "settled {0} paise for shop {1}", total, "S-1042");
        LOG.log(Level.WARNING, "the bank answered after {0} ms; the limit is {1} ms", 2_400, 2_000);
        LOG.log(Level.ERROR, "refund of payment 3 failed", new IllegalStateException("account closed"));
    }
}

# java.util.logging settings, read when the JVM starts with -Djava.util.logging.config.file=logging.properties.
# One handler: the console, which java.util.logging writes to standard error. It passes on every record that the
# loggers let through.
handlers = java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level = ALL
# Level, logger name, message and the exception, if any. No date or time: a platform that collects the console of
# a service adds its own.
java.util.logging.SimpleFormatter.format = %4$-7s %3$s: %5$s%6$s%n
# Every logger: INFO and above.
.level = INFO

# logging.properties, plus one line: the loggers of the payment code also let FINE through, which is System.Logger's
# DEBUG. All other loggers stay at INFO.
handlers = java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level = ALL
java.util.logging.SimpleFormatter.format = %4$-7s %3$s: %5$s%6$s%n
.level = INFO
com.example.payments.level = FINE

from session import run

# One day's settlement logged through System.Logger and java.util.logging: first with every logger at INFO, then
# with the payment code's loggers at FINE, which is System.Logger's DEBUG.
run(
    """
javac -d out payments/src/com/example/payments/Settlement.java
java -Djava.util.logging.config.file=payments/logging.properties -cp out com.example.payments.Settlement
java -Djava.util.logging.config.file=payments/logging-debug.properties -cp out com.example.payments.Settlement
"""
)

# openjdk version "25.0.4.1" LTS
$ javac -d out payments/src/com/example/payments/Settlement.java
$ java -Djava.util.logging.config.file=payments/logging.properties -cp out com.example.payments.Settlement
INFO    com.example.payments.Settlement: settled 494,800 paise for shop S-1042
WARNING com.example.payments.Settlement: the bank answered after 2,400 ms; the limit is 2,000 ms
SEVERE  com.example.payments.Settlement: refund of payment 3 failed
java.lang.IllegalStateException: account closed
	at com.example.payments.Settlement.main(Settlement.java:20)

$ java -Djava.util.logging.config.file=payments/logging-debug.properties -cp out com.example.payments.Settlement
FINE    com.example.payments.Settlement: total of 4 payments: 494,800 paise
INFO    com.example.payments.Settlement: settled 494,800 paise for shop S-1042
WARNING com.example.payments.Settlement: the bank answered after 2,400 ms; the limit is 2,000 ms
SEVERE  com.example.payments.Settlement: refund of payment 3 failed
java.lang.IllegalStateException: account closed
	at com.example.payments.Settlement.main(Settlement.java:20)

System.getLogger(name) gave the class a logger named after it, and the JDK’s default System.LoggerFinder handed its records to java.util.logging, which read logging.properties at start-up. With every logger at INFO, the first run printed the INFO, WARNING and ERROR lines, the last one with its exception and stack trace. The second run let the loggers of com.example.payments through at FINE and printed the DEBUG line as well. Neither run printed the TRACE lines, and their message suppliers never ran. The {0} placeholders are filled in by java.text.MessageFormat, which wrote 494,800 with the grouping of the run’s locale.

The levels printed are the names of java.util.logging, because that is the backend:

The mapping is the one in the System.Logger.Level documentation. Logging set up like this costs one line per class and a properties file per environment. Two more rules keep such logs safe to keep and to share: secrets and personal data are left out or masked, and values that users typed are escaped, so that a line break in a name cannot forge a second record.

Check yourself

Breakpoints beyond the line, measured: conditions, exceptions, watchpoints, attaching Pro: opens with a Pro, Premium or Ultimate pass

Logging that costs nothing when it is off, and levels a team can rely on Pro: opens with a Pro, Premium or Ultimate pass

Logs without secrets or forged lines: a leak found by a test, a forgery reproduced Pro: opens with a Pro, Premium or Ultimate pass

Key takeaways

• Reproduce first, then choose: a debugger for what you can reproduce, logs for what happens where you cannot look.
• Conditional, exception and field breakpoints stop where the bug is instead of on every pass.
• System.Logger writes through java.util.logging by default; its DEBUG is FINE and its ERROR is SEVERE.
• Levels and handlers are set in logging.properties, and secrets and personal data never reach a log.