Correlating Logs and Traces Across a Spatial Fan-Out

Give each fan-out branch its own trace with a link back to the originating edit rather than making it a child span, put the cell, zoom and feature id on every span, and derive the sampling decision from the originating trace id — independent sampling at one per cent means a sampled edit has almost none of its rebuilds sampled.

This guide sits under Structured Logging & Tracing for Spatial Handlers, within Monitoring & Observability for Spatial Pipelines. It is what makes the shard named by an alert in SLOs & Alerting for Spatial Webhook Pipelines investigable.

When to use this pattern

  • One input event produces many downstream units of work — tiles, index updates, notifications per subscriber.
  • Traces are already in place and are either unusably large or unusably disconnected.
  • Investigating “why was this tile stale” currently means grepping logs by timestamp.

A tree is the wrong shape for a fan-out

Four hundred children, or four hundred linked traces A single boundary edit invalidates four hundred tiles. Modelled as parentage, the edit's span becomes the root of a tree with four hundred children, some of which have children of their own for the render and upload steps — well over a thousand spans in one trace. No tracing backend renders that usefully, and the root span cannot end until the last child does, so a trace that should describe a two-second edit reports a duration of four hours, which is the length of the rebuild queue rather than of anything the edit did. Every percentile computed over edit spans is then a percentile of queue depth. Modelled as links, the edit is one small trace of half a dozen spans that ends when the edit is published, and each rebuild is its own small trace carrying a link back to it. Both traces render instantly, the edit's duration is the edit's duration, and a query can still walk in either direction — from the edit to all four hundred rebuilds, or from one slow rebuild back to the edit that caused it. The relationship is preserved without forcing it into a shape that the tooling and the arithmetic both reject. parentage — one trace, 1 000+ spans edit (root) …× 400, each with render and upload children the root cannot end until the last child does, so a 2-second edit reports a 4-hour duration — every percentile over edit spans becomes a percentile of queue depth links — many small traces edit · 6 spans rebuild z14 rebuild z15 rebuild z16 …each its own trace, each carrying a link back both render instantly · the edit's duration is the edit's duration · queries still walk in either direction from the edit to all 400 rebuilds, or from one slow rebuild back to its cause
Figure 1. The duration distortion is the part that outlives the rendering problem: parented, every edit-latency percentile silently measures the rebuild queue.

Complete runnable implementation

python 
import hashlib
import json
import logging

from opentelemetry import trace
from opentelemetry.trace import Link, SpanContext, TraceFlags

tracer = trace.get_tracer("tile-pipeline")
log = logging.getLogger("tile-pipeline")

SAMPLE_RATE = 0.01


def coherent_sample(origin_trace_id: int, rate: float = SAMPLE_RATE) -> bool:
    """Sample the whole fan-out or none of it.

    Deciding independently per branch at 1% means a sampled edit has almost
    none of its rebuilds sampled, so the correlation exists in principle and
    never in practice. Deriving from the origin makes it all-or-nothing.
    """
    digest = hashlib.blake2b(str(origin_trace_id).encode(), digest_size=8).digest()
    return int.from_bytes(digest, "big") / 2**64 < rate


def spatial_attributes(feature_id: str, cell: str, zoom: int | None = None) -> dict:
    """The dimensions every query in an investigation filters on.

    Without these a trace can be found only by time, which for a fan-out of
    four hundred concurrent rebuilds narrows nothing.
    """
    attrs = {
        "geo.feature_id": feature_id,
        "geo.cell": cell,
        "geo.cell_resolution": 8,
        "geo.crs": "EPSG:4326",
    }
    if zoom is not None:
        attrs["tile.zoom"] = zoom
    return attrs


def handle_edit(event: dict, enqueue) -> None:
    """The originating trace. Small, and it ends when the edit is published."""
    with tracer.start_as_current_span(
        "feature.edit",
        attributes=spatial_attributes(event["feature_id"], event["routing_key"]),
    ) as span:
        ctx = span.get_span_context()
        tiles = tiles_to_invalidate(event)

        span.set_attribute("fanout.tile_count", len(tiles))
        _log("edit received", event["feature_id"], event["routing_key"],
             trace_id=f"{ctx.trace_id:032x}", fanout=len(tiles))

        for tile in tiles:
            # Propagate the ORIGIN context, not the current span as a parent.
            enqueue({
                "tile": tile,
                "feature_id": event["feature_id"],
                "origin_trace_id": f"{ctx.trace_id:032x}",
                "origin_span_id": f"{ctx.span_id:016x}",
            })


