Order agent traces correctly when clocks disagree

A tool span appears to start before the model turn that requested it. Sorting the trace by timestamp puts the result before the request, and the failure localizer blames the wrong component. Nothing traveled backward in time. Two processes simply disagreed about the wall clock.

That is the trap in clock-skew testing. The test must contain a real timestamp inversion, read that timestamp, and still enforce the causal facts carried by the trace. A fixture that sorts by a prewritten sequence and never examines the skewed field proves nothing about skew.

Trust causal relationships more than wall-clock order

A timestamp answers when one clock believed an event occurred. It does not, by itself, prove that an event caused another event. Within one process, a monotonic clock or producer-assigned sequence can give strong local order. Across processes, synchronization error, virtual machine pauses, clock adjustments, serialization delay, and batch export can make wall times overlap or reverse.

Trace relationships carry different information. The W3C Trace Context specification defines identifiers that let systems propagate a trace and the caller's parent context across service boundaries. Specific tracing systems may also record a span's parent identifier. OpenAI's Agents SDK, for example, documents trace_id, parent_id, started_at, and ended_at on spans. The identifier relationship and the timestamps are both useful, but they answer different questions.

For QA, model the trace as a directed graph. Each required “happens before” fact is an edge. A span's start precedes its own end. A parent start precedes a child start. A tool request precedes the result correlated to that request. Events emitted by one producer follow that producer's trustworthy local sequence. If the runtime waits for a child before ending the parent, the child end also precedes the parent end. Do not add that last edge for detached work unless the product contract promises the join.

The graph defines a partial order. Independent branches can be arranged in more than one valid total order. That flexibility is important. A brittle test often writes one expected list and fails when two unrelated calls swap positions, even though every causal constraint remains satisfied. The better oracle checks all required edges and accepts any topological order that preserves them.

Wall time still has a role. Among events that are currently unconstrained, it is a useful, stable tie-breaker for display. It also supports latency analysis after you account for clock domain and uncertainty. What it must not do is override a known causal edge. If child-start has an earlier wall time than parent-start, the ordering layer should preserve parent before child and annotate the clock inversion.

Define the available evidence explicitly. The examples here use an application-owned producer_sequence field. It is not a standard property promised by W3C Trace Context or every agent SDK. If your telemetry does not emit a local sequence, do not pretend it does. You can still use span phase, parent relationships, and request correlation, but some same-process ambiguities may remain unresolved.

The same restraint applies to clock correction. Subtracting one estimated offset from every timestamp can improve a chart, yet a single offset may be wrong if drift changes during a long run. Causal ordering does not need to invent corrected times. Preserve the raw timestamp, preserve its clock source if available, and report that the observed order conflicts with causality.

Make the skew visible to the test oracle

This sorter consumes events from a normalized application trace. It builds edges from span phases, parent starts, and producer-local sequences. Wall time breaks ties only after the graph says that two events are both eligible. A cycle raises an error because silently dropping an edge would turn corrupt telemetry into a plausible story.

from __future__ import annotations

from collections import defaultdict
from dataclasses import dataclass
from datetime import datetime
import heapq
from typing import Iterable


@dataclass(frozen=True)
class Event:
    event_id: str
    span_id: str
    parent_span_id: str | None
    phase: str
    producer: str
    producer_sequence: int
    observed_at: datetime


def causal_edges(events: Iterable[Event]) -> set[tuple[str, str]]:
    rows = list(events)
    by_span: dict[str, dict[str, Event]] = defaultdict(dict)
    by_producer: dict[str, list[Event]] = defaultdict(list)

    for event in rows:
        if event.phase not in {"start", "end"}:
            raise ValueError(f"unsupported phase: {event.phase}")
        if event.phase in by_span[event.span_id]:
            raise ValueError(f"duplicate {event.phase} for span {event.span_id}")
        by_span[event.span_id][event.phase] = event
        by_producer[event.producer].append(event)

    edges: set[tuple[str, str]] = set()
    for span_id, phases in by_span.items():
        if set(phases) != {"start", "end"}:
            raise ValueError(f"incomplete span: {span_id}")
        edges.add((phases["start"].event_id, phases["end"].event_id))

        parent_id = phases["start"].parent_span_id
        if parent_id is not None:
            parent = by_span.get(parent_id)
            if parent is None or "start" not in parent:
                raise ValueError(f"missing parent span: {parent_id}")
            edges.add((parent["start"].event_id, phases["start"].event_id))

    for producer_events in by_producer.values():
        ordered = sorted(producer_events, key=lambda event: event.producer_sequence)
        sequences = [event.producer_sequence for event in ordered]
        if len(sequences) != len(set(sequences)):
            raise ValueError("duplicate producer sequence")
        edges.update(
            (before.event_id, after.event_id)
            for before, after in zip(ordered, ordered[1:])
        )

    return edges


