Logging & Debugging

System.out.println is fine while you learn, but it falls apart on a real server. You cannot turn it off, it has no timestamps, it does not say which class printed a line, and at 3 a.m., when a payment fails for one customer in Lucknow, you cannot find that customer's lines among millions of others. Professional Java code uses a logging framework instead.

In this lesson you will log with SLF4J (the standard logging API) and Logback (the library that actually writes the logs, and the default in Spring Boot), choose the right log level, log exceptions properly, configure output with logback.xml, and tag every line of a request with an ID. Then you will learn the debugging skills that go with logs: breakpoints in the IDE and thread dumps for a program that hangs.

SLF4J and Logback

SLF4J (Simple Logging Facade for Java) is a set of interfaces. Your code talks only to SLF4J, and a separate backend such as Logback or Log4j 2 does the writing. You can switch the backend without changing a line of code. Add two dependencies (versions at the time of writing):

<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-api</artifactId>
  <version>2.0.20</version>
</dependency>
<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
  <version>1.6.6</version>
</dependency>

Each class gets its own Logger, usually a private static final field named log:

package in.shop;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class OrderService {
    private static final Logger log = LoggerFactory.getLogger(OrderService.class);

    public void place(String orderId, String city, int amount) {
        log.debug("Validating order {} for {}", orderId, city);
        if (amount <= 0) {
            log.warn("Rejected order {}: amount {} is not positive", orderId, amount);
            return;
        }
        try {
            int perItem = amount / countItems(orderId);
            log.info("Order {} placed: Rs {} ({} per item)", orderId, amount, perItem);
        } catch (ArithmeticException e) {
            log.error("Could not price order {}", orderId, e);
        }
    }

    private int countItems(String orderId) {
        return orderId.endsWith("0") ? 0 : 2;          // pretend lookup with a bug
    }

    public static void main(String[] args) {
        OrderService service = new OrderService();
        service.place("A-101", "Pune", 1298);
        service.place("A-102", "Kochi", -5);
        service.place("A-110", "Jaipur", 750);
    }
}

With no configuration file, Logback prints everything at DEBUG and above to the console (your timestamps will differ):

00:55:53.305 [main] DEBUG in.shop.OrderService -- Validating order A-101 for Pune
00:55:53.323 [main] INFO in.shop.OrderService -- Order A-101 placed: Rs 1298 (649 per item)
00:55:53.323 [main] DEBUG in.shop.OrderService -- Validating order A-102 for Kochi
00:55:53.324 [main] WARN in.shop.OrderService -- Rejected order A-102: amount -5 is not positive
00:55:53.324 [main] DEBUG in.shop.OrderService -- Validating order A-110 for Jaipur
00:55:53.324 [main] ERROR in.shop.OrderService -- Could not price order A-110
java.lang.ArithmeticException: / by zero
	at in.shop.OrderService.place(OrderService.java:16)
	at in.shop.OrderService.main(OrderService.java:31)

Every line now carries the time, thread, level and class for free. Three habits to notice:

• Placeholders, not +. log.debug("Validating order {} for {}", orderId, city) fills each {} in order. If DEBUG is switched off, the message is never even built, so placeholders cost almost nothing.
• The exception goes last, without a {}. In log.error("Could not price order {}", orderId, e), SLF4J sees that the final argument is a Throwable and prints its full stack trace. Writing log.error("Failed: " + e) would print only the message and lose the trace.
• One logger per class, created from the class itself, so you can tell exactly where a line came from and configure levels per package.

Choosing the log level

Production servers usually run at INFO. When something goes wrong, a team can switch one package to DEBUG without redeploying. Never log passwords, OTPs, full card numbers, Aadhaar numbers or access tokens: logs are copied to many systems and read by many people, and India's DPDP Act 2023 makes careless handling of personal data a legal risk as well.

Configuring Logback

Put a file called logback.xml in src/main/resources. It defines appenders (where logs go), encoders with a pattern (what a line looks like) and loggers (which level each package uses).

<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss} %-5level [%X{requestId}] %logger{20} - %msg %kvp%n</pattern>
    </encoder>
  </appender>

  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>logs/shop.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>logs/shop.%d{yyyy-MM-dd}.log</fileNamePattern>
      <maxHistory>30</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] [%X{requestId}] %logger - %msg%n</pattern>
    </encoder>
  </appender>

  <logger name="in.shop" level="DEBUG"/>

  <root level="INFO">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="FILE"/>
  </root>
