Debug Logs for Every Failed Request

It's 2:40 a.m., and the alert says checkout errors are up. You open the logs and find the failed request:

ERROR c.shop.CheckoutService - payment failed for order 81734

That's all there is. The INFO lines around it say a request started and a request ended. What the code did in between was never written down: which cart it loaded, which price it computed, which provider it called, and what came back. The service knew all of it. It just didn't keep it.

Every team picks a log level for production, and both usual choices cost something:

• INFO only is cheap and readable, but it says nothing about the one request you need to understand.
• DEBUG always records every step of every request, at many times the log volume and cost, with the failures buried among millions of requests that succeeded.

So most teams run INFO. When something breaks, they turn DEBUG on and wait for the failure to happen again. Intermittent failures often don't, at least not while anyone is watching.

Meanwhile, every codebase is full of log.debug(...) calls. Developers write them for exactly this moment: log.debug("Price computed, total={}", total) is the line you want when checkout misbehaves. With DEBUG off in production, that knowledge is thrown away on every request, including the ones that fail.

The choice is made at the wrong moment. It is made before the request runs, when nobody knows whether it will fail. At the end of the request, you always know.

Log at DEBUG as usual, but hold each request's DEBUG lines in memory instead of writing them. INFO, WARN and ERROR lines are written straight away, exactly as today.

• The request succeeds: its DEBUG lines are thrown away. Nothing extra reaches the log.
• The request fails: its DEBUG lines are written, in order, with the time each one was logged.

Most requests succeed, so the log looks almost the same as an INFO-only log. The requests that fail come with their full history. The application code doesn't change: the log.debug(...) calls stay exactly as they are.

I built this as an open-source library for Java, debug-on-failure, with support for Logback and Log4j2 and a Spring Boot starter.

Every log.debug(...) call goes through two steps, and they are easy to confuse:

1. The logger's level decides whether the line is created. At INFO, a debug call does nothing. At DEBUG, it creates a log event.
2. The appender decides what happens to the line. Appenders are the parts of Logback and Log4j2 that write to the console, a file or a log service. Normally they write every event they receive.

That is why "DEBUG on" usually means "DEBUG lines in the log". debug-on-failure changes only the second step. It puts one appender in front of your existing ones, so every line passes through it first. Lines at INFO and above go straight through. DEBUG lines are held, grouped by the piece of work that logged them: one HTTP request, one run of a scheduled job, one call to an @Async method.

Your log format, destinations and encoders don't change. A held line reaches them later as the original log event, with its original timestamp, thread and MDC values, such as trace ids.

Writing the lines only when log.error is called would miss many failures. A request counts as failed when any of these happens:

A request that hangs may never fail at all, so it needs one more rule: if a request is still running after 5 minutes, its DEBUG lines so far are written without waiting for it to end. Each of these limits can be changed.

The project includes a small Spring Boot shop for trying it out. This is its console for a payment that the card network declines. To make the lines fit, I left out the date, process id and thread, shortened the logger names and Spring's error message, wrapped long lines, and cut the stack trace:

14:21:45.355  INFO OrderController  : Paying for order 42
14:21:45.359  WARN debugonfailure   : GET /orders/{id}/pay failed
                                     (exception IllegalStateException);
                                     writing 3 buffered debug lines
14:21:45.355 DEBUG OrderController  : Order 42 total 109.00, card ending 0000
14:21:45.355 DEBUG PaymentService   : Calling card network for order 42
14:21:45.355 DEBUG PaymentService   : Card network response: DECLINED code=51
14:21:45.360 ERROR dispatcherServlet: Request processing failed:
                                     IllegalStateException: Payment declined
                                     for order 42

Read it from the top:

• The INFO line was written as usual, the moment it was logged.
• When the exception escaped, a WARN line named the request by its route, GET /orders/{id}/pay, so order ids and other values in the URL stay out of it, and said why and how many lines follow.
• Then come the three DEBUG lines that explain the failure: the order total, the call to the card network, and its answer, DECLINED code=51. They were logged at 14:21:45.355, before the WARN at .359, and they keep that original time.
• Last is Spring's own error, exactly as it would be without debug-on-failure.

The same request with a card that works writes only its INFO line. Its DEBUG lines were created and held, then thrown away when the request succeeded.

Held lines are written late, so in a plain log file a failed request's DEBUG lines appear together, just before its error, possibly after lines from other requests that ran at the same time. Three things keep this readable:

