Fifty Minutes Is Not a Constant

A scheduled CI run failed on an assertion that an event created 50 minutes ago was between 49 and 51 minutes old.

The event had not changed. The code had not become wrong. The test suite had simply taken long enough for “50 minutes ago” to become “more than 51 minutes ago.”

This is the kind of flaky test that looks generous because it has a tolerance. The two-minute window feels like protection against timing noise. In reality it is a countdown: every second spent collecting tests, running fixtures, or waiting for a busy CI worker consumes part of the allowance.

The test had two clocks

The fixture defined one module-level timestamp:

NOW = datetime.now(timezone.utc)

Every ledger row was generated relative to it:

def _row(minutes_ago: float, phase: str, **extra: object) -> str:
    row = {
        "timestamp": (NOW - timedelta(minutes=minutes_ago)).isoformat(),
        "phase": phase,
    }
    ...

The assertion then asked whether the second launch of an item was still about 50 minutes old:

assert 49 * 60 <= age_seconds <= 51 * 60

But the production summarizer computed that age from a fresh wall-clock read:

now = datetime.now(timezone.utc)
age_seconds = (now - event_timestamp).total_seconds()

The fixture clock was captured during test-module import. The summarizer clock was captured when the test eventually ran. They agreed only while the elapsed suite time remained inside the assertion’s tolerance.

That makes the real equation:

reported age = 50 minutes + time since module import

The test was deterministic for exactly as long as the suite stayed fast.

A tolerance is not clock control

Timing tolerances are useful when the behavior under test is inherently asynchronous: a process should stop within a deadline, a retry should wait at least a backoff interval, or a scheduler should wake within some operating margin.

This test was different. It checked arithmetic over historical timestamps. There was no meaningful reason for the answer to depend on how busy the runner was. The expected age was part of the fixture, so the current time needed to be part of the fixture too.

Suite runtime only ever makes the event look older, so the upper bound is the only one that matters. Widening the range to 48–52 minutes would move it out by one more minute. Making it 45–55 would buy four. Both changes preserve the hidden dependency and turn the failure rate into a function of suite duration.

Freezing time globally would work, but it would be broader than necessary. The smallest repair was to make the clock an explicit input at the function that performs the time-dependent calculation:

def summarize(rows, hours, cap, *, now=None):
    now = now or datetime.now(timezone.utc)
    ...

Production callers keep the existing behavior. The test passes the same NOW used to construct its rows:

return summarize(loaded, hours, cap=5, now=NOW)

Now “50 minutes ago” means 50 minutes before one declared instant. Collection time, suite order, and CI load no longer participate in the result.

The failing run was already behind the fix

There was a second trap in the incident. The scheduled run tested commit 743e1c565552. By the time the failure was investigated, the clock-injection fix had already landed on the default branch as 9b571c39d6.

Patching the failing test again would have created duplicate work against a stale failure. The useful sequence was:

1. identify the exact failed assertion;
2. compare the failed run’s commit with current master;
3. reproduce the test on current HEAD (a pass is consistent, not proof);
4. inspect the intervening commits for the shared-instant injection;
5. require a new scheduled full-matrix run after the fix before declaring the incident closed.

The exact test passed locally, as did the full test file. That is consistent with a repaired checkout, but it is not proof: the unfixed test also passes whenever it still executes inside the original one-minute upper allowance. Code inspection of the intervening commits is what established that 9b571c39d6 injected the shared instant. Whether the scheduled environment has exercised that repair is a separate claim, so the incident is waiting on a machine-checkable post-fix run rather than being marked done on the strength of a local reproduction.

One instant per assertion

The general rule is simple: if a test constructs time-relative input and later asserts on time-relative output, both sides should share one explicit instant.

Look for this shape:

fixture timestamp = module_now - offset
result age       = function_now - fixture timestamp

Two calls to now() mean the elapsed test runtime has entered the contract. Sometimes that is intentional. Usually it is an undeclared input.

The same problem appears outside tests:

• pagination code captures a cutoff, then later filters with a new clock;
• cache expiry checks compare records created under a simulated clock with the host clock;
• replay tools load events relative to a recorded instant but render ages relative to wall time;
• scheduled reports define a window at startup and recompute “current time” in each stage.

Passing a clock everywhere can become ceremony. Passing an instant at the boundary where arithmetic happens is usually enough. It is explicit, local, and preserves the production default.

“Fifty minutes ago” sounds like data. Without a shared clock, it is a process that keeps running while your test suite does.