Structured Application Logging

Our application now has substantial production behavior: Products and Inventory, Order creation and cancellation, payments, authentication and ownership. It also has meaningful failure modes, from insufficient Inventory to a provider timeout with an unknown payment outcome.

When one of these things happens in production, engineers need to answer one question: what happened? Automated tests tell us what should happen before deployment; observability tells us what is actually happening after it. Our first observability capability is BACKEND-123, and the goal of this lesson is:

Produce deliberate, structured, safe application logs that communicate important production events and failures without turning the application into a stream of unsearchable text or leaking sensitive information.

Observability Is Not Just Logging

Observability can include logs, metrics, health checks, request correlation and tracing. This module implements structured logging, request correlation, health checks and application metrics; distributed tracing architecture is out of scope. Nor does "production observability" mean deploying Grafana, operating Prometheus or Elasticsearch, or writing a log aggregation service. Our engineering context already has centralized logging and metrics infrastructure.

The split is clear. Application instrumentation is ours: emit useful events with meaningful fields and appropriate levels, record important failures, avoid sensitive data, attach request correlation, expose health and publish metrics. Observability infrastructure belongs to the platform: collect, store, index, search and retain logs, build dashboards and deliver alerts. We implement the producer side, not the centralized platform.

Why System.out.println() Is Not a Logging Strategy

What can an engineer learn from System.out.println("Order failed")? Almost nothing. Which Order, which operation, which customer? Was it a business rejection, a database error or a provider timeout? With thousands of requests running, a stream of identical Order failed lines is useless.

A log event is a message from the running application to the engineer operating it. A useful one answers enough of these questions: what happened, in which operation, to which business resource, with what outcome and, for a failure, why and whether it was expected. Not every log needs every field, but every log needs a reason to exist.

Structured Logging

An unstructured log puts everything into prose:

Failed to create order for customer customer-123 because inventory was unavailable for product 9ed4...

Humans can read it, but a machine has to parse text to find "all failures for this Product". A structured event represents each concept as its own field: an event name order_creation_rejected, customerId=customer-123, productId=9ed4c9a9-…, reason=insufficient_inventory. The readable message can stay; the fields sit next to it, so we get human readability and machine searchability at once.

Log data should have stable semantic fields rather than encoding all useful information inside prose.

Spring Boot's Built-In Structured Logging

How the fields reach the platform is a format question. Our engineering context names no log product (Elasticsearch, Loki, Splunk, Datadog, CloudWatch…), so we must not pick one and pretend it is a requirement; we ask the platform team which format their collector reads.

Spring Boot 4.1 writes structured JSON itself, without a hand-written Logback encoder. The property logging.structured.format.console (or logging.structured.format.file for a log file) selects one of three built-in formats: ecs (Elastic Common Schema), logstash (the Logstash JSON layout) or gelf (Graylog Extended Log Format). For BACKEND-123, the platform team confirms that their collector reads one JSON object per line from the container's standard output, in ECS format. Another format later would change one configuration value, not our code.

The Logger and Parameterized Messages

Spring Boot logs through SLF4J with Logback underneath. Application code declares one SLF4J Logger per class, as ApiExceptionHandler has done since module 5:

private static final Logger log =
        LoggerFactory.getLogger(CreateOrderUseCase.class);

The logger's name is the class name, which lets us set levels per package and tells the reader which component spoke. Messages use placeholders instead of concatenation: log.info("Order created: " + order.id()) builds the string even when INFO is disabled, while log.info("Order created: orderId={}", order.id()) formats it only when the event is actually written.

Fields With the SLF4J Fluent API

A placeholder still produces text: orderId=36a2… inside the message is one string to a machine. SLF4J 2's fluent API attaches real key-value fields to an event, and Boot's structured formats write each one as its own JSON member. After a successful Order creation, CreateOrderUseCase records one event:

@Transactional
public Order execute(CreateOrderCommand command) {
    // ... validate, build the Order, consume Inventory (as before)
    orderRepository.save(order);
    log.atInfo()
            .setMessage("Order created")
            .addKeyValue("event.action", "order_created")
            .addKeyValue("orderId", order.id().value())
            .addKeyValue("customerId", order.customerId().value())
            .addKeyValue("itemCount", order.items().size())
            .addKeyValue("totalCents", order.totalCents())
            .log();
    return order;
}

The message communicates the event; the fields make it searchable. The event name goes into event.action because ECS defines event as an object with an action member for exactly this purpose; a plain string field named event would clash with the schema the platform indexes against. We pass order.id().value(), so the field is the UUID and not the record's toString().

Run locally with Spring Boot's default console format, and the fields are missing:

2026-10-23T00:15:47.389+03:00  INFO 12459 --- [order-management] [           main] c.t.o.o.application.CreateOrderUseCase   : Order created

The default text pattern prints only the message. This is the fluent API's one trap: in plain text, key-value pairs appear only if the pattern asks for them.

Making the Fields Visible Locally

Local development stays human-readable but should show the same fields. Logback's %kvp conversion word prints an event's key-value pairs; we add it to the local profile from 3.06, which already raises the level for our own code:

# application-local.yml
logging:
  pattern:
    console: "%d{HH:mm:ss.SSS} %5p %-40.40logger{39} : %m %kvp%n"
  level:
    com.tarkev.ordermanagement: DEBUG

The same event now reads:

00:15:48.016  INFO c.t.o.o.application.CreateOrderUseCase   : Order created event.action="order_created" orderId="36a25516-2af2-4644-b55d-d0cabf389c9e" customerId="customer-123" itemCount="2" totalCents="24930"

JSON in Deployed Environments

Our convention from 3.06 has no production profile file: deployed environments set values through environment variables, which relaxed binding maps to properties. The deployment sets two:

LOGGING_STRUCTURED_FORMAT_CONSOLE=ecs
LOGGING_STRUCTURED_ECS_SERVICE_ENVIRONMENT=production

The application then writes one JSON object per line. Here is the same event from a real run, formatted for reading:

{
  "@timestamp": "2026-10-22T21:15:48.616261Z",
  "log": {
    "level": "INFO",
    "logger": "com.tarkev.ordermanagement.order.application.CreateOrderUseCase"
  },
  "process": { "pid": 12467, "thread": { "name": "main" } },
  "service": { "name": "order-management", "environment": "production", "node": {} },
  "message": "Order created",
  "event": { "action": "order_created" },
  "orderId": "36a25516-2af2-4644-b55d-d0cabf389c9e",
  "customerId": "customer-123",
  "itemCount": 2,
  "totalCents": 24930,
  "ecs": { "version": "8.11" }
}

The ECS formatter nests the dotted key into the event object and keeps numbers as JSON numbers. An exception passed to the logger becomes error.type, error.message and error.stack_trace. service.name comes from spring.application.name, and anything in SLF4J's MDC is added to every event automatically, which the next lesson uses for the request ID.

The platform may already attach metadata such as the environment, instance or container; do not duplicate it or invent fields without knowing its contract. If the platform needs a slightly different shape, logging.structured.json.rename, .add and .exclude adjust the JSON, and a class implementing Boot's StructuredLogFormatter can replace it entirely. We need neither.

What Should We Log?

"Log everything" creates noise, storage cost, slow searches and sensitive-data risk; "log almost nothing" turns incidents into guesswork. We need deliberate signals: important business outcomes, unexpected failures, external integration outcomes, security-relevant denials where a policy asks for them, lifecycle events, and recovery or reconciliation states.

We do not log getters, constructors, every repository call or every line. Success events are chosen deliberately too: Order created, Order cancelled, payment confirmed, Product deactivated, Inventory changed by an administrator. A Product GET needs no INFO event; normal read traffic is visible in access logs and, later, in metrics.

Log at the Layer That Owns the Information

If every layer logs a successful Order creation (the handler "Creating order", the use case "Creating order", the repository "Saving order", the handler "Order created"), one operation produces several near-identical events. Each layer knows different things and logs only what it uniquely knows:

For a business outcome, the use case has the richest context. Logging context is never passed through signatures: createOrder(command, logger, requestId, logContext) makes application methods about logging instead of behavior, and request correlation arrives next lesson as cross-cutting context.

Domain objects do not log. A log.info(...) inside Order.cancel() makes the model less framework-light, less deterministic and harder to test. Order.cancel() decides whether the transition is legal; the use case knows which workflow requested it, which customer initiated it and whether persistence succeeded.

Log After the Outcome Is Known

A success event must not claim more than we know. "Order created" logged before the save is misleading if the save fails: the log says success, the database says otherwise.

Transactions add a subtler case. CreateOrderUseCase.execute is @Transactional, so our event is written just before the commit; if the commit itself fails, the log already says "Order created". That is rare, and the failed commit still produces an ERROR event from ApiExceptionHandler for the same request, which the next lesson lets us connect. In PayOrderUseCase, code after transaction.execute(...) returns already runs after the commit. Where the guarantee truly matters, Spring can run code in TransactionSynchronization.afterCommit(), but BACKEND-123 does not need transaction-aware event publication. Log where the application considers the operation successful, never earlier.

Business Failure vs System Failure