• Every held line keeps its original timestamp. It is the original event, written late, so it says when its step actually happened.
• A WARN line introduces them, naming the request, the reason and how many lines follow.
• Every line keeps its MDC values. Filter by a trace id and you get one request's complete story.

Log tools that sort by timestamp, such as Kibana, Grafana Loki or Datadog, show the request in its true order. Only a raw file read with tail -f shows the jump. Some log pipelines reject or mishandle entries that arrive late, so check yours before turning this on.

Holding lines in memory is only safe if the memory is bounded, whatever the application does. Two limits do that:

• Per request, job run or other piece of work: 1 MB. If a request logs more, lines from the middle are dropped. The first lines, which usually say what the request was, and the latest ones, which say what happened last, are kept, and a WARN line marks the gap.
• For the whole application: 5% of the heap, and never more than 64 MB. When the total is reached, new DEBUG lines are dropped until other requests finish. This is the guarantee that holding DEBUG lines cannot run the application out of memory.

Sizes are estimated from the text each line holds: the message, string arguments, stack trace and MDC values. The limits are in bytes rather than lines, because one line with a stack trace can be larger than a hundred short ones.

HTTP requests are the obvious unit of work, but not the only one. With the Spring Boot starter, each call to a @Scheduled or @Async method is covered too, with no change to your code. An async method is its own piece of work: if the request that started it succeeds but the async call fails, the async call's DEBUG lines are written on their own.

For anything else, such as a message listener, wrap the work:

import io.github.jchejarla.debugonfailure.core.DebugOnFailure;
import org.springframework.kafka.annotation.KafkaListener;
import org.springframework.stereotype.Component;

@Component
public class PaymentListener {

    @KafkaListener(topics = "payments")
    void onPayment(Payment payment) {
        DebugOnFailure.run("payment " + payment.id(), () -> handle(payment));
    }

    private void handle(Payment payment) {
        // log.debug(...) calls here are held for this message
    }
}

Wrap each message or item, not a whole long-running job. If a two-hour import fails on order 8,000, you want the DEBUG lines for order 8,000, not two hours of history.

Nothing here is free, and it's worth being precise about where the cost goes:

• CPU on every request. The logger has to be at DEBUG for the events to exist, so every log.debug call now creates an event, even when it is never written. Creating an event is much cheaper than formatting and writing it, but it happens on every request. An early benchmark that measured logging alone handled 327,000 requests per second with INFO only, 202,000 with DEBUG lines held, and 35,000 with DEBUG always written. Real services spend most of each request waiting on databases and other services, so the difference there is much smaller. Measure it on yours.
• Memory while requests run, bounded by the limits above.

In return, log volume stays close to INFO-only, and every failure comes with its full context, without changing the log level or waiting for the failure to happen again. The trade stops paying off when failures are common: if 30% of requests fail, you write about 30% of what DEBUG-always would. Failures are usually rare, which is when this works best.

• Your DEBUG lines carry data that must not reach production logs, such as request bodies, tokens or personal data. They will be written whenever a request fails, so treat turning this on as a data-exposure change, and fix those lines first.
• Your DEBUG lines are thin. It can only write what was logged. Lines that say "here" and "done" won't help.
• You need lines that survive a crash. Held lines live only in memory; if the process is killed, they are lost.
• Your work moves between threads. Lines are grouped on the thread that started the work. Work handed to another thread, for example with CompletableFuture.supplyAsync, is not part of the request, and WebFlux is not supported in this version.

This isn't a new idea, and it has proven itself elsewhere:

• .NET ships log buffering, including per-request buffering for ASP.NET Core (.NET Blog).
• Powertools for AWS Lambda buffers debug logs in Lambda functions and writes them on error (Powertools documentation).
• PHP's Monolog has had a "fingers crossed" handler for years (overview).

What Java services lacked was a drop-in version: one that works with existing SLF4J calls, catches failures from any source, and is safe to leave on in production.

debug-on-failure 0.1.0 is on Maven Central. With Spring Boot 4 and Java 17 or later, add the starter; no code changes are needed:

<dependency>
    <groupId>io.github.jchejarla</groupId>
    <artifactId>debug-on-failure-spring-boot-starter</artifactId>
    <version>0.1.0</version>
</dependency>

At startup it logs which packages it collects DEBUG lines from, and which scheduled and async methods it covers. Without Spring Boot, the Logback and Log4j2 appenders and the servlet filter can be set up by hand. The README on GitHub covers every setting, and the demo shop shows each kind of failure.

If you run Java services in production, I'd like to hear from you: would you turn this on, and what would stop you? Open an issue on GitHub, or tell me on LinkedIn.