# Trace 4471e0a2: no root

Filed against the tracing collector, not against any of the services involved,
because the services are behaving and the trace is not.

## The complaint

A latency dashboard showed `p99` for `checkout` at 41 seconds. The `p50` was
81 ms. Only one trace in the window exceeded a second, and it is this one, and
it is not a slow request. It is not a request.

## The trace

```
$ traceq show 4471e0a2 --tree
[ ! ] no root span; rendering by parent-child edges only

  checkout.handle            812 ms   span 0e11  parent 7c40
  ├─ pricing.quote            94 ms   span 3a92  parent 0e11
  ├─ inventory.reserve       141 ms   span 51bd  parent 0e11
  │  └─ ledger.hold           88 ms   span 7c40  parent 51bd
  │     └─ checkout.handle   812 ms   span 0e11  parent 7c40   [seen]
  ├─ payment.authorize       402 ms   span c118  parent 0e11
  └─ notify.enqueue            9 ms   span 22f5  parent 0e11

  19 spans, 18 edges, 0 roots, 1 cycle
  wall clock span:  41.6 s
  sum of durations: 1.454 s
```

```mermaid
graph TD
  A["checkout.handle<br/>span 0e11 · 812 ms"] --> B["pricing.quote<br/>span 3a92 · 94 ms"]
  A --> C["inventory.reserve<br/>span 51bd · 141 ms"]
  A --> D["payment.authorize<br/>span c118 · 402 ms"]
  A --> E["notify.enqueue<br/>span 22f5 · 9 ms"]
  C --> F["ledger.hold<br/>span 7c40 · 88 ms"]
  F --> A
  B --> G["cache.get<br/>span 9d04 · 2 ms"]
  D --> H["risk.score<br/>span b761 · 388 ms"]
  H --> I["risk.model.v3<br/>span 4e0c · 371 ms"]
  I --> J["feature.fetch<br/>span 6a55 · 18 ms"]
  J --> H
```

`checkout.handle` is its own great-grandparent. `risk.score` is its own
grandparent. Neither service calls the other one; `ledger` has no client for
`checkout`, and `feature-fetch` has no client at all, it is a library.

## What we checked

- **Clock skew.** All hosts in the trace are within 0.4 ms of the same NTP
  source. The 41.6 s wall clock is not skew; it is the distance between the
  earliest span start and the latest span end, and the durations do not fill it.
  There are 40.1 seconds inside this trace during which no span is open.
- **ID collision.** A parent id colliding with a real span id would do this. The
  ids are 64-bit and the collector holds 4.1 billion spans, which puts the
  birthday probability for a single collision at about one in a billion, and
  this trace contains two. Both collisions are between spans in the same trace.
- **The producing library.** Version pinned across all six services, no local
  patches, checksums match upstream.
- **Replay.** We replayed the exact request against staging 4,000 times. Every
  trace has a root.

## The order the spans arrived

The collector timestamps each span on receipt, independently of the span's own
clock. Span `0e11` — the one with no parent in the trace and a parent id of
`7c40` — was received at 04:41:19.882. Span `7c40` was received at 04:41:21.114.

A span's parent id is written by the parent, into the header it passes down, and
then by the child, into the span it emits. `0e11` was emitted with a parent id
that `7c40` had not generated yet.

## Status

The trace has been kept. It is excluded from the `p99` aggregation by a filter
on its trace id, which is a filter with exactly one entry in it, and I would
like it noted that this was the correct thing to do and not a fix.

Compare [[stories/nightly-0300]], where the completion also precedes the start.