def causal_order(events: Iterable[Event]) -> list[Event]:
    rows = list(events)
    by_id = {event.event_id: event for event in rows}
    if len(by_id) != len(rows):
        raise ValueError("duplicate event id")

    outgoing: dict[str, set[str]] = defaultdict(set)
    indegree = {event.event_id: 0 for event in rows}
    for before, after in causal_edges(rows):
        if after not in outgoing[before]:
            outgoing[before].add(after)
            indegree[after] += 1

    ready: list[tuple[datetime, str]] = [
        (event.observed_at, event.event_id)
        for event in rows
        if indegree[event.event_id] == 0
    ]
    heapq.heapify(ready)
    result: list[Event] = []

    while ready:
        _time, event_id = heapq.heappop(ready)
        result.append(by_id[event_id])
        for next_id in sorted(outgoing[event_id]):
            indegree[next_id] -= 1
            if indegree[next_id] == 0:
                next_event = by_id[next_id]
                heapq.heappush(ready, (next_event.observed_at, next_id))

    if len(result) != len(rows):
        blocked = sorted(event_id for event_id, degree in indegree.items() if degree)
        raise ValueError(f"causal cycle involving: {blocked}")
    return result

The fixture below is synthetic, and its timestamps are deliberately illustrative. No claim is being made about a measured production offset. The child process clock is placed behind the parent process clock so raw timestamp sorting produces the wrong order. The first assertion is essential: it proves that the skewed field creates the inversion described by the test.

from datetime import datetime

import pytest

from trace_order import Event, causal_edges, causal_order


def instant(value: str) -> datetime:
    return datetime.fromisoformat(value.replace("Z", "+00:00"))


def skewed_events() -> list[Event]:
    return [
        Event("parent-start", "model", None, "start", "agent", 40,
              instant("2026-08-04T12:00:00.500Z")),
        Event("child-start", "tool", "model", "start", "worker", 8,
              instant("2026-08-04T11:59:59.900Z")),
        Event("child-end", "tool", "model", "end", "worker", 9,
              instant("2026-08-04T12:00:00.000Z")),
        Event("parent-end", "model", None, "end", "agent", 41,
              instant("2026-08-04T12:00:00.800Z")),
    ]


def test_fixture_contains_a_real_wall_clock_inversion() -> None:
    events = skewed_events()
    by_id = {event.event_id: event for event in events}

    assert by_id["child-start"].observed_at < by_id["parent-start"].observed_at
    assert [event.event_id for event in sorted(events, key=lambda item: item.observed_at)] == [
        "child-start", "child-end", "parent-start", "parent-end"
    ]


def test_causal_order_overrides_the_skewed_wall_clock() -> None:
    assert [event.event_id for event in causal_order(skewed_events())] == [
        "parent-start", "child-start", "child-end", "parent-end"
    ]

If someone changes child-start to a time after parent-start, the first test fails because the fixture no longer covers clock skew. If someone changes the sorter to use raw wall time, the second test fails. If someone removes the parent relationship, the expected causal order is no longer justified and the test data review should reject that mutation. Each part of the advertised mechanism participates in the proof.

Do not stop with one golden list. Add property-style checks that every emitted edge points forward in the result. That accepts valid rearrangements of independent events and produces a precise failure when one required relation is broken.

The block below continues the same test file. It reuses the instant and skewed_events helpers defined above instead of redeclaring them, which is why the import header appears only once, at the top of the file. Copied into a separate module without those two helpers it would raise NameError on the first parameterized row. That is a useful reminder in its own right: a fixture builder shared by more than one suite belongs in conftest.py or an ordinary imported module, not pasted into both files where the two copies can drift apart and quietly stop describing the same trace.

