PHASE 15Advanced ~35 min· topic 6 of 6

Topic 15.6

Logging Done Right

In one line

Logging records what a running program did, so you can understand it in production where there's no debugger. Professional Java code logs through the SLF4J API with a back-end such as Logback, uses levels (TRACE to ERROR) to control volume, writes parameterized messages (log.info("Order {} placed", id)) instead of string concatenation, and passes exceptions as the last argument so their stack traces are kept.

Think of it like this

A ship's captain keeps a logbook: every important event is written down with the time, the ship's position and what happened. Routine entries ("weather calm") are short; serious ones ("engine failure") are detailed. Months later, investigators can reconstruct a voyage from it. Application logs are your program's logbook, and when something goes wrong at 3 a.m., they're often the only witness.

Words you'll meet

New words in this topic, in plain English. Come back here whenever one feels fuzzy.

Logger: The object you call to write log messages, usually one per class, named after the class.
Log level: How important a message is: ERROR, WARN, INFO, DEBUG or TRACE. A logger set to a level ignores anything less important.
Facade: A simple front API that hides which real implementation is used behind it. SLF4J is a logging facade.
Appender / handler: The part that writes log events somewhere: the console, a file, or a network log server.
Pattern / formatter: The template for each log line: time, level, thread, logger name, message.
Parameterized message: A message with {} placeholders filled in only if the message will actually be written.
MDC: Mapped Diagnostic Context: key-value pairs (like orderId) attached to every log line from the current thread.
Structured logging: Writing log events as fields (often JSON) instead of free text, so tools can search and count them.

Step by step

01One logger per class

Declare the logger as private static final, named after the class. The logger's name (com.shop.orders.PriceCalculator) is how configuration targets it: a setting for com.shop.orders applies to every logger under that package, because logger names form a hierarchy split at the dots.

Only slf4j-api is a compile dependency; the back-end (logback-classic) is runtime scope (Topic 15.4), so your code can't accidentally depend on Logback classes.

PriceCalculator.javawhole filejava

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

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

    public long total(long unitPrice, int quantity, int discountPercent) {
        long gross = unitPrice * quantity;
        long net = gross - gross * discountPercent / 100;
        log.debug("total: unitPrice={} quantity={} discount={}% -> {}", unitPrice, quantity, discountPercent, net);
        return net;
    }
}

02Levels, exceptions and context in practice

The application logs business events at INFO, puts the order ID in the MDC for the duration of the work, and logs the exception object (not just its message) at ERROR. The finally block clears the MDC so the next request on this thread doesn't inherit the old ID.

App.javawhole filejava

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

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

    public static void main(String[] args) {
        PriceCalculator calc = new PriceCalculator();
        MDC.put("orderId", "A-1042");
        try {
            log.info("Pricing order with {} items", 3);
            long total = calc.total(49_900, 3, 10);
            log.info("Order priced at {} paise", total);
            calc.total(49_900, 0, 10);                         // invalid: throws
        } catch (IllegalArgumentException e) {
            log.error("Could not price order", e);             // exception last, no placeholder
        } finally {
            MDC.remove("orderId");
        }
        log.warn("Cache {} is {}% full", "prices", 93);
    }
}

03Configuring Logback

logback.xml in src/main/resources defines appenders (where lines go) with an encoder pattern (what each line looks like), the root level, and per-logger overrides. Here everything logs at INFO, but PriceCalculator logs at DEBUG.

Pattern parts: %d{HH:mm:ss.SSS} time, %-5level the level padded to 5 characters, %thread, %logger{20} the logger name abbreviated to about 20 characters, %X{orderId} an MDC value, %msg%n the message and a newline. Logback can rescan the file while the app runs (scan="true"), so levels can be raised during an incident without a restart.

src/main/resources/logback.xmlwhole filexml

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

    <logger name="com.shop.orders.PriceCalculator" level="DEBUG"/>

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

terminal

$ java -cp target/classes:<dependencies> com.shop.orders.App

── expected output ──

14:51:21.053 INFO [main] com.shop.orders.App [A-1042] - Pricing order with 3 items

14:51:21.055 DEBUG [main] c.s.o.PriceCalculator [A-1042] - total: unitPrice=49900 quantity=3 discount=10% -> 134730

14:51:21.057 INFO [main] com.shop.orders.App [A-1042] - Order priced at 134730 paise

14:51:21.058 ERROR [main] com.shop.orders.App [A-1042] - Could not price order

java.lang.IllegalArgumentException: quantity must be positive: 0

at com.shop.orders.PriceCalculator.total(PriceCalculator.java:10)

at com.shop.orders.App.main(App.java:17)

14:51:21.060 WARN [main] com.shop.orders.App [] - Cache prices is 93% full

04How a log call flows

