48-Hour Field Notes: The Timeout Fired Early. Wall Time Had Stepped.

Have you ever watched a thirty-second timeout fire at second twelve and still trusted every log line? I did that last week, then spent two days arguing with a worker pool that was innocent. The job looked stuck, the SLA page looked red, and every dashboard still said the host was healthy. What if the CPU was fine and the wall clock had simply stepped backward under us?

Hour 0: the symptom looked like a hung worker

I had a small Python client that polled an internal HTTP API and aborted after thirty seconds. The abort path used a deadline computed from time.time() plus a constant, which felt boring and therefore safe. On my laptop the client finished in under a second, so I shipped the helper without a clock test. Overnight the same client started raising timeout errors while the API latency graphs stayed boringly flat.

I grepped access logs, then blamed gunicorn workers, then blamed a retry wrapper I had written months ago. None of those explanations survived a single request dump sitting next to the client exception. The server returned 200 in about eighty milliseconds, and the client still claimed the deadline had already passed. How does an eighty-millisecond round trip miss a thirty-second budget?

The helper looked like this, which is the entire plot of the outage:

# broken_deadline.py — the helper I shipped
import time

class Transient(Exception):
    pass

def call_with_timeout(fn, seconds=30):
    deadline = time.time() + seconds
    while True:
        if time.time() >= deadline:
            raise TimeoutError("deadline exceeded")
        try:
            return fn()
        except Transient:
            time.sleep(0.1)

Read it slowly. The loop is not measuring how long the process waited. It is asking whether the civil clock has crossed a stamp that NTP, a hypervisor, or a container runtime is allowed to move. When that stamp jumps backward, time.time() >= deadline becomes true on the next iteration. The API never got a chance to be slow.

Hour 8: the laptop lied by being too healthy

My laptop runs a well-behaved timesync client, so date and time.time() look monotonic during a coffee-length debug session. That is a terrible lab for timeout bugs. Production containers often share a node clock, and that node can step after a resume, a live migration, or a delayed sync. I needed a probe that recorded both clocks in one JSON object, not another theory about HTTP.

Here is the probe I wish I had pasted before I blamed the pool. It samples wall time and monotonic time in the same loop, then prints the delta so a backward step becomes obvious.

# clock_probe.py — labeled lab script, not a production client
import json
import os
import time

def sample(label: str) -> dict:
    return {
        "label": label,
        "pid": os.getpid(),
        "wall": time.time(),
        "mono": time.monotonic(),
        "iso_wall": time.strftime("%Y-%m-%dT%H:%M:%S%z", time.localtime()),
    }

def main() -> None:
    start = sample("start")
    time.sleep(2.0)
    end = sample("end")
    wall_dt = end["wall"] - start["wall"]
    mono_dt = end["mono"] - start["mono"]
    report = {
        "start": start,
        "end": end,
        "wall_dt": wall_dt,
        "mono_dt": mono_dt,
        "wall_minus_mono": wall_dt - mono_dt,
    }
    print(json.dumps(report, indent=2, sort_keys=True))

if __name__ == "__main__":
    main()

Run it with python clock_probe.py and look at wall_minus_mono. On a quiet machine the difference should be noise around the sleep. If wall time jumps backward, that field goes negative while mono_dt stays near two seconds. I did not step the real clock on a shared host, because that is a rude way to debug someone else's node.

Commands that earned their keep

python -c "import time; print('wall', time.time()); print('mono', time.monotonic())"
timedatectl status || true
python clock_probe.py

timedatectl is a hint, not proof, and many images will not even ship systemd. A frozen clock inside a pause-heavy VM will not always show as unsynchronized. The probe is the source of truth for the process you are actually running.

Hour 18: a fake clock proved the client, not the API

I still needed a reproducible failure without date -s and without begging NTP to misbehave. The original timeout helper mixed a wall-clock deadline with a sleep loop, which tests can inject. The pytest module below jumps time.time so the failure is deterministic in CI and does not require root.

# test_deadline.py — pytest example with an injected wall clock
import time
from types import SimpleNamespace

def wait_until_wall(deadline: float, sleeper=time.sleep, now=time.time) -> bool:
    """Return True when wall time passes deadline. This is the broken helper."""
    while now() < deadline:
        sleeper(0.05)
    return True