def assert_all_edges_point_forward(events: list[Event]) -> None:
    ordered = causal_order(events)
    position = {event.event_id: index for index, event in enumerate(ordered)}
    violations = [
        (before, after)
        for before, after in causal_edges(events)
        if position[before] >= position[after]
    ]
    assert violations == []


@pytest.mark.parametrize("child_start", [
    "2026-08-04T11:59:58.000Z",
    "2026-08-04T12:00:00.499Z",
    "2026-08-04T12:00:00.700Z",
])
def test_parent_edge_survives_multiple_clock_offsets(child_start: str) -> None:
    events = skewed_events()
    changed = [
        Event(
            event.event_id,
            event.span_id,
            event.parent_span_id,
            event.phase,
            event.producer,
            event.producer_sequence,
            instant(child_start) if event.event_id == "child-start" else event.observed_at,
        )
        for event in events
    ]
    assert_all_edges_point_forward(changed)


def test_rejects_a_parent_cycle() -> None:
    events = skewed_events()
    changed = [
        Event(
            event.event_id,
            event.span_id,
            "tool" if event.event_id == "parent-start" else event.parent_span_id,
            event.phase,
            event.producer,
            event.producer_sequence,
            event.observed_at,
        )
        for event in events
    ]
    with pytest.raises(ValueError, match="causal cycle"):
        causal_order(changed)

The parameter values are test inputs, not measurements. They cover a child clock far behind, just behind, and ahead. The causal edge must hold in all three. The cycle case changes the code-under-test input in a way that cannot be reconciled; it does not compare a hard-coded category with a list that already contains it.

Diagnose three failures without guessing at the clock

The first common failure is a clean parent-child inversion. A model span starts on the agent host, dispatches a tool, and a worker records the child start with an earlier wall time. Span IDs and correlation are complete. Producer sequences are unique. The causal graph is acyclic. This is the case the sorter can repair for presentation while retaining a clock_inversion diagnostic.

Look for the actual edge and both raw times. A useful message says parent-start must precede child-start, but wall time is later by the observed offset. Avoid claiming the exact host drift unless a clock-monitoring source measured it. The trace reveals disagreement between two event timestamps, not which clock is correct.

The second failure looks similar but comes from bad identity. A tool result is attached to the wrong call ID, perhaps because an adapter reused a mutable variable while requests ran concurrently. The result then appears before its supposed request even within one producer sequence. Clock correction cannot repair this because the correlation itself is false. Evidence includes a result payload belonging to another argument set, duplicate call IDs, or a request with two terminal results.

Test this by swapping result correlation IDs while leaving every timestamp unchanged. The integrity validator should fail before ordering. If the pipeline simply places the mismatched result after whichever request shares its ID, it creates a tidy but fictional trace. Ordering code must not compensate for identity defects.

The third failure is an incomplete export. The parent and tool start arrive, but the tool end is absent because a batch was dropped or the process ended before flushing. A negative duration may be calculated later when a consumer accidentally pairs the start with an end from another run. The correct outcome is incomplete_trace, not a repaired order and not a product timeout verdict.

Check cardinality before time. Each normalized span in this article requires one start and one end. If your source emits completed span objects instead of phase events, require one object per span ID and validate that required fields are present. The representation can differ, but the principle is the same: missing evidence remains missing.

A fourth case appears during fan-out. Two tools begin under the same model turn on separate workers. Their timestamps overlap, and repeated test runs swap their displayed order. There may be no defect at all. The parent precedes both children, each child start precedes its own end, and neither child causes the other. A test that demands tool-a before tool-b invents a dependency. Assert the edges, not the sibling order.

This distinction affects failure localization. Suppose tool-b fails and tool-a succeeds. Putting tool-b first on a timeline does not mean it caused tool-a. The localizer should traverse explicit dependencies or application-level links. Timestamps can guide a person through the display, but they cannot create a causal path between independent branches.

Work the request and result case at the event level. A model decision on producer agent-1 emits request call-74. A tool worker on worker-3 records a start and a result for that call. The request-to-start and start-to-result edges should come from the shared call identifier and the adapter's event types. If the result wall time is earlier than the request wall time but the identifiers, local sequences, and payload correlation agree, record a clock inversion and retain the causal order.

