Break/Fix: Time Skew Corrupts Correlation

Reported symptoms

Four tickets are open. On the face of it they belong to four different teams.

The impossible ordering. An engineer reconstructing a failed checkout finds the payments database logging a commit at 14:22:07.9 for a transaction the application logs as starting at 14:22:11.1. The commit precedes its own cause by three seconds. Duplicate transaction, then broken correlation ID - neither hypothesis survives the data. It is one transaction, one ID, one commit.

The broken traces. Two tickets, a week apart, describe opposite faults. One says traces through the checkout gateway show a child span starting three seconds before its parent. The other says a child starts three seconds after its parent finished, stranded to the right of the waterfall. Both were closed as “Tempo rendering bug”. Every trace in both touches worker-07.

The self-healing TLS failure. Every Friday, in the minute after certificate rotation, worker-07 refuses outbound TLS with x509: certificate is not yet valid, then recovers unaided. Reopened three times, closed three times as transient.

The logs that are not there. Narrowing Loki to a two-second window around the gateway’s timestamp returns the gateway lines and none of the worker lines - though the trace and the gateway’s own line both prove the worker handled the request. Widening to a minute brings them back.

And one thing that is not a symptom, which is what kept this alive for a month: every Prometheus panel is correct. Rates, errors, latency histograms, SLO burn - all of it matches reality for worker-07 exactly as for its peers. The platform even has a clock-skew alert. It has never fired.

Evidence provided

The cheapest check needs no SSH, no agent and no knowledge of NTP. Every HTTP server puts its own clock in the Date response header, so one request per host samples the whole fleet’s opinion of the time.

$ for h in edge-01 payments-03 worker-06 worker-07; do
printf '%s ' "$h"
curl -sI "http://$h.internal.example.com:9100/metrics" | awk -F': ' '/^[Dd]ate:/{print $2}'
done
date -u

edge-01     Tue, 15 Jul 2026 14:22:08 GMT
payments-03 Tue, 15 Jul 2026 14:22:08 GMT
worker-06   Tue, 15 Jul 2026 14:22:08 GMT
worker-07   Tue, 15 Jul 2026 14:22:11 GMT
Tue Jul 15 14:22:08 UTC 2026

Date carries one-second resolution, so this finds seconds-scale skew and nothing finer. That is enough here, and it is why to run it first: one command turns a four-ticket mystery into a single-host question.

On the host itself, chrony has been reporting the problem to nobody for a month.

$ chronyc tracking

Reference ID    : 00000000 ()
Stratum         : 0
Ref time (UTC)  : Thu Jun 11 09:41:22 2026
System time     : 0.000031415 seconds fast of NTP time
Frequency       : 11.204 ppm slow
Update interval : 0.0 seconds
Leap status     : Not synchronised

$ chronyc sources -v | tail -3

MS Name/IP address         Stratum Poll Reach LastRx Last sample
===============================================================================
^? ntp1.internal.example.com     0   10     0     -     +0ns[   +0ns] +/-    0ns
^? ntp2.internal.example.com     0   10     0     -     +0ns[   +0ns] +/-    0ns

One measurement taken without touching the clock confirms the path rather than the daemon. chronyd -Q queries and reports; it never adjusts anything.

# chronyd -Q 'server ntp1.internal.example.com iburst'

2026-07-15T14:22:14Z chronyd version 4.5 starting
2026-07-15T14:22:24Z No suitable source for synchronisation

And the fleet view, which is where the month went:

$ curl -sG http://prometheus.internal.example.com:9090/api/v1/query \
--data-urlencode 'query=topk(4, abs(node_timex_offset_seconds))' \
| jq -r '.data.result[] | .metric.instance + " " + .value[1]'

worker-07.internal.example.com:9100   0.000031415
worker-06.internal.example.com:9100   0.000024187
edge-01.internal.example.com:9100     0.000019902
payments-03.internal.example.com:9100 0.000012004

Work the evidence before reading on

Four tickets, one host, and a monitoring system reporting everything as fine.

1. The Date header says worker-07 is three seconds ahead. The Prometheus offset metric says thirty microseconds. Both were sampled in the same minute. What would have to be true for both to be honest measurements?
2. chronyc tracking reports a System time offset of 31 microseconds and a Ref time from thirty-four days ago. Which of those two numbers is a statement about now?
3. Every metric panel for this host is right while every log line and span from it is three seconds wrong. What is different about how each of those gets its timestamp?
4. The two trace tickets describe opposite symptoms. What single property of the estate produces both, depending on the direction of the call?

Before continuing: the platform has a clock-skew alert and the clock has been wrong for thirty-four days. Name the assumption inside that rule that made it unable to fire, and say what it should have measured instead.

Root cause

1. The clock free-ran because the time path was closed

An egress ACL on the worker subnet was tightened thirty-four days ago, removing outbound UDP/123. Nothing crashed. chronyd stayed running, kept polling on schedule, and kept getting nothing back

• which is what Reach 0 on both sources means, and what Leap status: Not synchronised means.

The kernel meanwhile kept applying the last frequency correction chrony gave it. That correction compensates for the crystal’s known error, so the clock ran wrong only by the residual error, on the order of one part per million - about 86 milliseconds a day. Thirty-four days is a little over three seconds, and three seconds fast is exactly what the Date sweep measured. The offset is therefore also a date stamp: skew divided by drift rate gives the age of the fault, which is how this landed on the ACL change before anyone opened the change calendar.

