The previous lesson left CicloUrbana under watch: Prometheus collects, Grafana draws and Alertmanager notifies. But alerts always end in the same sentence. At four in the morning a message arrives saying "3 % error rate on rental start", and the immediate question —what exactly failed— is answered by no graph. A metric knows how to count; it does not know how to tell you what happened.

That is answered by the second pillar of observability, and it is the one we have been using without treating it seriously since the very first lesson: the event log. So far CicloUrbana's log is whatever Spring Boot ships out of the box plus a pattern with the traceId we added in 03-06. It does the job on a laptop. In production, with three instances on Kubernetes writing at once, it is a tape of text nobody can query.

This lesson turns it into a tool. We will look at Spring Boot's logging stack and why you never program against the implementation, at levels with a concrete policy for each CicloUrbana layer, at property-based configuration and the complete logback-spring.xml with a human-readable console in dev and JSON in prod, at structured logs that turn text into queryable data, at the MDC that makes every line of one request share an identifier, at what must never be written about the citizens of Ribalta, at the real cost of logging, and at the centralised aggregation that lets you search all three instances as if they were one.

Contents

  1. What a log is and how it differs from a metric
  2. Spring Boot's logging stack
  3. Obtaining a logger
  4. Levels and CicloUrbana's policy
  5. Parameterised messages
  6. Property-based configuration
  7. logback-spring.xml and profiles
  8. Structured logs in JSON
  9. Context: the MDC and the traceId
  10. What must never be logged
  11. The cost of logging
  12. Centralised aggregation
  13. Loki and LogQL
  14. Correlating logs across instances
  15. Security audit versus application logging
  16. Testing the logs
  17. Common Mistakes and Tips
  18. Exercises

  1. What a log is and how it differs from a metric

A log is a discrete event with context: something that happened, when, where and with what data. A metric is a numerical aggregation: how many times, how long it took. The difference is not one of format, it is one of question.

Metric Log
Unit One number per interval One event
Answers How many? How much? Since when? What exactly happened?
Cardinality Must be low (09-03) High: each line is unique
Specific identifiers Forbidden as a tag Their whole reason for being
Cost Constant with traffic Proportional to traffic
Retention Months or years Days or weeks
For alerting Yes Only through rates

The relationship between the two is one of exact complement: what 09-03 forbade putting in a tag —the user identifier, the rental identifier, the specific URI— is precisely what should go in the log. The metric says "3 % of rental starts fail"; the log says "user 4711's rental at station 2 failed because the gateway returned CARD_EXPIRED".

A good production log meets three conditions the default log does not: it is queryable (you can filter by fields, not just search for text), it is correlatable (every line of one request shares an identifier) and it is safe (it contains nothing that should not leave the system). The three central sections of this lesson are those three requirements.

  1. Spring Boot's logging stack

flowchart LR
    A[Your code<br/>log.info] --> B[SLF4J<br/>facade]
    C[Spring, Hibernate,<br/>HikariCP] --> B
    D[Libraries using JCL,<br/>JUL or Log4j] --> E[Bridges<br/>jcl-over-slf4j, jul-to-slf4j]
    E --> B
    B --> F[Logback<br/>default]
    B -.alternative.-> G[Log4j2]
    F --> H1[Console<br/>stdout]
    F --> H2[Rotated<br/>file]
    F --> H3[JSON<br/>aggregator]

SLF4J is the facade: it defines Logger, LoggerFactory and the trace/debug/info/warn/error methods. Logback is the default implementation from spring-boot-starter-logging, included in every starter. The bridges redirect to SLF4J whatever older libraries write with other APIs, which is why CicloUrbana's log is homogeneous even though Hibernate, HikariCP and Spring use different mechanisms.

Why you program against SLF4J Consequence
The code does not depend on the implementation Switching to Log4j2 touches no business line
The libraries use it too A single configuration file governs everything
Parameterised messages are an SLF4J feature Section 5 does not exist outside the facade
It is what Spring Boot configures Everything works without writing anything

Switching to Log4j2 —which brings very efficient asynchronous appenders and somewhat more powerful configuration— is a matter of replacing a dependency: you exclude spring-boot-starter-logging from the web starter and add spring-boot-starter-log4j2.

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
    <exclusions>
        <exclusion>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>

CicloUrbana's decision is Logback, the default: it is sufficient, it is better documented within the Spring ecosystem and its <springProfile> elements (section 7) are a real convenience. Log4j2 is justified with very high log volumes.

  1. Obtaining a logger

package com.ciclourbana.rentals;

public class RentalService {
    private static final Logger log = LoggerFactory.getLogger(RentalService.class);
    // ...
}

Three details that are not cosmetic. static final: one logger per class, not per instance. You pass the class, not a string: that way the logger's name matches the class's fully qualified name, which is what allows levels to be configured per package (logging.level.com.ciclourbana.rentals: DEBUG). And you import org.slf4j.Logger and org.slf4j.LoggerFactory, not Logback's: importing ch.qos.logback.classic.Logger breaks the whole abstraction.

Lombok saves the repeated line with @Slf4j, which generates exactly that field. It is convenient and very widespread; CicloUrbana declares it explicitly so it is visible where log comes from, but both options are correct.

  1. Levels and CicloUrbana's policy

