Break/Fix: Log Timestamp Problem · Break/Fix · Observability

Reported symptoms

Three complaints have been open against the observability platform for months, filed by three different teams, and nobody has connected them.

The payments live tail is always empty. A five-minute window on {job="payments"} returns nothing. Not “a few lines”, nothing. It has been that way since roughly the spring, at every hour of the day. Widen the window to six hours and the stream is full, current-looking and busy, which is why the complaint was never escalated: the logs are obviously there, the tail is obviously a UI problem, somebody will look at it eventually.

The settlement job says its logs are missing. The nightly settlement run at 02:00 writes several hundred thousand lines and none of them are in Loki. The ticket has been raised twice and closed twice as “cannot reproduce”, because whoever picked it up ran a six-hour query on the payments selector, saw plenty of lines, and moved on.

The incident timeline does not reconcile. Reconstructing last week’s authorisation failure, the payments log burst sits one hour later than the Tempo trace timeline and one hour later than the Prometheus error-rate spike. Checkout and api-gateway line up with the traces to the millisecond. This is the complaint that finally got someone’s attention, and it arrived with a hypothesis attached: the payments hosts must have a clock problem.

They do not. Every payments host reports a synchronised clock, chronyc shows sub-millisecond offsets, and the agent has logged no parse failures at all.

There is one more fact on the ticket, contributed by a colleague who was asked whether they had ever seen this. They investigated a January incident on the same service and the payments timeline lined up with the traces perfectly.

Evidence provided

Read-only / Safea space instead of T, and no offset anywhere

$ sudo tail -n 1 /var/log/payments/payments.log

2026-08-18 09:14:02.417 INFO  settle-worker request_id=7f4a1c msg=authorisation accepted

Illustrative output

Read-only / Safethe clock is right, and the host is not on UTC

$ timedatectl status

               Local time: Tue 2026-08-18 09:14:03 BST
         Universal time: Tue 2026-08-18 08:14:03 UTC
              Time zone: Europe/London (BST, +0100)
System clock synchronized: yes
            NTP service: active

Illustrative output

Read-only / Safeclock skew is ruled out, and it is worth ruling out

$ chronyc tracking | grep 'System time'

System time     : 0.000000191 seconds fast of NTP time

Illustrative output

Read-only / Safeno parse failures - which is not the same as no problem

$ sudo journalctl -u alloy --no-pager | grep -ci 'failed to parse timestamp'

Illustrative output

What Loki returns, with its own stored timestamp on the left and the raw line on the right:

2026-08-18T09:14:02.417Z  2026-08-18 09:14:02.417 INFO  settle-worker request_id=7f4a1c msg=authorisation accepted

The span in Tempo carrying request_id=7f4a1c starts at 08:14:02.402Z.

The distributor’s rejection counters:

# Read-only, against the distributor's own metrics endpoint.
curl -s http://loki-distributor.monitoring.svc:3100/metrics \
  | grep '^loki_discarded_samples_total'

loki_discarded_samples_total{reason="out_of_order",tenant="payments"} 4821013
loki_discarded_samples_total{reason="older_than",tenant="payments"} 0
loki_discarded_samples_total{reason="out_of_order",tenant="checkout"} 0

And the pipeline stage that reads the payments log, unchanged since February:

// /etc/alloy/config.alloy
loki.process "payments" {
  stage.regex {
    expression = "^(?P<ts>\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2}\\.\\d+)\\s+(?P<level>\\S+)\\s+(?P<msg>.*)$"
  }
  stage.timestamp {
    source = "ts"
    format = "2006-01-02 15:04:05.000"
  }
  forward_to = [loki.write.default.receiver]
}

The settlement binary, which shares this file and these labels, was never migrated to the new logging library and still writes RFC 3339 with a Z.

Work the evidence before reading on

The clock hypothesis is dead and it deserved to be tested. Start from what survives it.

