diff --git a/.changeset/localization-context-ttl-cache.md b/.changeset/localization-context-ttl-cache.md new file mode 100644 index 0000000000..ff3c4fd46d --- /dev/null +++ b/.changeset/localization-context-ttl-cache.md @@ -0,0 +1,9 @@ +--- +"@objectstack/core": patch +--- + +`resolveLocalizationContext` now memoizes a FAILED read's fallback per `(ql, tenantId, userId)` for 30s (#10221). + +On a fresh environment whose `sys_setting` table hasn't been created/migrated yet, every authenticated request re-ran the same `sys_setting` localization read, and every one of those reads failed the same way ("no such table"). The `#2409` batching had already collapsed the three per-key reads a single request used to issue into one query, but that one query still repeated on every subsequent request, and `driver-sql`'s `backendStatementFault` logs a `[sql-driver] DATABASE_ERROR` warning on every failed read — so the identical warning printed once per request and buried real errors in between. + +Only the case where the underlying read genuinely fails (a backend fault, e.g. the missing table) is cached; a successful read — including a legitimate "nothing configured yet" empty result — is never cached and always re-reads on the next call, so a settings write takes effect immediately. (An earlier version of this fix cached every outcome, mirroring `packages/plugins/plugin-audit/src/audit-writers.ts`'s existing TTL cache of this same read — safe there because audit-trail enrichment is best-effort, but not safe for `@objectstack/rest`'s use of this function: analytics date-bucketing reads the org timezone on every query and `packages/qa/dogfood/test/analytics-timezone.dogfood.test.ts` — the #1982/#2018 golden regression — asserts the very next read reflects a just-written timezone.) The `UTC` / `en-US` fallback behavior itself is unchanged; this only stops the failing query — and its log line — from re-running every request. The cache is keyed on the `ql` engine instance first, so two environments/tenants sharing one process never share a cached outcome, and self-heals within one TTL window once `sys_setting` exists. diff --git a/packages/core/src/security/resolve-authz-context.test.ts b/packages/core/src/security/resolve-authz-context.test.ts index 11eb159ed6..5b9ce2a512 100644 --- a/packages/core/src/security/resolve-authz-context.test.ts +++ b/packages/core/src/security/resolve-authz-context.test.ts @@ -1,6 +1,6 @@ // Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. -import { describe, it, expect } from 'vitest'; +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; import { resolveAuthzContext, resolveUserAuthzGrants, resolveLocalizationContext } from './resolve-authz-context.js'; import { POSTURE_RANK } from './posture-ladder.js'; import { hashApiKey } from './api-key.js'; @@ -173,6 +173,116 @@ describe('resolveLocalizationContext — batched fallback read (#2409)', () => { }); }); +// #10221: a fresh environment's `sys_setting` table doesn't exist yet, so +// EVERY request's read used to fail and the sql-driver's `[sql-driver] +// DATABASE_ERROR` warning repeated once per request, burying real errors. +// The #2409 batching above already collapsed one request down to a single +// query; this collapses the FAILING query across requests with a short TTL +// cache — but ONLY the failure, never a successful (or legitimately empty) +// read. A first version cached every outcome, mirroring +// `packages/plugins/plugin-audit/src/audit-writers.ts` (`resolveWriteLocale`)'s +// existing memoization of this same read — that broke +// `packages/qa/dogfood/test/analytics-timezone.dogfood.test.ts` (#1982/#2018), +// which writes a new org timezone and expects the very next analytics read to +// bucket under it. See the cache doc on `resolveLocalizationContext` for why +// audit-writer's staleness tolerance doesn't transfer here. +describe('resolveLocalizationContext — failure-only cross-request cache (#10221)', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + afterEach(() => { + vi.useRealTimers(); + }); + + // Simulates a fresh environment: `sys_setting` not migrated/written yet, so + // every read rejects the way the real sql-driver's "no such table" does. + function makeMissingTableQl() { + const counts = { sys_setting: 0 }; + return { + counts, + async find(_object: string) { + counts.sys_setting += 1; + throw new Error('no such table: sys_setting'); + }, + }; + } + + it('does not re-query on a second call within the TTL window when the read fails (same tenant)', async () => { + const ql = makeMissingTableQl(); + const first = await resolveLocalizationContext({ ql, tenantId: 'o1' }); + const second = await resolveLocalizationContext({ ql, tenantId: 'o1' }); + // Functional behavior is unchanged — still the built-in defaults — the + // second call just doesn't repeat the failing query (and its log line). + expect(first).toEqual({ timezone: 'UTC', locale: 'en-US', currency: undefined }); + expect(second).toEqual(first); + expect(ql.counts.sys_setting).toBe(1); + }); + + it('re-queries once the TTL expires, so the cache self-heals once the table/migration lands', async () => { + const ql = makeMissingTableQl(); + await resolveLocalizationContext({ ql, tenantId: 'o1' }); + expect(ql.counts.sys_setting).toBe(1); + await vi.advanceTimersByTimeAsync(30_001); + await resolveLocalizationContext({ ql, tenantId: 'o1' }); + expect(ql.counts.sys_setting).toBe(2); + }); + + it('keys the failure cache per tenant, so a lookup for one tenant never reuses another tenant\'s entry', async () => { + const qlA = makeMissingTableQl(); + // Reuse the SAME underlying table state across two tenant-scoped calls by + // routing both through one `ql`, distinguished only by `tenantId` in the + // cache key (the direct-read fallback query itself is not tenant-scoped + // in its `where`, matching the real resolver's existing behavior). + await resolveLocalizationContext({ ql: qlA, tenantId: 'tenant-a' }); + await resolveLocalizationContext({ ql: qlA, tenantId: 'tenant-b' }); + expect(qlA.counts.sys_setting).toBe(2); + // A repeat for the first tenant hits its own cache entry, not tenant-b's. + await resolveLocalizationContext({ ql: qlA, tenantId: 'tenant-a' }); + expect(qlA.counts.sys_setting).toBe(2); + }); + + it('keys the failure cache per `ql` instance, so two environments in one process never share a cached outcome', async () => { + const qlA = makeMissingTableQl(); + const qlB = makeMissingTableQl(); + await resolveLocalizationContext({ ql: qlA, tenantId: 'o1' }); + await resolveLocalizationContext({ ql: qlB, tenantId: 'o1' }); + expect(qlA.counts.sys_setting).toBe(1); + expect(qlB.counts.sys_setting).toBe(1); + }); + + // The dogfood-test guard (#1982/#2018 golden regression): a SUCCESSFUL read + // must never be served stale. Simulates the exact shape of the failing CI + // scenario — a settings write changes the effective row between two calls — + // entirely at this unit level, without booting the dogfood stack. + it('never caches a successful read: a value change between two calls is visible on the very next call', async () => { + const rows = [{ namespace: 'localization', key: 'timezone', scope: 'tenant', value: 'UTC' }]; + const ql = makeCountingQl({ sys_setting: rows }); + const first = await resolveLocalizationContext({ ql, tenantId: 'o1' }); + expect(first.timezone).toBe('UTC'); + // Simulate a settings write landing between the two calls — no TTL + // advance, so a cache would still be "fresh" if one existed. + rows[0].value = 'America/Los_Angeles'; + const second = await resolveLocalizationContext({ ql, tenantId: 'o1' }); + expect(second.timezone).toBe('America/Los_Angeles'); + expect(ql.counts.sys_setting).toBe(2); + }); + + // A legitimate empty result (table exists, no settings configured for this + // tenant yet) is a successful read too — not a failure — so it must not be + // cached either: the first write for a previously-unconfigured tenant must + // be visible on the very next call, same as the value-change case above. + it('never caches a legitimate empty result: the first write for a previously-unconfigured tenant is visible immediately', async () => { + const rows: Array<{ namespace: string; key: string; scope: string; value: string }> = []; + const ql = makeCountingQl({ sys_setting: rows }); + const first = await resolveLocalizationContext({ ql, tenantId: 'o1' }); + expect(first).toEqual({ timezone: 'UTC', locale: 'en-US', currency: undefined }); + rows.push({ namespace: 'localization', key: 'timezone', scope: 'tenant', value: 'Asia/Tokyo' }); + const second = await resolveLocalizationContext({ ql, tenantId: 'o1' }); + expect(second.timezone).toBe('Asia/Tokyo'); + expect(ql.counts.sys_setting).toBe(2); + }); +}); + describe('grant validity windows (ADR-0091 D1/D2)', () => { const NOW = Date.parse('2026-07-10T12:00:00Z'); const PAST = '2026-07-01T00:00:00Z'; diff --git a/packages/core/src/security/resolve-authz-context.ts b/packages/core/src/security/resolve-authz-context.ts index 903d3e6347..cd376a0f38 100644 --- a/packages/core/src/security/resolve-authz-context.ts +++ b/packages/core/src/security/resolve-authz-context.ts @@ -577,43 +577,155 @@ export interface ResolveLocalizationInput { userId?: string; } +type LocalizationResult = { timezone: string; locale: string; currency?: string }; + +/** + * Process-local TTL cache for the FAILED-READ outcome of + * {@link resolveLocalizationContext} only (#10221; narrowed after a patch + * round — see below). + * + * `resolveAuthzContext`'s #2409 de-dup already collapsed the THREE per-key + * reads a request used to issue into one batched `sys_setting` query; what it + * did not address is the SAME query repeating on EVERY request. On a fresh + * environment (`sys_setting` not yet migrated / never written) that one query + * fails every time, and `packages/drivers/driver-sql`'s + * `backendStatementFault` — deliberately generic; see its doc — logs a + * `[sql-driver] DATABASE_ERROR` line for EVERY failed read, so the identical + * "no such table: sys_setting" warning repeats once per request and buries + * real errors in between. + * + * `tryFind`-style catches already guaranteed the FUNCTIONAL fallback (catch → + * `[]` → built-in `UTC` / `en-US` defaults) — this cache only stops the + * FAILING query (and therefore the log line) from re-running every request. + * + * ## Why only the failure, not every result (patch round, CI red) + * + * The first version of this cache memoized every outcome — including a + * SUCCESSFUL read — for 30s, mirroring `packages/plugins/plugin-audit/src/audit-writers.ts` + * (`resolveWriteLocale`)'s existing TTL cache of this same read. That is safe + * for audit-writer's use: audit trail enrichment is explicitly best-effort, + * so a stale locale in a log line for up to 30s costs nothing observable. + * It is NOT safe for `@objectstack/rest`'s use of this same function: analytics + * date-bucketing reads the org timezone on every query, and + * `packages/qa/dogfood/test/analytics-timezone.dogfood.test.ts` (the golden + * regression for #1982/#2018) writes a NEW org timezone via the real settings + * route and asserts the VERY NEXT analytics read buckets under it — a 30s-old + * cached value broke that test (CI: `expected undefined to be 3`, the bucket + * stayed on the previous timezone). Analytics bucketing is declared, tested + * behavior, not best-effort enrichment — it cannot tolerate the same + * staleness plugin-audit's cache is allowed to. + * + * So this cache is narrowed to memoize ONLY the case the underlying read + * itself THREW (a backend fault — e.g. "no such table" — not a legitimate + * empty/no-rows-yet result, which is a normal, cheap, un-failing read and + * stays uncached so a fresh write is visible on the next request same as + * before). That fully addresses #10221 — the log spam only exists on an env + * where the read is actively failing — while never caching a value a caller + * could observe going stale. + * + * Keyed on the `ql` instance (one entry-set per environment engine, so two + * environments/tenants sharing a process never see each other's cached + * outcome) and then `tenantId|userId` beneath it, matching the audit writer's + * key shape. A `ql` that isn't cacheable (missing/non-object) skips the cache + * entirely — there is no query to dedupe in that case. + */ +const LOCALIZATION_FAILURE_CACHE_TTL_MS = 30_000; +const localizationFailureCache = new WeakMap>(); + /** * Resolve workspace localization defaults (reference `timezone` / `locale` / * `currency`). Canonical path is the `localization` SettingsManifest (cascade: * platform default → global → tenant); falls back to direct tenant-scoped * `sys_setting` rows, then the built-ins `UTC` / `en-US`. Never throws. + * + * A read that fails outright (backend fault — table missing, connection + * refused, etc.) is memoized for {@link LOCALIZATION_FAILURE_CACHE_TTL_MS} + * per `(ql, tenantId, userId)` so the failing query — and the driver's log + * line for it — does not repeat every request (#10221). A successful read, + * including a legitimate "no settings configured yet" empty result, is NEVER + * cached: the next call always re-reads, so a settings write takes effect + * immediately (see the cache doc above for why — the dogfood analytics + * bucketing test pins this). */ -export async function resolveLocalizationContext( +export async function resolveLocalizationContext(input: ResolveLocalizationInput): Promise { + const { ql, tenantId, userId } = input; + const cacheKey = `${tenantId ?? ''}|${userId ?? ''}`; + if (ql && typeof ql === 'object') { + const hit = localizationFailureCache.get(ql)?.get(cacheKey); + if (hit && hit.expiresAt > Date.now()) return hit.value; + } + + const { value, failed } = await resolveLocalizationContextUncached(input); + if (failed && ql && typeof ql === 'object') { + const bucket = localizationFailureCache.get(ql) ?? new Map(); + bucket.set(cacheKey, { value, expiresAt: Date.now() + LOCALIZATION_FAILURE_CACHE_TTL_MS }); + localizationFailureCache.set(ql, bucket); + } + return value; +} + +async function resolveLocalizationContextUncached( input: ResolveLocalizationInput, -): Promise<{ timezone: string; locale: string; currency?: string }> { +): Promise<{ value: LocalizationResult; failed: boolean }> { const { ql, settings, tenantId, userId } = input; + let failed = false; try { if (settings && typeof settings.get === 'function') { const sctx = { tenantId, userId } as any; const [tzRes, localeRes, currencyRes] = await Promise.all([ - settings.get('localization', 'timezone', sctx).catch(() => undefined), - settings.get('localization', 'locale', sctx).catch(() => undefined), - settings.get('localization', 'currency', sctx).catch(() => undefined), + settings.get('localization', 'timezone', sctx).catch(() => { + failed = true; + return undefined; + }), + settings.get('localization', 'locale', sctx).catch(() => { + failed = true; + return undefined; + }), + settings.get('localization', 'currency', sctx).catch(() => { + failed = true; + return undefined; + }), ]); const tz = coerceTimeZone(tzRes?.value); const locale = coerceLocale(localeRes?.value); const currency = coerceCurrency(currencyRes?.value); - if (tz || locale || currency) return { timezone: tz ?? 'UTC', locale: locale ?? 'en-US', currency }; + if (tz || locale || currency) { + return { value: { timezone: tz ?? 'UTC', locale: locale ?? 'en-US', currency }, failed: false }; + } } } catch { // settings service unavailable → direct read + failed = true; } // One read for all three keys instead of a query per key (`$in` on `key`). - const rows = await tryFind( - ql, - 'sys_setting', - { namespace: 'localization', key: { $in: ['timezone', 'locale', 'currency'] }, scope: 'tenant' }, - 10, - ); + // Inlined (rather than the shared `tryFind`) so a genuine backend fault — + // as opposed to a legitimate empty result — is visible to the caller above, + // which is the signal the failure-only cache keys off. `ql` is already + // typed `any` (its shape varies by caller — REST's engine, a test double, + // …), so the options literal below needs no `as any` of its own (#4918 + // query-options-erasure guard: that cast is a distinct, counted erasure + // site, not implied by an already-`any` receiver). + let rows: any[] = []; + if (ql && typeof ql.find === 'function') { + try { + let result = await ql.find('sys_setting', { + where: { namespace: 'localization', key: { $in: ['timezone', 'locale', 'currency'] }, scope: 'tenant' }, + limit: 10, + context: { isSystem: true }, + }); + if (result && (result as any).value) result = (result as any).value; + rows = Array.isArray(result) ? result : []; + } catch { + failed = true; + } + } const valueOf = (k: string) => rows.find((r) => r.key === k)?.value; return { - timezone: coerceTimeZone(valueOf('timezone')) ?? 'UTC', - locale: coerceLocale(valueOf('locale')) ?? 'en-US', - currency: coerceCurrency(valueOf('currency')), + value: { + timezone: coerceTimeZone(valueOf('timezone')) ?? 'UTC', + locale: coerceLocale(valueOf('locale')) ?? 'en-US', + currency: coerceCurrency(valueOf('currency')), + }, + failed, }; }