The service with the most errors was healthy: root cause analysis from logs with ES|QL

Elasticsearch turns raw logs into structured, searchable data at ingest. Follow the collect and analyze logs tutorial to see it end-to-end. Start a free cloud trial or try Elastic on your local machine now.

Metrics ranked three services identically at 19.1%, so root cause analysis from logs had to do the ordering. Sorting error logs by volume put catalog-api on top with 1,820 errors, though it returned 200 to every request it received. Four ES|QL queries over the same 4,688 log records found ledger-service instead, starting 955 of 956 failure chains with a connection pool of 8 and 0 connections available. Getting there took no service dependency model and nothing to maintain between incidents, only a trace.id on every record.

In this article we instrument four Python services with the Elastic Distribution of OpenTelemetry (EDOT), saturate one of them, and use ES|QL to recover which service failed first. Metrics tell you that something is wrong; logs tell you why, once you group them by request instead of by service.

Prerequisites

• Elasticsearch and Kibana 9.1 or later.
• Python 3.10 or later.
• The Elastic Cloud Managed OTLP endpoint and an API key for it. Kibana shows both under Add data > OpenTelemetry.

A companion notebook replays this incident and runs every query below, so you can follow along against your own cluster.

Root cause analysis from logs: why error counts cannot build a causal graph

A causal graph is a directed graph whose nodes are the failing components and whose edges record which failure produced which. Reading it is mechanical: walk the edges backwards from the service the user complained about, and the node you cannot walk back from is the root cause.

Causal edges can be declared in advance from a service dependency model, which covers every failure the model anticipates and has to be kept in step with the architecture as it changes. This article derives them from log fields after the fact instead. That covers one incident rather than every possible failure and needs no model to maintain.

Error counts alone give you nodes and no edges. Every service in a cascade logs one error per failed request, so their counts converge. Meanwhile, a healthy service that logs an error on a routine event outranks all of them as soon as that event is common enough. In this lab catalog-api serves less traffic than checkout-api and still logs almost twice as many errors, because it errors on more than half of its requests while the cascade services error on a fifth of theirs.

The trace.id field supplies the structure that counts cannot:

• Two errors with the same trace.id belong to the same request, so one may have caused the other.
• Two errors with different trace.id values are unrelated, however close their timestamps.

Four Python services instrumented with EDOT

checkout-api receives the order and calls payment-gateway, which calls ledger-service, which holds a fixed pool of 8 database connections. catalog-api sits outside that path and logs an ERROR on every image cache miss while still returning 200.

Install EDOT Python and the instrumentation for the libraries in use, following the documented setup:

pip install elastic-opentelemetry flask requests
edot-bootstrap --action=install

edot-bootstrap inspects the installed packages and adds the matching instrumentation, including opentelemetry-instrumentation-logging, which attaches trace context to log records.

Each service is ordinary Flask code using the standard library logger. This is ledger-service, the one that fails:

POOL_SIZE = 8
ACQUIRE_TIMEOUT_S = 0.25

pool = threading.BoundedSemaphore(POOL_SIZE)
state = {"hold_ms": 15}

@app.post("/reserve")
def reserve():
    order_id = request.json.get("order_id")
    if not pool.acquire(timeout=ACQUIRE_TIMEOUT_S):
        logger.error(
            "connection pool exhausted, no connection available after %.0fms",
            ACQUIRE_TIMEOUT_S * 1000,
            extra={
                "db.connection_pool.size": POOL_SIZE,
                "db.connection_pool.available": 0,
                "error.kind": "pool_timeout",
                "order.id": order_id,
            },
        )
        return jsonify({"error": "pool_timeout"}), 503
    try:
        time.sleep(state["hold_ms"] / 1000.0)
        return jsonify({"reservation_id": f"res-{order_id}"}), 200
    finally:
        pool.release()

The ledger-service file contains no OpenTelemetry code. Every key in extra becomes a searchable field in Elasticsearch.

The two callers add one field; the others do not. When payment-gateway fails because its dependency failed, it records which dependency:

logger.error(
    "ledger rejected reservation with status %s, cannot authorize payment",
    resp.status_code,
    extra={
        "error.kind": "authorization_failed",
        "upstream.service": "ledger-service",
        "upstream.status_code": resp.status_code,
        "order.id": order_id,
    },
)

