Logging: The SLF4J Facade and Logback in Practice

System.out.println also prints. But all it can do is type on the screen. Real logging has to deliver five things at once: switchable per level (production must not stream DEBUG), written to files that roll automatically (the disk must not fill), carrying context (who is this request, what is its traceId), searchable by machines (ELK, one object per line), and swappable implementations without touching code. Those five together are what "a logging system" means — and Spring Boot already installs the whole set for you by default.

Six words, one line each (used throughout):

• Facade: the interface layer that only defines how you call and does no work itself — org.slf4j.Logger
• Implementation: the library that actually checks levels, formats lines and writes bytes — Logback, Log4j2
• Binding: the wire connecting facade to implementation; physically it is the logback-classic.jar on your classpath
• Bridge: a jar that quietly redirects a legacy implementation's output into the facade, e.g. jul-to-slf4j
• Appender: an outlet for log events — console, file and async queue are each one appender
• MDC: a small scratchpad bound to the current thread; whatever you write into it shows up in every subsequent log line

After this article you should be able to answer three questions:

• Why did I add log.debug(...) and get nothing printed? (The two real answers are not the two you suspect.)
• logback.xml versus logback-spring.xml: one word apart, how much functionality does that cost?
• One request crosses five services and writes twenty lines — how do I stitch them together in ten seconds?

Start with a real disaster. A project, to save a little effort, imported org.apache.log4j.Logger directly in every class, hard-wiring itself to one implementation. Years later Log4j shipped a critical security advisory and the whole company was told to move to Log4j2. Every other service changed one dependency version and moved on; this one had to edit dozens of classes and re-run the entire test suite, because log calls were scattered everywhere and coupled to the implementation.

The root cause is binding "what you need" to "who provides it". A logging stack has two kinds of players:

• Facade: defines the interface only, e.g. Logger.info(...). Business code knows nothing else.
• Implementation: decides where logs actually go and in what format — Logback, Log4j2, or the JDK's JUL.

Sometimes a bridge sits in between, redirecting the output of a legacy implementation into the unified pipeline.

The history goes roughly: JCL (2002) → a wild mix of implementations → SLF4J (2006) unified the facade. JCL failed because it looked up implementations dynamically at runtime; one messy classpath and you got bizarre NoClassDefFoundErrors. SLF4J switched to static binding at build time: with no implementation on the classpath it merely prints a warning instead of crashing. That is why every modern framework — Spring, Hibernate, MyBatis — talks to SLF4J internally.

That opening disaster deserves an animation to nail it down — on the left, the cost of soldering the wire into the socket; on the right, the cost of swapping an adapter. One security advisory, two endings:

A level is not an "importance ranking" but a filter threshold: only messages at or above the configured level get through. Confuse this and you get the classic outage — DEBUG enabled in production until the disk fills up.

Logback's levels form a tree. root is the trunk, and every package or class is a branch. A logger with no explicit configuration inherits the nearest configured ancestor. So:

"Whoever sits closest to the class wins" is easier to click through than to memorise. Step through the stack below, one box at a time; boxes ③ and ⑤ are the ones that answer real tickets:

You see it often in legacy code:

The conclusion is firm: in the vast majority of cases you do not need isDebugEnabled.

• When the arguments are plain variables or references, placeholders already avoid the formatting cost; the outer check is pure noise
• A guard is only worth it when building the argument is itself expensive — iterating a large collection, serializing a snapshot. In the first snippet above, expensiveToString runs even if the log is filtered, so the check earns its keep
• The cost is longer, less readable code. Default to not writing it; add it only when you have a real performance problem — do not optimize from imagination

Three settings in application.yml cover 80% of daily needs without changing any code:

Those three lines are the floor, not the ceiling: a real service also needs the profile split and the Actuator endpoint. Instead of borrowing someone's yml, tick the boxes and watch what comes out — the comments explaining why each line exists are the point:

The worst part of production troubleshooting is that changing config means restarting. Since Spring Boot 2.0 the actuator exposes a loggers endpoint for hot level changes:

When needs outgrow the three knobs — per-level routing, async, size-plus-time rolling — write a full config file, src/main/resources/logback-spring.xml:

The % tokens in those patterns are the only part of the whole file that fails silently — a wrong one simply prints nothing. Play a round: token on the left, what it actually does on the right; one of the six is a performance trap, see if you find it.

The killer feature of logback-spring.xml is per-environment behavior:

Development wants DEBUG on the console; production wants INFO written asynchronously — one file, two behaviors, which logback.xml cannot do.

Log files cannot grow forever; they must roll. Logback offers two practical policies:

SizeAndTimeBasedFNATP (SizeAndTimeBasedFileNamingAndTriggeringPolicy) is the component behind "size plus time" rolling; today you usually use the SizeAndTimeBasedRollingPolicy shorthand:

The most painful problem in microservices: one request crosses five services and writes twenty log lines — how do you stitch them together? The answer is the MDC (Mapped Diagnostic Context), a thread-bound key-value store referenced in the pattern via %X{key}.

Step one — a filter puts the traceId in place at the entry point:

Step two — reference it in the pattern (the [%X{traceId}] from Section 4), and the line becomes:

Both steps can be run in the kernel. The first is "put and get": underneath, the MDC is a ThreadLocal<Map<String,String>>, so put writes into the current thread's map and %X{} reads that same one:

The second lab is that pattern line: why does %X{traceId} sometimes print []? Because substitution happens inside the encoder, which asks whatever thread is doing the encoding, not "where this request came from":

The MDC is backed by a ThreadLocal, so a newly spawned thread does not see the parent's MDC. With @Async or a custom pool, the traceId turns up empty. The fix is a TaskDecorator that copies the context when the task is submitted:

With and without a TaskDecorator differ in exactly one line, and the consequence fits on one page. Note the last row of the left column — crossed wires are worse than blanks, because the log still looks healthy:

The decorator is easy to copy; the ordering is not. Spread the chain out as a single-step run and click through: watch the moment the thread name changes from http-nio-8080-exec-3 to async-2, and beat ④'s question — whose thread runs the snapshot?

The same chain in the kernel, with the async branch selected — you can watch the traceId disappear at beat ⑤:

Carrying it to the pool thread only solves one process. Once the call crosses the network, the MDC cannot follow — it is a ThreadLocal, and there is no thread on the other side. It has to be written into an HTTP header and put back into the downstream MDC by the downstream filter. The industry format is the W3C traceparent header:

This animation walks one id across two network hops — frame 4 is the empty-brackets moment from above:

The logs above are human-friendly but machine-hostile: to feed ELK you write a pile of regexes to extract fields. The more engineered option is to emit JSON directly, one object per line with its own fields:

The output is one line of standard JSON:

AsyncAppender defaults to discarding TRACE/DEBUG events once the queue is nearly full (20% remaining) — that is discardingThreshold. Set neverBlock=true (do not block business threads when full) with a small queueSize, and a traffic spike drops logs — precisely the ones you needed.

That trade-off has exactly one number you can drag, so drag it. From 64 to 8192, watch who gets dropped and who gets blocked:

This snippet is a recurring incident:

Aggregate instead:

log.debug("resp={}", hugeResponse) looks harmless, but if hugeResponse.toString() recursively serializes thousands of fields, every call does heavy work. Worse, some people pack a full payload into toString, and one log line costs tens of milliseconds.

Logging and the bean lifecycle share a natural connection: to log "this object was created", which of the eight lifecycle phases should you hook into? The demo below runs a bean from instantiation to destruction — watch it and think this through.

