From a4bfdb565777135685cce2e4fecbe6385aa60250 Mon Sep 17 00:00:00 2001 From: Jonas Braathen Date: Wed, 14 Oct 2026 00:36:54 +0200 Subject: [PATCH] web: harden the cache purge scheduler --- web/src/instrumentation.loop.test.ts | 43 ++++++++++++++++++++++ web/src/instrumentation.test.ts | 53 ++++++++++++++++++++++++++++ web/src/instrumentation.ts | 20 ++++++++--- web/src/lib/internalRevalidate.ts | 10 ++++-- web/src/lib/revalidation.test.ts | 29 ++++++++++++++- web/src/lib/revalidation.ts | 17 +++++---- 6 files changed, 159 insertions(+), 13 deletions(-) create mode 100644 web/src/instrumentation.loop.test.ts diff --git a/web/src/instrumentation.loop.test.ts b/web/src/instrumentation.loop.test.ts new file mode 100644 index 0000000..58fde8b --- /dev/null +++ b/web/src/instrumentation.loop.test.ts @@ -0,0 +1,43 @@ +import { afterEach, beforeEach, expect, it, vi } from "vitest"; + +const purgeOwnCache = vi.fn(); +vi.mock("@/lib/internalRevalidate", () => ({ + purgeOwnCache: (...args: unknown[]) => purgeOwnCache(...args), + setInternalRevalidateSecret: vi.fn(), +})); + +import { register } from "./instrumentation.ts"; + +beforeEach(() => { + vi.useFakeTimers(); + // 23:59:50 in Oslo (CEST) + vi.setSystemTime(new Date("2026-07-07T21:59:50Z")); + vi.stubEnv("NEXT_RUNTIME", "nodejs"); + vi.stubEnv("NODE_ENV", "production"); + vi.spyOn(console, "error").mockImplementation(() => {}); +}); + +afterEach(() => { + vi.useRealTimers(); + vi.unstubAllEnvs(); + vi.restoreAllMocks(); + purgeOwnCache.mockReset(); +}); + +// The cache only rolls over because this loop keeps running, so nothing +// thrown inside one check may end it +it("keeps checking after a check has thrown", async () => { + purgeOwnCache.mockResolvedValue(null); + register(); + await vi.advanceTimersByTimeAsync(0); + purgeOwnCache.mockClear(); + + purgeOwnCache.mockRejectedValueOnce(new Error("boom")); + await vi.advanceTimersByTimeAsync(11_000); // 00:00:01: throws + expect(purgeOwnCache).toHaveBeenCalledTimes(1); + expect(console.error).toHaveBeenCalledTimes(1); + + await vi.advanceTimersByTimeAsync(30_000); // the next check purges + expect(purgeOwnCache).toHaveBeenCalledTimes(2); + expect(purgeOwnCache).toHaveBeenLastCalledWith("today"); +}); diff --git a/web/src/instrumentation.test.ts b/web/src/instrumentation.test.ts index 88fe471..e774d28 100644 --- a/web/src/instrumentation.test.ts +++ b/web/src/instrumentation.test.ts @@ -74,6 +74,28 @@ describe("at startup", () => { expect(purgedTags()).toEqual(["cms", "today", "cms", "today"]); }); + it("gives up on a purge that hangs", async () => { + register(); + await vi.advanceTimersByTimeAsync(0); + + expect(fetchMock.mock.calls[0][1].signal).toBeInstanceOf(AbortSignal); + }); + + it.each([ + ["a wildcard bind", "http://localhost:8080", "http://127.0.0.1:8080"], + ["a specific address", "http://10.0.0.5:8080", "http://10.0.0.5:8080"], + ["IPv6 loopback", "http://[::1]:8080", "http://[::1]:8080"], + ])("uses the address Next recorded for %s", async (_what, recorded, origin) => { + vi.stubEnv("__NEXT_PRIVATE_ORIGIN", recorded); + + register(); + await vi.advanceTimersByTimeAsync(0); + + expect(String(fetchMock.mock.calls[0][0])).toBe( + `${origin}/api/revalidate?tag=cms` + ); + }); + it.each([ ["an IPv4 address", "10.0.0.5", "http://10.0.0.5:4321"], ["an IPv6 address", "::1", "http://[::1]:4321"], @@ -132,6 +154,37 @@ describe("at Oslo midnight", () => { expect(purgedTags()).toEqual(["today"]); }); + it("retries the follow-up purge if that one fails", async () => { + await start(); + fetchMock + .mockResolvedValueOnce({ ok: true, status: 200 }) // 00:00:01 + .mockResolvedValueOnce({ ok: false, status: 503 }); // the follow-up + + await vi.advanceTimersByTimeAsync(11_000); + await vi.advanceTimersByTimeAsync(30_000); + expect(purgedTags()).toEqual(["today", "today"]); + + await vi.advanceTimersByTimeAsync(30_000); + expect(purgedTags()).toEqual(["today", "today", "today"]); + + // and then it is done for the day + await vi.advanceTimersByTimeAsync(3600 * 1000); + expect(purgedTags()).toEqual(["today", "today", "today"]); + }); + + it("waits the full 25 hours on the day the clocks go back", async () => { + // 00:00:30 on søndag 25. oktober 2026 in Oslo; the next midnight is 25 h off + vi.setSystemTime(new Date("2026-10-24T22:00:30Z")); + await start(); + + // 23:59:30, 24 hours and 59 minutes later + await vi.advanceTimersByTimeAsync(24 * 3600 * 1000 + 59 * 60 * 1000); + expect(purgedTags()).toEqual([]); + + await vi.advanceTimersByTimeAsync(31 * 1000); + expect(purgedTags()).toEqual(["today"]); + }); + it("retries a failed purge at the next check, and says so", async () => { await start(); fetchMock.mockResolvedValueOnce({ ok: false, status: 503 }); diff --git a/web/src/instrumentation.ts b/web/src/instrumentation.ts index 21139b8..b230ad8 100644 --- a/web/src/instrumentation.ts +++ b/web/src/instrumentation.ts @@ -12,8 +12,8 @@ import { // How often the clock is checked. Timers alone can't be trusted to fire at // midnight: they stand still while a host or VM is paused const CHECK_INTERVAL_MS = 30_000; -// Until the first purge has gone through; the server isn't listening yet -// when register() runs +// Until the first purge has gone through. The server is already listening +// when register() runs, so this is only for a purge that fails const STARTUP_RETRY_MS = 1_000; function keepCacheCurrent() { @@ -24,6 +24,18 @@ function keepCacheCurrent() { let failures = 0; async function check() { + try { + await purgeWhatIsDue(); + } catch (error) { + // nothing in there is expected to throw, but if something does the + // loop must survive it: without it the cache never rolls over + console.error("Checking the page cache failed", error); + } finally { + schedule(); + } + } + + async function purgeWhatIsDue() { const day = osloDay(); let error: string | null = null; @@ -50,14 +62,14 @@ function keepCacheCurrent() { if (error) { failures += 1; - // at startup, connection errors are expected for the first moments + // report the first failure once running, and then now and again; at + // startup only if it goes on for a minute if (failures === 1 ? purgedDay !== undefined : failures % 60 === 0) { console.error(`Purging the page cache keeps failing: ${error}`); } } else { failures = 0; } - schedule(); } function schedule() { diff --git a/web/src/lib/internalRevalidate.ts b/web/src/lib/internalRevalidate.ts index 0319d10..ecc62a0 100644 --- a/web/src/lib/internalRevalidate.ts +++ b/web/src/lib/internalRevalidate.ts @@ -20,9 +20,15 @@ export function setInternalRevalidateSecret(secret: string) { const PURGE_TIMEOUT_MS = 10_000; -// The server is reached the way it listens (the standalone server binds to -// HOSTNAME); the wildcard addresses are reachable over loopback +// Where this server listens. Next records the address it actually bound to +// once it is listening (an internal variable, hence the fallback, which +// rebuilds it from the HOSTNAME and PORT the standalone server reads) function ownOrigin(): string { + const recorded = process.env.__NEXT_PRIVATE_ORIGIN; + if (recorded) { + // "localhost" stands for a wildcard bind; skip the name lookup + return recorded.replace("//localhost:", "//127.0.0.1:"); + } const hostname = process.env.HOSTNAME; const port = process.env.PORT || 3000; if (!hostname || hostname === "0.0.0.0" || hostname === "::") { diff --git a/web/src/lib/revalidation.test.ts b/web/src/lib/revalidation.test.ts index 5c8a9d2..b76e209 100644 --- a/web/src/lib/revalidation.test.ts +++ b/web/src/lib/revalidation.test.ts @@ -1,4 +1,4 @@ -import { describe, expect, it } from "vitest"; +import { afterEach, describe, expect, it } from "vitest"; import { secondsUntilOsloMidnight } from "./revalidation.ts"; @@ -28,3 +28,30 @@ describe("secondsUntilOsloMidnight", () => { expect(secondsUntilOsloMidnight(now)).toBe(23 * 3600); }); }); + +// The Dockerfile sets TZ=Europe/Oslo, but the result must not depend on it +describe.each(["Europe/Oslo", "UTC", "Asia/Tokyo", "America/Santiago"])( + "secondsUntilOsloMidnight with the process in %s", + (tz) => { + const originalTz = process.env.TZ; + afterEach(() => { + process.env.TZ = originalTz; + }); + + it("counts to the next Oslo midnight", () => { + process.env.TZ = tz; + // 14:00 CEST + expect(secondsUntilOsloMidnight(new Date("2026-09-05T12:00:00Z"))).toBe( + 10 * 3600 + ); + // 23:00 CEST, the night Chile moves its clocks + expect(secondsUntilOsloMidnight(new Date("2026-09-05T21:00:00Z"))).toBe( + 3600 + ); + // the 25-hour day in Oslo + expect(secondsUntilOsloMidnight(new Date("2026-10-24T22:00:00Z"))).toBe( + 25 * 3600 + ); + }); + } +); diff --git a/web/src/lib/revalidation.ts b/web/src/lib/revalidation.ts index 37a4726..41b0a9d 100644 --- a/web/src/lib/revalidation.ts +++ b/web/src/lib/revalidation.ts @@ -1,5 +1,4 @@ -import { addDays, startOfDay } from "date-fns"; -import { fromZonedTime, toZonedTime } from "date-fns-tz"; +import { formatInTimeZone, fromZonedTime } from "date-fns-tz"; import type { OperationContext } from "@urql/core"; const timeZone = "Europe/Oslo"; @@ -28,10 +27,16 @@ export const CMS_CACHE_LIFE = { }; export function secondsUntilOsloMidnight(now: Date = new Date()): number { - const osloNow = toZonedTime(now, timeZone); - const nextOsloMidnight = startOfDay(addDays(osloNow, 1)); - const instant = fromZonedTime(nextOsloMidnight, timeZone); - return Math.ceil((instant.getTime() - now.getTime()) / 1000); + // Worked out from the Oslo date as text, so the timezone the process runs + // in (and its daylight saving changes) can't shift the result + const [year, month, day] = formatInTimeZone(now, timeZone, "yyyy-MM-dd") + .split("-") + .map(Number); + const tomorrow = new Date(Date.UTC(year, month - 1, day + 1)) + .toISOString() + .slice(0, 10); + const nextOsloMidnight = fromZonedTime(`${tomorrow}T00:00:00`, timeZone); + return Math.ceil((nextOsloMidnight.getTime() - now.getTime()) / 1000); } // For per-user (search) and token-scoped (preview) queries, which must