48 小時排查筆記：牆上時鐘跳變令批次任務提早耗盡約 40 秒預算

Have you ever watched a job with a 20-minute budget give up at minute nineteen, on a host where every single call was fast? I spent two days chasing exactly that, and the fault was not in the network, the endpoint, or the model. My deadline accounting was reading the wall clock, and the wall clock on that box moved underneath me.

These are my field notes from a 48-hour window: what I ran, what broke, what I fixed, and what I would do again next time. If you run batch work on a machine you do not own, the shape of this bug should look familiar.

What I ran for 48 hours

I built a small batch job that classifies failure lines from a log file, one line per call, under a hard wall of twenty minutes per run. I scheduled it to fire every two hours, which gave me roughly twenty-four chances to watch the same code path under slightly different conditions. The calls went through MonkeyCode's free model access, and the process itself ran on the free server option, because I wanted rehearsal time without renting anything.

Disclosure: This article was prepared as part of MonkeyCode's product outreach.

Treat any free tier as volatile by default and verify current limits yourself before you build a dependency on it, because availability claims age fast. The job had three parts I actually cared about: a run budget, a retry delay read from the Retry-After header, and one log line recording every decision. Everything else was glue I did not need to think about.

What broke, and why it took two days

The first failure looked like a slow run, and I blamed the endpoint. The second looked like a flaky service, and I added a sleep. By the third run I had stopped guessing and started printing every clock I could reach on every decision point.

Failure one: the budget was measured with time.time()

My original budget did this, which I now consider a small crime against future me:

# Don't do this: wall clock can step backwards or forwards.
start = time.time()
while True:
    do_a_little_work()
    if time.time() - start > 1200:
        raise BudgetExhausted()

time.time() returns wall-clock epoch seconds, which can be adjusted by NTP, by a hypervisor, or by an operator typing date -s. In my window, the reported elapsed time on one run was roughly 40 seconds larger than the monotonic elapsed time, so the job bailed out early with most of its work still unfinished. I could not confirm the cause from the host's own logs, and I still cannot, because that server was not mine to inspect. What I could confirm is the shape of the bug: wall clock claimed 1,240 seconds had passed, and a stopwatch claimed 1,200.

Failure two: Retry-After is two formats, not one

The second bug was entirely mine, and it is embarrassingly common in retry code. My parser did int(response.headers.get("Retry-After", 0)), which works fine until a server sends an HTTP-date instead of delta-seconds. Then it raises ValueError, my bare except swallowed it, the computed sleep became zero, and the job hammered an endpoint that had politely asked it to wait.

RFC 9110 permits both forms, and that ambiguity is the whole reason this bites people. So which one are you going to parse, and how will your code know which one it received?

The artifact: an injectable clock and an honest parser

I replaced the inline deadline with a tiny object that accepts its clock as a constructor argument. Injection is not decoration here; it is the thing that makes the failure testable on a laptop instead of on a remote box at 3am.

# budget.py
from __future__ import annotations

import time
from dataclasses import dataclass
from typing import Callable


@dataclass
class Budget:
    """Deadline accounting that survives wall-clock steps."""

    total_seconds: float
    clock: Callable[[], float] = time.monotonic
    _start: float | None = None

    def start(self) -> "Budget":
        self._start = self.clock()
        return self

    @property
    def elapsed(self) -> float:
        if self._start is None:
            raise RuntimeError("call start() before reading elapsed")
        return self.clock() - self._start

    @property
    def remaining(self) -> float:
        return max(0.0, self.total_seconds - self.elapsed)

    def expired(self) -> bool:
        return self.remaining <= 0.0

Then the header parser, which keeps two different concepts separate instead of pretending they are the same number.

# retry_after.py
from __future__ import annotations

from datetime import datetime, timezone
from email.utils import parsedate_to_datetime

MAX_BACKOFF_SECONDS = 60.0


def parse_retry_after(value: str | None, now: float) -> float:
    """RFC 9110: Retry-After is delta-seconds OR an HTTP-date.

    `now` must be wall-clock epoch seconds (time.time()), because the
    HTTP-date branch is an absolute instant, not a duration.
    """
    if value is None:
        return 0.0
    value = value.strip()
    if not value:
        return 0.0

    if value.isdigit():
        return min(float(value), MAX_BACKOFF_SECONDS)

    try:
        when = parsedate_to_datetime(value)
    except (TypeError, ValueError):
        return 0.0

    if when.tzinfo is None:
        when = when.replace(tzinfo=timezone.utc)

    delta = when.timestamp() - now
    return min(max(delta, 0.0), MAX_BACKOFF_SECONDS)

