DEV Community

Taylor Wang
Taylor Wang

Posted on

The Poller Was Fine on My Laptop. The Deadline Was Reading the Wrong Clock.

Have you ever watched a health check fail, even though the process was still doing useful work? I spent two days chasing that exact pattern after a deploy that looked boring on my laptop. The service came up, the retries fired, and then the client declared the whole thing unreachable. Why would a timeout that passed locally start collapsing as soon as I left my own machine?

This is not a retry-storm recap, and it is not a performance bake-off with invented numbers. These are field notes from a forty-eight hour window where wall clocks lied to my deadlines. I will show the helper I trusted and the test that finally caught the jump. I will also keep a small decision table next to any timeout I ship after this.

Hour 0–8: I treated latency like a sleep schedule

The client was a tiny Python poller that waited for a worker to publish a ready file. I had written the deadline the way almost every snippet writes it, using time.time() plus a budget. Does that look familiar to you, or do you also paste that pattern without blinking? I needed the predicate to return something truthy before that budget ran out on me.

# buggy_deadline.py — demonstration helper, not production code
import time
from typing import Callable, TypeVar

T = TypeVar("T")


def wait_until(predicate: Callable[[], T], budget_s: float = 30.0) -> T:
    deadline = time.time() + budget_s
    last_error: Exception | None = None
    while time.time() < deadline:
        try:
            result = predicate()
            if result:
                return result
        except Exception as exc:  # demonstration: too broad on purpose
            last_error = exc
        time.sleep(0.25)
    raise TimeoutError(f"budget spent, last_error={last_error!r}")
Enter fullscreen mode Exit fullscreen mode

I ran it beside the worker on my laptop and watched the helper pass over and over. The ready file appeared in about four seconds, and the poller looked downright boring. So I shipped the same helper toward a shared box that was not compiling unrelated things. Would you have waited for a flaky NTP story, or would you have shipped it too?

Hour 8–20: the logs made the failure look like the network

Once the poller ran away from my laptop, the ready file still appeared on disk. The worker logs were calm, and a local curl to the port still returned 200. The poller still raised TimeoutError after what it claimed was a thirty second budget. Have you stared at two log streams that refuse to tell the same story?

I did the usual noisy things, and I did them in a fairly embarrassing order. Maybe you already have this checklist taped next to your incident channel at work. I still walked through it like the network had to be the villain here.

  1. Doubled budget_s from 30 to 60, then to 120, as if extra sleep would hide a race.
  2. Logged time.time() on every loop, hoping a raw float would confess something useful.
  3. Wrapped the predicate in extra try/except blocks that only duplicated the same traceback.
  4. Blamed DNS, then HTTP keep-alive, then the worker's os.replace of the ready file.

You can even print the three clocks Python already gives you without changing the service:

python - <<'PY'
import time
print("wall", time.time())
print("mono", time.monotonic())
print("perf", time.perf_counter())
PY
Enter fullscreen mode Exit fullscreen mode

None of those changes explained a timeout that fired while the worker was already serving traffic. The timestamps in the poller log were the first honest clue, and I almost missed them. One line jumped forward by more than a minute between two sleeps that should have been 250 milliseconds. Who still trusts a deadline after seeing a one minute gap like that?

Hour 20–32: I asked for a rewrite instead of a clock

I wanted a second pair of eyes, and I did not want to burn a dedicated box on a maybe. I dropped the helper into MonkeyCode because I needed free model access and a free server option for the repro. Disclosure: This article was prepared as part of MonkeyCode's product outreach.

The rewrite came back looking more production ready, which should have been a warning by itself. It added jitter, a max attempt counter, and a pretty log line, and it still used time.time(). I ran that prettier loop on the same scratch server and reproduced the false timeout immediately. If the model never sees your clock source, how can it know your budget is tied to NTP?

# still_wrong.py — labeled snapshot of a generated control flow, not a recommendation
import random
import time