A business failure means the system works and rejected an invalid operation: Product inactive, Inventory insufficient, Order already cancelled, Order not payable. A system failure means it could not behave normally: database unavailable, an unexpected persistence exception, a migration problem, a provider protocol failure, a programming error. They deserve different severities.

If thousands of insufficient-stock rejections are logged at ERROR, the error log becomes useless. OrderNotCancellable returns 409 ORDER_NOT_CANCELLABLE because the application behaved as designed; an ERROR would present a business conflict as an outage. The opposite is as dangerous: a PostgreSQL connection failure logged only at DEBUG is easy to miss. Our policy:

Business rejections are DEBUG, INFO or sometimes WARN, depending on their operational significance. Do not map HTTP 4xx to WARN and 5xx to ERROR mechanically; a policy is guidance, and each event still needs judgment. Malformed requests (quantity = -1, a malformed UUID) are client failures the response already explains; the metrics lesson counts 4xx responses without an event for each. Security denials can matter (repeated unauthorized administrator operations, authentication failures), but every 401 at ERROR is poor signal design; security logging needs a deliberate policy, and this course introduces no security-audit platform.

Logging Products, Inventory and Cancellation

Product administration events (product_created, product_updated, product_deactivated) carry the productId, the administrator's identity where appropriate and what changed, never the whole request body. An administrator's Inventory change, inventory_admin_updated with productId, previousQuantity and newQuantity, answers "why did Inventory suddenly become zero?". Inventory consumption is different: Order creation consumes constantly, and an INFO event for every "10 → 8" is enormous volume. That detail belongs at DEBUG or in metrics; order_created is the meaningful event.

Insufficient Inventory is also a volume question. An order_creation_rejected event with reason=insufficient_inventory, productId and requestedQuantity, at DEBUG or INFO and without a stack trace, helps diagnosis; counting such failures by reason is a job for metrics.

A successful cancellation changes the Order lifecycle and restores Inventory, so order_cancelled carries orderId, customerId and itemCount, not the entire Order. Cancelling a PAID Order is order_cancellation_rejected with reason=order_not_cancellable, not an ERROR; neither is the loser of two racing cancellations, which is usually a repeated request. An integrity failure must stand out: if restoring Inventory affects no row, JpaInventoryRepository.restore throws an IllegalStateException (7.12), the transaction rolls back and ApiExceptionHandler logs it at ERROR with the stack trace. A PostgreSQL deadlock is likewise a technical failure, never confused with INSUFFICIENT_INVENTORY.

Logging Payment Operations

Payment events must keep the distinctions module 9 built: payment_attempt_started, payment_confirmed, payment_rejected and payment_outcome_unknown. A timeout is not a confirmed failure (9.06), so "Payment failed for order X" after a timeout is a dangerous log. PayOrderUseCase records the unknown outcome where it learns it:

} catch (RuntimeException outcomeUnknown) {
    transaction.executeWithoutResult(
            tx -> recordUnknown(command, attempt.id()));
    log.atWarn()
            .setMessage("Payment outcome unknown")
            .addKeyValue("event.action", "payment_outcome_unknown")
            .addKeyValue("orderId", attempt.orderId().value())
            .addKeyValue("paymentAttemptId", attempt.id().value())
            .log();
    throw outcomeUnknown;
}

The event carries business context and no stack trace; ApiExceptionHandler logs the exception once, at WARN with its cause chain, when it maps it to 503 (9.10). Do not collapse a confirmed rejection and an integration problem into one "payment failed" either. Recovery has its own milestones ("provider call performed", "confirmed by the provider", "applied locally"), and none is logged before it is true. "Payment processed" is ambiguous: sent, accepted, confirmed or marked PAID? Each event name has exactly one meaning. Provider fields may include the provider operation and the configured timeout, never the API key, the Authorization header or a raw credential.

Unexpected Errors: Stack Traces in Logs, Once

Clients receive a safe 500 INTERNAL_ERROR. Engineers need the opposite: the operation, resource identifiers, the exception type, the stack trace and, after the next lesson, the request ID. Stack traces, SQL, Hibernate classes and provider internals never appear in API responses; logs are where they belong. ApiExceptionHandler already does this:

log.error("Unexpected failure on {}", request.getRequestURI(), exception);

The exception is the last argument, so SLF4J records its type, stack trace and cause chain; log.error(exception.getMessage()) loses exactly those. One failure should produce one stack trace. If the repository, the use case, the handler and the advice each log it, central logging holds four copies. Catching only to log and rethrow is the usual cause:

try {
    orderRepository.save(order);
} catch (RuntimeException exception) {
    log.error("Failed", exception);
    throw exception;
}

