Geospatial Orchestration Hub

Correlating Logs and Traces for One Tile Run

Four systems know something about a tile — the trace knows where its time went, the logs know what it decided, the metrics know how it compares to its siblings, and the ledger knows whether it counts as done. Correlating them takes exactly two shared identifiers: the trace id, injected into every log record and stored on the ledger row, and the work key, present as a span attribute and a log field. With those two in place an investigation moves between systems by clicking rather than by reconstructing, which is the difference between five minutes and an afternoon.

When to Use This Pattern

  • Traces and structured logs both exist but investigations still involve copying timestamps between two browser tabs.
  • A failure needs both signals — the trace shows a slow fetch, the log shows which source it fell back to.
  • Dead letters need explaining, so the queue row should lead to the trace of the run that produced it.
  • More than one person investigates, since the correlation is what makes an investigation reproducible by someone else.

Complete Working Example

The identifiers are established once and then simply carried. Everything below is plumbing rather than logic.

from __future__ import annotations

from dataclasses import dataclass
from typing import Optional

import structlog
from opentelemetry import trace

log = structlog.get_logger()
tracer = trace.get_tracer("geospatial.pipeline")


def current_trace_id() -> Optional[str]:
    ctx = trace.get_current_span().get_span_context()
    return format(ctx.trace_id, "032x") if ctx.is_valid else None


@dataclass(frozen=True)
class TileRun:
    """Everything a tile's four systems agree on."""

    work_key: str          # the idempotency key — stable across attempts
    trace_id: str          # this attempt's trace
    layer: str
    z: int
    x: int
    y: int


def process_tile(item, conn) -> None:
    with tracer.start_as_current_span("tile") as span:
        # 1. The work key goes on the span, so a trace can be found from the ledger.
        span.set_attribute("work.key", item.work_key)
        span.set_attribute("tile.z", item.z)
        span.set_attribute("tile.x", item.x)
        span.set_attribute("tile.y", item.y)

        run = TileRun(item.work_key, current_trace_id() or "", item.layer,
                      item.z, item.x, item.y)

        # 2. Both identifiers are bound to the logger, so every subsequent line
        #    carries them without any call site remembering to.
        structlog.contextvars.bind_contextvars(
            work_key=run.work_key, trace_id=run.trace_id, layer=run.layer,
            **{"tile.z": run.z, "tile.x": run.x, "tile.y": run.y},
        )
        try:
            # 3. The ledger stores the trace id of the attempt that claimed it,
            #    which is what turns a ledger row into a link.
            claim(conn, run.work_key, trace_id=run.trace_id)
            log.info("tile_started")

            features = warp_and_write(item)
            complete(conn, run.work_key, features=features, trace_id=run.trace_id)
            log.info("tile_written", features=features)

        except Exception as exc:
            log.error("tile_failed", failure_class=classify(exc), exc_info=exc)
            # 4. And the dead letter carries it too, so a failure found weeks
            #    later still leads to the trace that explains it.
            dead_letter(conn, work_key=run.work_key, trace_id=run.trace_id,
                        failure_class=classify(exc), error_text=str(exc))
            raise
        finally:
            structlog.contextvars.clear_contextvars()

The schema changes are two columns, and they are what make the joins possible from the database side:

ALTER TABLE tile_ledger  ADD COLUMN trace_id text;
ALTER TABLE geotask_dlq  ADD COLUMN trace_id text;

-- Not unique: a re-driven work key has a new trace each attempt, and keeping
-- all of them is what lets you compare a failing attempt with a later success.
CREATE INDEX tile_ledger_trace ON tile_ledger (trace_id);
CREATE INDEX geotask_dlq_trace ON geotask_dlq (trace_id);
Two identifiers, four systemsThe trace id appears on the trace, on every log record and on the ledger and dead-letter rows. The work key appears on the span, in the logs and on the ledger, and is stable across attempts.trace_id + work_keytwo strings, carried everywheretracewhere the time wentlogswhat it decidedledgerwhether it counts as donedead-letter queuewhy it never finished
Neither identifier is new: the trace id already exists and the work key already exists. The whole technique is refusing to let either of them stop at a system boundary.

The distinction between the two identifiers is worth holding onto, because they answer different questions and it is tempting to think one would do. The trace id is per attempt: it identifies one execution, and a tile that failed twice and then succeeded has three of them. The work key is per unit of work: it is stable across all three, which is what makes “show me every attempt at this tile” a query rather than a reconstruction. Carrying only the trace id gives you excellent within-attempt correlation and no history; carrying only the work key gives you history and no way to see where any single attempt spent its time.

One work key, three tracesA tile that failed twice before succeeding has one work key across all three attempts and a distinct trace id for each, so both the history and the individual executions remain reachable.work_key = sha256:ab12…:12/2100/1300 — one value, three attemptsattempt 1 — failedtrace 4bf9…attempt 2 — failedtrace 7c02…attempt 3 — succeededtrace 91da…Comparing attempt 2 with attempt 3 is usually the fastest diagnosis available, and it needs both identifiers:the work key to find the set, and the trace ids to open the two executions side by side.
Neither identifier is redundant. The work key finds the attempts; the trace ids explain them.

Parameter & Option Reference

Identifier Where it lives Spatial notes
trace_id span, log field, ledger, dead letter Per attempt. Two attempts of the same tile have two traces, which is what you want.
work_key span attribute, log field, ledger key Stable across attempts. It is what makes “show me every attempt at this tile” possible.
ledger trace_id non-unique column A re-drive adds a row or updates one; keeping the history is worth the bytes.
dead-letter trace_id column Turns a triage row into a link to the run that produced it.
log binding contextvars Bound once per unit of work, cleared in a finally.
span attribute work.key Namespaced, so it does not collide with an orchestrator’s own attributes.