A call first checks the logger's effective level (its own, or the nearest ancestor's). Only if the event is enabled does the framework build a log event, fill in placeholders, add the MDC and timestamp, and hand it to every appender attached to the logger and its ancestors. Disabled calls cost a method call and a comparison, which is why parameterized calls are cheap when the level is off.

How a log call flowsdiagram

Rendering diagram…

05The facade and its back-ends

Many libraries log through different APIs: Spring through Commons Logging, older code through Log4j 1, the JDK through java.util.logging. Bridges redirect them all into SLF4J (jcl-over-slf4j, log4j-over-slf4j, jul-to-slf4j), so one back-end and one configuration controls everything.

Exactly one back-end must be present. With none, SLF4J 2 warns once at startup and discards every message, a silent production problem.

terminal

$ java -cp target/classes:slf4j-api-2.0.17.jar com.shop.orders.App

── expected output ──

SLF4J(W): No SLF4J providers were found.

SLF4J(W): Defaulting to no-operation (NOP) logger implementation

SLF4J(W): See https://www.slf4j.org/codes.html#noProviders for further details.

The facade and its back-endsdiagram

Rendering diagram…

06The JDK's built-in logging

java.util.logging (JUL, in the java.logging module since Java 1.4) works without any library, which is why this topic's runnable examples use it. Loggers form a hierarchy by name; handlers write records; formatters shape them. The default console handler writes to System.err in a two-line format with a date.

