The question this answers
I have logs from three services. How do I reconstruct what actually happened, in order?
Sorting merged logs by timestamp gives no ordering guarantee whatsoever across machines. What propagated identifiers do give is a *causal* order: if event B was produced by a process that had observed event A, that relationship is recorded explicitly and is correct regardless of any clock. Events with no such relationship are genuinely unordered, and a good reconstruction shows that rather than inventing an order.
Everything below is bought to hold this sentence. "Strongly consistent" with no scope attached is a slogan, not a guarantee — read what it actually covers, and what it explicitly does not.
A node knows its own local clock reading and the order of events it processed itself. It does not know the offset between its clock and any other node’s, and it cannot learn it from a timestamp in a message — the message took an unknown time to arrive. So a node can honestly say "this happened after that, on me" and "this happened after I received that message". It cannot honestly say "this happened before that, on you".
A node knows its own state and the messages that arrived. Everything else is inference from evidence that was already stale. "B has not replied in five seconds" is knowledge; "B is down" is a decision — and usually the bug.
Why merge-and-sort produces a wrong story
Three services handle one request. Each writes a line with its local wall-clock time. You collect all three, sort ascending, and read the result as a narrative. The narrative is fiction whenever the clock offsets between the machines exceed the real intervals between the events — which, for services communicating in single-digit milliseconds over clocks that routinely differ by tens of milliseconds, is most of the time.
The visible symptom is an effect that precedes its cause. Service B logs "received order 8f3a" at 14:02:11.140, and service A logs "sent order 8f3a" at 14:02:11.180. A message was received forty milliseconds before it was sent. Everyone has seen this line; the usual response is to assume a logging bug, which sends the investigation into the wrong system entirely.
And the failure is worse when it is invisible. A skew of 40ms that reverses two events 5ms apart produces a plausible, readable, wrong ordering with nothing anomalous about it — and a debugging session that concludes the wrong service acted first. [[clock-skew]] explains why the offsets exist and why they are not fixable by trying harder; here we take them as given and ask what to do instead.
What timestamps can and cannot be used for
This is not an argument for removing timestamps. It is an argument for knowing what they support. Within a single process, successive readings of a *monotonic* clock order events correctly and measure durations correctly — that is [[monotonic-vs-wall-clock]], and it is the right tool for "how long did this take".
Across machines, wall-clock timestamps are usable for coarse work only: finding the rough window of an incident, filtering to a five-minute range, joining against a deploy marker. The rule of thumb is that they are trustworthy at a resolution far larger than your worst-case skew, and useless below it. If your fleet’s skew can reach 100ms, no cross-machine ordering claim at millisecond resolution is supportable.
What is *never* sound is using a timestamp as a decision input for correctness — expiry checked against a peer’s clock, conflicts resolved by comparing timestamps from different nodes, ordering derived from log time. Those are the failures that produce wrong answers silently rather than error messages.
| Sound? | Why | |
|---|---|---|
| How long did this operation take, on one machine?protocol | Yes — with a monotonic clock | Two readings of the same monotonic source; unaffected by skew or NTP steps |
| Which of two events on the same machine came first?protocol | Yes | Single clock source, single ordering |
| Roughly when did the incident start?typical | Yes, at coarse resolution | Skew is small relative to a five-minute window |
| Which of two events on different machines came first?protocol | No | Offset between the clocks is unknown and may exceed the interval |
| Did this message arrive before it was sent?protocol | No — the question is unanswerable from timestamps | The apparent inversion is skew, not a logging bug |
| Which write should win a conflict?assumption | No | Timestamp comparison across nodes lets a fast clock win permanently and silently |
Identifiers carry the order that clocks cannot
The working answer is to record relationships instead of inferring them. A trace id groups every log line belonging to one logical request, so reconstruction becomes a filter rather than a merge. A span id with a parent span id records that this unit of work was caused by that one — a genuine causal edge, immune to any clock. A sequence number per producer orders that producer’s own events unambiguously. A causal token carried in the message — a Lamport counter or a version vector — orders events across nodes wherever a real dependency exists.
What this buys is not a total order, and expecting one is a mistake. It buys the *partial* order that is actually true: a directed acyclic graph in which some pairs are ordered because one caused the other, and some pairs are genuinely concurrent. This is [[causal-ordering]] in its practical form, and the discipline it enforces is worth as much as the ordering — a reconstruction that leaves concurrent events unordered is telling you the truth, while a sorted list is asserting an order that does not exist.
One consequence for practice: propagation is everything. An identifier that stops at an async boundary breaks the chain exactly where reconstruction is hardest. The id must ride in the message envelope through queues, retries, dead-letter paths, scheduled jobs and batch processing — anywhere a unit of work is caused by an earlier one.
trace=8f3a21
span=a1 parent=— svc=orders seq=1 "sent order" @A 11.180
└ span=b7 parent=a1 svc=inventory seq=1 "received order" @B 11.140
├ span=c2 parent=b7 svc=stock seq=1 "stock reserved" @C 11.165
└ span=b8 parent=b7 svc=inventory seq=2 "reserving stock" @B 11.142
reading:
a1 -> b7 -> {b8, c2} is the true order, from parent edges alone.
b8 and c2 are CONCURRENT: no causal edge exists between them, and
no amount of timestamp comparison can order them. The reconstruction
says so, instead of guessing.
The @-times are printed for context only. Sorting by them yields
b7, b8, c2, a1 — an effect before its cause.Making logs correlatable in practice
The requirements are few and they are contractual rather than technical. Every log line carries the trace id and the span id. Every outbound call and every published message carries them onward. Structured fields, not interpolated text, so the id can be filtered rather than grepped. Both the local timestamp and the source of that clock, so an anomaly can be attributed to skew rather than to a bug. A per-service sequence number, which costs nothing and orders that service’s events even if its clock is nonsense.
Then a second, boring practice pays off repeatedly: monitor clock offset across the fleet as a first-class metric. Skew is a silent, gradual, correlated failure — a drifting node breaks lease logic, conflict resolution, expiry checks and log reading all at once, and none of them produce an error naming the clock. An offset alert converts a confusing multi-symptom incident into a one-line diagnosis.
Finally, expect the async boundaries to be where propagation breaks, and check them specifically. Queue publish and consume, retry paths, dead-letter reprocessing, scheduled and batch work: each one is a place where a framework default drops the context and nobody notices until an incident needs it.
- Trace id and span id on every line, as structured fields.
- Parent span id recorded, because that edge is the causal information.
- Per-producer sequence numbers — free, and correct under any clock.
- Both the timestamp and the clock source, so skew is attributable.
- Propagation verified across queues, retries, DLQ replays and scheduled jobs.
- Fleet-wide clock offset monitored and alerted on as a real signal.
Key points
- Merging logs from several machines and sorting by timestamp can show an effect before its cause.
- Clock offsets between machines routinely exceed the intervals you are trying to order.
- An apparent "received before sent" line is skew, not a logging bug — and the invisible reorderings are worse.
- Trace ids, span parents and sequence numbers record causality directly and survive any clock.
- The result is a partial order: some events are genuinely concurrent, and a good reconstruction says so.
- Propagation across async boundaries is where correlation breaks; verify it there specifically.
The chain, answered
Every field here is required, which is why no lesson in this domain can recommend a design without naming what an operator sees when it fails, what survives the partition, what repairs it afterwards, and the simpler thing to consider first.
- • Generate a trace id at the system edge and carry it through every call and every message.
- • Create a span per unit of work, recording its parent span id — that edge is the causal fact.
- • Emit every log line as structured data including trace id, span id, parent, and a per-producer sequence number.
- • Reconstruct by filtering on the trace id and walking parent edges, not by sorting on time.
- • Where no causal edge exists between two events, present them as concurrent rather than ordering them.
- • Use timestamps only for coarse windowing and for durations measured on a single monotonic clock.
- • The trace id is dropped at an async boundary and the chain ends mid-request.
- • Log lines are unstructured, so ids can be searched textually but not joined.
- • Clocks drift far enough that even coarse windowing pulls in the wrong five minutes.
- • Sampling drops the spans in the middle of a trace, leaving a chain with a hole.
- • A retry produces a second span with the same parent, and the reconstruction reads it as two distinct operations.
- • Log shipping delays vary per service, so a query at incident time shows a partial picture that fills in later.
- • Effect before cause: the operator reads a merged log and sees a message received before it was sent, then spends the next twenty minutes looking for a bug in the logging library.
- • Plausible wrong narrative: the operator reconstructs an order that reads perfectly, blames the service that appears to have acted first, and is wrong because a 40ms offset reversed two events 5ms apart.
- • Chain break at the queue: the operator follows a trace through three services and finds nothing after the publish, because the id was not put in the message envelope.
- • Ungreppable logs: the operator can find the id in one service’s text logs and cannot join it to another service’s, because one interpolates the id into a sentence and the other has a field.
- • Silent fleet drift: the operator sees unrelated symptoms — leases expiring early, conflicting writes resolved wrongly, logs out of order — and no alert anywhere names the drifting clock that caused all of them.
- • Partial trace at incident time: the operator sees an incomplete trace, concludes the request never reached service C, and the missing spans arrive four minutes later from a backed-up shipper.
- • Correlation requires agreement on the identifier format and on propagation, across every service and every message contract. That agreement is the coordination cost, and it is paid once at design time.
- • No coordination is required at logging time — each service writes locally and independently, which is what makes the approach work during a partition when a central ordering service would not.
- • Clock synchronisation is a coordination mechanism with a cost and a failure mode of its own; correlation by identifier deliberately avoids depending on it.
- • Cross-organisation propagation (to a vendor, a partner, a downstream tenant) needs an agreed header, which is why standard formats are worth adopting even inside one company.
- • Causal edges recorded in the data remain correct no matter how badly clocks behave — that is the property being bought.
- • A broken propagation chain does not corrupt what was recorded; it truncates it. The recorded portion stays trustworthy.
- • Under partition, each side logs its own causal graph correctly, and the two graphs can be joined afterwards by shared identifiers without any agreement having been reached during the partition.
- • Concurrent events remain concurrent forever. No later analysis can order them, and treating the absence of an edge as an order is the error to avoid.
- • Detect: alert on clock offset across the fleet, and treat "effect before cause" in any log as a skew indicator rather than a curiosity.
- • Contain: for the incident in progress, switch to causal reconstruction — filter by trace id and walk parents — instead of arguing about timestamps.
- • Recover: fix propagation at the boundary that broke, which is nearly always an async one.
- • Reconcile: any conclusion reached earlier from timestamp ordering should be re-derived from causal edges; several will change.
- • Verify: take a request that crosses every async boundary and confirm the reconstructed chain is complete end to end.
- • Fleet-wide clock offset distribution — the maximum matters more than the mean, since one drifting node is enough.
- • Trace completeness: the fraction of traces whose chain is unbroken from edge to leaf, per boundary type.
- • Count of log lines missing a trace id, per service — the direct measure of correlation coverage.
- • Occurrences of apparent causality violations in merged views, which is a free skew detector.
- • Log-shipping delay per service, so a partial picture during an incident is recognised as partial.
- • Any failure that crosses more than one service, which after the first split is most of them.
- • Systems with async hops, where ordering is least intuitive and timestamps are least trustworthy.
- • Post-incident reconstruction, where the story is being written down and a wrong order becomes an official wrong conclusion.
- • A single process with one clock, where local ordering is already correct and the machinery adds noise.
- • When the partial order is treated as a defect and someone forces a total order for presentation — that reintroduces exactly the fiction the approach removes.
- • Very high-volume paths where per-line ids materially increase log cost; sample the traces, not the ids.
- • Tightly synchronised clocks with a bounded, *measured* uncertainty interval — the approach used by systems that expose it as an explicit wait. It works, and it requires hardware and operational investment most fleets do not have.
- • Lamport counters propagated in messages: cheaper than full tracing, and they give a total order consistent with causality without needing a trace backend.
- • Version vectors when you need to distinguish concurrent from ordered rather than just impose an order — more expensive, and the only option that detects concurrency exactly.
- • A single centralised ordering service that stamps every event: gives a real total order and buys it with a coordination point that becomes a bottleneck and a shared failure.
Three nodes, three logs, and you cannot sort by timestamp
| Recorded ts | Service | Line | Reads as |
|---|---|---|---|
| -115 ms | orders | begin transaction | before the event that caused it |
| -112 ms | orders | commit order 7841 | — |
| -110 ms | orders | publish OrderPlaced | — |
| +0 ms | api | receive POST /orders | — |
| +2 ms | api | call orders.create | — |
| +99 ms | worker | consume OrderPlaced | — |
| +102 ms | worker | index document 7841 | — |
What people believe, and what is true
Sorting the merged logs by timestamp shows what happened.
It shows what the clocks said. Where offsets exceed the intervals, the narrative can be exactly inverted, and it will still read fluently.
This log line shows a message received before it was sent — the logger is broken.
The logger is fine. The two lines came from different clocks. This is the visible case; the invisible ones are the reason the practice must change.
NTP keeps our clocks close enough to order events.
Close enough for coarse windows, not for millisecond ordering. NTP also steps clocks backwards, so a single machine’s wall-clock sequence is not even monotonic.
With trace ids we get a total order of events.
You get a partial order. Some events are genuinely concurrent, and a reconstruction that presents them as ordered has reintroduced the original error in a new format.
Timestamps are fine for resolving write conflicts.
A node with a fast clock wins every conflict, permanently, and nothing reports it. That is [[last-write-wins]] under skew, and it is data loss without an error.
Go deeper
Only the levels this lesson can honestly fill — a missing level is a claim nobody had.
Overview
Three nodes, three clocks. Merging by timestamp can show effects before causes. Use trace ids and parent spans, which record causality directly.
Practical
Put trace id, span id and parent span id on every structured log line, propagate them across every boundary including queues and retries, add a per-producer sequence number, and monitor fleet clock offset. Reconstruct by filtering and walking parents; use timestamps only for coarse windows and single-clock durations.
Advanced
What you are building is the happened-before relation from the logs themselves: a partial order in which an edge exists only where one event could have influenced another. Parent span ids are that relation recorded at capture time rather than reconstructed later, which is why they survive arbitrary clock behaviour. The honest output is a DAG with concurrent branches, and the discipline is to resist flattening it — the flattening is where the false conclusions come from.
Apply it
- 🔧 Take one request that crosses a queue and verify that the trace id survives publish, consume, retry and dead-letter replay.
- 🔧 Add fleet clock-offset monitoring and record the maximum observed offset over a week. Compare it to the intervals you routinely try to order.
- ⚡ A conflict-resolution bug is reported: one node’s writes always win. Logs show its timestamps are consistently ahead. Which two lessons in this domain does that connect, and what is the fix?
- 💬 You have logs from three services and need the order of events. What do you do, and what do you refuse to do?
- 💬 A log shows a message received 40ms before it was sent. Explain it.
- 💬 Why does a parent span id order two events correctly when a timestamp does not?
- 💬 Your reconstruction leaves two events unordered. Is that a gap in the data or a fact about the system?