DEV Community

Jordan Huang
Jordan Huang

Posted on

Stop Calling It Latency Until the Log Line Has an Offset

A webhook looks five minutes late. You paste two log lines into chat. The model draws a timeline and blames the queue.

That timeline is a caption. It is not a measurement.

2026-09-13 09:04:11 with no offset is a wall clock with the zone torn off. Your laptop may be rendering that string in one zone. The process that wrote it may have used another. CI is often a third, and a unit test can freeze a fourth. Subtract those strings as if they were instants and you invent latency out of formatting.

This is a field guide for that mistake. You will print clocks. You will refuse to debug delay until three ISO-8601 values with offsets sit next to the same event.

You are not in the incident you named

You named a networking incident. Slow worker. Retry storm. Provider lag.

You might be right. You might be staring at a formatting incident that only looks like lag.

Naive datetime.now() in Python writes local time and drops the zone. date without %z does the same in a shell. Some log shippers then strip the offset to keep the column narrow. The agent reads the narrow column and performs arithmetic in English. English is not UTC.

Ask a sharper question before you file a vendor ticket: which process, in which timezone, with which idea of “now,” wrote the characters you pasted?

Four instruments, zero obligation to agree

Treat these as separate devices. They do not reconcile themselves.

  1. The laptop clock that painted your prompt.
  2. The application clock on the box that wrote the log.
  3. The CI clock that stamped the job.
  4. The process clock inside a test that stubbed time.

A laptop TZ export is a contaminant. If you probe time on the same machine you use for chat, you measure your profile, not the worker.

Disclosure: This article was prepared as part of MonkeyCode's product outreach. MonkeyCode offers free model access and a free server option. Those two things matter here only as a second machine whose timezone is not your laptop’s. This is not an NTP product claim. No model names, quotas, hardware, or disk lifetime belong in this workflow. Delete the product sentence and the probe still runs on any throwaway VM you already trust.

Artifact: clock-identity.sh

Proposed diagnostic. Read it before you run it. It prints zone knobs and offsets. It does not print secrets. It is not a benchmark.

#!/usr/bin/env bash
# clock-identity.sh
# Proposed diagnostic. Review before running.
set -euo pipefail

echo "## who and where"
id -un
hostname
pwd

echo "## knobs that change wall time"
printf 'TZ=%s\n' "${TZ-<unset>}"
printf 'LC_ALL=%s\n' "${LC_ALL-<unset>}"
printf 'LC_TIME=%s\n' "${LC_TIME-<unset>}"
printf 'LANG=%s\n' "${LANG-<unset>}"

echo "## POSIX date"
date
date -u
date +'%Y-%m-%dT%H:%M:%S%z'
date +'%Y-%m-%dT%H:%M:%SZ' -u

echo "## systemd clock, if present"
if command -v timedatectl >/dev/null 2>&1; then
  timedatectl
else
  echo 'timedatectl=absent'
fi

echo "## /etc/localtime"
ls -l /etc/localtime 2>/dev/null || echo 'no /etc/localtime'
readlink -f /etc/localtime 2>/dev/null || true

echo "## python process clock"
python3 - <<'PY'
import os, time, datetime as dt
print('TZ', os.environ.get('TZ', '<unset>'))
print('time.tzname', time.tzname)
print('time.timezone', time.timezone)
print('aware_utc', dt.datetime.now(dt.timezone.utc).isoformat())
local = dt.datetime.now().astimezone()
print('aware_local', local.isoformat())
print('utcoffset', local.utcoffset())
print('naive_now', dt.datetime.now().isoformat())
PY
Enter fullscreen mode Exit fullscreen mode

Save stdout next to the log line you care about. Redact hostnames if policy requires it. Keep every %z value. That offset is the whole point.

How to read the probe without helping the myth

Start with TZ. If it is set, the process may ignore /etc/localtime. If it is unset, the box zone file wins, until a library decides otherwise.

Then read aware_utc and aware_local. Those two should differ only by offset, not by a mystery five minutes. If they disagree by a few minutes after you account for the offset, you have skew, and skew is a different ticket from “the queue is slow.”

naive_now is the trap. It looks like a timestamp. It is a local wall time with no zone. Agents love it because it is short. CI hates it because UTC workers re-parse it as UTC. Your laptop hates that parse because it is not UTC.

timedatectl may say NTP is active. Treat that as a hint, not a certificate. The probe does not prove the clock is correct against a public second. It only proves which story this process is telling.

Three forgeries that show up as “lag”

Naive Python copied into a runbook

Proposed snippet. Not a result from your fleet.

# proposed anti-pattern
from datetime import datetime

def stamp_event():
    return datetime.now().isoformat()  # no offset