JUL uses {0}, {1} placeholders (Java's MessageFormat, which also groups digits by locale, so 134730 prints as 134,730 in an English locale). Since Java 8 it also accepts a Supplier<String>: log.fine(() -> "cart " + cart) builds the message only when FINE is enabled.

terminal

$ java J.java

── expected output ──

Oct 05, 2026 3:00:08 PM J main

INFO: order placed

07SLF4J 2's fluent API

SLF4J 2.0 adds a builder: log.atInfo().setMessage("order placed").addKeyValue("orderId", id).log();. Key-value pairs travel as data, so a JSON encoder can write them as separate fields for search and dashboards. log.atDebug().setMessage(() -> expensiveSummary()).log() takes a supplier, so the expensive part runs only when DEBUG is on.

Checkout.javawhole filejava

log.atInfo()
   .setMessage("order placed")
   .addKeyValue("orderId", order.id())
   .addKeyValue("items", order.items().size())
   .log();

log.atDebug().setMessage(() -> "cart: " + cart.describeEverything()).log();   // lazy

Try it yourself

1
Raise and lower the level
In the first example, change orders.setLevel(Level.INFO) to Level.WARNING. Predict which lines disappear (the INFO ones, including the child's "price rules loaded", until the level is changed to FINE later). Then try Level.OFF.
2
Turn FINE on
In "What string concatenation really costs", change the level to Level.FINE. Predict the counts: now every approach calls toString/expensiveSummary 1000 times, because the messages are really logged (to no handler, since setUseParentHandlers(false) and none was added). Laziness only saves work when the level is off.
3
Forget to clear the context
In the MDC example, remove ORDER_ID.remove(); from the finally block. Predict the fourth and fifth lines: the next request now claims to belong to order A-1042. In a thread pool this mislabels other users' requests (Topic 13.6).

Code & diagrams

java.util.logging: levels and the logger hierarchy Java 5+ New tab

pricing has no level of its own (null), so it uses its parent's. Changing shop.orders to FINE switched on FINE for the whole subtree: the same idea as a <logger name="com.shop.orders"> line in logback.xml.

Expected output

SEVERE  [shop.orders] payment gateway unreachable
WARNING [shop.orders] retrying payment, attempt 2
INFO    [shop.orders] order A-1042 placed
INFO    [shop.orders] order A-1043 has 3 items
pricing's parent: shop.orders
pricing's own level: null
FINE enabled for pricing? false
INFO    [shop.orders.pricing] price rules loaded
FINE    [shop.orders.pricing] now FINE is on for the whole shop.orders tree

What string concatenation really costs Java 8+ New tab

Nothing was ever printed, yet concatenation built 1000 strings. Placeholders defer formatting, but arguments are still evaluated: an expensive argument needs a supplier or a level guard. SLF4J behaves the same way.

Expected output

concatenation:   toString called 1000 times
placeholder:     toString called 0 times
placeholder arg: expensiveSummary called 1000 times
supplier:        expensiveSummary called 0 times
guarded:         expensiveSummary called 0 times

Exceptions and per-request context (a tiny MDC) Java 5+ New tab

The first error kept the exception object, so the handler can print where it came from; the second kept only the message text. Real MDC implementations work the same way, with a ThreadLocal map per thread.

Expected output

INFO [orderId=A-1042] checkout started
SEVERE [orderId=A-1042] payment failed
    java.lang.IllegalArgumentException: amount must be positive: -5
    at Main.charge
INFO [orderId=-] next request, no order yet
SEVERE [orderId=-] payment failed: amount must be positive: 0

SLF4J do's and don'tsjava

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

// DO: placeholders, exception as the last argument (no {} for it)
log.info("Order {} placed by customer {}", orderId, customerId);
log.error("Payment failed for order {}", orderId, e);

// DO: guard or use a supplier when computing the argument is expensive
if (log.isDebugEnabled()) log.debug("Cart dump: {}", cart.describeEverything());

// DON'T: concatenation (built even when DEBUG is off)
log.debug("Cart " + cart + " for " + customer);

// DON'T: lose the stack trace
log.error("Payment failed: " + e.getMessage());

// DON'T: log secrets or personal data
log.info("Login for {} with password {}", user, password);

// DON'T: log and rethrow at every layer (the same error appears five times)
catch (SQLException e) { log.error("DB error", e); throw new RepositoryException(e); }

Break it on purpose

Errors are the best teachers. Make each change, read the error, guess what went wrong, then reveal the answer.

Break #1

A placeholder for the exception

Write log.error("failed: {}", e); with SLF4J, expecting the exception's message in the {}.

terminal

$ java -cp <slf4j + logback> T.java

── what you'll see ──

15:00:06.737 [main] ERROR T -- failed: {}

java.lang.IllegalStateException: db down

at T.main(T.java:7)

Break #2

Too few arguments

Write log.info("Order {} for {}", orderId); with one argument for two placeholders.

terminal

$ java -cp <slf4j + logback> T.java

── what you'll see ──

15:00:06.733 [main] INFO T -- Order A-1 for {}

Break #3

No logging back-end

Ship the application with slf4j-api but without logback-classic (for example, scope set to test by mistake).

terminal

$ java -cp target/classes:slf4j-api-2.0.17.jar com.shop.orders.App

── what you'll see ──

SLF4J(W): No SLF4J providers were found.

SLF4J(W): Defaulting to no-operation (NOP) logger implementation

SLF4J(W): See https://www.slf4j.org/codes.html#noProviders for further details.

Myth vs fact

Myth

Logging is free, so log everything at INFO.

Fact

Each line costs CPU, I/O, network and storage, and noise hides real problems. Log business events at INFO, details at DEBUG, and keep DEBUG off in production unless investigating.

Myth

Placeholders make every log call lazy.

Fact

Placeholders delay formatting and toString, but the arguments are evaluated before the call. An expensive argument still needs a level check or a supplier.

Myth

log.error(e.getMessage()) is enough.

Fact

It loses the exception type, the stack trace and the cause chain. Pass the exception object as the last argument.

Myth

SLF4J and Logback are the same thing.

Fact

SLF4J is the API (facade) your code calls; Logback is one implementation of it. You could swap Logback for Log4j 2 without changing a line of code.

When it breaks

DEBUG logging is left on in production after an incident.

What you see

Log volume grows tenfold: disks fill, the log pipeline lags or drops events, CPU rises from formatting, and the log bill jumps. Important ERROR lines are buried.

Fix & prevent

Turn DEBUG on only for the specific logger being investigated and only temporarily (Logback scan, Spring Boot actuator loggers endpoint). Alert on log volume per service.

Passwords and tokens appear in logs because a request object's toString() includes every field.

What you see

Secrets are copied into log storage that many people and systems can read, often for months: a security incident and possibly a compliance breach.

Fix & prevent

Never log whole request objects; log chosen fields. Override toString() to omit secrets (records print every component by default), add masking rules in the encoder, and scan logs for secret patterns.

An exception is logged with only e.getMessage() and the root cause is a NullPointerException deep in a library.

What you see

The log says "Request failed: null"; there is no stack trace, so the team can't tell where it happened and must reproduce the problem blind.

Fix & prevent

Always pass the exception object as the last argument; add a static-analysis rule that flags getMessage() inside log calls.

Pro corner

Extra depth for experienced readers. New to this? Skip it for now and come back later.

▸
Asynchronous appenders (Logback's AsyncAppender, Log4j 2's async loggers on the LMAX Disruptor) move I/O off the request thread, but use bounded queues: when full, they either block or drop events (Logback's AsyncAppender drops TRACE, DEBUG and INFO by default once the queue is 80% full). Know which behaviour you configured before an incident.
▸
Logging inside hot loops can dominate CPU through formatting, Throwable.getStackTrace() (computing caller location for %line or %method patterns is expensive) and lock contention on appenders. Avoid caller-data patterns in production and prefer structured key-values over string building.
▸
The MDC is a ThreadLocal map, so it doesn't follow work into thread pools or CompletableFuture stages (Topic 13.7) unless you copy it (MDC.getCopyOfContextMap() then setContextMap in the task) or use a context-propagation library. With virtual threads it works per virtual thread. OpenTelemetry adds trace and span IDs to the MDC so logs connect to distributed traces.
▸
Security: Log4Shell (CVE-2021-44228, December 2021) was remote code execution through message lookups in Log4j 2 versions before 2.15; the defensive lessons are to keep logging libraries patched, never evaluate expressions inside logged data, and treat logged user input as untrusted. Strip or encode CR/LF in user-supplied values to stop forged log lines, and mask secrets with encoder rules.

Remember this

1
System.out.println is not logging: it has no levels, no timestamps or thread names, can't be switched off per package, can't be sent to files or log servers, and writes even when nobody needs it. A logging framework adds all of that, and lets operations staff change what is logged through configuration, without recompiling.
2
Levels say how important a message is. SLF4J has five: **ERROR (something failed and needs attention), WARN (unexpected but handled, may need attention later), INFO (important business events: started, order placed), DEBUG (details for developers diagnosing a problem) and TRACE** (very fine detail). A logger configured at INFO drops DEBUG and TRACE. The JDK's own java.util.logging uses SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST.
3
SLF4J (Simple Logging Facade for Java) is an API only: your code calls LoggerFactory.getLogger(MyClass.class) and log.info(...). A binding (Logback, Log4j 2 or java.util.logging) does the real work, chosen by which JAR is on the class path at runtime (SLF4J 2 finds it with ServiceLoader, Topic 15.3). Libraries depend only on slf4j-api, so the application decides the back-end. With no back-end at all, SLF4J prints a warning and discards everything.
4
Parameterized messages are the core habit. log.debug("Cart " + cart + " for " + user) builds the string (calling toString() on everything) before the method can check whether DEBUG is enabled, so in production you pay for messages that are thrown away. log.debug("Cart {} for {}", cart, user) formats only if the level is enabled. Arguments are still evaluated, so for expensive computations use a level check (if (log.isDebugEnabled())) or SLF4J 2's fluent API with a supplier.
5
Exceptions: pass the exception object as the last argument, log.error("Payment failed for order {}", orderId, e), with no placeholder for it. SLF4J recognises a trailing Throwable and prints the full stack trace. Writing log.error("failed: " + e.getMessage()) loses the stack trace and the cause chain, which is usually the most useful part. Log an exception once, where it's handled, not at every layer it passes through.
6
Good logs carry context and protect secrets. The MDC (Mapped Diagnostic Context) attaches values such as a request or order ID to every log line written by the current thread, so one request can be followed through thousands of lines; always clear it in a finally. Never log passwords, tokens, card numbers or personal data, and treat user input in logs as untrusted (escape line breaks to prevent forged log lines). In production, logs usually go out as structured JSON to a central system such as the ELK stack or Loki.

Explain it without notes

Why use a logging framework instead of System.out.println?

Why should you write log.debug("x {}", x) instead of log.debug("x " + x)?

How should an exception be logged, and what goes wrong otherwise?

What is SLF4J, and why do libraries depend on it instead of on Logback?

What is the MDC, and what is the common bug when using it with thread pools?

Practice

Write a JUL Formatter subclass that formats records as LEVEL|logger|message and use it with your own handler to log three messages at different levels.

Write a method mask(String card) that keeps only the last four digits ("** ** 4242") and log a payment with the masked card number.

Write a JUL handler that counts records per level in a TreeMap and prints the counts after logging five messages.

Trade-offs

↔
More logging means easier diagnosis but higher cost and more noise; fewer logs are cheaper but leave gaps during incidents.
↔
Text logs are easy for humans to read in a terminal; structured JSON logs are harder to read raw but can be searched, filtered and graphed reliably.
↔
Asynchronous appenders protect request latency, but can lose the last events in a crash or drop events under load; synchronous appenders are safer but slower.

Done when you can

Done when you can declare an SLF4J logger and choose the right level for a message.
Done when you can write parameterized messages and explain why concatenation is wasteful.
Done when you can log an exception with its stack trace and context in one call.
Done when you can configure Logback levels per package and read a pattern layout.
Done when you can use the MDC safely and explain why secrets must never be logged.

Command Palette

Words you'll meet

Step by step

01One logger per class

02Levels, exceptions and context in practice

03Configuring Logback

04How a log call flows

05The facade and its back-ends

06The JDK's built-in logging

07SLF4J 2's fluent API

Try it yourself

Raise and lower the level

Turn FINE on

Forget to clear the context

Code & diagrams

Break it on purpose

A placeholder for the exception

Too few arguments

No logging back-end

Myth vs fact

When it breaks

Pro corner

Remember this

Explain it without notes

Practice

Trade-offs

Done when you can