Correlating Logs Across Devices When Clocks Disagree

Merging logs from several devices into one timeline assumes the timestamps in those logs share a timebase. They usually do not. Each device keeps its own clock, that clock is disciplined by an independent protocol exchange, and the residual offset after disciplining is a quantity the device knows and almost never records in the log line. The merged timeline is therefore accurate to within the sum of the unknown offsets, and any causal claim finer than that bound is an artifact of the merge rather than a fact about the network.

What the timestamp in a log line actually represents

A log record’s timestamp is generated by the logging subsystem at the moment it formats the record, not at the moment the event it describes occurred. Between the event and the formatting there is a path through whatever buffering the device uses: a ring buffer in the kernel, a queue in the logging daemon, a rate limiter that suppresses repeated messages. Under load, that path can delay a record by an interval comparable to the intervals being investigated.

Devices that coalesce repeated messages make this worse in a way that is easy to misread. A logging subsystem that emits one record for a burst of identical events, with a count of how many occurred, produces a timestamp for the first event and a total. The remaining events in the burst have no timestamp at all, and treating the single record as one event loses both the volume and the duration of the burst.

Remote logging adds a second timestamp. A device that forwards records over the syslog protocol can include the time it generated the record in the message header, and the collector records its own time on receipt. Those two differ by the transit time plus any queueing at the collector, and a collector receiving from many devices under a burst records receipt times that reflect its own input processing rather than the events. The header timestamp is the one that matters for ordering, and it carries the sender’s clock error rather than the collector’s.

The offset bound, and why it is usually unknown

A clock disciplined by a network time protocol is not set to the true time; it is set to within an interval around it. The protocol estimates the round-trip delay to a server and assumes the outbound and inbound legs are equal, which yields an error bound of half the measured round trip. The device’s clock is known to be within that bound of the server, and the server is within its own bound of the reference, and the accumulation is what the protocol’s root dispersion and root delay fields report.

Those fields exist precisely so that a consumer can know the bound, and they are usually discarded. A log line that carries only a formatted timestamp has thrown away the one number that would make the timestamp usable in a correlation. Without it, the safe assumption is that offsets are bounded by the synchronisation quality of the worst device in the set, which on a device synchronised across a wide-area path is on the order of milliseconds and on an unsynchronised device is unbounded.

The practical consequence: two events recorded a millisecond apart on two devices may have occurred in either order, and two events recorded a minute apart almost certainly did occur in that order, provided both devices are synchronised at all. The threshold between “certainly ordered” and “possibly reversed” is the sum of the two offsets, and it should be stated before any causal reading of the timeline.

Building an ordering that does not depend on absolute time

When the offset bound is too large for the question, ordering has to come from something other than timestamps. Four sources are available, in decreasing order of reliability.

Sequence numbers within a single device are exact: a counter that increments per record orders records from that device with no ambiguity, and many logging subsystems include one. Across devices they mean nothing, since the counters are independent.

Protocol sequence numbers are the strongest cross-device ordering signal available. A transport connection’s sequence numbers order the segments of that connection exactly, and a routing protocol’s message identifiers order the messages of one session. An event recorded on one device that names a sequence number, and an event on another device that names the same number, can be ordered relative to each other without consulting clocks.

Causal markers carried in the protocol are the next best. A session identifier assigned by the initiator, echoed by the responder in its own records, links the two records and establishes that the second followed the first. This is the most useful signal in practice because it survives clock error entirely: the responder cannot have recorded the session before the initiator created it.

Content-derived ordering is the weakest and the most available. A message that carries an identifier assigned upstream, such as a transaction identifier in a tunnelled protocol, orders the records that carry it.

The method is to pick the strongest signal present in both records being compared and to fall back only when it is absent. Comparing two records from different devices by timestamp when they share a session identifier discards better evidence for worse.

When clocks are wrong by a large amount

A device whose clock is wrong by hours produces a log that appears to describe events before they happened, and the merged timeline places it at the wrong point entirely. The signature is a record that references an event the rest of the timeline places elsewhere, or a gap in one device’s records that matches activity visible on another.

Large offsets come from a few causes. A device that boots without a battery-backed clock and without reachable time sources starts from an arbitrary epoch, which on some systems is the last time recorded in a file and on others is a fixed default. A device that has been powered off for a long interval resumes from the time it was powered off, so its records appear to precede the outage. A device whose time source is unreachable falls back to its own oscillator, which drifts at a rate set by the hardware, typically on the order of seconds per day for an uncompensated crystal and much worse for some.

Detecting these before the merge is cheaper than repairing the timeline afterwards. Comparing the device’s reported time against the collector’s at the moment a record arrives gives a coarse offset estimate, and a device whose offset is changing steadily is drifting rather than merely offset. The steady drift is the more dangerous case, because an offset that is corrected in a step produces a visible discontinuity in the log while a drift produces a timeline that is wrong by an amount that varies with time and leaves no discontinuity to notice.

Merging without losing the bound

A merged timeline should carry the uncertainty with it. The practical form is to record, alongside each event, the device that produced it and the offset bound that applied to that device at that time, and to refuse to assert an ordering between events whose intervals overlap.

def ordered(a, b):
    """True if a certainly preceded b, given (time, halfwidth) pairs."""
    return a.time + a.halfwidth < b.time - b.halfwidth

# Overlapping intervals are concurrent as far as the evidence goes.

The test is one comparison and it settles most disputes about what the logs show. Events whose intervals overlap are not ordered by the evidence, and claiming they are is the most common error in reading a merged timeline. Reporting the overlap as an unknown is more useful than resolving it arbitrarily.

Where an overlap cannot be left unresolved because a decision depends on the order, the resolution is to find a stronger signal for that pair, not to tighten the assumed offset. Tightening the assumed offset to make the ordering come out as expected is how a timeline becomes a narrative.

What correlation can and cannot establish

Correlation establishes that events were concurrent or that one preceded another. It never establishes that one caused another. Two devices can record a session teardown and a routing change within the same second, and the ordering bound may even place the teardown first, without any evidence that the teardown caused the routing change. The causal claim needs a mechanism, which in this case means a documented rule about what the routing protocol does when a session ends.

The same limitation applies to the counts. A device that logs a suppression count rather than each event has discarded the data needed to say how long the burst lasted, and no amount of cross-device correlation recovers it. Where the duration matters, the device’s own counters, sampled over time, are the substitute; the difference between a counter’s attribution and a log’s is covered in interface drop counters.

The one thing a merged timeline reliably establishes is sequence within a device, and that is often enough. Most faults have a single device whose log shows the full progression, and the other devices’ logs serve only to establish that they were not the cause. Deciding which device that is comes from the path, and from knowing which device was in a position to produce the first observable change. Where the first change is a routing session going down, the state it reports is a better starting point than any timestamp, as reading a BGP session failure sets out.