Now mutate only the result's call identifier to call-75. The ordering outcome must not stay green. Either call-75 has no request, which is an orphan-result error, or it belongs to another request, which can produce a duplicate terminal result there. This mutation proves that request correlation drives the edge. A hard-coded expected array could still pass if it ignores the identifier, so add the orphan check before topological sorting.

Change a different field next: keep call-74, but set the worker's end sequence lower than its start sequence. The wall times may still look sensible. The producer-local contract now contradicts the phase contract, creating a causal cycle. The correct verdict is corrupt telemetry. Sorting by either time or numeric sequence alone would hide one side of the contradiction, while the graph exposes both asserted facts.

Detached work needs an explicit fixture because parent semantics differ. Imagine a model turn schedules an audit export and returns a receipt without waiting for the export. Parent start must precede child start, but child end may occur after parent end. If the sorter automatically adds child-end before parent-end for every relationship, it rejects this valid trace. Add a join_required fact at the normalized edge layer only when the workflow contract supplies it. Do not infer joining from the presence of parent_span_id.

The corresponding joined fixture should prove the opposite. A model turn invokes a tool and consumes its returned value before producing final text. In that application path, the tool result must precede the final-output event. The useful edge comes from data flow or a call/result contract, not merely from comparing span end timestamps. Removing that edge should let a deliberately early final output slip through, causing the mutation test to fail.

Retries add one more identity level. The logical operation may keep one operation ID while each attempt receives its own call or span ID. Order attempts by a producer sequence or an explicit attempt relationship. Do not merge them into one span simply because the arguments match. Separate spans preserve the first error, backoff interval, second dispatch, and terminal result. They also let QA tell a legitimate retry from a duplicate exporter record.

An agent handoff is another worked boundary. The source agent emits a handoff decision, the destination agent begins on another process, and both clocks disagree. A shared trace ID only proves membership in the same trace. The handoff event or destination parent relationship must supply the causal edge. Without it, placing the destination after the source is a plausible display choice, not a verified ordering fact.

For synthetic tests, state which edge each fixture is meant to exercise. A file named worker-behind-parent.json should include metadata such as expected_inversions and required_edges, but the oracle must calculate its verdict from events rather than trusting those labels. Test metadata selects assertions; it does not replace them. If the event is mutated and the calculated inversion disappears, the expected inversion assertion must fail.

For captured traces, keep the acceptance rule different. Production evidence may contain unrelated fields, more branches, and nondeterministic sibling order. Assert required relationships and diagnostic categories rather than comparing the entire normalized JSON with a golden file. Golden snapshots are appropriate for the small diagnostic rendering after unstable fields are removed, not for the causal truth itself.

Boundary tests should also cover timestamp parsing failure. Feed one valid RFC 3339 instant with an offset, one malformed value, and one otherwise valid local time that lacks an offset. The normalizer should reject the latter two under a UTC-required contract. If it silently attaches the CI machine's timezone, results will differ by runner location and daylight-saving rules.

Large traces require attention to diagnostics as well as runtime. A cycle report that lists every blocked event can become unreadable. Return at least one concrete cycle path or the smallest set your implementation can reliably find, plus the edges and their sources. Keep the full graph as an artifact. The reviewer needs to know whether the conflict came from parentage, local sequence, span phase, or request correlation.

Measure the sorter with generated data only if you label those figures as benchmarks from an actual run. Otherwise discuss complexity without invented timings. Edge construction is linear in events plus declared relationships, and heap-based topological sorting adds logarithmic ready-queue operations. That is usually acceptable for individual traces, but a viewer processing many traces should paginate and normalize outside the rendering thread.

For each diagnosis, save a compact evidence bundle: trace ID, involved event IDs, span and parent IDs, producer IDs, local sequences, raw times, and the violated edge. Redact input and output payloads unless they are necessary and approved. A clock-skew investigation rarely needs the customer's prompt.

Separate clock skew from other timestamp defects

Unit mismatch often masquerades as extreme skew. One adapter emits epoch milliseconds while another labels nanoseconds or seconds as the same field. Values differ by orders of magnitude, and any offset calculation becomes absurd. Validate range and unit at ingestion. Store the original representation beside the parsed instant so investigators can identify the producer that violated the contract.