Verification & Testing

The assertion worth making is round-trip: from any one system, the other three are reachable.

def test_all_four_systems_agree(conn, exporter, log_capture, sample_tile) -> None:
    process_tile(sample_tile, conn)

    span = next(s for s in exporter.get_finished_spans() if s.name == "tile")
    trace_id = format(span.context.trace_id, "032x")
    work_key = span.attributes["work.key"]

    # 1. Every log record for this unit carries both identifiers.
    records = [r for r in log_capture if r.get("work_key") == work_key]
    assert records, "no log records carry the work key"
    assert all(r["trace_id"] == trace_id for r in records)

    # 2. The ledger row points back at the trace.
    with conn.cursor() as cur:
        cur.execute("SELECT trace_id FROM tile_ledger WHERE work_key = %s", (work_key,))
        assert cur.fetchone()[0] == trace_id


def test_failure_reaches_the_dead_letter_with_its_trace(conn, exporter, failing_tile) -> None:
    with pytest.raises(RuntimeError):
        process_tile(failing_tile, conn)
    span = next(s for s in exporter.get_finished_spans() if s.name == "tile")
    with conn.cursor() as cur:
        cur.execute("SELECT trace_id FROM geotask_dlq WHERE work_key = %s",
                    (failing_tile.work_key,))
        assert cur.fetchone()[0] == format(span.context.trace_id, "032x")

With the columns populated, the queries that start an investigation are short. The first begins from a symptom and the second from a suspicion, which are the two ways investigations actually start:

-- From a bad tile on the map, to the trace that produced it.
SELECT work_key, trace_id, built_at, feature_count
FROM   tile_ledger
WHERE  z = 12 AND x = 2100 AND y = 1300 AND layer = 'ortho'
ORDER  BY built_at DESC LIMIT 5;

-- From a class of failure, to a handful of traces worth reading.
SELECT failure_class, count(*) AS n, min(trace_id) AS example_trace
FROM   geotask_dlq
WHERE  failed_at > now() - interval '24 hours' AND resolved_at IS NULL
GROUP  BY failure_class
ORDER  BY n DESC;
The same investigation, twiceWithout shared identifiers each system is searched separately by timestamp and tile index. With them, one query leads to a trace, which links to its logs, which link to the ledger row.WITHOUT CORRELATIONfind the timestampsearch the logssearch the traceshope they are the same runFour searches, two of them by timestamp across concurrent work — which is a guess, not a join.WITH trace_id AND work_keyquery the ledger by tileopen the traceits logs are one filter awayTwo columns and one processor. Everything else about both rows is identical.
The upper row is not merely slower — the timestamp join is unreliable under concurrency, so it can produce a confident answer about the wrong tile.

Common Pitfalls

  • Correlating by timestamp. With sixteen tiles in flight, a timestamp identifies a moment rather than a unit of work. It will sometimes give the right answer and there is no way to tell which times those were.
  • Storing only the latest trace id on the ledger. Overwriting on each attempt loses the failing attempt, which is the one worth reading. Keep the history, or at minimum keep the first failure alongside the eventual success.
  • A trace id on the log but not on the ledger. Then the journey works in one direction only: from a trace you can find the logs, and from a bad tile you can find nothing. Both columns are needed for the round trip.
  • Formatting the trace id inconsistently. format(trace_id, "032x") in one place and hex(trace_id) in another produce strings that never match. Format it in one helper and use it everywhere.
  • Assuming the orchestrator’s run id is enough. It identifies a flow run containing four hundred tiles, which narrows an investigation by a factor of one. It is a useful additional field and not a substitute for either identifier here.
  • Dropping the identifiers on a retry. A retried task that starts a fresh trace without recording the previous one loses the failing attempt entirely. Record both, and the comparison between them is often the whole diagnosis.

Frequently Asked Questions

Should the log carry the span id as well?

Yes, and it costs nothing since the processor is already reading the context. The span id narrows a log line to a phase rather than to the whole tile, which matters when the trace has fetch, warp and write spans and the question is which of them produced a particular message. Most backends can jump from a log line to the exact span when both ids are present.

What about the orchestrator's run id?

Add it as a third field. It answers a different question — “what else was in this run” — which is genuinely useful when a whole batch behaves oddly. It is bounded, cheap and unambiguous, and unlike the other two it lets an investigation move outward from one tile to its siblings rather than inward.

How do I link from a Grafana panel to a trace?

Grafana’s data links take a field value and build a URL, so a table panel over tile_ledger with a trace_id column becomes clickable with about three lines of panel configuration. That single link removes most of the copying that makes cross-system investigation tedious, and it is the highest-value thing to configure once the columns exist.

Does this work when traces are sampled away?

Partly, and it is worth understanding the limit. A trace dropped by the sampler leaves a trace id on the log and the ledger that resolves to nothing. That is not a failure — the id still correlates logs and ledger rows with each other — but it means the trace link is sometimes dead. Keeping every error trace, as the tail-sampling policies do, ensures the link works in exactly the cases where it matters.

Is the work key or the trace id the more important identifier?

The work key, narrowly. The trace id links one attempt across systems; the work key links every attempt across time, which is what answers “has this tile always been slow?” and “did the re-drive actually fix it?”. If only one could be carried, it would be the one that survives retries.

← Structured Logging for Geospatial Flows

Related in this section