Logging & Debugging in Production

Logs are the only thing you have when a system misbehaves in a way you cannot reproduce. Making them useful is mostly about three decisions: what level to use, what context to attach, and what shape to write.

Levels that mean something#

The common failure is logging expected conditions at ERROR. A client sending a malformed request is not an error in your application; it is a 400 and a DEBUG line. When ERROR becomes noisy, people stop reading it, and the one that mattered is the one they missed.

private static final Logger log = LoggerFactory.getLogger(OrderService.class);
 
public Receipt place(Order order) {
    // Parameterised: the string is only built if DEBUG is enabled.
    log.debug("placing order for customer={} lines={}", order.customerId(), order.lines().size());
 
    try {
        return gateway.charge(order);
    } catch (RateLimitedException ex) {
        log.warn("payment gateway rate limited, retrying in {}ms", ex.retryAfterMillis());
        throw ex;
    } catch (GatewayException ex) {
        // Pass the throwable as the LAST argument — never in the format string,
        // or you lose the stack trace.
        log.error("payment failed for order={}", order.reference(), ex);
        throw ex;
    }
}

Correlation IDs#

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class CorrelationIdFilter extends OncePerRequestFilter {
 
    public static final String HEADER = "X-Correlation-Id";
    public static final String MDC_KEY = "correlationId";
 
    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
                                    FilterChain chain) throws ServletException, IOException {
        String id = Optional.ofNullable(request.getHeader(HEADER))
                            .filter(StringUtils::hasText)
                            .orElseGet(() -> UUID.randomUUID().toString());
 
        MDC.put(MDC_KEY, id);
        MDC.put("path", request.getRequestURI());
        response.setHeader(HEADER, id);
 
        try {
            chain.doFilter(request, response);
        } finally {
            // The thread returns to the pool. Leaving MDC populated leaks this
            // request's id into whichever request picks the thread up next.
            MDC.clear();
        }
    }
}

Reference it in the pattern with %X{correlationId} and every line for a request carries it.

Propagating MDC across threads#

public class MdcTaskDecorator implements TaskDecorator {
 
    @Override
    public Runnable decorate(Runnable runnable) {
        // Captured on the submitting thread...
        Map<String, String> context = MDC.getCopyOfContextMap();
        return () -> {
            // ...and restored on the worker thread.
            if (context != null) MDC.setContextMap(context);
            try {
                runnable.run();
            } finally {
                MDC.clear();
            }
        };
    }
}
 
@Bean
public Executor taskExecutor() {
    var executor = new ThreadPoolTaskExecutor();
    executor.setTaskDecorator(new MdcTaskDecorator());
    executor.setCorePoolSize(8);
    executor.setQueueCapacity(500);
    executor.initialize();
    return executor;
}

The same problem exists for message consumers. Put the correlation id in a message header on publish and restore it into the MDC on consume, or the trail stops at the broker.

Configuration with logback-spring.xml#

Use logback-spring.xml, not logback.xml — the spring variant is loaded after the Spring environment, which is what makes springProfile and springProperty available.

<configuration>
  <springProperty scope="context" name="appName" source="spring.application.name"/>
 
  <springProfile name="local | test">
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
      <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%X{correlationId:-}] %logger{36} - %msg%n</pattern>
      </encoder>
    </appender>
    <root level="INFO"><appender-ref ref="CONSOLE"/></root>
  </springProfile>
 
  <springProfile name="staging | prod">
    <appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
      <encoder class="net.logstash.logback.encoder.LogstashEncoder">
        <includeMdcKeyName>correlationId</includeMdcKeyName>
        <includeMdcKeyName>userId</includeMdcKeyName>
        <customFields>{"service":"${appName}"}</customFields>
      </encoder>
    </appender>
 
    <!-- Decouples the request thread from disk or socket I/O. -->
    <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
      <appender-ref ref="JSON"/>
      <queueSize>8192</queueSize>
      <!-- 0 means never drop, even under pressure. The default silently
           discards INFO and below when the queue is 80% full. -->
      <discardingThreshold>0</discardingThreshold>
      <includeCallerData>false</includeCallerData>
    </appender>
 
    <root level="INFO"><appender-ref ref="ASYNC"/></root>
    <logger name="com.acme" level="DEBUG"/>
  </springProfile>