</configuration>

The root logger applies to everything at INFO, so chatty libraries stay quiet, while our own package in.shop shows DEBUG. The rolling file appender starts a new file every day and keeps 30 days, so the disk never fills up. In the pattern, %d is the date, %-5level the level padded to five characters, %logger{20} the logger name shortened to about 20 characters, %msg the message, %X{requestId} a value from the MDC (next section), %kvp key-value pairs and %n a line break.

Tracing one request with MDC

On a server, hundreds of requests run at the same time and their log lines interleave. The MDC (Mapped Diagnostic Context) stores values for the current thread, and the pattern adds them to every line. SLF4J 2 also has a fluent API that attaches structured key-value pairs, which log search tools can filter on.

package in.shop;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class Checkout {
    private static final Logger log = LoggerFactory.getLogger(Checkout.class);

    static void handleRequest(String requestId, String customer, int amount) {
        MDC.put("requestId", requestId);            // added to every log line of this thread
        try {
            log.info("Checkout started for {}", customer);
            log.atInfo()
               .setMessage("Payment captured")
               .addKeyValue("amount", amount)
               .addKeyValue("gateway", "upi")
               .log();
            if (log.isDebugEnabled()) {
                log.debug("Cart snapshot: {}", expensiveSnapshot(customer));
            }
        } finally {
            MDC.remove("requestId");                 // threads are reused: always clean up
        }
    }

    static String expensiveSnapshot(String customer) {
        return customer + " -> [atta 10kg, ghee 1L]";
    }

    public static void main(String[] args) {
        handleRequest("req-7f3a", "Meera", 1299);
        handleRequest("req-91bc", "Kabir", 499);
    }
}

00:57:03 INFO  [req-7f3a] in.shop.Checkout - Checkout started for Meera
00:57:03 INFO  [req-7f3a] in.shop.Checkout - Payment captured amount="1299" gateway="upi"
00:57:03 DEBUG [req-7f3a] in.shop.Checkout - Cart snapshot: Meera -> [atta 10kg, ghee 1L]
00:57:03 INFO  [req-91bc] in.shop.Checkout - Checkout started for Kabir
00:57:03 INFO  [req-91bc] in.shop.Checkout - Payment captured amount="499" gateway="upi"
00:57:03 DEBUG [req-91bc] in.shop.Checkout - Cart snapshot: Kabir -> [atta 10kg, ghee 1L]

Searching the logs for req-7f3a now shows everything that happened in Meera's request and nothing else. Web frameworks usually put the request ID into the MDC for you. The isDebugEnabled() check avoids calling an expensive method when its result would be thrown away; for cheap arguments, placeholders alone are enough.

Debugging in the IDE

Logs tell you what happened in production. On your own machine, a debugger lets you pause the program and look inside. Every Java IDE (IntelliJ IDEA, Eclipse, VS Code with the Java extensions) works the same way:

1. Click in the margin next to a line to set a breakpoint, then start the program with Debug instead of Run.
2. When execution reaches the line, it pauses. The Variables panel shows every local variable and field.
3. Step over runs the current line; step into enters the method called on that line; step out finishes the current method; resume runs to the next breakpoint.
4. Right-click a breakpoint to make it conditional, such as orderId.equals("A-110"), so it pauses only for the interesting case.
5. Use evaluate expression to run code such as countItems(orderId) while paused.

For the bug above, a breakpoint on the amount / countItems(orderId) line with the condition orderId.endsWith("0") shows immediately that countItems returns 0. To debug an application running on a server, start it with -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:5005 and attach the IDE's remote debugger to port 5005; only do this on a test server, never open that port to the internet.

When a program hangs: thread dumps

A program that freezes without an error is often deadlocked: two threads each hold a lock the other needs. Here two transfers lock the wallets in opposite order (the latch makes the deadlock happen every time):

import java.util.concurrent.CountDownLatch;

public class Deadlock {
    static final Object walletA = new Object();
    static final Object walletB = new Object();
    static final CountDownLatch bothLocked = new CountDownLatch(2);