timedatectl and chronyc both say the clock is correct. What is still capable of putting a log line in the wrong hour when the clock is right?
The stored timestamp and the timestamp inside the line agree exactly. Where can the wrongness have entered, given that those two agree and both disagree with the trace?
The agent reports zero timestamp parse failures. Is that reassuring, or is it the most important line of evidence on the page?
Read the Go layout in stage.timestamp character by character. What does it say about the zone?
A January investigation found the timeline correct. What changes in Europe/London between January and August, and on which date?
Work out the direction of the error before its size. If a line is stored one hour in the future, what does a query for the last five minutes return, and what does a query for the last six hours return? Check that both answers match the reported symptoms.
The settlement job is the only component still emitting an explicit Z, which is to say the only one that is correct. Why would being correct get your lines rejected, and what does the ingester compare a new entry against?

Before continuing: name the single property of the payments log format that produces an empty tail, a healthy six-hour view, a one-hour disagreement with traces, and a rejected batch job, all at once.

Root cause

A layout with no zone is a decision to assume UTC

The line says 2026-08-18 09:14:02.417. It does not say what that means. There is no T, no Z, no numeric offset - nothing that names the zone the numbers were read in.

The pipeline resolves that ambiguity with the Go layout 2006-01-02 15:04:05.000, which also names no zone, and a layout that names no zone is parsed as UTC. So Loki stores the numbers exactly as written, treating 09:14:02.417 as 09:14:02.417Z. The hosts are on Europe/London and the real UTC time of that event was 08:14:02.417Z.

Through February and March this was invisible, and not by luck. In a British winter local time and UTC are the same thing, so the wrong assumption produced the right answer. The change shipped, the rollout looked clean, and the January incident review confirmed the timeline. From the last Sunday in March the offset became one hour, and every payments line since has been stored exactly one hour in the future.

One hour into the future is a range problem, not a loss problem

This is why the two most-reported symptoms look like opposites.

A query is a range over stored timestamps. Events from the last five minutes are stored between fifty-five and sixty minutes ahead of now, which is outside a now-5m to now window, so the tail is empty - and empty in a stable, all-day, entirely reproducible way that reads much more like a broken tail than like a broken clock.

A six-hour window returns everything stored between now-6h and now, which is the events that really happened between seven and one hours ago. There are plenty of them, they are evenly spread, and the newest one displays a timestamp of about now. The view looks perfect. Nothing is lost, nothing is duplicated, and the only thing wrong with it is that every line is filed under the wrong hour - which a reader has no way to see, because the timestamp Loki shows and the timestamp inside the line agree.

That agreement is the trap. Every check that reads only the log line confirms the log line. The error is only visible against a clock that was not involved in producing it, which is why the trace timeline is the piece of evidence that cracked the case.

Being correct in a stream that is wrong gets you rejected

The settlement job writes into the same file, under the same labels, and therefore into the same stream. It is the one component still emitting an explicit Z, so its timestamps are true UTC.

The ingester accepts an entry whose timestamp is newer than the last timestamp it has seen on that stream. By 02:00 the main service has already pushed that stream’s head an hour into the future - to about 03:00Z. Settlement’s honest 02:00:00Z line arrives behind the head and is rejected as out of order, and so is every line after it, for the whole run. loki_discarded_samples_total with reason="out_of_order" has been counting them accurately for months, in the millions, on a dashboard nobody opened.

Two teams have therefore been carrying failures caused by a third team’s timestamp format, with no shared symptom between them, which is the ordinary shape of a shared-stream fault.

Under the hood

Loki holds two timestamps for every line: the one parsed from the line by the pipeline’s timestamp stage, and the wall-clock time at which the entry reached the distributor. The timestamp stage decides which one wins. If the parse succeeds, the parsed value is stored; if the parse fails, Loki falls back to ingest time and the agent raises a processing error the operator can count.

The whole difficulty of this incident sits in that word “succeeds”. The stage has exactly two outcomes and neither of them is “this value is ambiguous”. A parse failure is loud: a failed to parse timestamp line in the agent journal, an error metric that can be alerted on, and lines landing under the moment they arrived rather than the moment they happened - which is wrong in an obvious, attention-grabbing way. A parse that succeeds against a zoneless layout is completely silent, produces a plausible timestamp, and is wrong by the size of the host’s offset from UTC, which is zero for part of the year.