def wait_until_with_jitter(predicate, budget_s=30.0, attempts=40):
    deadline = time.time() + budget_s
    for attempt in range(attempts):
        if time.time() >= deadline:
            break
        value = predicate()
        if value:
            return value
        delay = min(0.25 * (2 ** attempt), 2.0) + random.random() * 0.05
        time.sleep(delay)
    raise TimeoutError("ready signal never arrived")
Enter fullscreen mode Exit fullscreen mode

Notice how the extra knobs make the function look engineered even though the comparison is still fragile. Jitter does not save you when the deadline is anchored to a clock that can step. I needed a repro that did not wait for the next NTP correction like a weather event. Can you honestly say your tests step the wall clock on purpose today?

Hour 32–48: inject the jump, stop waiting for NTP

The useful artifact is not a changed server, and it is not a screenshot of ntpq either. It is a fake clock you can step inside pytest, plus a helper that accepts that clock. I wanted the failure on demand, not at 3 a.m. when a hypervisor paused the VM. Should a timeout bug really require an operations window to prove it exists?

# clocks.py
from __future__ import annotations

import time
from dataclasses import dataclass
from typing import Callable, Protocol, TypeVar

T = TypeVar("T")


class Clock(Protocol):
    def monotonic(self) -> float: ...
    def wall(self) -> float: ...


@dataclass
class SystemClock:
    def monotonic(self) -> float:
        return time.monotonic()

    def wall(self) -> float:
        return time.time()


@dataclass
class FakeClock:
    """Deterministic clock for tests. Wall and monotonic stay independent."""

    wall_s: float = 1_700_000_000.0
    mono_s: float = 100.0

    def monotonic(self) -> float:
        return self.mono_s

    def wall(self) -> float:
        return self.wall_s

    def step_wall(self, delta_s: float) -> None:
        self.wall_s += delta_s

    def step_mono(self, delta_s: float) -> None:
        self.mono_s += delta_s


def wait_until(
    predicate: Callable[[], T],
    budget_s: float = 30.0,
    *,
    clock: Clock,
    sleeper: Callable[[float], None] = time.sleep,
    interval_s: float = 0.25,
) -> T:
    """Retry until predicate is truthy or the monotonic budget is spent."""
    started = clock.monotonic()
    last_error: Exception | None = None
    while (clock.monotonic() - started) < budget_s:
        try:
            result = predicate()
            if result:
                return result
        except Exception as exc:
            last_error = exc
        sleeper(interval_s)
    raise TimeoutError(
        f"monotonic budget {budget_s}s spent, last_error={last_error!r}"
    )
Enter fullscreen mode Exit fullscreen mode

The test that finally made the incident boring lives next to that helper:

# test_wait_until.py
from clocks import FakeClock, wait_until


def test_wall_clock_jump_does_not_burn_monotonic_budget():
    clock = FakeClock()
    calls = {"n": 0}

    def predicate():
        calls["n"] += 1
        if calls["n"] == 1:
            clock.step_wall(120.0)  # NTP step, VM resume, whoever
            return None
        return {"ready": True}

    def fake_sleep(seconds: float) -> None:
        clock.step_mono(seconds)
        clock.step_wall(seconds)

    result = wait_until(
        predicate, budget_s=30.0, clock=clock, sleeper=fake_sleep
    )
    assert result == {"ready": True}
    assert calls["n"] == 2


def test_true_stall_still_times_out():
    clock = FakeClock()

    def never():
        return None

    def fake_sleep(seconds: float) -> None:
        clock.step_mono(seconds)

    timed_out = False
    try:
        wait_until(
            never,
            budget_s=1.0,
            clock=clock,
            sleeper=fake_sleep,
            interval_s=0.5,
        )
    except TimeoutError:
        timed_out = True
    assert timed_out
Enter fullscreen mode Exit fullscreen mode

Run it locally like this, and keep the assertions in the same repo as the helper.