def handle_rebuild(job: dict) -> None:
    """A new root trace, linked back to the edit that caused it."""
    origin = SpanContext(
        trace_id=int(job["origin_trace_id"], 16),
        span_id=int(job["origin_span_id"], 16),
        is_remote=True,
        trace_flags=TraceFlags(TraceFlags.SAMPLED),
    )

    with tracer.start_as_current_span(
        "tile.rebuild",
        links=[Link(origin, {"link.type": "caused_by"})],
        attributes=spatial_attributes(job["feature_id"], job["tile"].cell,
                                      zoom=job["tile"].z),
    ) as span:
        ctx = span.get_span_context()
        _log("rebuild started", job["feature_id"], job["tile"].cell,
             trace_id=f"{ctx.trace_id:032x}",
             origin_trace_id=job["origin_trace_id"], zoom=job["tile"].z)
        render(job["tile"])


def _log(message: str, feature_id: str, cell: str, **fields) -> None:
    """One structured line. The same field names as the span attributes.

    Different names in logs and traces means every investigation is two
    vocabularies, and the join has to be done by a human.
    """
    log.info(json.dumps({
        "message": message,
        "geo.feature_id": feature_id,
        "geo.cell": cell,
        **fields,
    }))
Independent sampling destroys exactly what the links were for An edit fans out into four hundred tile rebuilds, with tracing sampled at one per cent. If each branch decides independently, the edit has a one in a hundred chance of being sampled and each rebuild has its own one in a hundred chance, so an edit that is sampled has on average four of its four hundred rebuilds sampled — and the four are a different four every time. Following a sampled edit to its rebuilds therefore almost always leads to a nearly empty result, and following a sampled slow rebuild back to its edit finds the edit unsampled ninety-nine times out of a hundred. The correlation was built and then made unusable by the sampler. Deriving the decision from a hash of the originating trace identifier makes it all-or-nothing: one edit in a hundred is sampled along with every one of its four hundred rebuilds, and the other ninety-nine are sampled nowhere. The total volume is identical — one per cent of spans either way — but what is retained is a complete picture of one per cent of edits instead of a scattering of fragments from all of them. one edit → 400 rebuilds · sampling at 1% independent decision per branch edit sampled 4 of 400 rebuilds following a sampled edit leads to a nearly empty result following a slow rebuild back finds its edit unsampled 99 times out of 100 the correlation was built, then made unusable by the sampler decision derived from the origin trace id edit sampled → all 400 rebuilds sampled one edit in a hundred, complete the other ninety-nine sampled nowhere identical total volume — 1% of spans either way what changes is whether any single picture is complete A complete picture of one per cent of edits beats a scattering of fragments from all of them, and costs exactly the same storage. The decision is a hash comparison, so no coordination between services is needed.
Figure 2. Both schemes retain one per cent of spans. Only one of them retains anything you can follow from end to end.

Parameter reference

Name Type Spatial constraint Default
origin_trace_id str Propagated in the job payload, not in the parent context —
Link span link caused_by; keeps each trace independently renderable —
geo.cell str H3 cell at a stated resolution; the primary investigation filter res 8
tile.zoom int Present on rebuild spans only —
SAMPLE_RATE float Applied to origins, not branches 0.01
Log field names — Identical to span attribute names, or every query is two vocabularies —