When PostgreSQL fails during Order creation, the repository knows a persistence operation failed, the use case knows for which customer, and the error boundary knows the request path and the exception. Choose one deliberate event, not the same exception everywhere:

Log an unexpected failure once, at the layer that has enough context and owns the handling decision.

Expected business exceptions such as OrderNotPayable get no stack trace. Repositories rarely log at all: "entering save()" adds nothing, and SQL diagnostics come from Hibernate's own logging when switched on, not from log.info("Running SQL: ...") in our code.

Sensitive Information and Personal Data

Logs outlive requests and are readable by more systems and people than the request was. Never log passwords, access tokens, Authorization headers, database passwords, payment provider credentials or secret keys. log.info("Authenticated request token={}", bearerToken) lets anyone with log access impersonate the caller until the token expires; log.debug("Calling provider with apiKey={}", properties.apiKey()) is a leak, however useful for debugging. "Payment provider configured", perhaps with its host, is enough.

Our payment model exposes no card details, and we keep it that way; should a provider introduce card numbers or payment tokens, the policy becomes stricter. Raw provider request and response bodies are not logged by default, because log.error("Provider failed: response={}", responseBody) may write customer data, tokens or internal fields. Extract the safe fields instead.

CustomerId is useful because ownership matters, but include it only when it improves diagnosis, and never log profile data such as name, email or address. Ownership hiding stays intact: a missing Order and another customer's Order both return 404 ORDER_NOT_FOUND, and whatever the logs record never flows back into a response. Resource IDs (orderId, productId, paymentAttemptId) usually suffice. Do not log whole entities with log.info("Order={}", order): toString() may change, sensitive fields may appear later, large collections create noise, lazy JPA relationships misbehave and the schema becomes unstable. Choose explicit fields, each with a diagnostic purpose. Such high-cardinality identifiers suit logs, but the metrics lesson must not turn them into metric tags.

Event Names and Field Names

Stable event names let the platform query event.action:payment_outcome_unknown instead of message prose. Once dashboards depend on order_created, renaming it to create_order_success breaks them: structured fields are an operational contract. Keep dynamic data out of the name (order_36a25516_created makes every name unique; order_created with an orderId field does not), and do not create events such as product_repository_find_started for method calls.

Field names need the same consistency; orderId, order_id and order in three events make every search harder. Ours are orderId, productId, customerId, paymentAttemptId, event.action, reason and durationMs. A structured reason=insufficient_inventory aggregates better than prose. It may overlap with the API code INSUFFICIENT_INVENTORY, but the audiences differ: the domain must not depend on an API error-code type just to log it.

Levels per Environment and the Cost of Logging

Levels are configuration, never code. Locally, DEBUG for our packages helps; production runs at INFO, Spring Boot's default root level. A targeted diagnostic can be switched on for one package through the environment, for example LOGGING_LEVEL_COM_TARKEV_ORDERMANAGEMENT_PAYMENT=DEBUG. Production DEBUG is no substitute for good events: if engineers need it permanently to understand basic behavior, our INFO, WARN and ERROR events are poorly designed.

Logging also has a runtime cost. log.debug("Order dump: {}", buildHugeDiagnosticRepresentation(order)) builds the representation even when DEBUG is off, because Java evaluates arguments first. The fluent API accepts a supplier that runs only when the event is written:

log.atDebug()
        .setMessage("Order dump: {}")
        .addArgument(() -> buildHugeDiagnosticRepresentation(order))
        .log();

Size matters too: entire payloads, entity graphs or thousands of OrderItems in one event increase cost, noise, indexing burden and sensitive-data exposure.

Logs Are One Signal Among Several

"Which Order failed?" is a log question. "What percentage of Order creations failed in the last hour?" is a metrics question; we could count order_created events in the logs, but a metric aggregates efficiently. "Is the application ready for traffic?" is a health check. "Which logs belong to one request?" needs correlation, the next lesson.

Logs are not an audit ledger either: not a financial record, not an immutable trail, not the source of truth. Our database is authoritative, and correctness must never depend on "we can reconstruct it from logs". Logging is instrumentation, so business correctness does not depend on log storage succeeding. We do not write logs to a table through a LogRepository (extra writes, retention and failure coupling the platform already handles), and we do not wrap the logger in a LoggingService.logOrderCreated(...); SLF4J is the abstraction. Request correlation is different: the same identifier must appear in many events, which deserves a shared mechanism.

Logging deserves a test only when it is an operational guarantee: a credential never appears, an unknown payment outcome emits its event, the request ID is propagated. Such tests assert the event name and fields rather than exact sentences, and Spring Boot's OutputCaptureExtension captures what was written. For most logic, test the business behavior, not the logging.