Point the services at your OTLP endpoint and start them under opentelemetry-instrument:

export OTEL_EXPORTER_OTLP_ENDPOINT="https://<your-managed-otlp-endpoint>"
export OTEL_EXPORTER_OTLP_HEADERS="Authorization=ApiKey%20<your-api-key>"
export OTEL_RESOURCE_ATTRIBUTES="service.name=ledger-service,deployment.environment=obs-labs-causal-graph"

opentelemetry-instrument python ledger_service.py

OTEL_EXPORTER_OTLP_HEADERS is URL-encoded, so the space after ApiKey has to be written as %20.

The traffic generator drives roughly 12 checkouts and 8 product lookups per second, then raises the ledger connection hold time from 15ms to 900ms. At 8 connections and a 900ms hold, the service can serve about 8.9 requests per second, so the pool saturates and requests time out on acquire. No service returns a hardcoded error. The recorded run is 2 minutes of baseline, 4 minutes of saturation, and 1 minute of recovery, producing 4,053 successful checkouts and 956 failures.

What does a trace-correlated log record contain?

Sending OTLP to the Managed OTLP endpoint stores the logs in logs-generic.otel-default in their native OpenTelemetry shape, with no schema translation. This is what an ERROR record from the run looks like, with scope and host metadata trimmed:

{
  "@timestamp": "2026-07-26T09:03:45.139Z",
  "resource": {
    "attributes": {
      "service.name": "ledger-service",
      "deployment.environment": "obs-labs-causal-graph"
    }
  },
  "trace_id": "f9b32dca62c1e142537413a047fb9b69",
  "span_id": "c4548cab42cbdd15",
  "severity_text": "ERROR",
  "body": { "text": "connection pool exhausted, no connection available after 250ms" },
  "attributes": {
    "error.kind": "pool_timeout",
    "order.id": "10c9e056ae8c",
    "db.connection_pool.size": 8,
    "db.connection_pool.available": 0
  }
}

Three details decide what the queries can do:

• trace_id and span_id arrive without any application code setting them, because the logging instrumentation attaches the active span context to records emitted inside a request.
• Every key in extra lands under attributes with its dots intact, and Elasticsearch exposes each one by its short name. The field the code wrote, upstream.service, is the field the queries use. Resource attributes work the same way, so service.name and deployment.environment are queryable as written.
• The ECS names still resolve. trace.id, span.id, log.level, and message are built-in aliases for trace_id, span_id, severity_text, and body.text, so the queries below use whichever reads better.

The four steps that follow add one piece of the graph each, starting from nodes with no edges:

Step 1: rank services by failure rate and by error volume

Start with the failure rate per service:

FROM traces-*.otel-*
| WHERE @timestamp >= "2026-07-26T08:59:00.000Z" AND @timestamp < "2026-07-26T09:07:00.000Z"
    AND deployment.environment == "obs-labs-causal-graph" AND kind == "Server"
| STATS failed = COUNT(*) WHERE status.code == "Error", total = COUNT(*) BY service.name
| EVAL failed_pct = ROUND(100.0 * failed / total, 1)
| SORT failed_pct DESC

checkout-api, ledger-service, and payment-gateway all sit at 19.1%, with 956 failures each. The rates match because in a synchronous call chain, every hop fails when the deepest hop fails. The metric names the affected services and gives no way to order them.

Now count ERROR records per service over the same window:

FROM logs-*.otel-*
| WHERE @timestamp >= "2026-07-26T08:59:00.000Z" AND @timestamp < "2026-07-26T09:07:00.000Z"
    AND deployment.environment == "obs-labs-causal-graph" AND log.level == "ERROR"
| STATS errors = COUNT(*), traces = COUNT_DISTINCT(trace.id) BY service.name
| SORT errors DESC

catalog-api leads with 1,820 errors, almost double any other service, and it returned 200 to all 3,345 of its requests. Sorting by error count ranks services by log verbosity, which is independent of where the failure started.

Step 2: group error logs by trace ID

Group by trace.id and count how many distinct services logged an error inside each request:

FROM logs-*.otel-*
| WHERE @timestamp >= "2026-07-26T08:59:00.000Z" AND @timestamp < "2026-07-26T09:07:00.000Z"
    AND deployment.environment == "obs-labs-causal-graph" AND log.level == "ERROR"