So the observable that mattered here was never available on the pipeline’s own error surface. It was available in two other places: in the ingester’s rejection counters, where the collision with the settlement job showed up as millions of out-of-order samples, and in the relationship between the newest stored timestamp for the job and wall-clock time. Neither of those is a parse metric, and that is exactly why they caught what the parse metric could not.

A parse failure is loud; a bad parse is silent

The instinct on a timestamp problem is to look for parse errors, and this estate had a perfectly good parse-error metric with a perfectly good alert on it. Both behaved correctly for four months, because there was nothing wrong with the parse.

Any parser that must resolve an ambiguity will resolve it, and it will do so without telling you, because from the parser’s point of view nothing unusual happened. Zoneless timestamps, two-digit years, ambiguous day-month ordering and bare Unix integers of uncertain unit all fail this way: they produce a valid answer that is wrong by a fixed, plausible amount.

The defence is not a better parser. It is to remove the ambiguity at the source and then to refuse the ambiguous form - a layout that only accepts an explicit offset turns every one of these into a loud parse failure, which is a category of problem this estate was already equipped to find in a day.

Resolution

Tell the three complaining teams that they have one fault, and tell anyone currently reconstructing an incident that payments log timestamps are an hour ahead of reality until further notice. This costs nothing and it is the only part of the fix that is instant.
Widen the pipeline to accept the correct form before anything starts emitting it. Add RFC3339Nano and RFC3339 as accepted formats alongside the existing layout, so old and new line shapes both parse while the application rollout is in flight.
Change the application to emit RFC 3339 with an explicit offset, in UTC. This is one configuration line per logging library and it is the only durable fix; everything done in the pipeline is interpretation of a value that should never have needed interpreting.
Work out the cutover cost before scheduling it. The instant the application starts telling the truth, its lines are stamped an hour behind a stream head that the previous hour of wrong lines has already established, so they are rejected as out of order - about an hour of total log loss for payments, caused by the fix.
Avoid that hour by landing corrected lines in a fresh stream. Change one bounded label on the payments emitters as part of the same deployment; a new label set is a new stream with no future head, so the corrected lines have nothing to collide with. Retire the old label value once the old stream has aged out, so this leaves one extra value behind rather than a growing set.
Give the settlement job its own bounded job value in the same change. A batch process and a long-running service sharing one stream is what coupled their correctness, and separating them means neither can reject the other again.
Remove the zoneless layout from the pipeline once every emitter has shipped the new format. This is the step that turns the fault into a loud failure for the next service that gets it wrong, and it is the step most likely to be forgotten, because by then everything looks fine.
If the deployment cannot be taken now, hold explicitly rather than by default: state that payments logs remain an hour out and settlement logs remain absent, name an owner and an end time, and put the correction factor where an on-call engineer will find it at 03:00.

Verification

A log line and its trace span agree. Take one request_id, find its span in Tempo, and require the stored log timestamp and the span start to match within milliseconds. This is the only check that is independent of the thing that was broken - every check that reads the log line alone agreed with itself throughout the incident.
The same holds against metrics. Compare the log burst with the Prometheus counter increment for the same event and require them to coincide, so the verification does not rest on a single second opinion.
The live tail returns lines. A five-minute window on the payments selector must return recent lines, which it has not done since March. It is the cheapest standing check for a timestamp shift, and it detects a shift in either direction.
Out-of-order rejections go to zero, not merely down. Take the rate of loki_discarded_samples_total{reason="out_of_order"} for the payments tenant across a full settlement run and require it to be flat, with the settlement lines present and queryable for that same run.
The raw line on disk carries an offset. Read it on the host rather than through Loki; the point of the fix is that the source now says what it means.
The guard can fail. In staging, emit one line in the old zoneless format and confirm the pipeline now reports a parse failure in the agent journal and increments its processing-error metric instead of accepting it. A pipeline that has only ever accepted lines has not been tested.
The cutover loss is what you predicted. Compare line counts either side of the deployment against the expected figure; a gap much larger than predicted means the stream rotation did not take effect and corrected lines are being rejected.
The estate is checked, not just the service. Run the newest-stored-timestamp-versus-wall-clock comparison across every job, because the layout that caused this was copied from a template and payments is unlikely to be the only place it landed.