python -m pytest test_wait_until.py -q
Enter fullscreen mode Exit fullscreen mode

If you want to see the old helper fail under the same jump, swap monotonic for wall inside the loop. Watch the first test start raising TimeoutError instead of returning the ready payload. That is the whole incident, compressed into a unit test you can rerun on a train. Do you still want to wait for the next virtual machine pause after that?

What the two clocks are actually for

I keep mixing them up unless I write the jobs down in a table I can scan. Wall time answers the civil question of what time it is for humans, certificates, and files. Monotonic time answers how long this attempt has been running inside this one process. Which of those questions is your retry loop actually trying to answer?

Job in the code Clock I want Why it bites me when I mix them
Retry budget, backoff cap, circuit cooldown time.monotonic() or time.perf_counter() NTP steps and VM pauses should not expire the budget early
Log timestamps, Date HTTP headers wall clock (time.time(), datetime.now(UTC)) Operators read civil time, not an arbitrary monotonic epoch
TLS not-after, cookie expiry, cron windows wall clock Certificates do not care how long your process thinks it has been up
Cache TTL that must survive process restart wall clock, stored with the entry Monotonic values are not comparable across boots
Duration of a single request inside one process monotonic This is the number I want in a histogram

Python's docs are blunt about this split, and I should have reread them before shipping. The monotonic clock cannot go backwards, and only differences between two calls are meaningful. time.time() is system time, which can jump when NTP steps or a host resumes. time.perf_counter() is also monotonic and is the better default for short intervals.

I still log wall timestamps beside those durations, because a histogram without a civil-time marker hides the outage window. I am not telling you to run date on a shared machine, and I will not paste that command here. Stepping the host clock is a great way to confuse every other tenant and your TLS stack. Inject the clock in tests, and leave NTP to whoever actually operates the box.

What broke, in one list

Here is the failure mode in plain language, without a vendor postmortem attached to it.

  • The original deadline used time.time() + budget, so a forward jump looked like a spent budget.
  • Pretty retries hid the bug by looking like engineering: jitter, attempt caps, structured logs.
  • Laptop NTP was quiet that week, so the helper never failed where I wrote it.
  • Logging only wall time made the worker and the poller disagree without explaining why.
  • Broad except Exception kept real predicate bugs in a variable I only printed after timeout.

What I would repeat

If I have to walk this path again, I will keep the following habits on a sticky note.

  1. Pass a Clock protocol into anything that owns a budget, even if production only uses SystemClock.
  2. Write one test that steps wall time by a ridiculous amount, like 120 seconds, during a single sleep.
  3. Keep time.sleep behind a callback so tests do not actually wait on the wall.
  4. Log both clocks: wall= for humans, mono_elapsed= for the budget that code is spending.
  5. Treat model output as a draft of control flow, then re-check every time source before it ships.

Would I use a generated retry helper again as a sketch of control flow? I would, but only after I make the clock an argument I can fake. Would I paste it into a poller because the names looked grown-up and the jitter felt mature? Not after watching wall time spend a budget that monotonic time still owned.

Limitations, and who should not copy this

This pattern is for in-process budgets such as polls, backoff, and giving one RPC a few seconds. It is the wrong tool when the business rule is civil time on a calendar. Do not convert a run at 09:00 in Tokyo job to monotonic math and call it safer. Do not serialize time.monotonic() into a queue and read it after a reboot.

Skip the fake-clock protocol if your code already sits behind a client that propagates deadlines for you. Also skip a scratch shared server when the repro needs confidential data, a pinned NIC, or a hard CPU cap. A free server option is enough for a clock-injection script you can throw away afterward. It is not a substitute for the environment that actually issues your certificates.

I still do not know which exact NTP step hit that box, and I will not invent a vendor name for it. The pytest file is the part of this story I can defend in review. If your timeouts only fail far from your laptop, ask which clock the deadline is reading. Then write the jump down as a test, before you double another sleep.

Top comments (0)