Log generation best practices, with a Spring Boot example

Good log analysis starts before anything is collected. If an application writes logs that are missing ids, mixed in time zones or full of secrets, no tool can make them easy to read later. This guide covers what to log and how to log it, using a Java Spring Boot service as the example. The ideas apply to any language, and the last section covers sending the logs to Graylog.

What makes a log line useful

A good log line answers four questions: when it happened, how serious it was, which part of the system wrote it, and which request or order it belongs to. Message text should describe the event in a stable form, so the same event always looks the same. Put the variable parts, such as ids and amounts, in named fields rather than building them into the message, so that you can group and filter them later.

A Spring Boot example

Spring Boot uses Logback by default. The example below has three parts: a filter that gives each request an id, a Logback configuration that puts that id on every line, and a service that logs a payment step with its outcome.

1. Give every request an id

The filter reads an id from the X-Request-Id header if the caller sent one, or makes a new one. It stores the id in MDC, a per-thread map that Logback can print on every line, and it removes the id when the request ends so that it cannot leak into the next request on the same thread. It also returns the id in the response, so a client can quote it when reporting a problem.

package com.example.checkout;

import jakarta.servlet.FilterChain;
import jakarta.servlet.ServletException;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.Optional;
import java.util.UUID;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;

@Component
public class RequestIdFilter extends OncePerRequestFilter {

    static final String HEADER = "X-Request-Id";
    static final String MDC_KEY = "requestId";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain chain)
            throws ServletException, IOException {
        String id = Optional.ofNullable(request.getHeader(HEADER))
                .filter(s -> !s.isBlank())
                .orElseGet(() -> UUID.randomUUID().toString());
        MDC.put(MDC_KEY, id);
        response.setHeader(HEADER, id);
        try {
            chain.doFilter(request, response);
        } finally {
            MDC.remove(MDC_KEY);
        }
    }
}

2. Put the id and the time on every line

This Logback configuration writes readable lines to the console. The pattern puts an ISO timestamp with its offset first, then the level, the thread, the service name, the request id (or none outside a request), the logger name and the message. Save it as src/main/resources/logback-spring.xml. Spring Boot reads this file automatically.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <property name="APP_NAME" value="checkout"/>

  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %-5level [%thread] service=${APP_NAME} requestId=%X{requestId:-none} %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="CONSOLE"/>
  </root>
  <logger name="com.example.checkout" level="DEBUG"/>
</configuration>

If your logs are read by a program, JSON is easier to parse than a text pattern. The logstash-logback-encoder library writes one JSON object per line, and it includes every MDC value as a field. To use it, add the library to your build and replace the encoder above with net.logstash.logback.encoder.LogstashEncoder. Check the library's README for the current version and its setup steps.

3. Log the events, not the noise

The service below logs when a payment starts and how it ends. It uses placeholders ({}) instead of string concatenation, so the message is only built when the level is enabled. It logs the exception as the last argument, so the stack trace is kept. It logs ids and amounts, but never card numbers or tokens.

package com.example.checkout;

import java.time.Duration;
import java.util.concurrent.TimeoutException;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Service;

@Service
public class PaymentService {

    private static final Logger log = LoggerFactory.getLogger(PaymentService.class);
    private static final Duration TIMEOUT = Duration.ofSeconds(2);

    public void charge(String orderId, long amountCents) {
        long started = System.nanoTime();
        log.info("payment started orderId={} amountCents={}", orderId, amountCents);
        try {
            callGateway(orderId, amountCents);
            log.info("payment succeeded orderId={} durationMs={}", orderId, millisSince(started));
        } catch (TimeoutException e) {
            log.warn("payment timed out orderId={} timeoutMs={} durationMs={}",
                    orderId, TIMEOUT.toMillis(), millisSince(started));
            throw new IllegalStateException("payment timed out", e);
        }
    }

    private void callGateway(String orderId, long amountCents) throws TimeoutException {
        // the real call to the payment provider goes here
    }

    private static long millisSince(long startNanos) {
        return (System.nanoTime() - startNanos) / 1_000_000;
    }
}

Notice the three log lines. Each one has the same field names, so they can be searched and grouped together. The timeout is logged at WARN with its ids and then rethrown. The service does not log the stack trace itself, so the handler higher up the call stack logs it once, rather than every layer logging the same error.

Best practices

• Use one message shape per event. Write payment timed out orderId=... every time, not a different sentence each time. Stable messages can be counted.
• Use fields for variable data. Ids, durations, counts and status codes go in named fields. Use the same name every time (orderId, not order_id in one place and order in another).
• Log in UTC or with an offset. A timestamp without a time zone is easy to misread when services run in different regions. The pattern above includes the offset.
• Choose levels by who needs to act. ERROR means something failed and a person or an alert should look at it. WARN means something went wrong but was handled. INFO records normal milestones such as a payment starting or finishing. DEBUG is for developers and should be off in production by default.
• Log an exception once. Log it where you handle it, and pass the exception object as the last argument so the stack trace is included.
• Never log secrets or personal data. Passwords, tokens, card numbers, session ids and full customer records should not reach the log. If you must refer to a customer, use an internal id.
• Set a request id on every request. Accept one from the caller, create one if none is sent, and return it in the response. This is the key that connects logs across services.
• Keep the hot path quiet. Do not log inside a loop that runs thousands of times per second. Log the summary instead: how many items were processed and how long it took.
• Make levels configurable. Change them per package at runtime or in configuration, so you can turn on DEBUG for one service during an incident without redeploying everything.

Sending the logs to Graylog

Once the application writes good lines, the logs need to reach Graylog. There are three common routes:

1. GELF over TCP or UDP. The application sends structured messages straight to Graylog. Set up a GELF input in Graylog first, then point an appender at it. The Graylog GELF input documentation explains the input options, including the protocol, port and TLS setting.
2. A log shipper reading the files. Filebeat, Fluent Bit or Fluentd reads the log files and forwards them. This keeps the application unchanged, and the shipper can add host and pod names. Check the shipper's documentation for the Graylog output it supports.
3. Syslog. For servers and older systems, a Syslog input in Graylog receives the lines directly. It is simple, but it carries fewer structured fields than GELF or JSON.

In all three cases, the Graylog inputs documentation describes how to create the input and check that messages arrive. After the logs arrive, the Graylog extractors guide shows how to pull fields such as requestId out of plain text lines when the application does not send them as structured fields.

Check your setup

Before you rely on the logs in an incident, run a test. Send a request with a known X-Request-Id, then search Graylog for that id. If the search returns the request's lines from every service it touched, the setup works. If it returns nothing, check the time zone, the field names and whether the input is running.

Next steps

Once the logs arrive, you can read them in order with the guides on reading production logs across several services and sorting a Graylog export. For a CSV file exported from Graylog, the Log Sorter can put the lines in time order and filter them. The Log Playground opens several log files side by side.

Questions