Observability: Why Your Logs Need Structure, Correlation and a Pipeline

A request comes in and takes 4 seconds. Nobody knows why. You SSH into a box, grep a log file, find the line, and it says:

2020-12-01 14:23:07 INFO  Getting test with id: 4471

Which tells you almost nothing. Was the database slow? Which of the 40 requests in flight was this one? Did it call another service, and was that slow? You have a fact with no context, on one machine, in a format only a human can read.

I’d hit that wall enough times to want to understand the alternative properly rather than copy a config from a blog post. Three concepts do almost all the work: making log events machine-readable, giving every event a correlation identifier tying it to the request it belongs to, and running a pipeline that collects events off ephemeral machines into one queryable place.

So I built a working stack end to end — a Spring Boot service instrumented and shipped into Elasticsearch, Logstash, Kibana and Elastic APM, all in Docker Compose: gitlab.com/rustam.niraula90/apm.

These are my notes from wiring it up.

---

Concept 1: Logs are data, so stop formatting them as prose

The line above is a string. To answer “all requests slower than 2s for user 4471 on the checkout path,” something has to re-derive fields from that string with regular expressions — and those regexes break every time someone edits a log message.

Structured logging inverts the relationship: emit the fields, let the tooling render the sentence. Same event, as JSON:

{
  "@timestamp": "2020-12-01T14:23:07.412Z",
  "level": "INFO",
  "logger_name": "com.apm.apm.test.TestController",
  "thread_name": "http-nio-8080-exec-3",
  "message": "Getting test with id: 4471",
  "trace": { "trace_id": "af3d1c...", "span_id": "b1e4..." }
}

Now level:ERROR AND trace.trace_id:af3d1c* is a query, not a parsing project.

The thing that sold me is that in Spring Boot this is a logging configuration change, not a code change. Application code keeps making ordinary SLF4J calls, and an encoder turns each event into JSON on the way out:

<appender name="jsonConsoleAppender" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LogstashEncoder">
        <providers>
            <timestamp><timeZone>UTC</timeZone></timestamp>
            <logLevel/>
            <message/>
            <loggerName/>
            <threadName/>
            <mdc/>
            <stackTrace/>
        </providers>
    </encoder>
</appender>

That separation is the part worth internalising: structured logging is a transport decision, not an API your business logic should know about. The controller still just writes log.info("Getting test with id: {}", id).

Two choices in that config I made deliberately. Timestamps in UTC, because correlating events across machines in different zones is otherwise guesswork. And <stackTrace/> as its own field, so a Java exception stays one event instead of becoming 30 unparseable lines — the classic failure mode of line-oriented log shipping.

Concept 2: Correlation IDs — the field that makes logs useful

Structure alone isn’t enough. With 40 concurrent requests you have 40 interleaved conversations and no way to follow one. You need a shared key on every event belonging to the same request.

That’s a trace ID: generated when a request enters the system, attached to every log line it produces, and propagated to every downstream service it calls. Filter by it and you get one request’s complete story, in order, across every process it touched.

The plumbing that makes this ergonomic is MDC — Mapped Diagnostic Context — a thread-local map the logging framework merges into every event. Instrumentation puts the IDs in; the encoder pulls them out:

<pattern>
    {
    "trace": {
    "trace_id": "%mdc{X-B3-TraceId}",
    "span_id": "%mdc{X-B3-SpanId}",
    "parent_span_id": "%mdc{X-B3-ParentSpanId}"
    }
    }
</pattern>

The three fields encode a hierarchy, and the distinction is what took me longest to internalise:

• trace_id — one per end-to-end request, identical across every service.
• span_id — one per unit of work inside it (an HTTP handler, a DB query).
• parent_span_id — which unit spawned this one.

With parent links, a flat event stream reconstructs into a tree, which is what lets a UI show a waterfall — and a waterfall is what answers “where did the 4 seconds go?”