Precision loss causes subtler trouble. A database column that truncates to whole seconds can make a start and end equal, while the source had subsecond separation. Equality is not negative duration, and it should not be “fixed” by adding a fabricated millisecond. Preserve an unknown_within_precision interpretation where the distinction matters.

Timezone parsing errors are not clock skew either. A timestamp without an offset may be interpreted as local time on one worker and UTC on another. Reject ambiguous wire timestamps or attach the producer's documented zone before conversion. The normalized examples use explicit Z values and timezone-aware Python objects so a test cannot compare naive and aware datetimes by accident.

Daylight-saving transitions can repeat local clock readings. They do not affect a properly encoded UTC instant. If the source sends local time without an offset during the repeated hour, two different instants can be indistinguishable. No ordering algorithm can recover information that was never recorded. Mark the trace ambiguous and fix the producer format.

Exporter latency is another separate axis. An event can execute first and arrive last. Do not use ingestion time as event time unless the field is clearly named and the limitation is accepted. Keeping observed_at and ingested_at separate lets the pipeline diagnose a slow exporter without rewriting execution history.

Clock adjustment within one host also challenges a naive assumption that process timestamps always increase. Producer sequence remains useful when generated independently of wall time. If no local sequence or monotonic reading exists, start and end phase still provide a required edge, but unrelated events from that host may be ambiguous. Report less rather than sorting with false confidence.

The command-line diagnostic should expose these distinctions. The script below uses the functions above, labels an actual edge conflict, and prints raw values. It does not claim a measured clock offset for the machines.

from __future__ import annotations

import argparse
from datetime import datetime
import json
from pathlib import Path

from trace_order import Event, causal_edges, causal_order


def parse_instant(value: str) -> datetime:
    parsed = datetime.fromisoformat(value.replace("Z", "+00:00"))
    if parsed.tzinfo is None or parsed.utcoffset() is None:
        raise ValueError("timestamp must include a UTC offset")
    return parsed


def load_events(path: Path) -> list[Event]:
    raw_events = json.loads(path.read_text())
    return [
        Event(
            event_id=str(raw["event_id"]),
            span_id=str(raw["span_id"]),
            parent_span_id=raw.get("parent_span_id"),
            phase=str(raw["phase"]),
            producer=str(raw["producer"]),
            producer_sequence=int(raw["producer_sequence"]),
            observed_at=parse_instant(str(raw["observed_at"])),
        )
        for raw in raw_events
    ]


def audit(path: Path) -> None:
    events = load_events(path)
    by_id = {event.event_id: event for event in events}
    for before_id, after_id in sorted(causal_edges(events)):
        before = by_id[before_id]
        after = by_id[after_id]
        if after.observed_at < before.observed_at:
            print(f"CLOCK_INVERSION {before_id} -> {after_id}")
            print(
                f"before observed_at={before.observed_at.isoformat()} "
                f"producer={before.producer} sequence={before.producer_sequence}"
            )
            print(
                f"after  observed_at={after.observed_at.isoformat()} "
                f"producer={after.producer} sequence={after.producer_sequence}"
            )
    print("causal_order=" + ",".join(
        event.event_id for event in causal_order(events)
    ))


def main() -> int:
    parser = argparse.ArgumentParser()
    parser.add_argument("traces", nargs="+", type=Path)
    args = parser.parse_args()
    for path in args.traces:
        print(f"TRACE {path}")
        audit(path)
    return 0


if __name__ == "__main__":
    raise SystemExit(main())

python trace_order_audit.py tests/fixtures/skewed-tool-span.json

# Expected output from this repository-owned diagnostic:
# TRACE tests/fixtures/skewed-tool-span.json
# CLOCK_INVERSION parent-start -> child-start
# before observed_at=2026-08-04T12:00:00.500000+00:00 producer=agent sequence=40
# after  observed_at=2026-08-04T11:59:59.900000+00:00 producer=worker sequence=8
# causal_order=parent-start,child-start,child-end,parent-end

Because the format belongs to your diagnostic, you can assert it exactly in a snapshot test. Do not quote this as output from OpenAI, W3C, or a vendor trace viewer. Their interfaces and wording are separate from the normalized layer described here.

Move the check into CI without freezing the viewer