| STATS services = COUNT_DISTINCT(service.name) BY trace.id
| STATS traces = COUNT(*) BY services
| SORT services ASC

The population splits into two. Traces with one erroring service are local problems that never propagated; traces with three are cascades.

catalog-api appears in no cascade, so the query removes the highest-volume service from the investigation without anyone reading a message.

Step 3: find which service failed first in each trace

Within a cascade, the service that logged the first error is the candidate cause. ES|QL has no window functions, so build a sortable string of timestamp plus service name, take the minimum per trace, and slice the service name back out:

FROM logs-*.otel-*
| WHERE @timestamp >= "2026-07-26T08:59:00.000Z" AND @timestamp < "2026-07-26T09:07:00.000Z"
    AND deployment.environment == "obs-labs-causal-graph" AND log.level == "ERROR"
| EVAL marker = CONCAT(DATE_FORMAT("yyyy-MM-dd HH:mm:ss.SSS", @timestamp), "|", service.name)
| STATS origin_marker = MIN(marker), services = COUNT_DISTINCT(service.name) BY trace.id
| WHERE services > 1
| EVAL origin_service = SUBSTRING(origin_marker, 25)
| STATS cascade_traces = COUNT(*) BY origin_service
| SORT cascade_traces DESC

MIN() accepts keyword fields from 8.16.0 onward, and the formatted timestamp is fixed at 23 characters, so the earliest marker is also the lexicographically smallest one. SUBSTRING(origin_marker, 25) skips the timestamp and the separator.

ledger-service is the origin in 955 of 956 cascades. checkout-api is the origin in one.

How reliable is timestamp ordering across services?

Measure it rather than assuming it:

FROM logs-*.otel-*
| WHERE @timestamp >= "2026-07-26T08:59:00.000Z" AND @timestamp < "2026-07-26T09:07:00.000Z"
    AND deployment.environment == "obs-labs-causal-graph" AND log.level == "ERROR"
| EVAL ms = DATE_FORMAT("yyyy-MM-dd HH:mm:ss.SSS", @timestamp)
| STATS spread_ms = DATE_DIFF("milliseconds", MIN(@timestamp), MAX(@timestamp)),
        distinct_ms = COUNT_DISTINCT(ms),
        services = COUNT_DISTINCT(service.name) BY trace.id
| WHERE services > 1
| STATS cascade_traces = COUNT(*),
        median_spread_ms = MEDIAN(spread_ms),
        max_spread_ms = MAX(spread_ms),
        traces_with_a_collision = COUNT(*) WHERE distinct_ms < services

Across 956 cascades, the median spread between the first and last error is 2ms, the maximum is 16ms, and 259 traces (27% of the total) contain at least one millisecond collision. Collisions are this common because the hops are local HTTP calls, while @timestamp only has millisecond resolution.

A collision is not automatically a wrong answer. Alphabetically, checkout-api sorts before ledger-service, which sorts before payment-gateway. When ledger-service and payment-gateway land in the same millisecond, MIN() still returns ledger-service, which is the correct origin. Only a tie between checkout-api and ledger-service flips the result. That is why 259 traces contain a collision and just one of them reports the wrong origin.

Timestamp ordering degrades on fast hops and on hosts whose clocks disagree by more than the gap being measured. Treat it as a strong hint rather than proof.

Step 4: build the causal edge list from upstream.service

The upstream.service field records which dependency the caller was waiting on, so every error carrying it is a directed edge. One CONCAT turns the set of them into an edge list:

FROM logs-*.otel-*
| WHERE @timestamp >= "2026-07-26T08:59:00.000Z" AND @timestamp < "2026-07-26T09:07:00.000Z"
    AND deployment.environment == "obs-labs-causal-graph"
    AND log.level == "ERROR" AND upstream.service IS NOT NULL
| EVAL edge = CONCAT(upstream.service, " -> ", service.name)
| STATS traces = COUNT_DISTINCT(trace.id), first_seen = MIN(@timestamp), last_seen = MAX(@timestamp) BY edge
| SORT traces DESC

Two edges, each observed in all 956 cascades:

ledger-service  -> payment-gateway   956 traces
payment-gateway -> checkout-api      956 traces

This edge list uses no timestamp comparison, so it needs no clock synchronization and no tie-breaking. It agrees with the timestamp method on all 956 traces, including the one the timestamp method got wrong.

Which services fail without naming an upstream?

The root of the graph is the node that appears as a source but never as a target. Query for candidates by asking which services fail without naming an upstream:

FROM logs-*.otel-*
| WHERE @timestamp >= "2026-07-26T08:59:00.000Z" AND @timestamp < "2026-07-26T09:07:00.000Z"
    AND deployment.environment == "obs-labs-causal-graph" AND log.level == "ERROR"
| STATS errors = COUNT(*), traces = COUNT_DISTINCT(trace.id),
        names_an_upstream = COUNT_DISTINCT(upstream.service) BY service.name
| WHERE names_an_upstream == 0
| SORT errors DESC

This returns catalog-api and ledger-service. Intersect it with the cascade participants from step 2 and one service remains: ledger-service.

What these two queries produce is the propagation structure of one incident, not a reusable causal model. The edges carry no probabilities and say nothing about failures that did not occur during the window. They are observations, and they hold for the traces you queried.

What the root cause service reported

Now read what that service reported, keeping the pool numbers so the evidence travels with the failure mode:

FROM logs-*.otel-*
| WHERE @timestamp >= "2026-07-26T08:59:00.000Z" AND @timestamp < "2026-07-26T09:07:00.000Z"
    AND deployment.environment == "obs-labs-causal-graph"
    AND log.level == "ERROR" AND service.name == "ledger-service"
| STATS events = COUNT(*), first_seen = MIN(@timestamp), last_seen = MAX(@timestamp)
        BY error.kind,
           db.connection_pool.size,
           db.connection_pool.available
| SORT events DESC

One failure mode, pool_timeout, across all 956 events, spanning the four minutes of saturation, with db.connection_pool.size at 8 and db.connection_pool.available at 0. The message behind it, which the next query shows in full:

connection pool exhausted, no connection available after 250ms

Expanding the trace where all three errors share a millisecond shows the chain intact without the timestamps:

FROM logs-*.otel-*
| WHERE trace.id == "f9b32dca62c1e142537413a047fb9b69"
| KEEP @timestamp, service.name, log.level, message, upstream.service
| SORT @timestamp ASC

upstream.service reads (null) for ledger-service, ledger-service for payment-gateway, and payment-gateway for checkout-api.

Add trace IDs and structured fields to your error logs

These queries need three things from your logging, and only one costs any effort:

• trace.id on every record. OpenTelemetry auto-instrumentation supplies it for logs emitted inside an active span. Access logs and background threads fall outside that scope. The Werkzeug access logs in this lab arrived with no trace context and were unusable for correlation.
• Structured fields instead of formatted strings. error.kind as a field lets you count failure modes. The same words inside a sentence do not.
• The upstream dependency named in the error. One key, upstream.service, on the errors your service logs when a dependency fails.

The pattern this lab reproduces is common in production incidents: a component absorbing overflow from an upstream failure often logs more errors than the component that caused it. The same ranking problem applies to automated investigation, where trace-scoped evidence is what makes a root cause claim checkable against specific records and queries.

Conclusion: what the logs proved and the metrics could not

Metrics reported three services broken at 19.1%. Error volume reported catalog-api, which was healthy. Grouping the same 4,688 log records by trace.id isolated 956 cascades, identified ledger-service as their origin, and returned the message that explained the failure.

Two techniques produced that result. Ordering by timestamp needs no code changes and was right 955 times out of 956, with the miss caused by millisecond ties. Reading a declared upstream.service field needs one extra key in your error logs and was right on every trace.

Neither technique needs a service dependency model, and neither one survives contact with logs that have no trace.id. That field is the whole investment.

Resources

• Companion notebook that replays the incident and runs every query in this article.
• ES|QL queries for debugging LLM latency, cost and GPU saturation for more query patterns over OpenTelemetry data.
• EDOT Python configuration reference to control which signals your services export.

Try root cause analysis from logs on your own data

• Run the step 2 query against your own logs-* data and check how many failing traces contain more than one erroring service.

• Audit one service's error logs for whether they name the dependency that failed.