BACKEND-123: Refined Scope

We can now refine the backlog item:

# BACKEND-123 Add Structured Application Logging

## Context
Logs are collected centrally. Engineers need useful production diagnostics
for important operations and failures.

## Scope
- SLF4J events with safe, consistent fields for important operations.
- ECS JSON on standard output in deployed environments (Spring Boot
  structured logging); readable text with fields locally.

## Out of Scope
- Logging infrastructure, a log platform, distributed tracing, an audit ledger.

## Acceptance Criteria
- [ ] Unexpected technical failures are logged once, with the exception.
- [ ] Known business failures are not logged as system errors.
- [ ] A payment timeout is distinguishable from a confirmed payment failure.
- [ ] Credentials, tokens, secrets and raw payloads are never logged.
- [ ] Application interfaces have no logging-specific parameters.

The initial event vocabulary is the one this lesson used, from product_created to payment_outcome_unknown; we implement only the events our changes need.

Practice Exercise 1: Test the Unknown Outcome Event

Solutions: lesson 11.08.

A payment timeout must never be logged as a confirmed failure, and that is an operational guarantee worth a test. Write M11PaymentLoggingTest, a plain JUnit test next to PayOrderUseCaseTest that builds PayOrderUseCase the same way and adds @ExtendWith(OutputCaptureExtension.class). Let the mocked PaymentService throw PaymentOutcomeUnknown("read timeout", null) and assert that the captured output contains event.action with the value payment_outcome_unknown and the Order's orderId, but neither payment_rejected nor the exception message. Add a second test for a decline that expects payment_rejected and no unknown-outcome event. Assert fields, not sentences, and run the class alone and then with the whole suite.

Practice Exercise 2: Review a Log Statement

A teammate opens a pull request with this cancellation code:

log.info("Cancelling order " + order + " for token " + bearerToken);
try {
    order.cancel();
    orderRepository.save(order);
    log.info("Order cancelled");
} catch (OrderNotCancellable exception) {
    log.error("Cancel failed", exception);
    throw exception;
}

Find at least five problems and write the event you would log instead.

Practice Exercise 3: Choose the Level

Give each situation a level, and say whether the event carries a stack trace: an administrator sets a Product's Inventory from 40 to 0; a Customer orders more than is in stock; PostgreSQL refuses connections while an Order is saved; the payment provider times out; a Customer cancels an already cancelled Order.

Knowledge Check

Question 1

Why does the event name go into event.action and the Order's ID into its own orderId field instead of "order 36a2… created"?

Question 2

The local console shows Order created without any fields. What is missing, and why does production still receive them?

Question 3

Why does Order.cancel() not log, even though the cancellation is an important event?

Question 4

CreateOrderUseCase logs order_created just before the commit. What can go wrong, and why is that acceptable for BACKEND-123?

Knowledge Check Answers

Answer 1

Stable fields can be searched and aggregated without parsing prose, and the event name stays one value for every Order. A name with the ID in it would create a new "event" per Order.

Answer 2

The default console pattern prints only the message; %kvp in the local pattern prints the key-value pairs. The ECS formatter in deployed environments writes every pair as its own JSON member.

Answer 3

The domain decides whether the transition is legal and stays free of framework concerns. The use case knows which workflow asked, for which Customer, and whether the save succeeded, so it logs the outcome.

Answer 4

If the commit itself fails, the log says "Order created" for an Order that does not exist. That is rare, and the same request then produces an ERROR event from ApiExceptionHandler, which correlation lets us connect to it.

Engineering Principle

Logs are production signals, not debug print statements. Every important log should communicate an operationally meaningful event or failure.

Summary

• Our backend produces useful signals; collecting, storing and searching them is the platform's job.
• Structured logs put stable, named fields next to a readable message; Spring Boot 4.1 writes ECS, Logstash or GELF JSON through logging.structured.format.console, set per environment.
• We log through SLF4J with placeholders and attach fields with the fluent API; locally, %kvp makes them visible in text.
• Events come from the layer that owns the information, usually the use case, after the outcome is known; domain objects and signatures stay free of logging.
• Severity follows operational meaning, and a payment timeout is never logged as a confirmed failure.
• Unexpected failures are logged once, with the exception object; clients get a safe 500.
• Secrets, personal data, raw payloads and whole entities stay out of logs; event and field names are an operational contract.

In the next lesson we implement BACKEND-124, request correlation: accepting or generating a request ID, adding it to every log event automatically, returning it safely to the client and cleaning up the request context, without passing it through every method and without a distributed tracing architecture.