Prevention

The source owns the timestamp and it must be unambiguous: RFC 3339 with an explicit offset, in UTC, generated in the process that observed the event. A value without an offset is a guess, and the guess is made by a parser that has no idea what zone the host is in.
Never write a parser layout that omits the zone. Such a layout is a silent decision to assume UTC, and it will be right in some months of the year and wrong in others, which is the worst possible distribution of correctness.
Put servers on UTC. Where a host must carry a local zone, treat it as a standing fault scheduled twice a year and review it either side of each transition.
Add a standing comparison of the newest stored log timestamp per job against wall-clock time. A job whose newest line is persistently in the future, or persistently far in the past, is broken in a way no parse-error metric will ever report, and one query covers both directions across every job at once.
Alert on loki_discarded_samples_total broken out by reason and tenant, and treat a non-zero out-of-order rate as a fault rather than as background noise. It was the loudest signal available in this incident and it had been correct and ignored for months.
Keep one emitter per stream. A batch job that shares labels with a long-running service inherits that service’s timestamp errors, and neither team can see the coupling from their own side of it.
Test the pipeline in CI against a captured line from every emitter that writes into it, including the ones nobody migrated. The settlement binary was invisible to this pipeline’s authors precisely because it had not changed.
Treat a logging-format change as a change to the observability contract, not as an application detail. It alters what every downstream query, alert and post-incident timeline means.

What if the service had emitted a format the pipeline could not parse at all?

Then this would have been over in a day. A parse failure writes failed to parse timestamp into the agent journal, increments a metric the alerting already watches, and drops the line into the store under ingest time. The last of those is the loud one: a backfilled or delayed batch lands under “now” instead of under the hour it belongs to, an analyst notices that an overnight job appears to have run during the investigation, and somebody looks at the pipeline.

The silent success is strictly worse than the loud failure, and that is the inversion worth carrying out of this scenario. The pipeline was working; the alerting was working; the parse-error metric was accurate. Every instrument that could have spoken was reporting correctly on a question adjacent to the one that mattered.

The counterfactual on the other side is just as instructive. Had the hosts been on a zone with a year-round offset - Europe/Berlin in July or America/New_York at any time - the fault would have appeared immediately on rollout, correlated with the deployment, and been fixed in the same afternoon. The four-month incubation and the plausible alibi both come from the same place: Europe/London in winter is UTC, so the bug agreed with reality for long enough to be trusted. A latent defect that is correct for part of the year is not a lucky defect. It is one that gets deployed, reviewed, validated and believed before it activates.

Why this matters

Three teams carried three unrelated-looking failures for four months, and the platform’s own error surfaces were silent throughout because nothing had failed. A value that did not say what it meant was interpreted by something that did not know, and the interpretation was wrong by exactly one hour for part of the year.

The transferable habit is to verify a timestamp against a clock that was not involved in producing it. A log line’s stored time and its embedded text will always agree, because one was derived from the other; that agreement is circular and it will confirm any error you care to make. Traces, metrics and wall clock are independent witnesses, and the routine question “does the newest line in this job look like now” is one query that would have caught this on the last Sunday in March.

The second habit is to be suspicious of parsers that never complain. An instrument that has only ever returned success has not been shown to be capable of returning anything else, and the fastest way to find out is to hand it something you know is wrong.

Reported symptoms

Evidence

Root cause

Remediation

Verification

Prevention

Reported symptoms

Evidence provided

Work the evidence before reading on

Root cause

A layout with no zone is a decision to assume UTC

One hour into the future is a range problem, not a loss problem

Being correct in a stream that is wrong gets you rejected

Resolution

Verification

Prevention