2. Metrics were fine because Prometheus stamps them itself

This is the asymmetry that hid the fault for a month.

Prometheus assigns a sample the timestamp of the scrape, read from the Prometheus server’s own clock. The target’s clock plays no part, so worker-07 could be an hour wrong and its rates, errors and histograms would still land in the right place. Logs and spans work the other way: a log line’s timestamp is written by the process that emitted it, and a span’s start_time_unix_nano is a wall-clock reading taken on the emitting host. Loki and Tempo store what they are given.

The last row is why the log-to-trace pivot kept working. The join key is an identifier, not a timestamp. Correlation by identity survived intact; correlation by time was fiction. The team had both, used them interchangeably, and had no reason to think they could disagree.

3. Both trace shapes come from one skew

A parent on a correct host calling into worker-07 produces a child whose recorded start is 3.2 seconds later than its parent’s: a child stranded to the right of a parent that has already finished. A parent on worker-07 calling out produces a child whose recorded start is 3.2 seconds earlier than its parent’s: the classic child-before-parent. Same skew, opposite rendering, depending on which end of the call the fast clock sits on. Two tickets, one cause, and neither ticket named a host.

4. The alert measured the daemon, not the clock

node_timex_offset_seconds is the kernel’s record of the offset, written by the NTP daemon when it takes a measurement. A daemon that cannot reach a source takes no measurements. The last value stands, and the kernel’s applied correction pulls it toward zero rather than away from it.

So abs(avg_over_time(node_timex_offset_seconds[5m])) > 0.5 was neither broken nor misconfigured. It was answering a different question from the one the team believed it asked. It reports how far off the clock was when something last checked. The open question for thirty-four days was whether anything was checking at all, and the metric that answers it, node_timex_sync_status, had been reporting 0 the whole time with nothing watching.

Resolution

1. Establish the blast radius before repairing anything. The ACL covers a subnet, not a host: run the Date sweep across every host behind it and record which are affected. Repairing worker-07 alone leaves the same fault on its neighbours.
2. Reopen the time path. Restore outbound UDP/123 from the worker subnet to the internal NTP servers. This is the actual fix; everything after it is the clock catching up.
3. Confirm the path with chronyd -Q, which measures without adjusting. If it still finds no source, the ACL change has not taken effect and there is nothing to gain from touching the clock.
4. Let chrony slew. Do not step a host carrying production traffic: at roughly ten per cent slew a 3.2 second offset closes in about half a minute, so a step buys seconds and costs a wave of corrupt in-flight telemetry.
5. Watch it converge rather than assuming it did. chronyc tracking should move from Not synchronised to a real Reference ID, and chronyc sources -v should climb toward Reach 377 over the next few polls.
6. Mark the affected window. Annotate the dashboards and state plainly in the incident channel which signals from the last thirty-four days are untrustworthy - every log and span timestamp from the affected hosts, and nothing else. Metrics from the window are sound, and saying so is as useful as the warning.
7. Fix the alert in the same change, not a follow-up ticket. Alert on node_timex_sync_status == 0 and on the absence of the metric; keep the offset rule as a second, narrower signal.
8. Close the TLS and Tempo tickets against this incident, so the next engineer searching for certificate is not yet valid finds the cause rather than a fourth reopening.

Verification

1. The independent check passes fleet-wide. The Date sweep shows every host within a second of the reference, not only the one you repaired. It does not trust chrony, which is the point - the daemon is what failed.
2. The daemon agrees. chronyc tracking shows a real Reference ID, Leap status: Normal and an offset in the milliseconds; chronyc sources -v shows Reach 377 on at least two sources.
3. The fleet query is empty. count(node_timex_sync_status == 0) returns zero and absent(node_timex_sync_status) returns nothing, so a host that stopped exporting the metric cannot hide inside a healthy count.
4. The traces are sane. Reopen a trace crossing a repaired host and confirm every child sits inside its parent. This is the check that maps onto the original complaint; no host-level command substitutes for it.
5. The original investigation now reads correctly. Re-run the checkout query on traffic from after the fix: the application line must precede the commit. A repaired clock does not repair historical data.
6. The guard can fail. On a staging host, block UDP/123 and confirm the new alert fires within its for window and pages the right rota. An alert that has only ever been green has never been tested, which is how the old one survived a month.

Prevention

• Alert on whether the clock is disciplined, not on the number a broken daemon reports. node_timex_sync_status answers “is anything steering this clock”. node_timex_offset_seconds answers “how far off was it when something last measured”. The first question was open for a month; the second was answered, correctly and uselessly, every fifteen seconds.
• Alert on the absence of the metric. A host that stops exporting node_timex_* looks exactly like a healthy host on every dashboard.
• Keep one check that does not trust the host. The Date sweep costs one request per host, needs no agent, and finds the whole class of fault - including hosts that were never added to monitoring, which are precisely the hosts that drift.
• Put NTP in the blast-radius review for egress changes. Time fails silently and surfaces weeks later inside someone else’s incident. A review line item would have cost nothing and saved a month.
• Ship chrony in the base image, enforce it in configuration management, and audit anyway. Provisioning covers the hosts that went through provisioning; the audit covers the rest.
• Write down the asymmetry. Metrics carry the collector’s clock; logs and traces carry the emitter’s. Teams learn this during an incident, at the moment a wrong timeline costs most.