Begin with fixtures from known topology patterns: one process, parent and child on different processes, fan-out siblings, a joined child, detached work, missing end, duplicate identity, and a causal cycle. Replace sensitive payloads with minimal values while preserving IDs and time relationships. Label synthetic offsets as synthetic in fixture metadata.

Run ingestion validation before ordering. Schema and cardinality errors should stop the score. Next build causal edges and reject cycles. Then calculate a valid topological order and verify every edge. Finally emit wall-clock inversion warnings for required edges whose raw times disagree. This sequence keeps a missing event from being mislabeled as clock drift.

Add shadow comparison before changing production displays. Generate both the existing timestamp order and the causal order for sampled traces. Review where they differ. Some differences reveal real skew; others uncover hidden business assumptions, such as a parent that does not actually wait for a detached child. Update the topology contract rather than forcing the new sorter to match the old picture.

When rollout reaches the viewer, show that an event was repositioned for causality. Hiding the raw timestamp makes the trace look cleaner but removes the clue an infrastructure engineer needs. A tooltip or diagnostic panel can display the original time, producer, and reason for the causal placement.

CI can keep deterministic ordering tests separate from environment clock tests. Do not alter the CI runner's system clock, which can affect unrelated processes and often requires privileges. Synthetic fixtures provide all offsets needed to test the algorithm safely.

name: trace-order-contract

on:
  pull_request:
    paths:
      - "trace_order/**"
      - "tests/trace_order/**"

jobs:
  causal-order:
    runs-on: ubuntu-latest
    timeout-minutes: 10
    steps:
      - uses: actions/checkout@v4
      - uses: actions/setup-python@v5
        with:
          python-version: "3.12"
          cache: "pip"
          cache-dependency-path: requirements-test.txt
      - run: python -m pip install -r requirements-test.txt
      - run: python -m pytest tests/trace_order -q
      - run: python trace_order_audit.py tests/fixtures/trace_order/*.json

The cache-dependency-path line is not optional here. When cache: "pip" is set and that key is omitted, actions/setup-python looks for its default glob of **/requirements.txt with **/pyproject.toml as a backup. A repository that pins its test dependencies in requirements-test.txt and ships no requirements.txt matches neither pattern, so the setup step fails with a message about no file being matched, and it fails before a single test runs. The symptom looks like a caching problem and is actually a missing input, which is an easy half hour to lose. Point the key at the file the next line installs from and the two stay consistent.

The trade-off is additional complexity at ingestion and display. A graph sort costs more than a timestamp sort. Producers need stable identifiers and, ideally, local sequence data. Analysts must learn that screen position can reflect causality rather than raw wall time. In return, QA stops filing failures against whichever event happens to own the smallest timestamp.

Version normalized schemas and ordering rules. If a producer starts emitting detached spans, that change belongs beside fixtures showing the new allowed relationship. Historical traces may lack the new field, so the migration needs an explicit legacy mode or an insufficient_evidence outcome. Guessing a default parent behavior rewrites old evidence.

Do not force a total order where none exists

Independent sibling spans do not need a winner. If the product contract allows both orders, tests should allow both. A deterministic tie-breaker is useful for a stable UI or snapshot, but downstream logic must not treat that chosen order as causation.

Avoid correcting and overwriting raw timestamps. Derived display times can be stored separately, with the algorithm version and uncertainty. The original evidence should remain available for latency and infrastructure investigations. Once overwritten, a bad correction is hard to unwind.

Do not use parent relationships alone to infer business dependency. A trace parent can represent instrumentation scope rather than data flow. If tool B consumes tool A's result, record or derive that application dependency from a contractually reliable field. If both merely share a model-turn parent, they can remain unordered siblings.

Skip latency assertions across unsynchronized clock domains unless you have measured clock uncertainty or a server-side duration from one clock. Subtracting a child timestamp from a parent timestamp can produce a precise-looking number with no defensible meaning. Test causal order first and measure latency within a trusted clock domain.

Finally, do not classify every inversion as harmless skew. A valid causal sorter can make the display coherent while identity corruption, missing events, or illegal cycles remain. Run integrity checks first, preserve diagnostics, and let unresolvable traces fail as evidence. A neat timeline is not worth a false account of what the agent did.