Level Meaning Does anyone have to act? In production?
ERROR Something failed and the request could not be fulfilled Yes, now or tomorrow Yes
WARN Something anomalous that could be handled Watch it; if it repeats, yes Yes
INFO A relevant business or lifecycle milestone No Yes
DEBUG Detail for diagnosis No No (temporarily yes)
TRACE Exhaustive detail No Never

CicloUrbana's level policy, layer by layer:

Controllers. Nothing on the happy path: http.server.requests from 09-03 already counts and times every request far better than a log line would. Logging "entering method X" on every request is duplicating a metric at three times the cost.

Domain services. INFO on the business milestones: rental started, rental finished with amount, bike sent to maintenance. These are the events a council operator would understand, and the ones consulted when investigating. DEBUG for the detail of the calculation.

Expected business errors. A user who already has a rental in progress, an insufficient balance: WARN or even INFO, never ERROR. They are the system working, and the GlobalExceptionHandler from 03-06 already returns the right ProblemDetail. If they are logged as ERROR, the "error spike" alert fires every single day and stops being believed.

Unexpected errors. ERROR with the full exception, in the global handler and in one place only. That is the level that feeds the alert on logback_events_total{level="error"}.

Integrations (07-06). WARN on each retry, ERROR when they are exhausted, INFO when the circuit breaker opens and closes.

And the most important rule of all, which deserves to be explicit: a catch that only does e.printStackTrace() is a serious mistake. It writes to System.err, with no timestamp, no level, no logger, no traceId and without passing through any configuration: it cannot be filtered, it cannot be disabled, it never reaches the aggregator and it cannot be correlated. Worse still is the empty catch, which makes the problem disappear. A legitimate catch does one of three things: it rethrows a domain exception, it logs it with log.error("...", e) passing the exception as the last argument —never e.getMessage(), which loses the stack trace— or it ignores it with a comment explaining why.

try {
    gateway.charge(rentalId, amount);
} catch (GatewayUnavailableException e) {          // the exception, as the last argument
    log.warn("Deferred charge for rental {}: the gateway is not responding", rentalId, e);
    pendingCharges.enqueue(rentalId, amount);
}

  1. Parameterised messages

log.debug("Rental {} started by user {} at station {}", id, userId, stationId);

Never like this:

log.debug("Rental " + id + " started by user " + userId);   // WRONG

The reason is one of performance and it is concrete. In the + version, the concatenation always happens, before the method is called, even if the DEBUG level is disabled: String objects are created, toString()s are invoked and garbage is generated that the GC will have to collect, all of it to be discarded. In the parameterised version, SLF4J receives the template and the array of arguments, checks the level and only if it is enabled builds the message. In a method running a hundred times a second with DEBUG off, the difference is real and shows up in profiles as an unexpected tower under StringBuilder.append.

Three useful details: the placeholder is {} and takes no indexes, so order matters; the exception goes as the last argument with no {} (log.error("Failed to charge {}", id, e)), and SLF4J detects it and writes the stack trace; and if building an argument really is expensive —serialising a large object— you guard it with if (log.isDebugEnabled()), which in any other case is unnecessary noise.

  1. Property-based configuration

For most cases you do not need an XML file: the YAML from 02-04 is enough.

