TT Lab
Get started
Learn Learning paths Courses

Finding the Cause in Logs

A Timestamp Without an Offset Is Not a Timestamp

Continue in TT Lab

One-line summary

The time written in a log is a claim, not a fact. Without an offset, you cannot tell which region's clock it is, and even if the offset is accurate, if that host's clock itself is off by a few seconds, the cause lines up after the effect.

Why this is needed

However well you normalize the format, if the times are false, every conclusion built on top of them is false. The first thing you do in an outage investigation is "what happened first," and the basis for deciding that order is exactly these numbers.

Three things come together in the bundles you receive in the field. First, local time with no offset at all. It is still common for an application logger's default to be 2026-03-08 15:04:57.200. RFC 3339 pins this down in section 4.4 — it writes that local time without an offset fails to be interpreted in about 23/24 of the world, so on the internet it is unacceptable as an interoperability problem. Whether that line was stamped in Seoul or in Frankfurt is not in the line.

Second, offsets whose meaning is subtly different. Section 4.3 of the same document separately defines -00:00. It is the notation used when you know the UTC time but not the local offset of the place that made the record, and it means something different from Z or +00:00 — the latter two mean that UTC is the reference point for that time. As numbers, both are 0, so the calculated result is the same, but the information it gives the reader differs.

Third, error in the clock itself. A host that is not attached to NTP drifts by a few seconds a day. Even if it carries the offset exactly right, if its clock is 7 seconds ahead, every time that host stamped is 7 seconds ahead. For a request that finishes in 1 second, the cause is recorded 6 seconds after the effect. Looking at the log alone, it appears the database answered before it received the request.

How it works

The way to make untrustworthy times trustworthy is to settle on one reference and measure against it.

Find a reference event. Anything that leaves a mark on several hosts at the same time will do — a deployment marker, a configuration reload, a check signal sprayed by an operations scheduler. If the same marker is in all three files, the time difference among those three lines is the difference among the three clocks. The precision of this method cannot exceed the scatter in the time it takes that signal to reach the three hosts — you must write that fact down as well so the estimate is not exaggerated.

Split the difference into two shares. The difference from the reference mixes a local offset and a clock error. IANA local offsets are multiples of 15 minutes, so if you fold the difference to the nearest 15 minutes you get the local offset, and the remaining seconds are the clock error. You read 8 hours 59 minutes 57 seconds as "a 9-hour offset + a clock 3 seconds behind." You must not round away those 3 seconds — it is exactly those 3 seconds that reverse the causal order.

A region name is not an offset. A region is a set of rules maintained by the IANA time zone database, and even the offset of the same region changes with the season. Python reads these rules as they are with zoneinfo. For a region with daylight saving time, local time with no offset becomes risky twice — in spring a time that does not exist appears (America/New_York at 02:30 on 2026-03-08), and in autumn a time that occurs twice appears. fold in datetime is the knob that points to the latter.

Finally, fix it to one notation. Exactly as the property written in RFC 3339 section 5.1, if the offset notation and the number of decimal places are the same, string sorting is time-order sorting. If you deal with syslog, section 6.2.3 of RFC 5424 tightens further — T and Z must be uppercase, leap seconds cannot be used, and the fractional part of a second cannot exceed six digits.

What you see in the field

Keep both the original clock and the observing clock. This is exactly why the OpenTelemetry log data model separates Timestamp and ObservedTimestamp. The former is the time of the original clock where the event occurred and may be absent. The latter is the time the collector saw the event. If you hold both together, you have a yardstick to cross-check against when the original clock is suspect. When handing off to a system that accepts only one, the specification recommends using Timestamp if present and ObservedTimestamp if not.

A correction value is an assumption, not data. "This host is +09:00 and 3 seconds behind" is a value you estimated from a reference event. Do not overwrite the original lines; leave the corrected time and the original string side by side. If you change the reference later, you must be able to recompute from the beginning.

The real solution is on the customer's side. Estimation is first aid to save this bundle. The real solution is to demand that from the next bundle on, every host be attached to NTP, the logger always attach an offset, and, if possible, stamp in UTC. The basis for making that demand is exactly the numbers you measured.

What you will do in the next lab

You reproduce the logs of three hosts and examine their notations, and test for yourself how a local time in a region with daylight saving time disappears and how it occurs twice. Then, using a check signal stamped in all three files, you split and estimate each host's local offset and clock error, and correct every line to line them up as one timeline. Finally, you count how many requests had the cause stamped after the effect before correction, and leave a report of what you corrected and on what grounds.