X-B3-* is the B3 propagation format from Zipkin: the IDs travel as HTTP headers, so a downstream service adopts the caller’s trace instead of starting its own. Realising that this header contract is the entire mechanism of distributed tracing — everything else is presentation — was the moment the topic stopped feeling like magic.

One detail in that config: the same keys are excluded from the generic <mdc/> provider.

<mdc>
    <excludeMdcKeyName>traceId</excludeMdcKeyName>
    <excludeMdcKeyName>X-B3-TraceId</excludeMdcKeyName>
    ...
</mdc>

Otherwise every trace ID appears twice — once flat, once nested — and Elasticsearch indexes both. Structure your fields once, in the shape you’ll query.

Concept 3: Instrumentation without touching your code

Logs tell you what your code chose to say. Traces need timing around everything — every HTTP handler, every JDBC call, every outbound request — and hand-wrapping all of that isn’t realistic.

The answer is a runtime agent. On the JVM, -javaagent loads before main and rewrites bytecode as classes load, wrapping known framework entry points with timing and ID propagation:

entrypoint: ["java",
  "-javaagent:/app/libs/elastic-apm-agent-1.19.0.jar",
  "-Delastic.apm.application_packages=com.apm",
  "-Delastic.apm.service_name=apm-service",
  "-Delastic.apm.server_urls=http://apm-server:8200",
  "-cp", "/app/resources:/app/classes:/app/libs/*",
  "com.apm.apm.ApmApplication"]

Four flags is the whole integration. There’s no tracing code in the application, and yet every controller method, every Hibernate query and every outgoing call gets a span with a parent link. The agent also seeds the MDC keys the logging config above reads — which is exactly how logs and traces end up sharing an ID without either subsystem knowing about the other. Watching that happen for the first time is what made the design click.

application_packages is the flag I’d have skipped if I hadn’t read what it does: it tells the agent which frames are yours, so stack traces highlight your code rather than 60 lines of framework internals.

The trade-off is worth stating plainly: agents give you breadth for free, but they only know the frameworks they were taught, they cost startup time and some overhead, and they’re opaque when they misbehave. Modern practice has largely converged on OpenTelemetry for this role — same agent concept, vendor-neutral wire format — and that’s what I’d reach for now.

Concept 4: The pipeline — collect, parse, store, visualise

Application containers are ephemeral. Logs written inside them die with them, so events have to be moved somewhere durable. Every observability stack, whatever the brand names, is the same four stages:

  app (stdout, JSON)
        │
    ┌───▼────┐   collect       ┌──────────┐   parse/enrich
    │Filebeat│ ──────────────▶ │ Logstash │ ─────────────┐
    └────────┘                 └──────────┘              │
                                                    ┌────▼─────────┐
  app (APM agent) ──── traces ───▶ APM Server ────▶ │Elasticsearch │
                                                    └────┬─────────┘
                                                         │ query
                                                    ┌────▼───┐
                                                    │ Kibana │
                                                    └────────┘

• Collect (Filebeat) — a lightweight agent that tails logs and forwards them. Deliberately dumb, because it runs everywhere.
• Parse and enrich (Logstash) — heavier processing: reshape fields, add metadata, route.
• Store and index (Elasticsearch) — the inverted index that makes ad-hoc queries over billions of events fast.
• Visualise (Kibana) — search, dashboards, trace waterfalls.

Splitting collect from parse is the architectural decision that matters. Collection has to be cheap and ubiquitous; parsing is CPU-hungry and centralised. Keeping the sidecar dumb is what makes running one per host affordable.

Discovery by label, not by path

The obvious way to collect container logs is to mount known paths. That breaks the moment a container is rescheduled or a new service appears — someone has to go update config.

The better concept is autodiscovery: the collector watches the Docker socket and configures itself from container metadata, so a service opts itself in.

filebeat.autodiscover:
  providers:
    - type: docker
      labels.dedot: true
      templates:
        - condition:
            contains:
              container.labels.collect_logs_with_filebeat: "true"
          config:
            - type: container
              paths:
                - "/var/lib/docker/containers/${data.docker.container.id}/*.log"
              processors:
                - decode_json_fields:
                    when.equals:
                      docker.container.labels.decode_log_event_to_json_object: "true"
                    fields: ["message"]
                    target: ""
                    overwrite_keys: true