</configuration>

Two details in that async block are easy to miss. discardingThreshold defaults to dropping lower level events under load, which means your logs thin out exactly when an incident is happening. And includeCallerData is false by default because computing the calling class and line number requires building a stack trace on every event — enabling it is expensive.

In a containerised deployment, log to stdout and let the platform collect it. Writing to files inside a container adds rotation, disk-pressure and permissions problems that the collector already solves.

What must never be logged#

Passwords, API keys, bearer tokens, session identifiers, card numbers, national identifiers, and full request or response bodies for anything carrying personal data. Once written, a log line propagates into every downstream index and backup, and removing it later is a project rather than a task.

The practical defence is a masking pattern applied in the encoder, so a mistake in a single log statement does not become a breach:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
  <jsonGeneratorDecorator class="net.logstash.logback.mask.MaskingJsonGeneratorDecorator">
    <defaultMask>****</defaultMask>
    <path>/password</path>
    <path>/authorization</path>
  </jsonGeneratorDecorator>
</encoder>

What makes a log line worth writing#

The test for a log statement is simple: during an incident, would this line change what someone does next? Most log statements fail it. "Entering method" and "Returning from method" describe control flow that a stack trace already shows, and they push the useful lines further apart.

The lines that repeatedly earn their place fall into a few categories. Decisions — which branch was taken and why, especially when the reason came from configuration or a feature flag, because that is the question nobody can answer from code alone. Boundaries — a call left this service for that one, with the target and the outcome. State transitions — an order moved from pending to paid, an account was locked, a circuit breaker opened. Anomalies handled silently — a retry succeeded on the third attempt, a fallback value was used, a cache was bypassed. That last category is the one most often missing, and it is exactly what you want when a system is degraded but not failing.

Include the identifiers that let you pivot. An order reference, a customer id, a message id: these are what turn a log search from "read everything around this timestamp" into a single query. Keep them as separate structured fields rather than interpolating them into the message, so they can be indexed and filtered.

Be deliberate about cardinality in the same way you are with metrics, but for a different reason. High-cardinality values are fine in logs — that is the point of logs — but a log line emitted once per item in a large loop will generate megabytes per request and cost real money in an indexed log store. Log the summary, not the iteration.

Logs, metrics and traces#

These three are complementary and it is worth being clear about which question each answers, because teams routinely try to make one do another's job.

Metrics answer "how much, how often, how fast" across all requests. They are cheap, aggregated and pre-indexed, which makes them the right thing to alert on. They cannot tell you what happened to one specific request.

Traces answer "where did the time go for this request" across service boundaries. A trace shows the call tree with timings, which is what you need when latency is the symptom and the cause is two services away.

Logs answer "what happened, in detail, at this point". They carry the arbitrary context the other two cannot — the branch taken, the value rejected, the exception message.

The practical integration is to make them navigable from one another. Include the trace id and span id in every log line alongside the correlation id, and a trace in Tempo or Jaeger becomes one click away from the exact log lines it produced. Micrometer Tracing populates the MDC with traceId and spanId automatically, so this costs one extra key in the encoder configuration.

Changing levels at runtime#

curl -X POST localhost:9090/actuator/loggers/com.acme.payments \
  -H 'Content-Type: application/json' -d '{"configuredLevel":"DEBUG"}'

Raise a package to DEBUG on a running instance, capture what you need, and set it back to null to restore the configured level. No redeploy, no restart, and no permanently verbose logger somebody forgot to turn off.

What to take away#

Reserve ERROR for things that need a human. Put a correlation id in the MDC on the way in and propagate it everywhere, including async work and message headers. Emit JSON in deployed environments through an async appender that does not silently drop events, and mask secrets at the encoder so one careless statement cannot leak them.