fix: a stalled server no longer reads as "your clock is ahead"
CI / Build & Quality Checks (pull_request) Successful in 3m1s
CI / Trigger Desktop Build (pull_request) Skipped
CI / Docker image build & smoke test (pull_request) Skipped
CI / Secret scan (gitleaks) (pull_request) Successful in 7s
CI / Playwright smoke (e2e) (pull_request) Failing after 11m28s

Incident 2026-09-29: the homeserver's host ran out of memory and stalled for
~2 minutes. The /sync that finally went out carried events whose `age` was
computed ~30 s before it arrived, so every client showed "Your computer's
clock is 30 seconds ahead of the server" while the real problem was the
server (all host clocks were within 0.25 s the whole evening).

The skew estimate was the median of the last 5 samples, and a sample is
local skew + delivery delay, so one late /sync with a handful of events
tripped it.

- Estimate = the LOWEST sample of the last 5 minutes: delay only ever adds,
  so the fastest-delivered event is the truest.
- "Behind" (which a delay can't cause) is reported as soon as there are 3
  samples, like before. "Ahead" must hold across samples received at least
  a minute apart, so a single late burst never trips it.
- Samples are aged on the monotonic clock, and a change of the local clock
  (someone fixing it) resets the measurement, so the warning clears at once.
- Only events stamped by our own homeserver are sampled: a federated event's
  origin_server_ts is the other server's clock.
- Wording: "This device's clock is … Voice calls and encrypted messages can
  fail until it's corrected." / call bar "Device clock … : calls may fail"
  (was "will fail").

Unit tests: the incident (late burst after normal traffic, and a fresh
client whose first samples are all late), mixed slow/fast deliveries,
ahead only after a minute, behind at once, hysteresis, clock fixed.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PPmy3tPq869XDW4njjVaKA
This commit is contained in:
Lotus CI
2026-09-28 21:40:02 -04:00
co-authored by Claude Opus 5.5
parent c0c93213c1
commit bb569d69a2
5 changed files with 141 additions and 43 deletions
+76 -27
View File
@@ -8,44 +8,96 @@ import {
formatSkew,
} from './clockSkew';
// A live event received when the local clock is `skew` ms ahead of the server:
// origin_server_ts = T (server clock), age = a, localTimestamp = (T + a + skew) - a.
const feed = (m: ClockSkewMonitor, skew: number, age = 500, t = 1_700_000_000_000) =>
m.sample(t, age, t + skew);
const T = 1_700_000_000_000;
test('needs three samples, then reports the median with direction', () => {
/**
* A live event received `atSec` seconds into the test, when the local clock is
* `skew` ms off the server and the response took `delay` ms to arrive:
* localTimestamp − origin_server_ts = skew + delay.
*/
const feed = (m: ClockSkewMonitor, skew: number, atSec = 0, delay = 0, wallJump = 0) =>
m.sample(T, 500, T + skew + delay, { wall: T + atSec * 1000 + wallJump, mono: atSec * 1000 });
test('behind: reported as soon as there are three samples', () => {
const m = new ClockSkewMonitor();
assert.equal(feed(m, 60_000).skewMs, null);
assert.equal(feed(m, 61_000).skewMs, null);
const s = feed(m, 59_000);
assert.equal(s.skewMs, 60_000);
assert.equal(feed(m, -60_000, 0).skewMs, null);
assert.equal(feed(m, -61_000, 1).skewMs, null);
const s = feed(m, -59_000, 2);
assert.equal(s.skewMs, -61_000);
assert.equal(s.warning, true);
assert.equal(formatSkew(s.skewMs!), '60 seconds ahead');
assert.equal(formatSkew(s.skewMs!), '61 seconds behind');
});
test('one bad sample cannot trip the warning (median) and hysteresis clears only under 15 s', () => {
test('ahead: only once it has held for a minute', () => {
const m = new ClockSkewMonitor();
feed(m, 1000);
feed(m, 1500);
assert.equal(feed(m, 90_000).warning, false); // outlier
assert.equal(m.getState().skewMs, 1500);
feed(m, 60_000, 0);
feed(m, 60_000, 10);
assert.equal(feed(m, 60_000, 20).warning, false);
assert.equal(m.getState().skewMs, 60_000);
assert.equal(feed(m, 60_000, 59).warning, false);
assert.equal(feed(m, 60_000, 61).warning, true);
});
test('server stall (2026-09-29): a burst of late events does not read as a wrong clock', () => {
const m = new ClockSkewMonitor();
// Normal traffic, then the homeserver stalls and one /sync arrives 30 s late
// with a pile of events, then normal traffic again.
feed(m, 200, 0);
feed(m, 150, 5);
feed(m, 300, 10);
[1, 2, 3, 4, 5, 6].forEach(() => feed(m, 0, 130, 31_000));
assert.equal(m.getState().warning, false);
assert.ok(m.getState().skewMs! < 1000);
// Fresh client whose first samples are all from the late burst.
const fresh = new ClockSkewMonitor();
[1, 2, 3, 4, 5, 6].forEach(() => feed(fresh, 0, 0, 31_000));
assert.equal(fresh.getState().warning, false);
// …and the next timely event brings the estimate back down.
feed(fresh, 0, 70, 100);
assert.equal(fresh.getState().warning, false);
assert.equal(fresh.getState().skewMs, 100);
});
test('slow deliveries mixed with fast ones: the fastest one wins', () => {
const m = new ClockSkewMonitor();
[0, 20, 40, 60, 80].forEach((at, i) => feed(m, 45_000, at, i === 2 ? 0 : 20_000));
assert.equal(m.getState().skewMs, 45_000);
assert.equal(m.getState().warning, true);
});
test('hysteresis: once on, clears only under 15 s', () => {
const w = new ClockSkewMonitor();
[40_000, 41_000, 39_000, 40_000, 40_000].forEach((s) => feed(w, s));
[0, 1, 2].forEach((at) => feed(w, -40_000, at));
assert.equal(w.getState().warning, true);
// drifting down to 20 s: still >= 15 s → stays on
[20_000, 20_000, 20_000, 20_000, 20_000].forEach((s) => feed(w, s));
// Samples expire after 5 minutes; drifting to -20 s keeps it on (>= 15 s).
[400, 401, 402].forEach((at) => feed(w, -20_000, at));
assert.equal(w.getState().skewMs, -20_000);
assert.equal(w.getState().warning, true);
[10_000, 10_000, 10_000, 10_000, 10_000].forEach((s) => feed(w, s));
[800, 801, 802].forEach((at) => feed(w, -10_000, at));
assert.equal(w.getState().warning, false);
});
test('fixing the local clock starts the measurement afresh', () => {
const m = new ClockSkewMonitor();
[0, 1, 2].forEach((at) => feed(m, -14 * 60_000, at));
assert.equal(m.getState().warning, true);
// The user sets the clock forward 14 minutes: wall jumps vs the monotonic clock.
const jump = 14 * 60_000;
feed(m, 0, 10, 0, jump);
assert.equal(m.getState().warning, false);
assert.equal(m.getState().skewMs, null);
feed(m, 0, 11, 0, jump);
feed(m, 0, 12, 0, jump);
assert.equal(m.getState().skewMs, 0);
assert.equal(m.getState().warning, false);
});
test('stale or missing age is ignored (cache replay must not read as skew)', () => {
const m = new ClockSkewMonitor();
const t = 1_700_000_000_000;
m.sample(t, undefined, t + 3_600_000);
m.sample(t, 40 * 24 * 60 * 60 * 1000, t + 3_600_000);
m.sample(t, -5, t);
m.sample(T, undefined, T + 3_600_000);
m.sample(T, 40 * 24 * 60 * 60 * 1000, T + 3_600_000);
m.sample(T, -5, T);
assert.equal(m.getState().skewMs, null);
});
@@ -53,10 +105,7 @@ test('subscribe fires on change only; reset clears', () => {
const m = new ClockSkewMonitor();
const seen: (number | null)[] = [];
m.subscribe((s) => seen.push(s.skewMs));
feed(m, -120_000);
feed(m, -120_000);
feed(m, -120_000);
feed(m, -120_000);
[0, 1, 2, 3].forEach((at) => feed(m, -120_000, at));
assert.deepEqual(seen, [-120_000]);
assert.equal(formatSkew(-120_000), '2 minutes behind');
m.reset();