Notice the deliberate split: durations use time.monotonic(), while absolute instants use wall-clock epoch seconds. That single distinction is the entire lesson, and it fits in about two lines of code.

The test plan I actually ran

I did not want to argue with myself about clock semantics at midnight, so I wrote the clock step itself as a test.

1. Write test_budget.py with a FakeClock you can advance by hand, using two instances to model two independent real clocks.
2. Assert that a backwards wall-clock step leaves Budget.remaining untouched, since only the monotonic clock moved forward.
3. Assert that both Retry-After formats parse, including an HTTP-date already in the past.
4. Assert that unreadable garbage returns zero rather than raising, because a header you cannot parse must not blow up a retry path.
5. Run python -m pytest -q test_budget.py and keep the file in CI next to the retry code.

# test_budget.py
import pytest

from budget import Budget
from retry_after import MAX_BACKOFF_SECONDS, parse_retry_after


class FakeClock:
    """A clock you can move by hand. Two instances model two real clocks."""

    def __init__(self, t: float = 0.0) -> None:
        self.t = t

    def __call__(self) -> float:
        return self.t

    def advance(self, dt: float) -> None:
        self.t += dt


def test_budget_ignores_a_backwards_wall_clock_step():
    monotonic = FakeClock(0.0)
    wall = FakeClock(1_700_000_000.0)

    budget = Budget(60.0, clock=monotonic).start()
    wall.advance(-45.0)        # NTP steps the wall clock back 45 seconds
    monotonic.advance(10.0)    # ten real seconds have passed

    assert budget.remaining == 50.0
    assert not budget.expired()


def test_delta_seconds_form():
    assert parse_retry_after("12", now=1_700_000_000.0) == 12.0


def test_http_date_form():
    now = 1_700_000_000.0
    assert parse_retry_after(
        "Tue, 14 Nov 2023 22:13:40 GMT", now=now
    ) == pytest.approx(20.0)


def test_garbage_is_zero_not_an_exception():
    assert parse_retry_after("soon", now=0.0) == 0.0


def test_absolute_date_is_clamped_and_capped():
    now = 1_700_000_000.0
    assert parse_retry_after("Tue, 14 Nov 2023 22:00:00 GMT", now=now) == 0.0
    assert parse_retry_after("9999999999", now=now) == MAX_BACKOFF_SECONDS

That gives you four behaviours under test without a fake network, a container, or root access.

The second half of my plan ran on the host, and it needs no privileges at all. I put this ten-line script at the top and bottom of each job run:

python3 - <<'PY'
import time

wall_a, mono_a = time.time(), time.monotonic()
time.sleep(5)
wall_b, mono_b = time.time(), time.monotonic()

print(f"wall delta {(wall_b - wall_a):.3f}s")
print(f"mono delta {(mono_b - mono_a):.3f}s")
print(f"divergence {((wall_b - wall_a) - (mono_b - mono_a)):+.3f}s")
PY

If divergence grows across a run, you have found your culprit and can stop reading your network code. If it stays near zero, your budget bug lives somewhere else, and you have saved yourself a day of suspicion. Five seconds is enough to reveal a step, but it does not prove the step happened during your specific job window.

Decision table: which clock answers which question

What I would repeat, and what I would change

I would absolutely repeat the injectable clock, because it turned a vague "the box is slow" feeling into a test that fails in under a second. I would also repeat printing the monotonic and wall deltas side by side at the start and end of every run, which cost me two lines and paid for itself immediately. And I would keep the parser's two branches separate, since merging them is how the int() bug got in.

What I would change is smaller and more honest. I would stop writing bare except clauses around header parsing, because a swallowed ValueError became a zero-second backoff and a needless burst of traffic. I would add a modest cap to every server-supplied delay, since a header can legally ask you to wait almost forever. And I would decide the clock question during design rather than during an incident.

Limitations and who should skip this

This approach fixes your own accounting, not the platform's, so it will not tell you why a managed host restarted or suspended anything. My unit tests prove that the code behaves correctly given a stepping wall clock, and they do not prove that your production host's clock actually stepped. If you need that proof, you have to gather host evidence such as NTP daemon logs or a hypervisor report, which you may not have permission to read.

Monotonic time also cannot be persisted or compared between machines, so any distributed lock, lease, or expiry timestamp still needs wall-clock UTC. If your workload is one short request with no deadline logic at all, you can skip this entire article and go outside instead. And if your team already standardises on a tracing library that records both clocks, read your spans before adding new instrumentation.

So the next time a job quits early on a box you do not own, which clock in your code is answering the question "how long has this been running?" If you cannot say out loud, fix that before you touch the retry logic.