The logs came from the future

One-line summary

A timestamp is not a fact; it is a claim that machine made at that moment by looking at its own clock. If you gather many such claims and line them up in time order, the order of events quietly flips.

Why this is needed

The tool used most often in incident retrospectives is merging logs in time order. You collect the logs of four servers on one screen, read from the top, and look for "here is where it started." This method works well on most days. That is exactly why the days it does not work are so hard to recognize.

A day it does not work looks like this. The worker's "received the request" is above the API's "sent the request." It processed something it never received. The conclusion people draw from this screen is almost always the same — "the worker seems to have replayed a duplicate request," "the message queue broke the ordering," "somebody set up retries wrong." All three hypotheses are plausible, and all three are wrong. The worker's clock was simply 12 seconds behind.

The opposite direction is nastier. The lines from a machine whose clock is ahead look as if they flew in from the future. The round-trip time is stamped as 4 minutes 37 seconds, and the latency graph on the dashboard spikes at that moment. Nothing ever slowed down, yet evidence of slowness is left behind. And that evidence is never erased.

How it works

What matters here is that the error does not occur on just one line. On a machine whose clock is off, every line from that machine is off by the same amount. So if only one line looks strange, it is not a clock problem but something else, and if a host's lines are all shifted by a constant amount, it is almost certainly the clock. This distinction is the first fork in the investigation.

You do not guess the size of the error; you measure it. You can measure it because a single request leaves four timestamps: the time the sender sent it (T1), the time the receiver received it (T2), the time the receiver replied (T3), and the time the sender got the reply (T4). This is exactly the calculation NTP has used for 30 years, and it is written like this in RFC 5905, section 8.

theta = T(B) - T(A) = 1/2 * [(T2-T1) + (T3-T4)]      두 시계의 차이
delta = T(ABA)      = (T4-T1) - (T3-T2)              왕복에 걸린 시간

Why the two terms are added and halved is the whole point of this formula. (T2-T1) mixes two things: the true clock difference and the network delay of the outbound leg. (T3-T4) also contains the clock difference, but this time the delay of the return leg comes in with the opposite sign. When you add the two, the delays cancel each other and only the clock difference remains, doubled. That is why you halve it.

The cancellation is perfect only when the outbound and return delays are equal. On a real network they are not equal, so a value from one measurement is off by half of (outbound delay - return delay). That is why you use the median of many samples rather than one sample. If you also look at how widely the samples are spread, you learn how far to trust the estimate. If the spread is tens of milliseconds and the error is 277 seconds, the conclusion leaves no room for doubt.

In practice, a daemon such as chrony does the job of setting the clock. If the error is small, the daemon gradually catches up by slightly changing the clock's speed (slew), and if the error is large, it makes the time jump in one go (step). The difference between the two approaches leads into the next story.

What you see in the field

You run into this problem especially often in container environments. A container does not have its own clock; it sees the host kernel's clock as is. So when NTP dies on one node, all the Pods running on that node go off together, while Pods on other nodes are fine. The symptom shows up not as "a particular service is strange" but as "only the things running on a particular node are strange," and the habit of gathering logs by service name makes that pattern hard to see.

There are two things to observe when recording. One is always writing the time together with its offset. That is why the RFC 3339 format is useful. 2025-11-01T18:30:00.694+09:00 points to the same instant when read on any machine, but 2025-11-01 18:30:00 depends on the reader's guess. The other is not leaving the ordering to timestamps alone. If you also keep a request ID and a causal chain (what caused what), the order can be restored even when clocks are off. That is exactly what distributed tracing does.

There is also an order to follow when investigating. Once you find out that a clock is off, do not delete or re-stamp the logs; record the error and correct for it when reading. The original is evidence of what that machine believed at that moment, and that belief may be the cause of the incident.

What to check in the next quiz

Check how to tell one strange line apart from a whole host being shifted, why the formula that measures error with four timestamps cancels the delay, and why you use the median of many samples rather than a single one.