    static void transfer(String name, Object first, Object second) {
        synchronized (first) {
            bothLocked.countDown();
            try {
                bothLocked.await();                  // wait until the other thread holds its lock
            } catch (InterruptedException e) {
                Thread.currentThread().interrupt();
            }
            synchronized (second) {
                System.out.println(name + " finished");
            }
        }
    }

    public static void main(String[] args) {
        new Thread(() -> transfer("Meera to Kabir", walletA, walletB), "transfer-1").start();
        new Thread(() -> transfer("Kabir to Meera", walletB, walletA), "transfer-2").start();
    }
}

The program prints nothing and never ends. In a second terminal, jcmd -l lists Java processes; jcmd <pid> Thread.print prints every thread's stack, and the JVM detects the deadlock for you (shortened):

Found one Java-level deadlock:
=============================
"transfer-1":
  waiting to lock monitor 0x000002956b07ed10 (object 0x0000000712dda648, a java.lang.Object),
  which is held by "transfer-2"

"transfer-2":
  waiting to lock monitor 0x000002956b07eab0 (object 0x0000000712dda638, a java.lang.Object),
  which is held by "transfer-1"

Java stack information for the threads listed above:
===================================================
"transfer-1":
	at Deadlock.transfer(Deadlock.java:17)
	- waiting to lock <0x0000000712dda648> (a java.lang.Object)
	- locked <0x0000000712dda638> (a java.lang.Object)

The fix is to always take locks in the same order (for example, the wallet with the smaller ID first). Naming your threads, as here, makes dumps far easier to read. jstack <pid> prints the same information in older guides.

Common mistakes

• Building messages with +. Use {} placeholders.
• log.error(e.getMessage()). The stack trace is lost; pass e as the last argument.
• Logging and rethrowing at every layer. The same error appears five times; log it once, where it is handled.
• Logging secrets or personal data. Mask or leave them out.
• Forgetting to clear the MDC. Pooled threads carry the old request ID into the next request.
• Debugging with print statements left in the code. Use the debugger, and delete temporary output before committing.

Key points

• Code logs through SLF4J; Logback (Spring Boot's default) or Log4j 2 writes the output.
• Use one private static final Logger per class, {} placeholders, and the exception as the last argument.
• Pick levels deliberately: ERROR, WARN, INFO, DEBUG, TRACE; production usually runs at INFO.
• logback.xml sets appenders, patterns, rolling files and per-package levels.
• MDC tags all lines of a request; the fluent API adds key-value pairs.
• Breakpoints, stepping and conditional breakpoints find bugs locally; jcmd <pid> Thread.print diagnoses hangs and deadlocks.

package in.college;

import java.util.List;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class MarksImporter {
    private static final Logger log = LoggerFactory.getLogger(MarksImporter.class);

    static int importLines(List<String> lines) {
        int saved = 0;
        for (int i = 0; i < lines.size(); i++) {
            String line = lines.get(i);
            log.debug("Line {}: {}", i + 1, line);
            String[] parts = line.split(",");
            try {
                int marks = Integer.parseInt(parts[1].strip());
                if (marks > 100) {
                    log.warn("Line {}: marks {} for {} are above 100, skipped", i + 1, marks, parts[0]);
                    continue;
                }
                saved++;
            } catch (NumberFormatException | ArrayIndexOutOfBoundsException e) {
                log.error("Line {} could not be read: '{}'", i + 1, line, e);
            }
        }
        log.info("Imported {} of {} lines", saved, lines.size());
        return saved;
    }

    public static void main(String[] args) {
        importLines(List.of("Ananya, 91", "Rohan, 1O5", "Isha, 104", "Priya, 77"));
    }
}

<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%-5level %logger{0} - %msg%n</pattern>
    </encoder>
  </appender>
  <logger name="in.college" level="INFO"/>
  <root level="WARN">
    <appender-ref ref="CONSOLE"/>
  </root>
</configuration>

ERROR MarksImporter - Line 2 could not be read: 'Rohan, 1O5'
java.lang.NumberFormatException: For input string: "1O5"
	at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
	at java.base/java.lang.Integer.parseInt(Integer.java:662)
	at java.base/java.lang.Integer.parseInt(Integer.java:778)
	at in.college.MarksImporter.importLines(MarksImporter.java:17)
	at in.college.MarksImporter.main(MarksImporter.java:32)
WARN  MarksImporter - Line 3: marks 104 for Isha are above 100, skipped
INFO  MarksImporter - Imported 2 of 4 lines