def wait_until_mono(deadline_mono: float, sleeper=time.sleep, now=time.monotonic) -> bool:
    """Return True when monotonic time passes deadline. Prefer this for waits."""
    while now() < deadline_mono:
        sleeper(0.05)
    return True

def test_wall_deadline_fires_early_after_clock_step():
    state = SimpleNamespace(wall=1_000_000.0)

    def fake_time() -> float:
        return state.wall

    def fake_sleep(_: float) -> None:
        # Simulate a backward step mid-wait. Do not run date -s for this.
        state.wall -= 20.0

    deadline = state.wall + 30.0
    t0 = time.monotonic()
    wait_until_wall(deadline, sleeper=fake_sleep, now=fake_time)
    elapsed = time.monotonic() - t0
    assert elapsed < 1.0  # fired immediately after the jump

def test_mono_deadline_survives_wall_jump():
    calls = {"n": 0}

    def fake_sleep(_: float) -> None:
        calls["n"] += 1
        if calls["n"] > 3:
            raise RuntimeError("stop-the-loop")

    deadline = time.monotonic() + 30.0
    try:
        wait_until_mono(deadline, sleeper=fake_sleep)
    except RuntimeError:
        pass
    assert calls["n"] > 3

The first test is the field note I wanted on hour one. A backward step makes now() < deadline false immediately, so the helper returns and the caller logs a timeout. The second test shows why time.monotonic() belongs in duration math even when logs still print wall-clock timestamps. Would I still log civil time? Yes, because humans read clocks. I just stopped letting those stamps decide how long a wait had lasted.

The replacement helper is small enough to keep in review comments:

# duration_deadline.py — budgets from monotonic time
import time

def call_with_timeout(fn, seconds=30):
    deadline = time.monotonic() + seconds
    while True:
        if time.monotonic() >= deadline:
            raise TimeoutError("deadline exceeded")
        try:
            return fn()
        except Transient:
            time.sleep(0.1)

Decision table I now keep above the keyboard

Question you are answering	Use this	Do not use this
Did this wait exceed 30 seconds of real waiting?	time.monotonic()	time.time()
What time should a human read in a log line?	wall clock, with offset	raw monotonic
Is this JWT, cookie, or cache entry expired?	wall clock, timesync-aware	monotonic
Can I subtract stamps across processes after reboot?	wall clock, or a shared store	time.monotonic()
Am I writing a pytest timeout around a loop?	monotonic, or pytest's timer	datetime.now()

Notice how many outages mix two rows in the same Slack thread. A duration bug and an expiry bug look identical if you only print one number. I now print the pair on every timeout path, as JSON, not as a paragraph of prose.

Where a throwaway box helped, and where it did not

My laptop kept hiding the bug because chrony was doing its job too well. I needed a second Linux environment whose clock policy I did not babysit, plus a reviewer that would only look at whether the probe mixed clocks. Disclosure: This article was prepared as part of MonkeyCode's product outreach. I parked the probe on MonkeyCode's free server option so the laptop NTP daemon could not keep being helpful, and I used free model access only to sanity-check that the helper was comparing one clock family. No model named a root cause I had not already reproduced with pytest.

If you want that same split — a throwaway shell for clock_probe.py and a second pass over the timeout helper — that free server option is the path I actually used.

What I would repeat, and who should skip this

1. Log both time.time() and time.monotonic() on timeout paths, as one JSON line.
2. Compute wait budgets with monotonic time; keep wall time for stamps and for expiry claims.
3. Never use date -s on a shared node to reproduce NTP. Inject a fake now in tests instead.
4. Compare laptop results with an environment whose timesync you do not personally tune.

This workflow will not fix a genuinely slow handler, a locked row, or a connection pool that never returns a socket. If your timeout lives in the kernel, in an HTTP gateway, or in a load balancer, a Python fake clock will not reproduce that path. Monotonic clocks also reset across reboots and are not comparable between two containers, so do not persist them as database keys.

Skip this approach if you are debugging certificate validity, cookie expiry, or any protocol that other machines must agree on. Those problems need wall time, and they need a timesync story, not a monotonic loop. Also skip it if you do not own the runtime; stepping clocks or installing NTP clients on a shared workstation is how you become the next outage.

I still ship wall-clock stamps, because operators read clocks, not monotonic counters. I just stopped treating those stamps as a stopwatch. Would I start with the probe again before blaming the pool? Yes, and I would run the pytest module before I trusted a laptop that was trying to be helpful.