• To record "who was created", the best spot is post-initialization (BeanPostProcessor#postProcessAfterInitialization), once dependencies are injected and proxies are ready
• To record "resources released", use the destruction callback (@PreDestroy)
• Logging inside the constructor is usually too early — dependencies are not injected yet and the message is incomplete

The sections above gave you the conclusions; this one shows why they hold. The pipeline figure from Section 0 — business call → facade → binding → filter → layout → appender → disk — is exactly the spine of the lab below:

Level filtering happens before formatting, which makes the key point of Section 2 worth verifying live:

Async and rolling come last because they decide the fate of an event after it was let through:

• Binding happens very early in startup, which is why two bindings on the classpath warn immediately (row 1 of Section 17)
• Level checks belong to the Logger while filters belong to the Appender — they are not the same thing, and confusing them produces "the level is clearly on yet nothing prints"
• Layout/Encoder is the only place that can see the MDC; %X{key} is resolved there
• AsyncAppender changes who performs the I/O, not whether the event should be emitted
• Rolling policies trigger only on size or time; totalSizeCap is the real fuse protecting the disk

Three peripheral mechanisms sit outside the pipeline yet decide its behaviour, one lab each.

First: how does your logging.level.* actually reach Logback? Through Spring's property system — meaning it obeys the precedence and profile rules entirely:

Second: who powers the hot level change of Section 4.1? Actuator exposes a writable endpoint that calls Logback's API to mutate the Logger objects directly:

Third: Section 7.1 says the MDC vanishes on async threads, Section 10.1 says AsyncAppender drops events. Those two "asyncs" are one problem seen from two sides — one loses context, the other loses events:

Enough buttons — type it yourself. This console is wired to the same in-browser Java kernel, and every line of output is computed there: logs shows what this container is printing right now, then work down the lab lines:

What beginners really want to know is not "what levels exist" but "with my configuration, what will the screen show?". This sandbox pins root: INFO and switches only which extra package gets DEBUG, comparing output lines side by side:

A warm-up question, straight from the disaster that opens Section 1:

Now a combined question threading Section 2's level inheritance, Section 4's configuration sources and the logback.xml trap of Section 5:

That "second config file" clue is best practised live. The scene below raises no exception at all, yet it deletes the production environment's entire level decision. Do not read the analysis — click the line you think is guilty:

Goal: assemble a minimal setup that shows colour on the console in development, writes JSON files in production, and carries a traceId.

Step one — dependencies stay at the default (spring-boot-starter-web already brings SLF4J + Logback); add structured output:

Step two — src/main/resources/logback-spring.xml:

Step three — reuse the TraceIdFilter from Section 7 to populate the MDC, then write one line in any service:

Step four — the command and the expected output:

You pass when the console line carries the bracketed traceId and logs/ is still empty.

1. Switch to -Dspring-boot.run.profiles=prod and hit the endpoint again. You will observe: logs/bee-json.log appears, containing one standard JSON object with a "traceId":"9f2c1a7b3e5d8401" field.
2. Set maxFileSize to 1KB and log 5000 lines in a loop. You will observe: the directory fills with bee-json.2026-10-07.0.log.gz, .1.log.gz… — that is %i at work. Now set totalSizeCap to 1MB and you will observe: the oldest shards start disappearing.
3. Delete the <charset>UTF-8</charset> line and run on a machine whose default encoding is not UTF-8. You will observe: non-ASCII text turns into mojibake; adding the line back fixes it. Then rename the file to logback.xml (dropping -spring) and restart. You will observe: startup fails with Logging system failed to initialize, because <springProfile> is not understood in that file.

Deliver an "operable logging baseline" — a configuration someone else could debug an incident with. Acceptance checklist:

• [ ] Three profiles (dev / staging / prod) driven by one logback-spring.xml via <springProfile>, with no duplicate config files
• [ ] Business packages at INFO, the SQL package at DEBUG on demand, third-party frameworks (Hibernate, Hikari) pushed down to WARN or INFO
• [ ] An unbroken traceId chain: entry filter writes it → pattern prints it → async threads keep it via TaskDecorator → response header echoes it
• [ ] ERROR routed to its own file and receiving only ERROR (both onMatch and onMismatch of a LevelFilter put to use)
• [ ] Files constrained simultaneously by maxFileSize, maxHistory and totalSizeCap, and you can explain what breaks without totalSizeCap
• [ ] One incident reproduced by promoting a package to DEBUG through Actuator and reverted to INFO afterwards, with zero restarts
• [ ] A README stating the exact first curl command to run when production misbehaves