The service declares its own participation with two labels:

labels:
  collect_logs_with_filebeat: "true"
  decode_log_event_to_json_object: "true"

Add a service, give it the labels, and it appears in Kibana. Nothing about the logging infrastructure changes. Configuration flows from the workload to the platform, rather than the platform maintaining a registry of workloads — the same inversion Kubernetes label selectors are built on, which is where I recognised the pattern from.

That second label solves a specific annoyance I ran straight into. Docker wraps container stdout in its own JSON envelope, so a carefully structured event arrives as a string stuffed inside a message field — JSON inside JSON, and none of the inner fields are queryable. decode_json_fields with target: "" re-parses that inner string and hoists the fields to the top level. Anyone shipping JSON logs through Docker meets this; knowing the name of the fix saves an afternoon.

Concept 5: Reproducible topology

Six services with a specific wiring order isn’t something to set up by hand twice. Declaring the topology — dependency order, private network, environment — is what makes the whole thing one command:

services:
  apm:
    depends_on:
      - apm_db
      - filebeat
      - apm-server
    environment:
      SPRING.DATASOURCE.URL: jdbc:mysql://apm_db:3306/APM?createDatabaseIfNotExist=true
    networks:
      - apm-network

Two things this taught me beyond “use Compose.” Service names are DNS inside the network, so jdbc:mysql://apm_db:3306 resolves by name and no IPs appear in config anywhere. And environment-variable overrides mean the same build artifact runs locally and in the stack with only its wiring changed — the twelve-factor rule, and Spring’s relaxed binding (SPRING.DATASOURCE.URL → spring.datasource.url) exists precisely to make it painless.

I built the image with Jib rather than a Dockerfile:

<plugin>
    <groupId>com.google.cloud.tools</groupId>
    <artifactId>jib-maven-plugin</artifactId>
    <configuration>
        <from><image>openjdk:8-jdk-alpine</image></from>
        <to><image>${docker.registry.host}/${docker.registry.repository}:${docker.registry.version}</image></to>
    </configuration>
</plugin>

Jib layers dependencies separately from application classes, so a code change rebuilds only the thin top layer while dependencies stay cached. That layering insight generalises to any Dockerfile: order build steps from least-frequently-changed to most.

Design notes: what this stack is scoped for

I built this to understand the concepts on a laptop, and the configuration reflects that. Worth being explicit about the gap between this and a production deployment, since the delta is itself a useful list:

• Elasticsearch runs discovery.type=single-node as root with no authentication. One node means no replicas, and open unauthenticated search is fine on a private Docker network and nowhere else. Production wants a multi-node cluster with TLS and role-based access.
• Credentials are inline (MYSQL_ROOT_PASSWORD: root). Fine for a disposable local stack; secrets management is the real answer.
• No retention policy. Log volume grows without bound, so index lifecycle management — rollover and delete — is the next thing to add.
• No sampling. Tracing every request is exactly right at demo traffic and untenable at scale, which is what head-based and tail-based sampling exist for.
• The Logstash output index is logstash-s%{+YYYY.MM.dd}, one character off the conventional logstash- prefix. Harmless in isolation, and a neat demonstration that index naming is a contract: dashboards and lifecycle policies match on those patterns, so the convention is worth pinning down before you have dashboards.

What I took away

The concepts turned out to be small and to compose cleanly. Structure your events so machines can read them. Stamp every one with the ID of the request that caused it. Let an agent instrument what you’d never wrap by hand. Ship it all somewhere durable and queryable. Get those four right and the 4-second request stops being a mystery — you filter by its trace ID and read the waterfall.

What I hadn’t expected was how much of the work is plumbing decisions rather than tooling choices: UTC or local, nested or flat fields, labels or paths, collect-then-parse or parse-at-source. The brand names change every few years; those decisions don’t.