Enter fullscreen mode Exit fullscreen mode

An agent will “fix” a failing test by printing that stamp and calling it UTC. The test passes in a container where TZ=UTC. Production runs with a city zone. The webhook consumer subtracts the two naive strings. You get a delay equal to the offset. That delay is not in the network.

Corrected shape, still proposed:

from datetime import datetime, timezone

def stamp_event():
    return datetime.now(timezone.utc).isoformat()
Enter fullscreen mode Exit fullscreen mode

ISO-8601 with +00:00 survives paste. Naive local time does not.

Cron that says 02:00 and never says where

0 2 * * * /usr/local/bin/invoice is not 02:00 in your city. It is 02:00 in whatever zone the cron daemon uses on that box. An agent comments # 2am, after East Coast close above the line. Comments are not TZ=.

Print the daemon’s zone before you accept the comment. On many boxes that means /etc/localtime plus the crontab header CRON_TZ. If both are missing, you do not have a schedule. You have folklore.

A test clock that escaped into the explanation

freezegun, time-machine, and hand-stubbed datetime.now make tests deterministic. They also teach models a fake calendar. If the chat pastes 2024-01-01 as “today” because a fixture froze it, you are no longer debugging production. You are debugging a cassette.

Proposed check, to run in the same tree the agent claimed was green:

# proposed; does not modify the tree
grep -nE 'freezegun|time.machine|freeze_time|FakeDatetime' -r tests || true
python3 -m pytest -q --collect-only 2>/dev/null | tail -n 5
Enter fullscreen mode Exit fullscreen mode

Collection is not proof the suite ran. It only tells you which files the runner can see. If the agent quoted 400 passed tests and collection shows 40, the caption lied before time arithmetic began.

Decision table

Use the table when the chat sounds sure.

You observed Check this Do not conclude
A log line with no offset date +%z in the writer process A five-minute provider delay
Cron 0 2 * * * plus a city-name comment CRON_TZ, /etc/localtime, timedatectl 02:00 in your office
JWT exp built from datetime.now() aware UTC stamp versus naive stamp Token lifetime equals the number in the chat
pytest date tests passed freeze libraries, TZ in the job Production uses the test clock
CI and laptop “same time” as text both ISO strings with offsets The two machines share a zone
Agent converted the stamp in prose re-print from the writer, do not re-parse in chat The conversion was lossless

If you cannot fill the middle column, you do not have evidence. You have narration.

A fifteen-minute exercise

Label this a plan. It is not a published result.

  1. Pick one disputed event. One webhook. One invoice. One cron fire. Not a stack of them.
  2. Copy the raw log line into a file. Do not let the model rewrite it first.
  3. On the writer box, run clock-identity.sh in the same user and same TZ as the app.
  4. On your laptop, run date +'%Y-%m-%dT%H:%M:%S%z' once. Do not convert it by hand.
  5. In CI, print the same format from the job that built the worker. One line is enough.
  6. Place the three ISO strings with offsets in a table. Subtract only after every offset is visible.
  7. Only then decide whether you have skew, a zone bug, a frozen test clock, or an actual queue delay.

If step 3 and step 4 differ by a whole-hour offset, stop saying “late.” Say “zone.” If they differ by a few minutes after offsets match, then you may talk about skew. If they match and the provider still looks late, you finally have a latency hypothesis that deserves a packet capture.

Limitations

This probe does not authenticate time. It does not implement a signed timestamp. It does not detect a paused VM with any rigor. timedatectl can report synchronization while the guest still jumps.

It also does not prove the log line you pasted came from the process you probed. Process identity is a different checklist. Do not merge the two because both involve a box.

date output changes with LC_TIME. That is why the script prints locale knobs. A translated month name is not UTC either.

The Python block assumes python3 exists. If it does not, you still have POSIX date. Lack of Python is not proof the app is UTC.

Who should not use this approach

Do not paste production request bodies into a model to “explain the delay.” Offsets and zone names are enough.

Do not use this as your legal time source. Finance, medical, and evidence holds need their own timestamp authorities. A shell script on a rented VM is not that authority.

Do not run the probe on a laptop and then claim you measured the worker. The whole method exists because those clocks diverge.

If your org forbids unsanctioned remote boxes, skip the free server path. Run the same script on an approved runner. The script does not care which vendor owns the CPU.

After the offsets exist

Keep the arithmetic boring. Compare ISO-8601 strings that include offsets. Refuse captions. Refuse naive now. Refuse cron comments that name a city without naming a zone file.

When a model pastes a timestamp, demand the writer’s date +%z from the same shell that produced the log. If you cannot get that offset, you do not have a latency number. You have a sentence that looks like one.

Top comments (0)