logging:
  level:
    root: INFO
    com.ciclourbana.rentals: DEBUG             # only the package under investigation
    org.hibernate.SQL: WARN
  pattern:
    console: "%d{HH:mm:ss.SSS} %-5level [%X{traceId:-no-trace}] %logger{36} - %msg%n"
    file: "%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] [%X{traceId:-}] %logger - %msg%n"
  file.name: /var/log/ciclourbana/application.log
  logback.rollingpolicy:
    max-file-size: 100MB
    max-history: 7            # days of history
    total-size-cap: 2GB       # hard ceiling for the directory
    file-name-pattern: ${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz    # compressed

The elements of the pattern: %d the date, %-5level the level padded to five characters, %thread the thread, %X{traceId:-no-trace} reads the MDC with a default value after :-, %logger{36} the name shortened to 36 characters, %msg the message and %n the line break.

The rotation policy deserves attention because it is what prevents the classic incident. Without total-size-cap, a forgotten DEBUG fills the disk, and a full disk stops the application: writing a log stops being a harmless operation. The three protections combine —size per file, days of history and total ceiling— and the .gz shrinks the text by around 90 %.

And a limitation that gives rise to the next section: properties do not let you make things conditional on a profile or define several destinations with different formats. To have a readable console in dev and JSON in prod you need the XML.

  1. logback-spring.xml and profiles

The name matters: logback-spring.xml (and not logback.xml) is the one Spring Boot loads, and only that one allows <springProfile> and <springProperty>, because the other is read by Logback before the Spring context exists.

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false">

    <!-- Brings in Spring Boot's defaults: colours, converters, CONSOLE_LOG_PATTERN -->
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>

    <springProperty scope="context" name="APP" source="spring.application.name"/>
    <springProperty scope="context" name="ENVIRONMENT" source="spring.profiles.active"/>

    <!-- ============ dev and test: human-readable console ============ -->
    <springProfile name="dev,test,local">
        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>%clr(%d{HH:mm:ss.SSS}){faint} %clr(%-5level) %clr([%X{traceId:-no-trace}]){magenta} %clr(%logger{36}){cyan} - %msg%n</pattern>
            </encoder>
        </appender>
        <root level="INFO"><appender-ref ref="CONSOLE"/></root>
        <logger name="com.ciclourbana" level="DEBUG"/>
    </springProfile>

    <!-- ============ pre and prod: JSON to stdout ============ -->
    <springProfile name="pre,prod">
        <appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="net.logstash.logback.encoder.LogstashEncoder">
                <includeMdcKeyName>traceId</includeMdcKeyName>
                <includeMdcKeyName>userId</includeMdcKeyName>
                <fieldNames>
                    <timestamp>@timestamp</timestamp>
                    <message>message</message>
                </fieldNames>
                <customFields>{"application":"${APP}","environment":"${ENVIRONMENT}"}</customFields>
                <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
                    <maxDepthPerThrowable>30</maxDepthPerThrowable>
                    <exclude>^sun\.reflect\..*</exclude>
                </throwableConverter>
            </encoder>
        </appender>

        <!-- Absorbs I/O spikes without blocking the request thread -->
        <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
            <queueSize>2048</queueSize>
            <discardingThreshold>0</discardingThreshold>   <!-- do not discard WARN or ERROR -->
            <neverBlock>true</neverBlock>                  <!-- on a full queue, discard -->
            <appender-ref ref="JSON"/>
        </appender>

        <root level="INFO"><appender-ref ref="ASYNC"/></root>
        <logger name="org.hibernate.SQL" level="WARN"/>
    </springProfile>
</configuration>

The decisions, one by one. <include> of the defaults saves rewriting Spring Boot's converters and patterns. <springProperty> brings values from application.yml into the XML, which allows the application name and the environment to travel in every JSON line. %clr(...) colours only in dev, where a person is looking. In prod the destination is the console, not a file: that is the decision from section 12 and from the 12-Factor principles of 08-01. And AsyncAppender with neverBlock: true decides something important in advance: faced with an avalanche, losing log lines is preferred to slowing down citizens' requests; discardingThreshold: 0 guarantees that what gets discarded will not be the WARNs or the ERRORs.

  1. Structured logs in JSON

In production, a log is not text: it is data. The difference is clear when you compare the same event.

Plain text:

2026-08-31 08:14:22.481 INFO  [http-nio-8080-exec-7] [a3f19c2e] c.c.r.RentalService - Rental 84213 started by user 4711 at station 2 with fare STUDENT

The same event in JSON:

{
  "@timestamp": "2026-08-31T08:14:22.481+02:00", "level": "INFO",
  "thread_name": "http-nio-8080-exec-7",
  "logger_name": "com.ciclourbana.rentals.RentalService",
  "message": "Rental 84213 started by user 4711 at station 2 with fare STUDENT",
  "traceId": "a3f19c2e", "application": "ciclourbana", "environment": "prod",
  "rentalId": 84213, "stationId": 2, "fare": "STUDENT"
}

What changes: on plain text you can only do substring searches and fragile regular expressions; on the JSON you can query fare = "STUDENT" AND level = "ERROR", group by stationId, count by environment and build a panel. Structure turns a file into a queryable database, and that is the whole argument.

Spring Boot 3.4 ships native support with no dependencies:

logging.structured:
  format.console: ecs        # ecs (Elastic Common Schema), gelf or logstash
  ecs.service:
    name: ciclourbana
    version: ${APP_VERSION:unknown}
    environment: ${SPRING_PROFILES_ACTIVE:local}

The alternative, available for longer and still more flexible, is logstash-logback-encoder (the one from section 7):

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>7.4</version>
</dependency>
Spring Boot 3.4 native logstash-logback-encoder
Dependencies None One
Configuration YAML properties Logback XML
Formats ECS, GELF, Logstash Logstash and custom
Custom fields logging.structured.json.add customFields, StructuredArguments
Fine-grained control Limited Total

The rentalId, stationId and fare fields in the example come from structured arguments, which add fields to the JSON without cluttering the message:

import static net.logstash.logback.argument.StructuredArguments.kv;

log.info("Rental {} started by user {} at station {} with fare {}",
         kv("rentalId", id), kv("userId", userId),
         kv("stationId", stationId), kv("fare", fare));

kv writes the value into the message and adds it as an indexable field. It is what later lets you count rentals per station from the log itself, cross-referencing with the metrics from 09-04.

  1. Context: the MDC and the traceId

The MDC (Mapped Diagnostic Context) is a map associated with the current thread whose contents are added to every line that thread writes. It is what turns loose lines into the story of a request.

CicloUrbana has used it since 03-06: the TraceFilter generates an identifier, puts it in the MDC under the key traceId, returns it in a header and removes it in a finally —that MDC.remove() is not optional, because the thread is reused and the identifier would stick to the next request—. With that, the %X{traceId:-no-trace} pattern and the <includeMdcKeyName>traceId</includeMdcKeyName> in the JSON do the rest.

It is worth adding some more context in the same filter, with the same cleanup discipline:

MDC.put("traceId", trace);
MDC.put("method", request.getMethod());
MDC.put("path", request.getRequestURI());
Optional.ofNullable(SecurityContextHolder.getContext().getAuthentication())
        .map(Authentication::getName)
        .ifPresent(name -> MDC.put("userId", name));   // the identifier, NOT the email
try {
    chain.doFilter(request, response);
} finally {
    MDC.clear();                        // essential: the thread goes back to the pool
}

Propagating it to asynchronous threads. The MDC lives in a ThreadLocal, so it does not travel on its own to the @Async executor. We solved that back in 07-03 with the MdcDecorator, a TaskDecorator that copies the map on the calling thread and restores it in the worker thread's finally. The practical consequence is exactly this lesson's: the log line for sending the confirmation email carries the same traceId as the POST /api/v1/rentals request that originated it, even though it is written ten seconds later from another thread.

Why this changes everything: with the traceId on every line and in JSON format, an incident is investigated with a single query —traceId: "a3f19c2e"— that returns the complete story of that request, in order, including the lines from the asynchronous work. Without it, you have to reconstruct it from timestamps among thousands of lines from concurrent requests all interleaved. The difference between five seconds and an hour.

  1. What must never be logged

Warning. CicloUrbana's logs contain data about Ribalta's citizens and are subject to the GDPR. A log is not a private space: it is copied to an aggregator, replicated, kept for weeks, consulted by people outside the team and often ends up in a third-party service. Everything written there leaves the system.

Never Why What to do instead
Passwords, in clear or encrypted Direct account compromise Nothing; not even their length
JWT tokens (05-04) Whoever reads the log can impersonate the user The sub or the internal identifier
Card numbers, CVV Forbidden by PCI-DSS The last four digits, if needed
Email, phone, ID number, address GDPR personal data The internal identifier (userId: 4711)
The citizen's GPS coordinates They allow a person to be tracked The station, which is already public
Complete request bodies They usually contain everything above Specific, chosen fields
Authorization, Cookie headers Credentials The header name, with no value
e.getMessage() from a database error It can leak SQL and data from other rows A message of your own (03-06)

Masking. When a value has to appear, it is masked before being logged:

public final class Masker {

    public static String email(String e) {        // [email protected] -> a***@ribalta.example
        if (e == null || !e.contains("@")) return "***";
        return e.charAt(0) + "***" + e.substring(e.indexOf('@'));
    }

    public static String card(String number) {    // -> **** **** **** 4242
        return number == null || number.length() < 4 ? "****"
                : "**** **** **** " + number.substring(number.length() - 4);
    }
}

In case something does slip through, Logback allows a RegexReplaceRule or a custom MessageConverter that replaces patterns —long 16-digit numbers, strings beginning with eyJ, typical of a JWT— before writing. It is a safety net, not an excuse for relaxing the discipline in the code.

Retention and rights. Two GDPR consequences that surprise people and are worth deciding early: logs must have a defined and enforced retention period —30 days for the application log is a common and defensible value— and, if they contain personal data, a citizen's right to erasure reaches the logs too. The cheapest way to satisfy both is the one in the table: log internal identifiers and not personal data, which means the log stops being a store of personal data and the problem disappears at source.

  1. The cost of logging

Writing a log is not free and its cost has three components: formatting the message, serialising to text or JSON and writing to the destination. The third dominates, because a write to disk or to a socket is blocking I/O on the request thread.

Indicative numbers, per line: an INFO to the console costs on the order of tens of microseconds; with AsyncAppender the handover drops to single-digit microseconds, because the thread only enqueues. That sounds like little until you multiply it: leaving DEBUG enabled on the Hibernate package in production easily produces twenty lines per request, and at 100 requests per second that is 2,000 lines per second, tens of megabytes per minute, a full disk within hours and noticeably worse latency. It is one of the most frequent causes of degradation after a deployment, and it is entirely self-inflicted.

Three concrete measures. AsyncAppender (section 7), which decouples the request thread from the writing, with the explicit decision to discard rather than block. Parameterised messages (section 5), which avoid building what is not going to be written. And /actuator/loggers from 07-01, which resolves the whole dilemma:

# Raise the detail on a specific package, at runtime, with no restart
curl -X POST -u admin:*** -H 'Content-Type: application/json' \
     -d '{"configuredLevel":"DEBUG"}' \
     http://localhost:8081/actuator/loggers/com.ciclourbana.rentals

# And put it back when you are done: {"configuredLevel":null}

That is the correct way to investigate in production: INFO as the permanent baseline, DEBUG for fifteen minutes on one specific package and on one single instance, and back again. Never a global DEBUG "to see what is going on", and never leaving it on.

It is also worth watching the log itself as a metric: logback_events_total{level="error"} from 09-03 lets you alert on an error spike in 09-04 without reading a single line, which is the cheap way to use logs for alerting.

  1. Centralised aggregation

With three replicas on Kubernetes, each one writes its own lines and none has the complete story. Worse: containers are ephemeral, and when the pod that failed disappears, its log disappears with it. Centralised aggregation solves both things.

The first step is a consequence of principle XI of the 12-Factor app from 08-01: logs are an event stream and the application writes to stdout. It does not manage files, or rotation, or destinations. The reasons:

  • The container has no durable disk: a file inside the container is lost on every restart and nobody sees it.
  • Rotation is already done by the platform; doing it in the application as well duplicates work and fills the node's disk.
  • Writing to stdout makes docker logs and kubectl logs work, which is the first thing anyone is going to try.
  • The collector —Promtail, Fluent Bit, the cloud agent— reads that output and adds pod metadata the application does not know.

Hence in logback-spring.xml the prod profile uses a ConsoleAppender, even though it seems to contradict the rotation policy from section 6: that policy is for runs outside a container.

Stack Components Strong at Cost When
ELK / Elastic Elasticsearch + Logstash/Beats + Kibana Full-text search, very powerful High: memory and operation Large volume and a need for analysis
Grafana Loki Loki + Promtail + Grafana Indexes labels, not content: cheap Low CicloUrbana: Grafana is already there
CloudWatch Logs (08-03) Agent included in ECS Zero operation on AWS Medium, per GB ingested Everything on AWS
Datadog Logs Agent Integrated with metrics and APM High Datadog is already being paid for

CicloUrbana's choice is Loki, for three reasons: its indexing model makes it very cheap to operate, it is queried from the same Grafana as 09-04 —so one panel can show metrics and logs together— and it uses the same label vocabulary as Prometheus, which halves what has to be learned.

  1. Loki and LogQL

# added to docker-compose.observability.yml from 09-04
  loki:
    image: grafana/loki:3.0.0
    command: ["-config.file=/etc/loki/local-config.yaml"]
    ports: ["3100:3100"]
    volumes: ["loki-data:/loki"]
    networks: [ciclourbana-network]

  promtail:
    image: grafana/promtail:3.0.0
    command: ["-config.file=/etc/promtail/config.yml"]
    volumes:
      - ./observability/promtail.yml:/etc/promtail/config.yml:ro
      - /var/lib/docker/containers:/var/lib/docker/containers:ro
    depends_on: [loki]
    networks: [ciclourbana-network]

And the data source provisioned in Grafana, alongside the Prometheus one:

  - name: Loki
    type: loki
    access: proxy
    url: http://loki:3100

How Loki works. It does not index the content of the lines, only a small set of labels (app, environment, pod, level). It first selects by labels —which is instantaneous— and then filters the text of that subset by brute force. Hence it is cheap, and hence too its golden rule, identical to the one in 09-03: labels must be of low cardinality; labelling by traceId in Loki is the same disaster as labelling by it in Prometheus.

LogQL starts out like PromQL and adds filters and analysis:

# 1. Every line of one specific request: the query that resolves incidents
{app="ciclourbana", environment="prod"} | json | traceId = "a3f19c2e"

# 2. Errors from one specific station, using the StructuredArguments fields
{app="ciclourbana"} | json | level = "ERROR" | stationId = 2

# 3. From log to metric: errors per second and per pod
sum by (pod) (rate({app="ciclourbana"} | json | level = "ERROR" [5m]))

# 4. Rentals finished per minute, counted from the log
sum(count_over_time({app="ciclourbana"} |= "Rental finished" [1m]))

# 5. Latency extracted from the message itself
{app="ciclourbana"} | json | unwrap durationMs | quantile_over_time(0.95, [5m])

The key operators: |= and != filter by substring, |~ by regular expression, | json parses the JSON line and exposes its fields —which is what makes section 8 pay off— and rate, count_over_time and quantile_over_time turn logs into time series that are drawn on the same panel as the Prometheus metrics.

That last capability is what justifies the choice: on a single Grafana dashboard you can have the p95 latency graph from 09-04 and, right underneath it, the ERROR log lines from the same interval, synchronised in time. Detecting and understanding on the same screen.

  1. Correlating logs across instances

With Loki and the traceId in the MDC, investigating an incident becomes a three-step procedure:

  1. The citizen or the alert supplies the identifier. The GlobalExceptionHandler from 03-06 already returns the traceId in the ProblemDetail and in the response header, so whoever calls the council can read it off their screen.
  2. A LogQL query with that identifier returns every line of that request, from whichever instance and whichever thread, including those from the asynchronous work thanks to the TaskDecorator.
  3. You read the complete story in order: the request coming in, the domain's decisions, the exception with its stack trace, the deferred charge.

Without correlation, that same job consists of searching by approximate timestamp among the interleaved lines of three pods, with dozens of concurrent requests. The traceId is, by a wide margin, the best investment per line of code in this whole module.

One honest limitation remains: CicloUrbana's traceId exists only inside the application. When the request goes out to the payment gateway (07-06), the provider does not know it and its log does not contain it. And if tomorrow the monolith is split up (07-05), each service will generate its own and the correlation will break at the boundary. The solution to that is a standard for propagation between processes, and it is exactly the subject of the next lesson.

  1. Security audit versus application logging

The security events from 05-05 —logins, authentication failures, @PreAuthorize denials, role changes— look like logs and are not quite:

Application log Audit record
Purpose Diagnose Account for: who did what and when
Audience The technical team Security, compliance, a judge
Retention Days or weeks Months or years, by regulation
May be lost Yes (AsyncAppender discarding) No: it must be reliable
Modifiable Irrelevant It must be tamper-proof
Volume High Low
Where it lives Loki, 30 days A table in PostgreSQL or WORM storage

Why it is worth separating them. An audit record that gets discarded when the queue fills up is no good as evidence; one that expires after 30 days does not meet the regulation; and one mixed in among millions of INFO lines cannot be handed to anyone. In CicloUrbana, the AuthenticationSuccessEvent, AuthenticationFailureBadCredentialsEvent and AuthorizationDeniedEvent from 05-05 are listened to with an @EventListener and stored in a security_audit table —with its Flyway migration— and are also logged as WARN in the application log so they can be seen in context. The first is the evidence; the second, the convenience.

A final warning that links back to section 10: the audit record does contain identifiers of people, by definition. Precisely for that reason it must be controlled —restricted access, defined retention— and not mixed in with the general log the whole team can reach.

  1. Testing the logs

When a log line is part of the expected behaviour —a security warning, an error that feeds an alert— it is worth testing it. JUnit 5 and Spring Boot offer two ways.

OutputCaptureExtension, which captures standard output:

@ExtendWith(OutputCaptureExtension.class)
class RentalServiceLogTest {
    @Test
    void warnsWhenTheChargeIsDeferred(CapturedOutput output) {
        rentalService.finish(84213L, new FinishRentalRequest(2L));
        assertThat(output).contains("Deferred charge for rental 84213")
                          .doesNotContain("4111111111111111");   // the card, never
    }
}

Logback's ListAppender, more precise because it inspects the events rather than the text:

class GlobalExceptionHandlerTest {

    private final ListAppender<ILoggingEvent> appender = new ListAppender<>();
    private final Logger logger = (Logger) LoggerFactory.getLogger(GlobalExceptionHandler.class);

    @BeforeEach
    void attachAppender() { appender.start(); logger.addAppender(appender); }

    @AfterEach
    void detachAppender() { logger.detachAppender(appender); }

    @Test
    void aBusinessErrorIsNotLoggedAsError() {
        handler.handle(new RentalInProgressException(4711L));

        assertThat(appender.list).singleElement().satisfies(event -> {
            assertThat(event.getLevel()).isEqualTo(Level.WARN);       // WARN, not ERROR
            assertThat(event.getFormattedMessage()).contains("4711");
        });
    }
}

The second test is the interesting one: it verifies the level, which is exactly the decision from section 4 and the one that makes the 09-04 error alert credible. And the doesNotContain in the first is a cheap and effective way of turning the policy from section 10 into an automated test: a test that fails if somebody logs a card.

Two warnings: ListAppender requires Logback's Logger and that is why it is the only exception to the rule about not importing the implementation; and you have to detach the appender in the @AfterEach, because the logger is static and it would leak into the following tests.

Common Mistakes and Tips

e.printStackTrace() or an empty catch. No level, no timestamp, no traceId, outside all configuration and never reaching the aggregator. Always log.error("message", e) with the exception as the last argument, or rethrow.

Concatenating instead of parameterising. log.debug("Rental " + id) builds the string even if DEBUG is off. Always {}.

Logging e.getMessage() instead of the exception. You lose the stack trace, which is the only thing that lets you locate the failure, and a database exception's message can leak data.

Marking expected business errors as ERROR. A user with a rental in progress is not a system failure. If they are logged as ERROR, the error alert fires daily and the team stops looking at it.

Logging tokens, passwords, emails or complete bodies. A JWT in the log allows a Ribalta citizen to be impersonated, and the log is copied, replicated and read by people outside the team. Internal identifiers and masking.

Forgetting MDC.clear(). The thread goes back to the pool with the previous request's traceId and contaminates the log exactly when it is needed most. Always in the finally.

Leaving DEBUG on in production. Tens of megabytes per minute, worse latency and a full disk. You raise it at runtime with /actuator/loggers, on one package and for a while.

Writing to a file inside a container. The file is lost with the pod and nobody sees it. To stdout, and let the platform collect it (12-Factor, 08-01).

Tip: adopt JSON in pre and prod from day one, with a coloured console only in dev. Migrating later forces you to redo every query in the aggregator.

Tip: always set total-size-cap and max-history whenever you write to a file. A full disk stops the application, and it is an incident avoidable with two lines.

Tip: write a test that fails if a sensitive value appears in the log. It is the only way for the policy from section 10 to survive team turnover.

Exercises

Exercise 1: fixing a method

This method concentrates six of the logging mistakes covered in the lesson. Find them, explain the risk of each and write the corrected version.

@PostMapping("/api/v1/rentals")
public ResponseEntity<RentalResponse> start(@RequestBody StartRentalRequest p,
                                            @RequestHeader("Authorization") String token) {
    log.info("Entering start with " + p.toString() + " and token " + token);
    try {
        RentalResponse r = rentalService.start(p);
        log.info("Rental created");
        return ResponseEntity.status(201).body(r);
    } catch (UserWithRentalInProgressException e) {
        log.error("Error: " + e.getMessage());
        throw e;
    } catch (Exception e) {
        e.printStackTrace();
        throw e;
    }
}

Exercise 2: the investigation

It is 04:12. Alertmanager warns: "4.1 % error rate in prod". You have Grafana with Prometheus and Loki, three replicas, JSON logs with traceId, and the dashboard from 09-04. Describe the complete investigation procedure step by step, writing the specific PromQL and LogQL queries you would run at each step and what you would decide depending on what each one returns.

Exercise 3: designing the logging policy

Ribalta council is asking for a written logging policy ahead of the data protection audit. Draft it for CicloUrbana covering: what is logged in each layer and at what level, the format and destination per environment, which data is forbidden and how that is guaranteed, retention for each type of record, who has access, and how the detail is raised for investigation without deploying. Justify each decision.

Solutions

Solution 1.

Mistake 1 — concatenation instead of parameterisation. "Entering start with " + p.toString() is always built, even with INFO disabled.

Mistake 2 — logging the token. The serious failure: whoever reads that log can impersonate the citizen until the JWT expires, and the log is copied to the aggregator and seen by the whole team. It is also a reportable security incident.

Mistake 3 — dumping the complete request body. p.toString() may contain personal data, present or future; all it takes is for somebody to add a field to the record for it to start leaking without anyone noticing.

Mistake 4 — an entry log in the controller. It duplicates what http.server.requests from 09-03 already measures better and more cheaply, and it multiplies the volume by the traffic.

Mistake 5 — ERROR for a business error, and only the message. A user with a rental in progress is the partial unique index from 04-08 working: it is WARN or INFO. And e.getMessage() loses the stack trace.

Mistake 6 — e.printStackTrace(). It goes to System.err with no level, no timestamp, no traceId and never reaching Loki. Besides, this catch contributes nothing: the GlobalExceptionHandler from 03-06 already centralises the handling and the logging.

Corrected version:

@PostMapping("/api/v1/rentals")
public ResponseEntity<RentalResponse> start(@RequestBody StartRentalRequest p) {
    RentalResponse r = rentalService.start(p);
    return ResponseEntity.status(201).body(r);
}

The controller logs nothing, which is correct: the metric counts the request and the global handler deals with the errors. The business milestone is logged where it happens, in the service:

log.info("Rental started {} {} {}",
         kv("rentalId", rental.getId()),
         kv("userId", user.getId()),               // the identifier, never the email
         kv("stationId", request.originStationId()));

And the global handler decides the level according to the nature of the error: WARN with no stack trace for business ones, ERROR with the full exception for unexpected ones. The traceId is supplied by the TraceFilter's MDC, without anybody writing it.

Solution 2.

Step 1 — which endpoint and which instance? In Grafana, over Prometheus:

sum by (uri, instance) (rate(http_server_requests_seconds_count{outcome="SERVER_ERROR"}[5m]))

If the errors are spread across all three instances, the problem is common —code, database or an external service—; if they concentrate on one, it is that instance —memory, disk, a degraded pod— and the immediate action may be to take it out of the load balancer. Let us suppose they are spread out and the uri is /api/v1/rentals.

Step 2 — since when, and does it coincide with anything? You widen the range to 6 hours and compare the start of the rise with the deployments panel or with application_ready_time_seconds. If it started right after a deployment, the main hypothesis is a regression and the action is to roll back (08-05) before investigating further: you restore the service first.

Step 3 — which specific error? In Loki:

{app="ciclourbana", environment="prod"} | json | level = "ERROR"

You look for the dominant pattern. If dozens of GatewayUnavailableExceptions appear, the cause is external; if CannotAcquireLockException or connection timeouts appear, it is the database.

Step 4 — quantify by error type:

sum by (logger_name) (rate({app="ciclourbana"} | json | level = "ERROR" [5m]))

It turns the logs into a time series and says which component dominates, instead of deducing it by reading.

Step 5 — the complete story of one case. You take a traceId from an ERROR line and:

{app="ciclourbana", environment="prod"} | json | traceId = "9c4b21fa"

It returns the whole request, in order, including the asynchronous lines: what was attempted, what the external system answered, with what message and at what point it broke.

Step 6 — confirm with the metrics of the cause. If the suspect is the gateway: resilience4j_circuitbreaker_state{state="open"} and histogram_quantile(0.95, sum by (le) (rate(http_client_requests_seconds_bucket[5m]))). If it is the pool: hikaricp_connections_pending. The point of this step is not to settle for the first hypothesis: the logs show the symptom in one case, the metrics confirm that it is general.

Decision: if the cause is external and the circuit breaker is doing its job, you document it, notify the provider and go back to sleep, because the fallback from 07-06 keeps the service up. If it is a regression of our own, you roll back. If it is the database, you look at the postgres_exporter and pg_stat_activity for locks. In all three cases, the investigation has taken minutes because all three signals were prepared in advance.

Solution 3.

What is logged and at what level. Controllers: nothing on the happy path, because http.server.requests already measures it. Services: INFO on the business milestones —rental started, rental finished with amount, bike to maintenance, deferred charge— with internal identifiers as structured arguments; DEBUG for the detail of the calculation, off by default. Expected business errors: WARN with no stack trace. Unexpected errors: ERROR with the full exception, only in the GlobalExceptionHandler. Integrations: WARN per retry, ERROR when they are exhausted, INFO on circuit breaker state changes. Security: the 05-05 events to the audit table and to WARN.

Format and destination. dev and test: a coloured, readable console, com.ciclourbana at DEBUG. pre and prod: JSON to stdout with AsyncAppender, root level INFO, collected by Promtail into Loki. Justification: humans read text and machines read JSON, and in a container the only sensible destination is standard output (12-Factor).

Forbidden data and how it is guaranteed. Forbidden: passwords, tokens, cards, emails, phone numbers, ID numbers, addresses, coordinates and complete request bodies. Internal identifiers are logged instead. Guarantees at three levels: code review with this policy as an explicit criterion; automated tests asserting doesNotContain for sensitive data on the critical paths; and a RegexReplaceRule in Logback masking 16-digit numbers and JWT-looking strings, as a safety net and not as a substitute for the above.

Retention. Application log in Loki: 30 days, enough to investigate and proportionate under the GDPR. Security audit in PostgreSQL: 2 years, with restricted access and no deletion. Metrics in Prometheus: 30 days, with annual aggregates in long-term storage if the council asks for reports. Since the application log contains no personal data by design, the 30-day retention raises no conflict with the right to erasure: only the audit table does, and its legal basis is the obligation to account.

Access. Loki, through Grafana with authentication and integration with the council's directory: the whole technical team. The audit table: only the security officer, and their queries are themselves logged.

Investigating without deploying. /actuator/loggers from 07-01, protected with ADMIN on port 8081, allows a specific package to be raised to DEBUG at runtime. Mandatory procedure: one package only, one instance only if possible, a bounded amount of time and set it back to null when finished. A global DEBUG in prod is expressly forbidden, because of its effect on latency and disk.

Conclusion

The second pillar is standing. You know how a log differs from a metric and why they are exact complements: what 09-03 forbade putting in a tag is precisely what should go in the log. You know Spring Boot's stack —SLF4J as the facade, Logback by default, the bridges that unify what Hibernate and HikariCP write, and Log4j2 as an alternative you switch to with an exclusion— and why you never program against the implementation. You have a per-layer level policy, with the decision that makes the 09-04 error alert credible: expected business errors are not ERROR. And you have the serious mistake typified, e.printStackTrace(), along with the only three legitimate things a catch can do.

You know why messages are parameterised with {} and what it costs not to; you configure logging through properties with a rotation policy that stops the disk filling up; and you have CicloUrbana's complete logback-spring.xml with <springProfile>, a coloured console in dev, JSON to stdout in prod and an AsyncAppender that decides in advance to lose lines rather than slow the citizens down. You understand why in production a log is data and not text, with the same event compared in both formats, Spring Boot 3.4's native support (logging.structured.format.console: ecs) against logstash-logback-encoder, and the structured arguments that add queryable fields without cluttering the message.

The MDC and the traceId from the 03-06 TraceFilter —propagated to asynchronous threads by the 07-03 TaskDecorator— turn loose lines into the story of a request, and with Loki and LogQL that story is recovered with a single query from the same Grafana where you live with the metrics, crossing rate over logs with rate over metrics on the same panel. You have the table of aggregation stacks and the reason for writing to stdout in a container, the separation between security audit and application logging, and the tests with OutputCaptureExtension and ListAppender that make both an event's level and the absence of sensitive data verifiable. And, above all, the warning that admits no nuance: passwords, tokens, cards and personal data about Ribalta's citizens never go into a log, because the log is copied, replicated, kept for weeks and read by people outside the team.

One limit remains, the one that appeared at the end of section 14 and that neither of the two signals can overcome. CicloUrbana's traceId exists only inside the application: when the request goes out to the payment gateway from 07-06, the provider does not know it; if tomorrow the monolith is split into services (07-05), each will generate its own and the correlation will break at the boundary. And there is a question that neither metrics nor logs answer well: when a request takes two seconds and passes through the controller, three queries, a cache and a remote call, where did those two seconds go? Neither a metric's aggregate nor a succession of timestamped lines says so precisely. The module's last lesson, Distributed Tracing, answers both: spans and traces, context propagation with W3C's traceparent, Micrometer Tracing in place of the discontinued Sleuth, custom spans with the Observation API from 09-03, exemplars that jump from a point on a graph to the specific trace, and a backend where you can see the complete waterfall of a rental and point a finger at the span that ate 80 % of the time.

Spring Boot Course

Module 1: Introduction to Spring Boot

Module 2: Spring Boot Core Concepts

Module 3: Building RESTful Web Services

Module 4: Data Access with Spring Boot

Module 5: Security in Spring Boot

Module 6: Testing in Spring Boot

Module 7: Advanced Spring Boot Features

Module 8: Deploying Spring Boot Applications

Module 9: Performance and Monitoring

Module 10: Best Practices and Tips

© Copyright 2026. All rights reserved