fix(spine): the daily journey was watched by a clock that could not see it #5593
3 changed files+115−3
Modifiedsrc/__tests__/medic.test.ts+63−1View fileUnifiedSplit
@@ -301,10 +301,11 @@ describe("spine doctor age math (injected clock)", () => {
301301 latestWith([
302302 { name: "healthz", ageMs: 3 * 60_000 },
303303 { name: "journey:login-form", ageMs: 4 * 60_000 },
304 { name: "journey:first-run", ageMs: 6 * 60 * 60_000 }, // < 30h budget
304305 { name: "surface:/admin", ageMs: 30 * 60_000 }, // < 60m budget
305306 ]),
306307 });
307 expect(results).toHaveLength(4);
308 expect(results).toHaveLength(5);
308309 for (const r of results) {
309310 expect(r.status).toBe("green");
310311 // The age lives in the detail, per the contract.
@@ -438,3 +439,64 @@ describe("registry hygiene", () => {
438439 }
439440 });
440441});
442
443
444describe("the daily journey is watched on its own clock", () => {
445 const nowMs = 10_000_000_000;
446 const latestWith = (rows: Array<{ name: string; ageMs: number }>) => {
447 const out: Record<string, { name: string; checkedAt: Date }> = {};
448 for (const r of rows) {
449 out[r.name] = { name: r.name, checkedAt: new Date(nowMs - r.ageMs) };
450 }
451 return out;
452 };
453 const find = (rs: Array<{ name: string; status: string; error?: string }>, n: string) =>
454 rs.find((r) => r.name === n)!;
455
456 it("goes RED when the daily journey is stale but its 5-minute siblings are fresh", async () => {
457 // The actual bug, 2026-08-31: journey:first-run had not run for 9 hours
458 // and doctor:journeys read "newest row 1s old (max 15m)" — because it
459 // took MAX(checkedAt) across every journey:* row, so the five-minute
460 // journeys kept it green. A daily check measured against five-minute
461 // siblings can never go stale, which makes watching it theatre.
462 const results = await spineDoctorChecks({
463 now: () => nowMs,
464 lastTickFinishedAt: () => new Date(nowMs - 60_000).toISOString(),
465 latest: async () =>
466 latestWith([
467 { name: "healthz", ageMs: 60_000 },
468 { name: "journey:login-form", ageMs: 60_000 }, // fresh sibling
469 { name: "journey:first-run", ageMs: 40 * 60 * 60_000 }, // 40h — dead
470 { name: "surface:/admin", ageMs: 60_000 },
471 ]),
472 });
473 expect(find(results, "doctor:journeys").status).toBe("green");
474 expect(find(results, "doctor:journey-first-run").status).toBe("red");
475 });
476
477 it("does not go red merely because a day has not passed", async () => {
478 // 24h cadence with restart-driven extra runs: 26h is normal, not dead.
479 // A watcher that cries on every ordinary gap gets muted.
480 const results = await spineDoctorChecks({
481 now: () => nowMs,
482 lastTickFinishedAt: () => new Date(nowMs - 60_000).toISOString(),
483 latest: async () =>
484 latestWith([
485 { name: "healthz", ageMs: 60_000 },
486 { name: "journey:first-run", ageMs: 26 * 60 * 60_000 },
487 ]),
488 });
489 expect(find(results, "doctor:journey-first-run").status).toBe("green");
490 });
491
492 it("reports never-run as its own state, not as fresh", async () => {
493 // No row at all must not read as green. "It has never run" and "it ran
494 // recently" are different facts and only one is reassuring.
495 const results = await spineDoctorChecks({
496 now: () => nowMs,
497 lastTickFinishedAt: () => new Date(nowMs - 60_000).toISOString(),
498 latest: async () => latestWith([{ name: "healthz", ageMs: 60_000 }]),
499 });
500 expect(find(results, "doctor:journey-first-run").status).not.toBe("green");
501 });
502});
Modifiedsrc/lib/autopilot.ts+30−1View fileUnifiedSplit
@@ -666,7 +666,36 @@ export function defaultTasks(): AutopilotTask[] {
666666 name: "first-run-journey",
667667 run: async () => {
668668 const now = Date.now();
669 if (now - _lastFirstRunJourneyAt < FIRST_RUN_JOURNEY_INTERVAL_MS) return;
669
670 // Last-run comes from the DATABASE, not from this process.
671 //
672 // `_lastFirstRunJourneyAt` is a module variable, so it resets to 0 on
673 // every restart — and autodeploy restarts this container whenever main
674 // moves. The effect was that "daily" never described reality: on
675 // 2026-08-30 the journey ran six times in four hours, once per deploy,
676 // and the 24h schedule had almost certainly never fired on its own.
677 // The same shape AlecRae documented on its account-deletion job, where
678 // a daily interval never fired at all because the process restarted
679 // every 15 minutes. An in-process timer in a frequently-restarted
680 // process is not a schedule.
681 //
682 // synthetic_checks already records every run, so the real answer is
683 // one query away. The in-process value stays as the fallback: if the
684 // read fails we keep today's behaviour rather than either spamming
685 // journeys or silently never running one.
686 let lastRunAt = _lastFirstRunJourneyAt;
687 try {
688 const latest = await latestStatusByCheck();
689 const row = latest["journey:first-run"];
690 const t = row?.checkedAt?.getTime?.();
691 if (Number.isFinite(t)) lastRunAt = Math.max(lastRunAt, t as number);
692 } catch (err) {
693 console.warn(
694 "[autopilot] first-run-journey: could not read last run, falling back to in-process clock:",
695 err
696 );
697 }
698 if (now - lastRunAt < FIRST_RUN_JOURNEY_INTERVAL_MS) return;
670699 // Stamped BEFORE the run, not after. This task can take minutes;
671700 // stamping on completion would let a second tick start a parallel
672701 // run — two throwaway accounts racing through repo creation and
Modifiedsrc/lib/medic.ts+22−1View fileUnifiedSplit
@@ -570,6 +570,9 @@ export async function runMedic(
570570
571571export const DOCTOR_CHECK_PREFIX = "doctor:";
572572
573/** The daily end-to-end journey, watched separately from its 5-minute siblings. */
574export const FIRST_RUN_JOURNEY_CHECK = "journey:first-run";
575
573576/**
574577 * Max acceptable age per watcher, ~3× its cadence: the tick and the two
575578 * suites that ride it run every 5 minutes (60s in .env.example, but the
@@ -581,6 +584,17 @@ export const DOCTOR_MAX_AGES: Readonly<Record<string, number>> = {
581584 "doctor:synthetic-monitor": 15 * 60_000,
582585 "doctor:journeys": 15 * 60_000,
583586 "doctor:surface-monitor": 60 * 60_000,
587 // The first-run journey runs on a DAILY cadence, not five-minutely, so it
588 // needs its own threshold — and its own row. Folded into "doctor:journeys"
589 // it was invisible: that check takes MAX(checkedAt) across every journey:*
590 // row, so the five-minute journeys kept it green while the daily one could
591 // have been dead for a week. Measured 2026-08-31: journey:first-run had not
592 // run for 9 hours and doctor:journeys read "newest row 1s old (max 15m)".
593 //
594 // 30h, not the 3x-cadence used above. Three days of blindness on the only
595 // check that covers register -> repo -> PAT -> push -> PR -> merge is too
596 // long; a full day with no successful run is exactly the thing to know.
597 "doctor:journey-first-run": 30 * 60 * 60_000,
584598};
585599
586600export interface SpineDoctorDeps {
@@ -657,12 +671,18 @@ export async function spineDoctorChecks(
657671 // never count its own rows as proof the monitors ran.
658672 let core: number | null = null;
659673 let journey: number | null = null;
674 let firstRun: number | null = null;
660675 let surface: number | null = null;
661676 for (const row of Object.values(latest)) {
662677 const t = row.checkedAt?.getTime?.();
663678 if (!Number.isFinite(t)) continue;
664679 if (row.name.startsWith(DOCTOR_CHECK_PREFIX)) continue;
665 if (row.name.startsWith("journey:")) {
680 if (row.name === FIRST_RUN_JOURNEY_CHECK) {
681 // Deliberately NOT folded into `journey` — see the threshold comment.
682 // A daily check whose freshness is measured against five-minute
683 // siblings can never go stale, which makes watching it theatre.
684 firstRun = t;
685 } else if (row.name.startsWith("journey:")) {
666686 journey = journey === null ? t : Math.max(journey, t);
667687 } else if (row.name.startsWith("surface:")) {
668688 surface = surface === null ? t : Math.max(surface, t);
@@ -698,6 +718,7 @@ export async function spineDoctorChecks(
698718
699719 results.push(doctorResult("doctor:synthetic-monitor", core, nowMs));
700720 results.push(doctorResult("doctor:journeys", journey, nowMs));
721 results.push(doctorResult("doctor:journey-first-run", firstRun, nowMs));
701722 results.push(doctorResult("doctor:surface-monitor", surface, nowMs));
702723 return results;
703724}
704725
c comment · e edit title · m merge · a approve · r request changes · ? shortcuts