Gotchas and spatial edge cases

  1. Cell as a span attribute is fine; cell as a metric label is not. Attributes are stored per span and queried after the fact, so high cardinality costs storage; metric labels create a time series each, and a resolution-8 cell space would create millions. The two look similar and have completely different cost models.

  2. Log field names must match the span attribute names exactly. geo.cell in one and h3_index in the other means every investigation involves translating between two vocabularies, and the automated join most backends offer will not find anything.

  3. The originating trace id has to be in the job payload. Relying on context propagation across a broker means it survives only if every producer, broker client and consumer preserves headers — and the first component that does not silently breaks the chain. An explicit field in the message body survives transports and archives.

  4. A rebuild that fans out again needs the same treatment. If a tile rebuild triggers downstream cache invalidations, those link to the rebuild rather than back to the edit, so the chain is walkable one hop at a time. Flattening every level to link to the original edit loses the intermediate structure that explains where the time went.

  5. Sampled-out branches still need logs. Coherent sampling means ninety-nine per cent of rebuilds produce no trace at all, so structured logs carrying the cell and feature id remain the only record for those. Log at a lower volume rather than not at all, and keep the same fields.

  6. The fan-out count belongs on the edit span. fanout.tile_count turns “this edit was expensive” into a queryable fact, and it is the single most useful attribute when investigating why a rebuild queue grew — usually one edit to a very large feature, which Scoping Tile Invalidation to the Zoom Levels That Changed exists to reduce.

Attribute or label — the same field, two cost models An H3 cell identifier at resolution 8 is attached to telemetry in two places. As a span attribute it is one key-value pair stored alongside each span, queried after the fact, and costs storage proportional to the number of sampled spans — which at one per cent sampling is a small and predictable amount, and gives an investigation the ability to filter directly to one cell. As a metric label it creates a distinct time series per cell value, and a fleet spanning a hundred thousand active resolution-8 cells therefore creates a hundred thousand series per metric, each with its own retention and its own memory in the scrape target. Adding the zoom level as a second label multiplies that again. The two look identical in code — the same string on the same event — and their costs differ by orders of magnitude, which is why the cell belongs on spans and a coarse region code belongs on metrics. the same H3 cell string, attached in two places span attribute — geo.cell one key-value pair per sampled span queried after the fact, not indexed in advance cost scales with sampled spans — at 1%, small and predictable lets an investigation filter straight to one cell metric label — cell="..." one time series per distinct value 100 000 active res-8 cells → 100 000 series per metric add zoom as a second label and multiply again use a coarse region code here instead Identical in code — the same string on the same event — and the costs differ by orders of magnitude.
Figure 3. The mistake is easy because the two look the same at the call site. The cell belongs on spans; metrics get a coarse region code.

Verification

python 
import pytest
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter


@pytest.fixture
def spans():
    exporter = InMemorySpanExporter()
    provider = TracerProvider()
    provider.add_span_processor(SimpleSpanProcessor(exporter))
    trace.set_tracer_provider(provider)
    yield exporter
    exporter.clear()


def test_rebuild_is_a_root_with_a_link_not_a_child(spans):
    jobs = []
    handle_edit(_edit(feature_id="4471"), enqueue=jobs.append)
    handle_rebuild(jobs[0])

    edit, rebuild = spans.get_finished_spans()
    assert rebuild.parent is None, "rebuild must not be parented to the edit"
    assert rebuild.links[0].context.trace_id == edit.context.trace_id


def test_every_span_carries_the_spatial_dimensions(spans):
    jobs = []
    handle_edit(_edit(feature_id="4471"), enqueue=jobs.append)
    handle_rebuild(jobs[0])

    for span in spans.get_finished_spans():
        assert "geo.feature_id" in span.attributes
        assert "geo.cell" in span.attributes


def test_sampling_is_all_or_nothing_per_edit():
    """Independent decisions would give ~4 of 400; this must give 0 or 400."""
    sampled_origins = [t for t in range(10_000) if coherent_sample(t)]
    for origin in sampled_origins[:20]:
        assert all(coherent_sample(origin) for _ in range(400))
    assert 50 < len(sampled_origins) < 150      # ~1% of 10 000


def test_origin_id_travels_in_the_payload_not_the_context(spans):
    """It must survive a broker that drops headers."""
    jobs = []
    handle_edit(_edit(feature_id="4471"), enqueue=jobs.append)
    assert "origin_trace_id" in jobs[0] and "origin_span_id" in jobs[0]

The first test is the one that fails if someone replaces the link with a parent while “tidying up the tracing” — a change that looks like a simplification, produces a more familiar-looking trace tree, and silently turns every edit-latency measurement into a measurement of the rebuild queue.