From 00a4cb2271d6e7ef2f43e3d9795c3ae818e8c46d Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Fri, 14 Aug 2026 17:43:06 -0700 Subject: [PATCH 1/9] feat(shadow): replace logMismatches with mismatchLogging content controls and log hooks Shadow mismatch warnings are now composed field by field through the runtime ShadowConfig.mismatchLogging group ({key, value, diff}, each default-off, merged leaf-wise) instead of the removed all-or-nothing logMismatches boolean. Two per-use-case hooks shape the logged content: shadowMismatchLogValue projects both sides before value logging and the built-in diff, and shadowMismatchLogDiff replaces the built-in diff and receives the raw compared values. The built-in structural diff uses microdiff over the projected-or-raw forms, oriented cached-to-source, with non-plain-object roots collapsing to one root-level change entry. All rendering happens eagerly at mismatch confirmation, fails closed to null fields, and keeps the existing byte caps; raw compared values are no longer retained until log time. The removed shadow.logMismatches field is rejected like shadowRamp: defaults throw at registration and stale runtime configs fail resolution as config_error, so live configs must migrate to shadow.mismatchLogging before adopting this release. --- README.md | 44 ++- package.json | 3 +- pnpm-lock.yaml | 8 + scripts/test-package.mjs | 21 +- src/config.ts | 47 ++- src/dialcache.ts | 202 ++++++++-- src/index.ts | 9 +- src/internal/runtime-config.ts | 38 +- src/internal/shadow-log-json.ts | 54 ++- test/dialcache-config-ramp.test.ts | 67 +++- .../dialcache-observability-internals.test.ts | 10 +- test/dialcache-shadow-confirmation.test.ts | 374 ++++++++++++++++-- test/dialcache-shadow-validation.test.ts | 8 +- test/shadow-log-json.test.ts | 95 ++++- 14 files changed, 825 insertions(+), 155 deletions(-) diff --git a/README.md b/README.md index 405f0e6..69895cd 100644 --- a/README.md +++ b/README.md @@ -124,6 +124,8 @@ Use `cached(fn, options)` for an extracted, reusable function. The wrapped calla | `defaultConfig` | no | `DialCacheKeyConfig` baseline policy that runtime config overlays field by field (see [Runtime config](#runtime-config-and-ramp-controls)). | | `serializer` | when the return type is not statically JSON-compatible | Per-function `Serializer` for Redis values (see [Serialization](#serialization)). | | `shadowComparator` | no | Synchronous application-level equality for shadow validation; defaults to Node's strict deep equality. | +| `shadowMismatchLogValue` | no | Projects a compared value into its loggable form for opted-in mismatch warnings; without it those warnings log raw native JSON (see [Mismatch logging](#shadow-validation)). | +| `shadowMismatchLogDiff` | no | Replaces the built-in structural diff in opted-in mismatch warnings; receives the raw compared values. | | `trackForInvalidation` | no (default `false`) | Opts this use case's Redis entries into watermark-based targeted invalidation. | | `fallbackTimeoutMs` | no (default `60_000`) | Fallback deadline in milliseconds, at most 2,147,483,647; `null` disables it (see [Fallback deadlines](#fallback-deadlines)). | @@ -209,23 +211,23 @@ Instance-wide behavior is set through the `DialCache` constructor: | `metrics` | disabled | A `DialCacheMetricsAdapter` (see [Metrics](#metrics)). | | `logger` | `console` | Receives operational cache failures and opted-in confirmed shadow mismatch warnings (`debug`, `warn`, `error`). Synchronous throws and rejections from returned promises or thenables are isolated without being awaited. | -Per-invocation cache policy is a `DialCacheKeyConfig`: per-layer `ttlSec` and `ramp` maps keyed by `CacheLayer.LOCAL` (process-local) and `CacheLayer.REMOTE` (Redis), a `requestLocal` boolean, a `coalesce` boolean (see [Request coalescing](#request-coalescing)), an optional `remoteReadTimeoutMs`, and an optional `shadow` group. `ShadowConfig` contains the independent shadow `ramp` percentage plus the default-off `logMismatches` control. +Per-invocation cache policy is a `DialCacheKeyConfig`: per-layer `ttlSec` and `ramp` maps keyed by `CacheLayer.LOCAL` (process-local) and `CacheLayer.REMOTE` (Redis), a `requestLocal` boolean, a `coalesce` boolean (see [Request coalescing](#request-coalescing)), an optional `remoteReadTimeoutMs`, and an optional `shadow` group. `ShadowConfig` contains the independent shadow `ramp` percentage plus the default-off `mismatchLogging` group: independent `key`, `value`, and `diff` booleans selecting the content of confirmed-mismatch warnings. Every cached definition or `getOrLoad()` invocation can provide an optional per-use-case `defaultConfig`. It is the baseline policy, and the `cacheConfigProvider` result is a sparse field-level overlay on that baseline. For cache enablement fields, precedence is runtime config, then `defaultConfig`, then DialCache's disabled baseline. For the remote-read deadline, precedence is runtime `remoteReadTimeoutMs`, `defaultConfig.remoteReadTimeoutMs`, `redis.readTimeoutMs`, then the 50 ms library default. -The disabled baseline sets `requestLocal` to false, leaves the process-local and Redis TTLs unset, and sets `shadow.ramp` to 0% with mismatch logging false. A shared layer with no effective TTL is disabled by policy. When a shared layer has an effective TTL but no effective ramp, its ramp defaults to 100%. Shadow work remains disabled unless `shadow.ramp` is explicitly greater than zero. +The disabled baseline sets `requestLocal` to false, leaves the process-local and Redis TTLs unset, and sets `shadow.ramp` to 0% with every `mismatchLogging` field false. A shared layer with no effective TTL is disabled by policy. When a shared layer has an effective TTL but no effective ramp, its ramp defaults to 100%. Shadow work remains disabled unless `shadow.ramp` is explicitly greater than zero. `DialCacheKeyConfig` preserves an omitted `requestLocal` as `undefined` so the overlay can distinguish omission from an explicit `false`; the effective value still defaults to false after resolution. An omitted `coalesce` is preserved the same way, and its effective value defaults to true, so request coalescing stays on unless a use case explicitly opts out. -A provider result of `null` (or defensive `undefined`) applies no overrides. An empty `DialCacheKeyConfig` and omitted runtime fields also inherit the baseline. Top-level fields, cache-layer leaves, and leaves inside `shadow` merge independently; an explicit `false` logging flag overrides an inherited `true`. Use explicit values to override inherited policy: `requestLocal: false` disables request-local caching and a layer ramp of `0` disables that shared layer. `DialCacheKeyConfig.disabled()` is the complete new-cache-invocation kill switch in one call: request-local and shadow work off, shadow logging off, and both shared layers ramped to 0. It leaves `coalesce` unset: with every layer off there is no in-flight sharing to disable, and a use case ramped back up at runtime coalesces again unless it explicitly opts out. It does not cancel already-admitted work, and explicit maintenance operations such as `invalidateRemote()` remain available. To stop new cache-invocation Redis reads and fills while preserving other runtime settings, explicitly set both `ramp.remote` and `shadow.ramp` to `0`; the remote ramp alone stops serving but does not override an inherited nonzero shadow ramp. +A provider result of `null` (or defensive `undefined`) applies no overrides. An empty `DialCacheKeyConfig` and omitted runtime fields also inherit the baseline. Top-level fields, cache-layer leaves, leaves inside `shadow`, and leaves inside `shadow.mismatchLogging` merge independently; an explicit `false` logging leaf overrides an inherited `true`. Use explicit values to override inherited policy: `requestLocal: false` disables request-local caching and a layer ramp of `0` disables that shared layer. `DialCacheKeyConfig.disabled()` is the complete new-cache-invocation kill switch in one call: request-local and shadow work off, shadow logging off, and both shared layers ramped to 0. It leaves `coalesce` unset: with every layer off there is no in-flight sharing to disable, and a use case ramped back up at runtime coalesces again unless it explicitly opts out. It does not cancel already-admitted work, and explicit maintenance operations such as `invalidateRemote()` remain available. To stop new cache-invocation Redis reads and fills while preserving other runtime settings, explicitly set both `ramp.remote` and `shadow.ramp` to `0`; the remote ramp alone stops serving but does not override an inherited nonzero shadow ramp. -DialCache validates `defaultConfig` when `cached()` registers a definition and whenever `getOrLoad()` is invoked: TTLs must be positive safe integers no greater than 31,536,000 seconds (a fixed 365-day duration), remote-read deadlines must be positive safe integers within their documented limit, layer and shadow ramps must be finite percentages from 0 to 100, layer maps and `shadow` must be objects, and `requestLocal`, `coalesce`, and `shadow.logMismatches` must be booleans when present. Invalid defaults are rejected immediately. +DialCache validates `defaultConfig` when `cached()` registers a definition and whenever `getOrLoad()` is invoked: TTLs must be positive safe integers no greater than 31,536,000 seconds (a fixed 365-day duration), remote-read deadlines must be positive safe integers within their documented limit, layer and shadow ramps must be finite percentages from 0 to 100, layer maps, `shadow`, and `shadow.mismatchLogging` must be objects, and `requestLocal`, `coalesce`, and the `shadow.mismatchLogging` fields must be booleans when present. Invalid defaults are rejected immediately. Each registration or one-shot invocation captures an immutable internal snapshot of `defaultConfig`; mutating the supplied config or its maps later does not change that operation's baseline. Runtime policy changes belong in the provider's returned overlay. -Runtime TTL and ramp leaves are used as supplied instead of falling back to valid default leaves. A TTL outside the same 1-to-31,536,000-second range disables that layer with `invalid_ttl`; a nonnumeric, non-finite, or out-of-range ramp disables it with `invalid_ramp`. Valid ramps include both `0` and `100`. Other layers can still run, and invalid leaves also record a `config_resolution` error so provider garbage is alertable separately from intentional ramp-downs. A malformed runtime config object, layer-map shape, `requestLocal` value, `coalesce` value, explicit `remoteReadTimeoutMs`, or removed top-level `shadowRamp` fails config resolution for the invocation, records `config_error`, and executes the fallback uncached without attempting Redis. The public `DialCacheKeyConfig` constructor and static defaults likewise reject `shadowRamp` immediately; migrate it to `shadow.ramp`. +Runtime TTL and ramp leaves are used as supplied instead of falling back to valid default leaves. A TTL outside the same 1-to-31,536,000-second range disables that layer with `invalid_ttl`; a nonnumeric, non-finite, or out-of-range ramp disables it with `invalid_ramp`. Valid ramps include both `0` and `100`. Other layers can still run, and invalid leaves also record a `config_resolution` error so provider garbage is alertable separately from intentional ramp-downs. A malformed runtime config object, layer-map shape, `requestLocal` value, `coalesce` value, explicit `remoteReadTimeoutMs`, removed top-level `shadowRamp`, or removed `shadow.logMismatches` fails config resolution for the invocation, records `config_error`, and executes the fallback uncached without attempting Redis. The public `DialCacheKeyConfig` constructor and static defaults likewise reject both removed fields immediately; migrate `shadowRamp` to `shadow.ramp` and `shadow.logMismatches` to `shadow.mismatchLogging`. -An invalid runtime `shadow.ramp` does not affect the cache result or disable an otherwise valid Redis policy. If normal traversal reaches an otherwise shadow-eligible Redis path, DialCache skips shadow work and records a `config_resolution` error. An invalid runtime `shadow.logMismatches` likewise preserves the cache result, Redis policy, shadow result, and shadow metric while suppressing the warning. DialCache validates this diagnostic leaf only after the metrics hook, exact-key cohort, and capacity gates admit shadow work, then records one remote `config_resolution` error for that admitted resolution. +An invalid runtime `shadow.ramp` does not affect the cache result or disable an otherwise valid Redis policy. If normal traversal reaches an otherwise shadow-eligible Redis path, DialCache skips shadow work and records a `config_resolution` error. An invalid runtime `shadow.mismatchLogging` shape or field likewise preserves the cache result, Redis policy, shadow result, and shadow metric; an invalid field acts false while valid sibling fields still log. DialCache validates these diagnostic leaves only after the metrics hook, exact-key cohort, and capacity gates admit shadow work, then records one remote `config_resolution` error for that admitted resolution. `cacheConfigProvider` is called for every enabled cache invocation before DialCache performs any cache lookup. Keep it cheap, cache any remote/config-store reads inside the provider, and avoid work that would erase the benefit of a cache hit. @@ -241,8 +243,9 @@ const dialcache = new DialCache({ // Independently sample Redis keys for detached validation/fill. shadow: { ramp: 5, - // Emit one warning with a bounded key and native-JSON value strings. - logMismatches: true, + // Emit one bounded warning per confirmed mismatch: key plus a + // structural diff, without the full value payloads. + mismatchLogging: { key: true, diff: true }, }, // Can be changed by the provider at runtime for this use case. remoteReadTimeoutMs: 35, @@ -526,22 +529,25 @@ const getUser = dialcache.cached( // Optional: override strict deep equality with use-case semantics. shadowComparator: (cached, source) => cached.id === source.id && cached.version === source.version, + // Optional: opted-in warnings log this projection instead of raw values, + // and the built-in diff runs over the same projected forms. + shadowMismatchLogValue: (value) => ({ id: value.id, version: value.version }), defaultConfig: new DialCacheKeyConfig({ ttlSec: { [CacheLayer.REMOTE]: 300 }, // Exercise and populate Redis without serving it to callers. ramp: { [CacheLayer.REMOTE]: 0 }, shadow: { ramp: 5, - // Default-off warning with a bounded key and native-JSON value strings. - // Enable only after approving the logger and data-handling policy. - logMismatches: true, + // Default-off warning content, chosen field by field. Enable only + // after approving the logger and data-handling policy. + mismatchLogging: { key: true, value: true, diff: true }, }, }), }, ); ``` -Shadow work is eligible only when a valid remote TTL/policy exists, its effective `shadow.ramp` selects the exact cache key, a configured metrics adapter implements `shadowValidation`, and capacity is available. Tracked and untracked Redis keys are both eligible; each keeps its existing read and write mode. Logging is supplemental to the metric; enabling `logMismatches` does not activate shadow work without the metrics hook. The bundled Prometheus and Datadog adapters implement that hook. There are two paths: +Shadow work is eligible only when a valid remote TTL/policy exists, its effective `shadow.ramp` selects the exact cache key, a configured metrics adapter implements `shadowValidation`, and capacity is available. Tracked and untracked Redis keys are both eligible; each keeps its existing read and write mode. Logging is supplemental to the metric; enabling `mismatchLogging` does not activate shadow work without the metrics hook. The bundled Prometheus and Datadog adapters implement that hook. There are two paths: - When remote serving is enabled and produces a Redis hit, DialCache retains the exact serialized payload that supplied the caller as `C0`. - When the remote policy is valid but disabled specifically by `ramped_down`, DialCache starts a detached Redis read for `C0` using the key's existing tracked or untracked mode. Its result can be validated or used to decide whether a clean miss may be filled, but can never supply the caller or populate an in-memory layer. @@ -588,9 +594,19 @@ Shadow metrics use the bounded outcomes `match`, `mismatch`, `superseded`, `fill A `match` or `mismatch` verdict additionally records the validated value's age through the optional `observeShadowValueAge` adapter hook: the observing process's epoch clock minus the validated frame's `createdAtMs` (the served `C0` frame, or the detached `C0` frame on a ramped-down path), in seconds, clamped at zero. The age is captured at verdict time, so a mismatch age lands one confirmation read after the comparison itself. A confirmed `mismatch` age therefore measures how long the stale value had been readable when validation caught it. Tracked frames are stamped with Redis server time and untracked frames with the writer's client clock, so the age mixes clocks and is coarse operational evidence rather than a precise measurement. Outcomes that deliver no verdict on a retained value — including `superseded`, `filled`, and every error or timeout outcome — record no age. The hook does not gate shadow eligibility; only `shadowValidation` does. -Confirmed-mismatch logging is separately opt-in through `shadow.logMismatches`; it never replaces the required `shadowValidation` metric or emits for a mismatch candidate that becomes `superseded`. The single warning contains `cacheNamespace`, `useCase`, `keyType`, `outcome: "mismatch"`, `cacheKey`, `cachedValueJson`, and `sourceValueJson`. `cacheKey` is the logical DialCache URN capped at 2 KiB, not the physical Redis storage key. DialCache independently applies native `JSON.stringify` to the deserialized cached snapshot and raw source value supplied to the comparator, then caps each resulting string at 8 KiB. A byte-clipped field ends in `...[truncated]`, counted inside its cap. If native JSON throws or returns `undefined`, the corresponding JSON field is `null`; the other side is still attempted. DialCache does not compute a textual diff or call the configured serializer again for logging. +Confirmed-mismatch logging is separately opt-in through the `shadow.mismatchLogging` group; it never replaces the required `shadowValidation` metric or emits for a mismatch candidate that becomes `superseded`. One warning is emitted per confirmed mismatch when at least one group field is true, and it always carries `cacheNamespace`, `useCase`, `keyType`, and `outcome: "mismatch"`. Each enabled field adds one bounded piece of content, so warnings stay useful for values that must not reach logs whole: -Mismatch logging is intentionally default-off. Logical URNs can contain ids and arguments, while cached and source values may contain secrets or personal data; truncation is not redaction. DialCache creates the JSON strings only after terminal mismatch confirmation and never passes the raw compared-value references to the logger. Native JSON semantics apply: getters and `toJSON` methods may run, unsupported values may be omitted or normalized, and cycles or `bigint` can make a field unavailable. Stringification is synchronous, and the 8 KiB caps apply only after `JSON.stringify` returns; they do not bound input traversal, hook execution, event-loop time, or the intermediate JSON string. Enable mismatch logging only for trusted, reasonably bounded values and with an approved logger, redaction, transport, access, and retention policy. +- `key: true` adds `cacheKey`: the logical DialCache URN capped at 2 KiB, not the physical Redis storage key. +- `value: true` adds `cachedValueJson` and `sourceValueJson`: native `JSON.stringify` of each compared side, capped at 8 KiB per side. When the use case defines `shadowMismatchLogValue`, each side is that projection's result instead of the raw value; the projector runs once per side. Without a projector the deserialized cached snapshot and raw source value are stringified as-is. +- `diff: true` adds `diffJson`, capped at 8 KiB: the `shadowMismatchLogDiff` result when the use case defines one (it receives the raw compared values), and otherwise a built-in structural diff — computed over the same loggable forms `value` uses, so a projector bounds the diff exactly as it bounds value logging. + +A byte-clipped field ends in `...[truncated]`, counted inside its cap. Every hook invocation and JSON step fails closed: a projector throw logs `null` for that side (and a `null` built-in diff), a diff-hook throw or unserializable diff logs `diffJson: null`, and native-JSON failure on one side leaves the other side attempted. DialCache never calls the configured serializer again for logging. + +The built-in diff (the [microdiff](https://github.com/AsyncBanana/microdiff) library) emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. Plain-object and array roots diff recursively and cycle-safely, with array entries compared by index, so an element shift reports every later index. Any other root pair — dates, Maps, class instances, primitives, or mixed shapes — collapses to one root-level change entry when the inputs are not identical. `[]` means the loggable inputs held no visible difference; with a projector that reads as "the difference is inside fields the projection hides". The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures the built-in diff cannot see into. + +Both hooks run only after terminal mismatch confirmation, inside detached shadow work, under the comparator's discipline: synchronous, deterministic, side-effect-free, non-mutating, and bounded, over borrowed references. Hook output feeds `JSON.stringify` directly. + +Mismatch logging is intentionally default-off, and its runtime fields choose exposure per use case: logical URNs can contain ids and arguments, while cached and source values may contain secrets or personal data, and truncation is not redaction. Without a projector, `value: true` and `diff: true` log raw value material — define `shadowMismatchLogValue` for any use case whose values can carry sensitive fields before enabling those flags, and prefer `key` plus a projected `diff` over full value payloads. DialCache creates the JSON strings only after terminal mismatch confirmation and never passes the raw compared-value references to the logger. Native JSON semantics apply: getters and `toJSON` methods may run, unsupported values may be omitted or normalized, and cycles or `bigint` can make a field unavailable. Stringification is synchronous, and the byte caps apply only after `JSON.stringify` returns; they do not bound input traversal, hook execution, event-loop time, or the intermediate JSON string. Enable mismatch logging only for trusted, reasonably bounded values and with an approved logger, redaction, transport, access, and retention policy. The byte caps apply before logger framing or escaping, so they do not guarantee a final transport event below a sink-specific limit; the metadata fields are not size-clamped. A detail-construction failure degrades to the metadata-only warning. Logger throws and rejected promises or thenables remain isolated from cache and shadow correctness. diff --git a/package.json b/package.json index 9a5fc01..d1bd5cf 100644 --- a/package.json +++ b/package.json @@ -98,7 +98,8 @@ }, "dependencies": { "@types/node": "^24.10.1", - "lru-cache": "^11.5.2" + "lru-cache": "^11.5.2", + "microdiff": "^1.6.0" }, "devDependencies": { "@valkey/valkey-glide": "2.0.0", diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 47b5450..d7b4bc1 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -18,6 +18,9 @@ importers: lru-cache: specifier: ^11.5.2 version: 11.5.2 + microdiff: + specifier: ^1.6.0 + version: 1.6.0 devDependencies: '@valkey/valkey-glide': specifier: 2.0.0 @@ -1193,6 +1196,9 @@ packages: resolution: {integrity: sha512-hXdUTZYIVOt1Ex//jAQi+wTZZpUpwBj/0QsOzqegb3rGMMeJiSEu5xLHnYfBrRV4RH2+OCSOO95Is/7x1WJ4bw==} engines: {node: '>=10'} + microdiff@1.6.0: + resolution: {integrity: sha512-w7JWt8Bno6I8h0rEqlxr4lNG4UbT1FVtWo42wWosIiaJ+rP3pXh7shCYDnyqBrYx36LJ1CZ64p8A62aVp0sJpQ==} + minimatch@5.1.9: resolution: {integrity: sha512-7o1wEA2RyMP7Iu7GNba9vc0RWWGACJOCZBJX2GJWip0ikV+wcOsgVuY9uE8CPiyQhkGFSlhuSkZPavN7u1c2Fw==} engines: {node: '>=10'} @@ -2629,6 +2635,8 @@ snapshots: dependencies: semver: 7.8.5 + microdiff@1.6.0: {} + minimatch@5.1.9: dependencies: brace-expansion: 5.0.8 diff --git a/scripts/test-package.mjs b/scripts/test-package.mjs index 03b00ed..6040f23 100644 --- a/scripts/test-package.mjs +++ b/scripts/test-package.mjs @@ -47,6 +47,7 @@ const rootConsumer = `import { type Serializer, type ShadowComparator, type ShadowConfig, + type ShadowMismatchLoggingConfig, type ShadowValidationMetricLabels, type ShadowValidationOutcome, } from "dialcache"; @@ -147,9 +148,14 @@ const shadowCacheConfig: DialCacheConfig = { shadowMaxInFlight: 2, }; const shadowCache = new DialCache(shadowCacheConfig); +const shadowMismatchLoggingConfig: ShadowMismatchLoggingConfig = { + key: true, + value: true, + diff: true, +}; const shadowConfig: ShadowConfig = { ramp: 50, - logMismatches: true, + mismatchLogging: shadowMismatchLoggingConfig, }; const shadowKeyConfig = new DialCacheKeyConfig({ shadow: shadowConfig }); const dogStatsDClient: DatadogDogStatsDClient = { @@ -203,6 +209,11 @@ const load = cache.cached(async (id: string) => id, { cacheKey: (id) => id, fallbackTimeoutMs: 1_000, shadowComparator: stringShadowComparator, + shadowMismatchLogValue: (value) => value.length, + shadowMismatchLogDiff: (cachedValue, sourceValue) => ({ + cachedLength: cachedValue.length, + sourceLength: sourceValue.length, + }), defaultConfig: new DialCacheKeyConfig({ ttlSec: { [CacheLayer.LOCAL]: 60, [CacheLayer.REMOTE]: 60 }, ramp: { [CacheLayer.LOCAL]: 100, [CacheLayer.REMOTE]: 100 }, @@ -909,7 +920,9 @@ if ( esmDisabledOverlay.requestLocal !== false || esmDisabledOverlay.coalesce !== undefined || esmDisabledOverlay.shadow?.ramp !== 0 - || esmDisabledOverlay.shadow.logMismatches !== false + || esmDisabledOverlay.shadow.mismatchLogging?.key !== false + || esmDisabledOverlay.shadow.mismatchLogging.value !== false + || esmDisabledOverlay.shadow.mismatchLogging.diff !== false || esmDisabledOverlay.ramp[root.CacheLayer.LOCAL] !== 0 || esmDisabledOverlay.ramp[root.CacheLayer.REMOTE] !== 0 ) { @@ -1284,7 +1297,9 @@ if ( cjsDisabledOverlay.requestLocal !== false || cjsDisabledOverlay.coalesce !== undefined || cjsDisabledOverlay.shadow?.ramp !== 0 - || cjsDisabledOverlay.shadow.logMismatches !== false + || cjsDisabledOverlay.shadow.mismatchLogging?.key !== false + || cjsDisabledOverlay.shadow.mismatchLogging.value !== false + || cjsDisabledOverlay.shadow.mismatchLogging.diff !== false || cjsDisabledOverlay.ramp[root.CacheLayer.LOCAL] !== 0 || cjsDisabledOverlay.ramp[root.CacheLayer.REMOTE] !== 0 ) { diff --git a/src/config.ts b/src/config.ts index 5b89c81..1135acf 100644 --- a/src/config.ts +++ b/src/config.ts @@ -11,15 +11,34 @@ export enum CacheLayer { export type Awaitable = T | Promise; export type LayerConfig = Partial>; +/** + * Content controls for the one warning emitted per confirmed shadow mismatch. + * Every field defaults to false; the warning is emitted only when at least one + * field is true. Fields merge independently at runtime, like cache-layer leaves. + */ +export interface ShadowMismatchLoggingConfig { + /** Include the logical cache key (the DialCache URN, byte-capped). */ + readonly key?: boolean; + /** + * Include bounded native-JSON strings for the compared values. Values pass + * through the use case's `shadowMismatchLogValue` projection when one is + * defined and are logged raw otherwise. + */ + readonly value?: boolean; + /** + * Include a bounded JSON diff of the compared values: the use case's + * `shadowMismatchLogDiff` result when defined, and otherwise a structural + * diff of the same loggable forms `value` uses. + */ + readonly diff?: boolean; +} + /** Per-use-case runtime policy for detached Redis shadow work. */ export interface ShadowConfig { /** Independent stable cohort percentage. Omitted and zero disable shadow work. */ readonly ramp?: number; - /** - * Emit one warning with the logical key and bounded native-JSON strings for - * the compared values for each confirmed mismatch. Defaults to false. - */ - readonly logMismatches?: boolean; + /** Confirmed-mismatch warning content. Omitted, empty, and all-false disable the warning. */ + readonly mismatchLogging?: ShadowMismatchLoggingConfig; } export class DialCacheKeyConfig { @@ -109,7 +128,11 @@ export class DialCacheKeyConfig { requestLocal: false, shadow: { ramp: 0, - logMismatches: false, + mismatchLogging: { + key: false, + value: false, + diff: false, + }, }, ramp: { [CacheLayer.LOCAL]: 0, @@ -136,7 +159,17 @@ function cloneShadowConfig(config: ShadowConfig | undefined): ShadowConfig | und if (config === null || typeof config !== "object" || Array.isArray(config)) { throw new TypeError("DialCache shadow config must be an object"); } - return { ...config }; + if (Object.hasOwn(config, "logMismatches")) { + throw new TypeError('ShadowConfig.logMismatches was replaced by "shadow.mismatchLogging"'); + } + const mismatchLogging = config.mismatchLogging; + if (mismatchLogging === undefined) { + return { ...config }; + } + if (mismatchLogging === null || typeof mismatchLogging !== "object" || Array.isArray(mismatchLogging)) { + throw new TypeError("DialCache shadow mismatchLogging config must be an object"); + } + return { ...config, mismatchLogging: { ...mismatchLogging } }; } /** diff --git a/src/dialcache.ts b/src/dialcache.ts index afd8468..bbd3fad 100644 --- a/src/dialcache.ts +++ b/src/dialcache.ts @@ -41,7 +41,11 @@ import { type LayerConfigResolution, type ResolvedLayerConfig, } from "./internal/runtime-config.js"; -import { shadowMismatchLogDetails } from "./internal/shadow-log-json.js"; +import { + previewShadowLogDiff, + previewShadowLogJson, + previewShadowLogKey, +} from "./internal/shadow-log-json.js"; type CacheKeyArgs = Record; type Id = string | number | bigint; @@ -126,6 +130,22 @@ interface CacheOperationOptionsBase { * This is stable use-case behavior, not runtime rollout configuration. */ readonly shadowComparator?: ShadowComparator; + /** + * Projects a compared value into its loggable form for mismatch warnings. + * Feeds `mismatchLogging.value` output and the built-in structural diff; + * without it, opted-in warnings log the raw native-JSON forms. Runs once per + * side after terminal mismatch confirmation, inside detached shadow work. + * Must be synchronous, deterministic, side-effect-free, non-mutating, and + * bounded; inputs are borrowed snapshots. A throw logs `null` for that side. + */ + readonly shadowMismatchLogValue?: (value: Value) => unknown; + /** + * Replaces the built-in structural diff for mismatch warnings that enable + * `mismatchLogging.diff`. Receives the raw compared values, not the + * `shadowMismatchLogValue` projections. Same execution constraints as + * `shadowMismatchLogValue`; a throw logs a `null` diff. + */ + readonly shadowMismatchLogDiff?: (cachedValue: Value, sourceValue: Value) => unknown; /** * Monotonic deadline applied once an initially enabled invocation starts its * fallback, in milliseconds. Must be at most 2,147,483,647. Defaults to 60 @@ -221,11 +241,24 @@ interface ShadowValidationPlan { readonly comparator: ShadowComparator; readonly timeoutMs: number; readonly didCallerFallbackTimeout: () => boolean; + readonly logValue?: (value: Value) => unknown; + readonly logDiff?: (cachedValue: Value, sourceValue: Value) => unknown; +} + +/** Resolved runtime content controls for one admitted shadow job's warning. */ +interface ShadowLogPlan { + readonly key: boolean; + readonly value: boolean; + readonly diff: boolean; } -interface ShadowMismatchDetails { - readonly cachedValue: unknown; - readonly sourceValue: unknown; +const SHADOW_LOG_PLAN_OFF: ShadowLogPlan = { key: false, value: false, diff: false }; + +/** Pre-rendered bounded JSON strings; raw compared values are not retained. */ +interface ShadowMismatchLogDetails { + readonly cachedValueJson?: string | null; + readonly sourceValueJson?: string | null; + readonly diffJson?: string | null; } type ShadowValidationStart = @@ -422,6 +455,12 @@ export class DialCache { comparator: shadowComparator, timeoutMs: fallbackTimeoutMs ?? DEFAULT_FALLBACK_TIMEOUT_MS, didCallerFallbackTimeout: () => callerFallbackTimedOut, + ...(options.shadowMismatchLogValue === undefined + ? {} + : { logValue: options.shadowMismatchLogValue }), + ...(options.shadowMismatchLogDiff === undefined + ? {} + : { logDiff: options.shadowMismatchLogDiff }), }; let key: DialCacheKey; @@ -845,7 +884,7 @@ export class DialCache { this.recordShadowValidation(key, "dropped"); return; } - const logMismatches = this.resolveShadowLogging(key, resolvedShadowConfig); + const logPlan = this.resolveShadowLogging(key, resolvedShadowConfig); const flight: ShadowFlight = { cachedFrame: start.kind === "retained" ? start.frame : null, @@ -865,23 +904,43 @@ export class DialCache { runStart, validation, readTimeoutMs, - logMismatches, + logPlan, ); } private resolveShadowLogging( key: DialCacheKey, shadowConfig: Record, - ): boolean { - const configuredLogMismatches = shadowConfig.logMismatches; - if (configuredLogMismatches === undefined) { - return false; + ): ShadowLogPlan { + const configured = shadowConfig.mismatchLogging; + if (configured === undefined) { + return SHADOW_LOG_PLAN_OFF; + } + if (configured === null || typeof configured !== "object" || Array.isArray(configured)) { + this.recordError(key, CacheLayer.REMOTE, "config_resolution"); + return SHADOW_LOG_PLAN_OFF; } - if (typeof configuredLogMismatches !== "boolean") { + const group = configured as Record; + let sawInvalidLeaf = false; + const resolveLeaf = (leaf: unknown): boolean => { + if (leaf === undefined) { + return false; + } + if (typeof leaf !== "boolean") { + sawInvalidLeaf = true; + return false; + } + return leaf; + }; + const plan: ShadowLogPlan = { + key: resolveLeaf(group.key), + value: resolveLeaf(group.value), + diff: resolveLeaf(group.diff), + }; + if (sawInvalidLeaf) { this.recordError(key, CacheLayer.REMOTE, "config_resolution"); - return false; } - return configuredLogMismatches; + return plan; } private deferShadowValidation( @@ -891,7 +950,7 @@ export class DialCache { start: ShadowValidationRunStart, validation: ShadowValidationPlan, readTimeoutMs: number, - logMismatches: boolean, + logPlan: ShadowLogPlan, ): void { setImmediate(() => { this.runShadowValidation( @@ -901,7 +960,7 @@ export class DialCache { start, validation, readTimeoutMs, - logMismatches, + logPlan, ); }).unref(); } @@ -913,7 +972,7 @@ export class DialCache { start: ShadowValidationRunStart, plan: ShadowValidationPlan, readTimeoutMs: number, - logMismatches: boolean, + logPlan: ShadowLogPlan, ): void { const pendingRedisReads = new Set>(); let operationFinished = false; @@ -963,7 +1022,7 @@ export class DialCache { }; const elapsedBeforeStartMs = Math.max(performance.now() - deadlineStartedAtMs, 0); const remainingTimeoutMs = Math.max(plan.timeoutMs - elapsedBeforeStartMs, 0); - let mismatchDetails: ShadowMismatchDetails | undefined; + let mismatchLogDetails: ShadowMismatchLogDetails | undefined; let validatedValueAgeSeconds: number | undefined; const validation = withMonotonicDeadline({ @@ -1099,8 +1158,12 @@ export class DialCache { if (confirmationFrame === null || !redisPayloadsEqual(originalFrame.payload, confirmationFrame.payload)) { return "superseded"; } - if (logMismatches) { - mismatchDetails = { cachedValue, sourceValue }; + if (logPlan.value || logPlan.diff) { + try { + mismatchLogDetails = renderShadowMismatchLog(logPlan, plan, cachedValue, sourceValue); + } catch { + // Log rendering is best-effort and must not affect the outcome. + } } validatedValueAgeSeconds = shadowValueAgeSeconds(originalFrame.createdAtMs); return "mismatch"; @@ -1111,7 +1174,7 @@ export class DialCache { }); void validation.then( - (outcome) => this.recordShadowValidation(key, outcome, logMismatches, mismatchDetails, validatedValueAgeSeconds), + (outcome) => this.recordShadowValidation(key, outcome, logPlan, mismatchLogDetails, validatedValueAgeSeconds), () => this.recordShadowValidation(key, "timeout"), ); } @@ -1119,8 +1182,8 @@ export class DialCache { private recordShadowValidation( key: DialCacheKey, outcome: ShadowValidationOutcome, - logMismatches = false, - mismatchDetails?: ShadowMismatchDetails, + logPlan: ShadowLogPlan = SHADOW_LOG_PLAN_OFF, + mismatchLogDetails?: ShadowMismatchLogDetails, valueAgeSeconds?: number, ): void { const labels = { @@ -1133,7 +1196,7 @@ export class DialCache { if (valueAgeSeconds !== undefined) { this.metrics?.observeShadowValueAge?.(labels, valueAgeSeconds); } - if (outcome !== "mismatch" || !logMismatches) { + if (outcome !== "mismatch" || !(logPlan.key || logPlan.value || logPlan.diff)) { return; } @@ -1143,23 +1206,15 @@ export class DialCache { keyType: key.keyType, outcome: "mismatch", } as const; - if (mismatchDetails !== undefined) { - try { - this.logger.warn( - "DialCache shadow validation mismatch", - { - ...warning, - ...shadowMismatchLogDetails( - key.urn, - mismatchDetails.cachedValue, - mismatchDetails.sourceValue, - ), - }, - ); - return; - } catch { - // JSON detail construction is best-effort; preserve the metadata warning. - } + try { + this.logger.warn("DialCache shadow validation mismatch", { + ...warning, + ...(logPlan.key ? { cacheKey: previewShadowLogKey(key.urn) } : {}), + ...mismatchLogDetails, + }); + return; + } catch { + // Warning detail construction is best-effort; preserve the metadata warning. } this.logger.warn("DialCache shadow validation mismatch", warning); } @@ -1454,14 +1509,23 @@ function snapshotDefaultConfig(config: DialCacheKeyConfig | null | undefined): D throw new RangeError("DialCache defaultConfig shadow.ramp must be between 0 and 100"); } } - if (snapshot.shadow.logMismatches !== undefined && typeof snapshot.shadow.logMismatches !== "boolean") { - throw new TypeError("DialCache defaultConfig shadow.logMismatches must be a boolean"); + const mismatchLogging = snapshot.shadow.mismatchLogging; + if (mismatchLogging !== undefined) { + for (const leaf of ["key", "value", "diff"] as const) { + const configured = mismatchLogging[leaf]; + if (configured !== undefined && typeof configured !== "boolean") { + throw new TypeError(`DialCache defaultConfig shadow.mismatchLogging.${leaf} must be a boolean`); + } + } } } Object.freeze(snapshot.ttlSec); Object.freeze(snapshot.ramp); if (snapshot.shadow !== undefined) { + if (snapshot.shadow.mismatchLogging !== undefined) { + Object.freeze(snapshot.shadow.mismatchLogging); + } Object.freeze(snapshot.shadow); } return Object.freeze(snapshot); @@ -1574,6 +1638,60 @@ function resolveShadowComparator( return comparator ?? isDeepStrictEqual; } +// Runs only after terminal mismatch confirmation, inside detached shadow work. +// Every hook invocation and JSON step fails closed to a `null` field so a bad +// projection can never surface raw values or affect the recorded outcome. +function renderShadowMismatchLog( + logPlan: ShadowLogPlan, + plan: ShadowValidationPlan, + cachedValue: Value, + sourceValue: Value, +): ShadowMismatchLogDetails { + let cachedLoggable: unknown = cachedValue; + let sourceLoggable: unknown = sourceValue; + let cachedLoggableOk = true; + let sourceLoggableOk = true; + const needsProjection = plan.logValue !== undefined + && (logPlan.value || (logPlan.diff && plan.logDiff === undefined)); + if (needsProjection && plan.logValue !== undefined) { + try { + cachedLoggable = plan.logValue(cachedValue); + } catch { + cachedLoggableOk = false; + } + try { + sourceLoggable = plan.logValue(sourceValue); + } catch { + sourceLoggableOk = false; + } + } + + let diffJson: string | null | undefined; + if (logPlan.diff) { + if (plan.logDiff !== undefined) { + try { + diffJson = previewShadowLogJson(plan.logDiff(cachedValue, sourceValue)); + } catch { + diffJson = null; + } + } else { + diffJson = cachedLoggableOk && sourceLoggableOk + ? previewShadowLogDiff(cachedLoggable, sourceLoggable) + : null; + } + } + + return { + ...(logPlan.value + ? { + cachedValueJson: cachedLoggableOk ? previewShadowLogJson(cachedLoggable) : null, + sourceValueJson: sourceLoggableOk ? previewShadowLogJson(sourceLoggable) : null, + } + : {}), + ...(diffJson === undefined ? {} : { diffJson }), + }; +} + // Frame stamps are epoch-based (Redis server time for tracked writes, writer // client clock for untracked), so the age uses the epoch clock and clamps // negative cross-clock skew to zero. A custom client that violates the decode diff --git a/src/index.ts b/src/index.ts index cc10a23..a5df1e2 100644 --- a/src/index.ts +++ b/src/index.ts @@ -1,5 +1,12 @@ export { CacheLayer, DialCacheKeyConfig } from "./config.js"; -export type { CacheConfigProvider, DialCacheConfig, LayerConfig, Logger, ShadowConfig } from "./config.js"; +export type { + CacheConfigProvider, + DialCacheConfig, + LayerConfig, + Logger, + ShadowConfig, + ShadowMismatchLoggingConfig, +} from "./config.js"; export { DialCacheContext } from "./context.js"; export type { CacheMetricLabels, diff --git a/src/internal/runtime-config.ts b/src/internal/runtime-config.ts index fdabb70..7152466 100644 --- a/src/internal/runtime-config.ts +++ b/src/internal/runtime-config.ts @@ -4,6 +4,7 @@ import { type CacheConfigProvider, type LayerConfig, type ShadowConfig, + type ShadowMismatchLoggingConfig, } from "../config.js"; import type { DialCacheKey } from "../key.js"; import type { DisabledReason } from "../metrics.js"; @@ -170,18 +171,47 @@ function mergeShadowConfig( } const ramp = overlay?.ramp !== undefined ? overlay.ramp : defaults?.ramp; - const logMismatches = overlay?.logMismatches !== undefined - ? overlay.logMismatches - : defaults?.logMismatches; + const mismatchLogging = mergeMismatchLoggingConfig(defaults?.mismatchLogging, overlay?.mismatchLogging); return { ...(ramp === undefined ? {} : { ramp }), - ...(logMismatches === undefined ? {} : { logMismatches }), + ...(mismatchLogging === undefined ? {} : { mismatchLogging }), }; } +function mergeMismatchLoggingConfig( + defaults: ShadowMismatchLoggingConfig | undefined, + overlay: ShadowMismatchLoggingConfig | undefined, +): ShadowMismatchLoggingConfig | undefined { + assertMismatchLoggingConfig(defaults); + assertMismatchLoggingConfig(overlay); + + if (defaults === undefined && overlay === undefined) { + return undefined; + } + + const merged: { -readonly [Leaf in keyof ShadowMismatchLoggingConfig]: boolean } = {}; + for (const leaf of ["key", "value", "diff"] as const) { + const overlayValue = overlay?.[leaf]; + const value = overlayValue !== undefined ? overlayValue : defaults?.[leaf]; + if (value !== undefined) { + merged[leaf] = value; + } + } + return merged; +} + function assertShadowConfig(config: ShadowConfig | undefined): void { if (config !== undefined && (config === null || typeof config !== "object" || Array.isArray(config))) { throw new TypeError("DialCache shadow config must be an object"); } + if (config !== undefined && Object.hasOwn(config, "logMismatches")) { + throw new TypeError('ShadowConfig.logMismatches was replaced by "shadow.mismatchLogging"'); + } +} + +function assertMismatchLoggingConfig(config: ShadowMismatchLoggingConfig | undefined): void { + if (config !== undefined && (config === null || typeof config !== "object" || Array.isArray(config))) { + throw new TypeError("DialCache shadow mismatchLogging config must be an object"); + } } diff --git a/src/internal/shadow-log-json.ts b/src/internal/shadow-log-json.ts index a43b2db..d245e7a 100644 --- a/src/internal/shadow-log-json.ts +++ b/src/internal/shadow-log-json.ts @@ -1,17 +1,14 @@ +import diff, { type Difference } from "microdiff"; + export const SHADOW_LOG_KEY_MAX_BYTES = 2 * 1024; export const SHADOW_LOG_VALUE_MAX_BYTES = 8 * 1024; +export const SHADOW_LOG_DIFF_MAX_BYTES = 8 * 1024; export const SHADOW_LOG_TRUNCATION_MARKER = "...[truncated]"; const UTF8_ENCODER = new TextEncoder(); const UTF8_DECODER = new TextDecoder("utf-8", { fatal: true }); const TRUNCATION_MARKER_BYTES = UTF8_ENCODER.encode(SHADOW_LOG_TRUNCATION_MARKER); -export interface ShadowMismatchLogDetails { - readonly cacheKey: string; - readonly cachedValueJson: string | null; - readonly sourceValueJson: string | null; -} - export function previewShadowLogKey(value: string): string { return clampUtf8(value, SHADOW_LOG_KEY_MAX_BYTES); } @@ -25,16 +22,41 @@ export function previewShadowLogJson(value: unknown): string | null { } } -export function shadowMismatchLogDetails( - cacheKey: string, - cachedValue: unknown, - sourceValue: unknown, -): ShadowMismatchLogDetails { - return { - cacheKey: previewShadowLogKey(cacheKey), - cachedValueJson: previewShadowLogJson(cachedValue), - sourceValueJson: previewShadowLogJson(sourceValue), - }; +/** + * Bounded JSON of the structural differences between the two loggable inputs, + * oriented from the cached side to the source side: `oldValue` is cached, + * `value` is source. Plain-object and array roots diff recursively (cycle-safe); + * any other root pair collapses to one root-level change entry when the inputs + * are not identical. `[]` means the inputs held no visible difference. + */ +export function previewShadowLogDiff(cachedInput: unknown, sourceInput: unknown): string | null { + try { + const entries = isDiffableRoot(cachedInput) && isDiffableRoot(sourceInput) + ? diff(cachedInput, sourceInput) + : rootDifference(cachedInput, sourceInput); + const json = JSON.stringify(entries); + return json === undefined ? null : clampUtf8(json, SHADOW_LOG_DIFF_MAX_BYTES); + } catch { + return null; + } +} + +function isDiffableRoot(value: unknown): value is Record | unknown[] { + if (Array.isArray(value)) { + return true; + } + if (value === null || typeof value !== "object") { + return false; + } + const proto: unknown = Object.getPrototypeOf(value); + return proto === Object.prototype || proto === null; +} + +function rootDifference(cachedInput: unknown, sourceInput: unknown): Difference[] { + if (Object.is(cachedInput, sourceInput)) { + return []; + } + return [{ type: "CHANGE", path: [], value: sourceInput, oldValue: cachedInput }]; } function clampUtf8(value: string, maxBytes: number): string { diff --git a/test/dialcache-config-ramp.test.ts b/test/dialcache-config-ramp.test.ts index eb0d8ae..322a9c3 100644 --- a/test/dialcache-config-ramp.test.ts +++ b/test/dialcache-config-ramp.test.ts @@ -50,28 +50,58 @@ describe("DialCache runtime config and ramp controls", () => { expect(new DialCacheKeyConfig({ shadow: { ramp: 0, - logMismatches: false, + mismatchLogging: { + key: false, + value: false, + diff: false, + }, }, }).shadow).toEqual({ ramp: 0, - logMismatches: false, + mismatchLogging: { + key: false, + value: false, + diff: false, + }, }); }); + it("rejects the removed shadow logMismatches flag", () => { + expect(() => new DialCacheKeyConfig({ + shadow: { logMismatches: true } as never, + })).toThrow('ShadowConfig.logMismatches was replaced by "shadow.mismatchLogging"'); + }); + + it("rejects a non-object shadow mismatchLogging group", () => { + for (const mismatchLogging of [null, 5, "keys", [true]]) { + expect(() => new DialCacheKeyConfig({ + shadow: { mismatchLogging } as never, + })).toThrow("DialCache shadow mismatchLogging config must be an object"); + } + }); + it("clones the supplied shadow policy", () => { const suppliedShadow = { ramp: 25, - logMismatches: true, + mismatchLogging: { + key: true, + value: true, + }, }; const config = new DialCacheKeyConfig({ shadow: suppliedShadow }); suppliedShadow.ramp = 0; - suppliedShadow.logMismatches = false; + suppliedShadow.mismatchLogging.key = false; + suppliedShadow.mismatchLogging.value = false; expect(config.shadow).not.toBe(suppliedShadow); + expect(config.shadow?.mismatchLogging).not.toBe(suppliedShadow.mismatchLogging); expect(config.shadow).toEqual({ ramp: 25, - logMismatches: true, + mismatchLogging: { + key: true, + value: true, + }, }); }); @@ -81,7 +111,7 @@ describe("DialCache runtime config and ramp controls", () => { ramp: { [CacheLayer.LOCAL]: 100 }, shadow: { ramp: 25, - logMismatches: true, + mismatchLogging: { key: true, value: true }, }, coalesce: false, }); @@ -105,10 +135,10 @@ describe("DialCache runtime config and ramp controls", () => { suppliedDefault.ramp[CacheLayer.LOCAL] = 0; const mutableShadow = suppliedDefault.shadow as { ramp?: number; - logMismatches?: boolean; + mismatchLogging?: { key?: boolean; value?: boolean }; }; mutableShadow.ramp = 0; - mutableShadow.logMismatches = false; + mutableShadow.mismatchLogging = { key: false, value: false }; const first = await dialcache.enable(async () => await getUser("123")); const second = await dialcache.enable(async () => await getUser("123")); @@ -121,13 +151,14 @@ describe("DialCache runtime config and ramp controls", () => { expect(observedDefaults[0]?.ramp[CacheLayer.LOCAL]).toBe(100); expect(observedDefaults[0]?.shadow).toEqual({ ramp: 25, - logMismatches: true, + mismatchLogging: { key: true, value: true }, }); expect(observedDefaults[0]?.coalesce).toBe(false); expect(Object.isFrozen(observedDefaults[0])).toBe(true); expect(Object.isFrozen(observedDefaults[0]?.ttlSec)).toBe(true); expect(Object.isFrozen(observedDefaults[0]?.ramp)).toBe(true); expect(Object.isFrozen(observedDefaults[0]?.shadow)).toBe(true); + expect(Object.isFrozen(observedDefaults[0]?.shadow?.mismatchLogging)).toBe(true); }); it("enables request-local caching without TTL or ramp policy", async () => { @@ -400,10 +431,16 @@ describe("DialCache runtime config and ramp controls", () => { "must be a number", ], [ - "wrong-type shadow mismatch logging flag", - new DialCacheKeyConfig({ shadow: { logMismatches: null as unknown as boolean } }), + "wrong-type shadow mismatch logging leaf", + new DialCacheKeyConfig({ shadow: { mismatchLogging: { value: null as unknown as boolean } } }), + TypeError, + "shadow.mismatchLogging.value must be a boolean", + ], + [ + "removed shadow logMismatches", + { ttlSec: {}, ramp: {}, shadow: { logMismatches: true } } as unknown as DialCacheKeyConfig, TypeError, - "must be a boolean", + 'logMismatches was replaced by "shadow.mismatchLogging"', ], ["primitive config", 42 as unknown as DialCacheKeyConfig, TypeError, "must be an object"], ["array config", [] as unknown as DialCacheKeyConfig, TypeError, "must be an object"], @@ -489,7 +526,11 @@ describe("DialCache runtime config and ramp controls", () => { requestLocal: false, shadow: { ramp: 0, - logMismatches: false, + mismatchLogging: { + key: false, + value: false, + diff: false, + }, }, ramp: { [CacheLayer.LOCAL]: 0, [CacheLayer.REMOTE]: 0 }, })); diff --git a/test/dialcache-observability-internals.test.ts b/test/dialcache-observability-internals.test.ts index d6ec4a4..5df3111 100644 --- a/test/dialcache-observability-internals.test.ts +++ b/test/dialcache-observability-internals.test.ts @@ -18,7 +18,7 @@ describe("DialCache observability internal compatibility paths", () => { ramp: { [CacheLayer.LOCAL]: 25, [CacheLayer.REMOTE]: 50 }, shadow: { ramp: 20, - logMismatches: true, + mismatchLogging: { key: true, value: true }, }, }); const cases = [ @@ -37,7 +37,7 @@ describe("DialCache observability internal compatibility paths", () => { ramp: { [CacheLayer.LOCAL]: 25, [CacheLayer.REMOTE]: 75 }, shadow: { ramp: 80, - logMismatches: true, + mismatchLogging: { key: true, value: true }, }, }), }, @@ -46,7 +46,7 @@ describe("DialCache observability internal compatibility paths", () => { ttlSec: { [CacheLayer.REMOTE]: 90 }, ramp: { [CacheLayer.LOCAL]: 10 }, shadow: { - logMismatches: false, + mismatchLogging: { value: false, diff: true }, }, }), expected: new DialCacheKeyConfig({ @@ -56,7 +56,7 @@ describe("DialCache observability internal compatibility paths", () => { ramp: { [CacheLayer.LOCAL]: 10, [CacheLayer.REMOTE]: 50 }, shadow: { ramp: 20, - logMismatches: false, + mismatchLogging: { key: true, value: false, diff: true }, }, }), }, @@ -69,7 +69,7 @@ describe("DialCache observability internal compatibility paths", () => { ramp: { [CacheLayer.LOCAL]: 25, [CacheLayer.REMOTE]: 50 }, shadow: { ramp: 20, - logMismatches: true, + mismatchLogging: { key: true, value: true }, }, }), }, diff --git a/test/dialcache-shadow-confirmation.test.ts b/test/dialcache-shadow-confirmation.test.ts index 0bd33b7..b3c5704 100644 --- a/test/dialcache-shadow-confirmation.test.ts +++ b/test/dialcache-shadow-confirmation.test.ts @@ -161,14 +161,19 @@ class RecordingMetrics implements DialCacheMetricsAdapter { function remoteConfig( remoteRamp: number, shadowPercentage = 100, - logging: { - readonly logMismatches?: boolean; - } = {}, + mismatchLogging?: { + readonly key?: boolean; + readonly value?: boolean; + readonly diff?: boolean; + }, ): DialCacheKeyConfig { return new DialCacheKeyConfig({ ttlSec: { [CacheLayer.REMOTE]: 60 }, ramp: { [CacheLayer.REMOTE]: remoteRamp }, - shadow: { ramp: shadowPercentage, ...logging }, + shadow: { + ramp: shadowPercentage, + ...(mismatchLogging === undefined ? {} : { mismatchLogging }), + }, }); } @@ -338,7 +343,7 @@ describe("DialCache Redis shadow confirmation", () => { const getUser = dialcache.cached(async () => ({ id: "private-id", version: 2 }), { ...trackedOptions( "ShadowMismatchJson", - remoteConfig(100, 100, { logMismatches: true }), + remoteConfig(100, 100, { key: true, value: true }), ), cacheKey: () => ({ id: "private-id", @@ -388,9 +393,7 @@ describe("DialCache Redis shadow confirmation", () => { const getUser = dialcache.cached(async () => sourceValue, { ...trackedOptions( "ShadowMismatchRampedDownJson", - remoteConfig(0, 100, { - logMismatches: true, - }), + remoteConfig(0, 100, { key: true, value: true }), ), cacheKey: () => ({ id: "123", @@ -440,16 +443,16 @@ describe("DialCache Redis shadow confirmation", () => { }, { ...trackedOptions( "ShadowMismatchJsonFailure", - remoteConfig(100, 100, { - logMismatches: true, - }), + remoteConfig(100, 100, { key: true, value: true }), ), cacheKey: () => "123", }); await dialcache.enable(async () => await getUser()); await sourceStarted.promise; - const encodeInto = vi.spyOn(TextEncoder.prototype, "encodeInto").mockImplementationOnce(() => { + // A persistent throw nulls both value previews at render time and then + // fails the key preview inside warning assembly, forcing the metadata path. + const encodeInto = vi.spyOn(TextEncoder.prototype, "encodeInto").mockImplementation(() => { throw new Error("preview unavailable"); }); try { @@ -491,9 +494,7 @@ describe("DialCache Redis shadow confirmation", () => { const getUser = dialcache.cached(async () => sourceValue, { ...trackedOptions( "ShadowMismatchClampedJson", - remoteConfig(100, 100, { - logMismatches: true, - }), + remoteConfig(100, 100, { key: true, value: true }), ), cacheKey: () => id, }); @@ -519,6 +520,292 @@ describe("DialCache Redis shadow confirmation", () => { } }); + it("logs a key-only warning when only mismatchLogging.key is enabled", async () => { + const useCase = "ShadowMismatchKeyOnly"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true })), + cacheKey: () => "123", + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cacheKey: `{urn:user_id:123}#${useCase}`, + }, + ); + }); + + it("logs values without the key when mismatchLogging.key is off", async () => { + const useCase = "ShadowMismatchValueOnly"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { value: true })), + cacheKey: () => "123", + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cachedValueJson: '{"id":"123","version":1}', + sourceValueJson: '{"id":"123","version":2}', + }, + ); + }); + + it("projects both sides through shadowMismatchLogValue before logging", async () => { + const useCase = "ShadowMismatchProjectedValues"; + const payload = JSON.stringify({ id: "123", version: 1, secret: "cached-secret" }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached( + async () => ({ id: "123", version: 2, secret: "source-secret" }), + { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true, value: true })), + cacheKey: () => "123", + shadowMismatchLogValue: (value) => ({ version: value.version }), + }, + ); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cacheKey: `{urn:user_id:123}#${useCase}`, + cachedValueJson: '{"version":1}', + sourceValueJson: '{"version":2}', + }, + ); + }); + + it("logs null for the side whose shadowMismatchLogValue projection throws", async () => { + const useCase = "ShadowMismatchProjectionThrow"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { value: true })), + cacheKey: () => "123", + shadowMismatchLogValue: (value) => { + if (value.version === 1) { + throw new Error("unprojectable"); + } + return { version: value.version }; + }, + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cachedValueJson: null, + sourceValueJson: '{"version":2}', + }, + ); + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch"]); + }); + + it("logs a structural diff of the raw values when no hooks are defined", async () => { + const useCase = "ShadowMismatchBuiltInDiff"; + const payload = JSON.stringify({ id: "123", version: 1, tags: ["a", "b"] }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached( + async () => ({ id: "123", version: 2, tags: ["a", "c"] }), + { + ...trackedOptions(useCase, remoteConfig(100, 100, { diff: true })), + cacheKey: () => "123", + }, + ); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + const warning = warn.mock.calls[0]?.[1] as Record; + expect(warning).not.toHaveProperty("cacheKey"); + expect(warning).not.toHaveProperty("cachedValueJson"); + expect(warning).not.toHaveProperty("sourceValueJson"); + expect(JSON.parse(warning.diffJson as string)).toEqual([ + { type: "CHANGE", path: ["version"], value: 2, oldValue: 1 }, + { type: "CHANGE", path: ["tags", 1], value: "c", oldValue: "b" }, + ]); + }); + + it("computes the built-in diff over projected values", async () => { + const useCase = "ShadowMismatchProjectedDiff"; + const payload = JSON.stringify({ id: "123", version: 1, secret: "cached-secret" }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached( + async () => ({ id: "123", version: 2, secret: "source-secret" }), + { + ...trackedOptions(useCase, remoteConfig(100, 100, { diff: true })), + cacheKey: () => "123", + shadowMismatchLogValue: (value) => ({ id: value.id, version: value.version }), + }, + ); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + const warning = warn.mock.calls[0]?.[1] as Record; + expect(warning.diffJson).not.toContain("secret"); + expect(JSON.parse(warning.diffJson as string)).toEqual([ + { type: "CHANGE", path: ["version"], value: 2, oldValue: 1 }, + ]); + }); + + it("logs an empty diff when the projection hides the difference", async () => { + const useCase = "ShadowMismatchRedactedDiff"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true, diff: true })), + cacheKey: () => "123", + shadowMismatchLogValue: (value) => ({ id: value.id }), + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + const warning = warn.mock.calls[0]?.[1] as Record; + expect(warning.diffJson).toBe("[]"); + }); + + it("prefers shadowMismatchLogDiff over the built-in diff and passes raw values", async () => { + const useCase = "ShadowMismatchCustomDiff"; + const cachedValue = { id: "123", version: 1 }; + const payload = JSON.stringify(cachedValue); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const projector = vi.fn(() => ({})); + const logDiff = vi.fn( + (cached: { version: number }, source: { version: number }) => + ({ from: cached.version, to: source.version }), + ); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { diff: true })), + cacheKey: () => "123", + shadowMismatchLogValue: projector, + shadowMismatchLogDiff: logDiff, + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(logDiff).toHaveBeenCalledTimes(1); + expect(logDiff).toHaveBeenCalledWith({ id: "123", version: 1 }, { id: "123", version: 2 }); + expect(projector).not.toHaveBeenCalled(); + expect(warn).toHaveBeenCalledTimes(1); + const warning = warn.mock.calls[0]?.[1] as Record; + expect(warning.diffJson).toBe('{"from":1,"to":2}'); + }); + + it("logs a null diff when shadowMismatchLogDiff throws", async () => { + const useCase = "ShadowMismatchCustomDiffThrow"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true, diff: true })), + cacheKey: () => "123", + shadowMismatchLogDiff: () => { + throw new Error("diff unavailable"); + }, + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cacheKey: `{urn:user_id:123}#${useCase}`, + diffJson: null, + }, + ); + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch"]); + }); + it.each([ { name: "missing", confirmation: null }, { @@ -623,9 +910,7 @@ describe("DialCache Redis shadow confirmation", () => { const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { ...trackedOptions( "ShadowMismatchSuperseded", - remoteConfig(100, 100, { - logMismatches: true, - }), + remoteConfig(100, 100, { key: true, value: true }), ), cacheKey: () => "123", }); @@ -1506,7 +1791,7 @@ describe("DialCache Redis shadow confirmation", () => { const warn = vi.fn(); const dialcache = createCache(redis, metrics, { cacheConfigProvider: async () => new DialCacheKeyConfig({ - shadow: { logMismatches: "yes" as never }, + shadow: { mismatchLogging: { value: "yes" as never } }, }), logger: { debug: () => undefined, @@ -1515,12 +1800,7 @@ describe("DialCache Redis shadow confirmation", () => { }, }); const getUser = dialcache.cached(async () => sourceValue, { - ...trackedOptions( - useCase, - remoteConfig(100, 100, { - logMismatches: true, - }), - ), + ...trackedOptions(useCase, remoteConfig(100)), cacheKey: () => "123", }); @@ -1536,6 +1816,50 @@ describe("DialCache Redis shadow confirmation", () => { expect(warn).not.toHaveBeenCalled(); }); + it("resolves an invalid mismatch logging leaf to off without suppressing valid leaves", async () => { + const useCase = "ShadowInvalidLoggingLeaf"; + const cachedValue = { id: "123", version: 1 }; + const payload = JSON.stringify(cachedValue); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + cacheConfigProvider: async () => new DialCacheKeyConfig({ + shadow: { mismatchLogging: { key: true, value: 5 as never } }, + }), + logger: { + debug: () => undefined, + error: () => undefined, + warn, + }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100)), + cacheKey: () => "123", + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch"]); + expect(metrics.ordinaryEvents.filter(({ name: metricName, labels }) => + metricName === "error" + && labels.layer === CacheLayer.REMOTE + && labels.error === "config_resolution" + )).toHaveLength(1); + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cacheKey: `{urn:user_id:123}#${useCase}`, + }, + ); + }); + it("treats DialCacheKeyConfig.disabled() as a complete shadow kill switch", async () => { const redis = new ScriptedRedis([]); const metrics = new RecordingMetrics(); diff --git a/test/dialcache-shadow-validation.test.ts b/test/dialcache-shadow-validation.test.ts index 0eed650..4f31ec4 100644 --- a/test/dialcache-shadow-validation.test.ts +++ b/test/dialcache-shadow-validation.test.ts @@ -487,7 +487,7 @@ describe("DialCache Redis shadow validation", () => { error, }, { cacheConfigProvider: async () => new DialCacheKeyConfig({ - shadow: { logMismatches: "yes" as never }, + shadow: { mismatchLogging: { value: "yes" as never } }, }), logger: { debug: () => undefined, @@ -502,7 +502,7 @@ describe("DialCache Redis shadow validation", () => { ramp: { [CacheLayer.REMOTE]: 100 }, shadow: { ramp: 100, - logMismatches: true, + mismatchLogging: { key: true, value: true }, }, }), cacheKey: () => "123", @@ -538,7 +538,7 @@ describe("DialCache Redis shadow validation", () => { const source = vi.fn(async (id: string) => ({ id })); const dialcache = createShadowCache(redis, metrics, { cacheConfigProvider: async () => new DialCacheKeyConfig({ - shadow: { logMismatches: "yes" as never }, + shadow: { mismatchLogging: { value: "yes" as never } }, }), }); const getUser = dialcache.cached(source, { @@ -1063,7 +1063,7 @@ describe("DialCache Redis shadow validation", () => { shadowMaxInFlight: 1, cacheConfigProvider: async (key) => key.id === "b" ? new DialCacheKeyConfig({ - shadow: { logMismatches: "yes" as never }, + shadow: { mismatchLogging: { value: "yes" as never } }, }) : null, }); diff --git a/test/shadow-log-json.test.ts b/test/shadow-log-json.test.ts index 22b1707..7296db4 100644 --- a/test/shadow-log-json.test.ts +++ b/test/shadow-log-json.test.ts @@ -1,36 +1,28 @@ import { describe, expect, it } from "vitest"; import { + SHADOW_LOG_DIFF_MAX_BYTES, SHADOW_LOG_KEY_MAX_BYTES, SHADOW_LOG_TRUNCATION_MARKER, SHADOW_LOG_VALUE_MAX_BYTES, + previewShadowLogDiff, previewShadowLogJson, previewShadowLogKey, - shadowMismatchLogDetails, } from "../src/internal/shadow-log-json.js"; describe("shadow mismatch log JSON", () => { it("uses native JSON for the values supplied to the comparator", () => { - expect(shadowMismatchLogDetails( - "urn:user_id:123#GetUser", - { id: "123", updatedAt: new Date("2026-07-31T00:00:00.000Z") }, - { id: "123", updatedAt: new Date("2026-08-01T00:00:00.000Z") }, - )).toEqual({ - cacheKey: "urn:user_id:123#GetUser", - cachedValueJson: '{"id":"123","updatedAt":"2026-07-31T00:00:00.000Z"}', - sourceValueJson: '{"id":"123","updatedAt":"2026-08-01T00:00:00.000Z"}', - }); - }); - - it("returns null independently for values that native JSON cannot serialize", () => { + expect(previewShadowLogJson({ + id: "123", + updatedAt: new Date("2026-07-31T00:00:00.000Z"), + })).toBe('{"id":"123","updatedAt":"2026-07-31T00:00:00.000Z"}'); + }); + + it("returns null for values that native JSON cannot serialize", () => { const circular: { self?: unknown } = {}; circular.self = circular; - expect(shadowMismatchLogDetails("key", circular, { version: 2 })).toEqual({ - cacheKey: "key", - cachedValueJson: null, - sourceValueJson: '{"version":2}', - }); + expect(previewShadowLogJson(circular)).toBeNull(); expect(previewShadowLogJson(1n)).toBeNull(); expect(previewShadowLogJson(undefined)).toBeNull(); }); @@ -56,7 +48,70 @@ describe("shadow mismatch log JSON", () => { expect(Buffer.byteLength(valuePreview!)).toBeLessThanOrEqual(SHADOW_LOG_VALUE_MAX_BYTES); expect(keyPreview.endsWith(SHADOW_LOG_TRUNCATION_MARKER)).toBe(true); expect(valuePreview!.endsWith(SHADOW_LOG_TRUNCATION_MARKER)).toBe(true); - expect(keyPreview).not.toContain("\uFFFD"); - expect(valuePreview).not.toContain("\uFFFD"); + expect(keyPreview).not.toContain("�"); + expect(valuePreview).not.toContain("�"); + }); + + it("diffs plain objects and arrays from the cached side to the source side", () => { + const diffJson = previewShadowLogDiff( + { id: "123", version: 1, tags: ["a", "b"] }, + { id: "123", version: 2, tags: ["a"] }, + ); + + expect(JSON.parse(diffJson!)).toEqual([ + { type: "CHANGE", path: ["version"], value: 2, oldValue: 1 }, + { type: "REMOVE", path: ["tags", 1], oldValue: "b" }, + ]); + }); + + it("returns an empty diff for equal inputs", () => { + expect(previewShadowLogDiff({ id: "123" }, { id: "123" })).toBe("[]"); + expect(previewShadowLogDiff("same", "same")).toBe("[]"); + }); + + it("collapses non-plain-object roots to one root-level change entry", () => { + expect(JSON.parse(previewShadowLogDiff("cached", "source")!)).toEqual([ + { type: "CHANGE", path: [], value: "source", oldValue: "cached" }, + ]); + expect(JSON.parse(previewShadowLogDiff({ id: "123" }, null)!)).toEqual([ + { type: "CHANGE", path: [], value: null, oldValue: { id: "123" } }, + ]); + expect(JSON.parse(previewShadowLogDiff( + new Date("2026-07-31T00:00:00.000Z"), + new Date("2026-08-01T00:00:00.000Z"), + )!)).toEqual([ + { + type: "CHANGE", + path: [], + value: "2026-08-01T00:00:00.000Z", + oldValue: "2026-07-31T00:00:00.000Z", + }, + ]); + }); + + it("survives cyclic inputs", () => { + const cached: { id: string; self?: unknown } = { id: "cached" }; + cached.self = cached; + const source: { id: string; self?: unknown } = { id: "source" }; + source.self = source; + + // The traversal is cycle-safe; JSON rendering of a cyclic leaf still fails + // closed to null rather than throwing. + expect(() => previewShadowLogDiff(cached, source)).not.toThrow(); + }); + + it("returns null when the diff entries cannot be serialized", () => { + expect(previewShadowLogDiff({ n: 1n }, { n: 2n })).toBeNull(); + }); + + it("byte-clamps the diff", () => { + const diffJson = previewShadowLogDiff( + { text: "a".repeat(SHADOW_LOG_DIFF_MAX_BYTES) }, + { text: "b".repeat(SHADOW_LOG_DIFF_MAX_BYTES) }, + ); + + expect(diffJson).not.toBeNull(); + expect(Buffer.byteLength(diffJson!)).toBeLessThanOrEqual(SHADOW_LOG_DIFF_MAX_BYTES); + expect(diffJson!.endsWith(SHADOW_LOG_TRUNCATION_MARKER)).toBe(true); }); }); From ad8cdddf892bb74a48cf5602a0478cc3990fc92f Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Fri, 14 Aug 2026 17:46:58 -0700 Subject: [PATCH 2/9] test(shadow): pin diff logging edge behavior Covers the gaps in diff-logging coverage: CREATE entries, nested Date leaves rendering as ISO strings, index-wise array-shift noise, cyclic inputs failing closed to a null diff, a projection throw nulling the built-in diff, one projection per side feeding value and diff output together, an idle shadowMismatchLogDiff hook when diff logging is off, and hooks staying uninvoked for superseded candidates. --- test/dialcache-shadow-confirmation.test.ts | 125 +++++++++++++++++++++ test/shadow-log-json.test.ts | 38 ++++++- 2 files changed, 159 insertions(+), 4 deletions(-) diff --git a/test/dialcache-shadow-confirmation.test.ts b/test/dialcache-shadow-confirmation.test.ts index b3c5704..6ff9804 100644 --- a/test/dialcache-shadow-confirmation.test.ts +++ b/test/dialcache-shadow-confirmation.test.ts @@ -771,6 +771,131 @@ describe("DialCache Redis shadow confirmation", () => { expect(warning.diffJson).toBe('{"from":1,"to":2}'); }); + it("logs a null built-in diff when the projection throws for either side", async () => { + const useCase = "ShadowMismatchDiffProjectionThrow"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true, diff: true })), + cacheKey: () => "123", + shadowMismatchLogValue: (value) => { + if (value.version === 1) { + throw new Error("unprojectable"); + } + return { version: value.version }; + }, + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cacheKey: `{urn:user_id:123}#${useCase}`, + diffJson: null, + }, + ); + }); + + it("projects each side once when value and diff logging are both enabled", async () => { + const useCase = "ShadowMismatchSharedProjection"; + const payload = JSON.stringify({ id: "123", version: 1, secret: "cached-secret" }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const projector = vi.fn( + (value: { version: number }) => ({ version: value.version }), + ); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached( + async () => ({ id: "123", version: 2, secret: "source-secret" }), + { + ...trackedOptions(useCase, remoteConfig(100, 100, { value: true, diff: true })), + cacheKey: () => "123", + shadowMismatchLogValue: projector, + }, + ); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(projector).toHaveBeenCalledTimes(2); + expect(warn).toHaveBeenCalledTimes(1); + const warning = warn.mock.calls[0]?.[1] as Record; + expect(warning.cachedValueJson).toBe('{"version":1}'); + expect(warning.sourceValueJson).toBe('{"version":2}'); + expect(JSON.parse(warning.diffJson as string)).toEqual([ + { type: "CHANGE", path: ["version"], value: 2, oldValue: 1 }, + ]); + }); + + it("does not invoke shadowMismatchLogDiff when diff logging is off", async () => { + const useCase = "ShadowMismatchDiffHookIdle"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const logDiff = vi.fn(() => ({})); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { value: true })), + cacheKey: () => "123", + shadowMismatchLogDiff: logDiff, + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(logDiff).not.toHaveBeenCalled(); + expect(warn).toHaveBeenCalledTimes(1); + const warning = warn.mock.calls[0]?.[1] as Record; + expect(warning).not.toHaveProperty("diffJson"); + expect(warning.cachedValueJson).toBe('{"id":"123","version":1}'); + }); + + it("does not invoke log hooks or warn for a superseded mismatch candidate", async () => { + const useCase = "ShadowSupersededHooksIdle"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const confirmation = JSON.stringify({ id: "123", version: 3 }); + const redis = new ScriptedRedis([() => payload, () => confirmation]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const projector = vi.fn(() => ({})); + const logDiff = vi.fn(() => ({})); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true, value: true, diff: true })), + cacheKey: () => "123", + shadowMismatchLogValue: projector, + shadowMismatchLogDiff: logDiff, + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["superseded"]); + expect(projector).not.toHaveBeenCalled(); + expect(logDiff).not.toHaveBeenCalled(); + expect(warn).not.toHaveBeenCalled(); + }); + it("logs a null diff when shadowMismatchLogDiff throws", async () => { const useCase = "ShadowMismatchCustomDiffThrow"; const payload = JSON.stringify({ id: "123", version: 1 }); diff --git a/test/shadow-log-json.test.ts b/test/shadow-log-json.test.ts index 7296db4..1312a00 100644 --- a/test/shadow-log-json.test.ts +++ b/test/shadow-log-json.test.ts @@ -64,6 +64,36 @@ describe("shadow mismatch log JSON", () => { ]); }); + it("reports source-only fields as CREATE entries", () => { + expect(JSON.parse(previewShadowLogDiff({ a: 1 }, { a: 1, b: 2 })!)).toEqual([ + { type: "CREATE", path: ["b"], value: 2 }, + ]); + }); + + it("renders nested Date leaves as ISO strings in diff entries", () => { + expect(JSON.parse(previewShadowLogDiff( + { updatedAt: new Date("2026-07-31T00:00:00.000Z") }, + { updatedAt: new Date("2026-08-01T00:00:00.000Z") }, + )!)).toEqual([ + { + type: "CHANGE", + path: ["updatedAt"], + value: "2026-08-01T00:00:00.000Z", + oldValue: "2026-07-31T00:00:00.000Z", + }, + ]); + }); + + it("reports an element shift as index-wise changes", () => { + // Documented noise: array entries compare by index, so a shift reports + // every later index instead of one insertion. + expect(JSON.parse(previewShadowLogDiff(["a", "b", "c"], ["x", "a", "b"])!)).toEqual([ + { type: "CHANGE", path: [0], value: "x", oldValue: "a" }, + { type: "CHANGE", path: [1], value: "a", oldValue: "b" }, + { type: "CHANGE", path: [2], value: "b", oldValue: "c" }, + ]); + }); + it("returns an empty diff for equal inputs", () => { expect(previewShadowLogDiff({ id: "123" }, { id: "123" })).toBe("[]"); expect(previewShadowLogDiff("same", "same")).toBe("[]"); @@ -89,15 +119,15 @@ describe("shadow mismatch log JSON", () => { ]); }); - it("survives cyclic inputs", () => { + it("fails closed to null for cyclic inputs instead of throwing", () => { const cached: { id: string; self?: unknown } = { id: "cached" }; cached.self = cached; const source: { id: string; self?: unknown } = { id: "source" }; source.self = source; - // The traversal is cycle-safe; JSON rendering of a cyclic leaf still fails - // closed to null rather than throwing. - expect(() => previewShadowLogDiff(cached, source)).not.toThrow(); + // The traversal is cycle-safe, but the resulting entries reference the + // cyclic structures, so JSON rendering fails closed to null. + expect(previewShadowLogDiff(cached, source)).toBeNull(); }); it("returns null when the diff entries cannot be serialized", () => { From 585959de99b62ad84db2cd0ec964e32efd011aec Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Fri, 14 Aug 2026 21:08:11 -0700 Subject: [PATCH 3/9] fix(shadow): review fixes for mismatch logging semantics, diff fidelity, and hardening Resolves the accepted findings from the multi-lane review of the mismatchLogging feature: - The built-in diff now renders both sides to native JSON before diffing, so toJSON redaction and serializer normalization bound the diff exactly as they bound value logging: no more leaking fields that toJSON hides, no phantom entries for serializer-normalized Dates, and mixed object/array roots collapse to one root-level change entry as documented. Identical loggable forms short-circuit to []. - diffJson has one cap owner: previewShadowLogJson takes a byte budget, the hook path and built-in path both clamp with the diff cap, and previewShadowLogDiff delegates instead of duplicating the body. - Runtime shadow config is read by own properties only (group, leaves, and ramp, in both the merge and admission reads), so prototype-carried values can neither enable payload logging nor admit shadow work. - A non-object runtime mismatchLogging group is documented as malformed config shape that fails resolution as config_error, matching the layer-map precedent; the unreachable admission-time branch is deleted and the behavior pinned by runtime-overlay tests alongside the previously uncovered removed-logMismatches rejection. - The leaf set is derived from one exhaustive, compile-checked list; ShadowLogPlan aliases Required; the disabled() kill-switch literal is annotated exhaustive. - Dead emit-time fallback deleted: every preview fails closed to a null field (previewShadowLogKey included), the warning path is throw-free by construction, and the warning payload is built fresh so a mutating metrics adapter cannot contaminate it. - New tests: both-hooks projection/raw split, prototype pollution, Object.create-carried leaves, per-field fail-closed, toJSON-bounded diff, serializer-normalization phantom, mixed-kind roots, explicit byte budgets, and the runtime rejection rows. --- README.md | 8 +- src/config.ts | 22 ++++- src/dialcache.ts | 74 ++++++++------- src/internal/runtime-config.ts | 25 +++-- src/internal/shadow-log-json.ts | 65 +++++++------ test/dialcache-config-ramp.test.ts | 2 + .../dialcache-observability-internals.test.ts | 16 ++++ test/dialcache-shadow-confirmation.test.ts | 93 ++++++++++++++++++- test/shadow-log-json.test.ts | 64 +++++++++++-- 9 files changed, 285 insertions(+), 84 deletions(-) diff --git a/README.md b/README.md index 69895cd..17babca 100644 --- a/README.md +++ b/README.md @@ -225,9 +225,9 @@ DialCache validates `defaultConfig` when `cached()` registers a definition and w Each registration or one-shot invocation captures an immutable internal snapshot of `defaultConfig`; mutating the supplied config or its maps later does not change that operation's baseline. Runtime policy changes belong in the provider's returned overlay. -Runtime TTL and ramp leaves are used as supplied instead of falling back to valid default leaves. A TTL outside the same 1-to-31,536,000-second range disables that layer with `invalid_ttl`; a nonnumeric, non-finite, or out-of-range ramp disables it with `invalid_ramp`. Valid ramps include both `0` and `100`. Other layers can still run, and invalid leaves also record a `config_resolution` error so provider garbage is alertable separately from intentional ramp-downs. A malformed runtime config object, layer-map shape, `requestLocal` value, `coalesce` value, explicit `remoteReadTimeoutMs`, removed top-level `shadowRamp`, or removed `shadow.logMismatches` fails config resolution for the invocation, records `config_error`, and executes the fallback uncached without attempting Redis. The public `DialCacheKeyConfig` constructor and static defaults likewise reject both removed fields immediately; migrate `shadowRamp` to `shadow.ramp` and `shadow.logMismatches` to `shadow.mismatchLogging`. +Runtime TTL and ramp leaves are used as supplied instead of falling back to valid default leaves. A TTL outside the same 1-to-31,536,000-second range disables that layer with `invalid_ttl`; a nonnumeric, non-finite, or out-of-range ramp disables it with `invalid_ramp`. Valid ramps include both `0` and `100`. Other layers can still run, and invalid leaves also record a `config_resolution` error so provider garbage is alertable separately from intentional ramp-downs. A malformed runtime config object, layer-map shape, `requestLocal` value, `coalesce` value, explicit `remoteReadTimeoutMs`, non-object `shadow.mismatchLogging` group, removed top-level `shadowRamp`, or removed `shadow.logMismatches` fails config resolution for the invocation, records `config_error`, and executes the fallback uncached without attempting Redis. The public `DialCacheKeyConfig` constructor and static defaults likewise reject both removed fields immediately; migrate `shadowRamp` to `shadow.ramp` and `shadow.logMismatches` to `shadow.mismatchLogging`. -An invalid runtime `shadow.ramp` does not affect the cache result or disable an otherwise valid Redis policy. If normal traversal reaches an otherwise shadow-eligible Redis path, DialCache skips shadow work and records a `config_resolution` error. An invalid runtime `shadow.mismatchLogging` shape or field likewise preserves the cache result, Redis policy, shadow result, and shadow metric; an invalid field acts false while valid sibling fields still log. DialCache validates these diagnostic leaves only after the metrics hook, exact-key cohort, and capacity gates admit shadow work, then records one remote `config_resolution` error for that admitted resolution. +An invalid runtime `shadow.ramp` does not affect the cache result or disable an otherwise valid Redis policy. If normal traversal reaches an otherwise shadow-eligible Redis path, DialCache skips shadow work and records a `config_resolution` error. An invalid runtime `shadow.mismatchLogging` field likewise preserves the cache result, Redis policy, shadow result, and shadow metric; an invalid field acts false while valid sibling fields still log. DialCache validates these diagnostic leaves only after the metrics hook, exact-key cohort, and capacity gates admit shadow work, then records one remote `config_resolution` error for that admitted resolution. A non-object `mismatchLogging` group is malformed config shape rather than an invalid field: like a malformed layer map, it fails resolution as `config_error` and the invocation runs uncached. Runtime shadow config is read by own properties only; prototype-inherited `ramp` or logging fields are ignored. `cacheConfigProvider` is called for every enabled cache invocation before DialCache performs any cache lookup. Keep it cheap, cache any remote/config-store reads inside the provider, and avoid work that would erase the benefit of a cache hit. @@ -602,13 +602,13 @@ Confirmed-mismatch logging is separately opt-in through the `shadow.mismatchLogg A byte-clipped field ends in `...[truncated]`, counted inside its cap. Every hook invocation and JSON step fails closed: a projector throw logs `null` for that side (and a `null` built-in diff), a diff-hook throw or unserializable diff logs `diffJson: null`, and native-JSON failure on one side leaves the other side attempted. DialCache never calls the configured serializer again for logging. -The built-in diff (the [microdiff](https://github.com/AsyncBanana/microdiff) library) emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. Plain-object and array roots diff recursively and cycle-safely, with array entries compared by index, so an element shift reports every later index. Any other root pair — dates, Maps, class instances, primitives, or mixed shapes — collapses to one root-level change entry when the inputs are not identical. `[]` means the loggable inputs held no visible difference; with a projector that reads as "the difference is inside fields the projection hides". The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures the built-in diff cannot see into. +The built-in diff first renders both sides to native JSON — the same loggable forms `value: true` shows — so `toJSON` redaction and serializer normalization bound the diff exactly as they bound value logging, and a cached side deserialized to an ISO string never phantom-differs from a live source `Date` at the same instant. Identical loggable forms yield `[]`; with a projector that reads as "the difference is inside fields the projection hides", and structures native JSON flattens (a `Map` renders as `{}`) read the same way. Otherwise the [microdiff](https://github.com/AsyncBanana/microdiff) library emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. Loggable roots of the same container kind (both objects or both arrays) diff recursively, with array entries compared by index, so an element shift reports every later index; any other root pair — primitives, `null`, or mixed object/array kinds — collapses to one root-level change entry. Cyclic inputs fail closed to a `null` diff. The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures native JSON flattens. Both hooks run only after terminal mismatch confirmation, inside detached shadow work, under the comparator's discipline: synchronous, deterministic, side-effect-free, non-mutating, and bounded, over borrowed references. Hook output feeds `JSON.stringify` directly. Mismatch logging is intentionally default-off, and its runtime fields choose exposure per use case: logical URNs can contain ids and arguments, while cached and source values may contain secrets or personal data, and truncation is not redaction. Without a projector, `value: true` and `diff: true` log raw value material — define `shadowMismatchLogValue` for any use case whose values can carry sensitive fields before enabling those flags, and prefer `key` plus a projected `diff` over full value payloads. DialCache creates the JSON strings only after terminal mismatch confirmation and never passes the raw compared-value references to the logger. Native JSON semantics apply: getters and `toJSON` methods may run, unsupported values may be omitted or normalized, and cycles or `bigint` can make a field unavailable. Stringification is synchronous, and the byte caps apply only after `JSON.stringify` returns; they do not bound input traversal, hook execution, event-loop time, or the intermediate JSON string. Enable mismatch logging only for trusted, reasonably bounded values and with an approved logger, redaction, transport, access, and retention policy. -The byte caps apply before logger framing or escaping, so they do not guarantee a final transport event below a sink-specific limit; the metadata fields are not size-clamped. A detail-construction failure degrades to the metadata-only warning. Logger throws and rejected promises or thenables remain isolated from cache and shadow correctness. +The byte caps apply before logger framing or escaping, so they do not guarantee a final transport event below a sink-specific limit; the metadata fields are not size-clamped. Every warning field fails closed independently — a failed preview logs `null` for that field while the rest still emit. Logger throws and rejected promises or thenables remain isolated from cache and shadow correctness. Detached Redis reads, serializer loads/dumps, payload sizes, and read/write errors use the existing layer label with `layer="remote_shadow"`. This distinguishes non-serving Redis cost from caller-path `layer="remote"` telemetry without adding a metric or label. The established `observeGet{layer="remote"}` boundary includes caller-path deserialization, while `observeGet{layer="remote_shadow"}` ends when the deadline-bounded Redis read result settles; detached serializer work and any later raw-client settlement are outside that timer. The request-path read that supplied a served `C0` keeps `layer="remote"`, and a ramped-down caller keeps `disabled{layer="remote", reason="ramped_down"}`. No `disabled{layer="remote_shadow"}` event is emitted for ineligible or dropped work; `dropped` remains the terminal shadow outcome. Confirmation reads use the same `remote_shadow` value, with `superseded` or `confirmation_error` describing their role. diff --git a/src/config.ts b/src/config.ts index 1135acf..2e7272f 100644 --- a/src/config.ts +++ b/src/config.ts @@ -41,6 +41,19 @@ export interface ShadowConfig { readonly mismatchLogging?: ShadowMismatchLoggingConfig; } +// `satisfies Record` fails to compile when the interface gains +// a field this set is missing, so every leaf loop stays exhaustive. +const SHADOW_MISMATCH_LOGGING_LEAF_SET = { + key: true, + value: true, + diff: true, +} as const satisfies Record; + +/** Internal: the exhaustive `ShadowMismatchLoggingConfig` field list. */ +export const SHADOW_MISMATCH_LOGGING_LEAVES = Object.keys( + SHADOW_MISMATCH_LOGGING_LEAF_SET, +) as readonly (keyof ShadowMismatchLoggingConfig)[]; + export class DialCacheKeyConfig { /** Per-layer TTLs in seconds, from 1 through 31,536,000 (365 days). */ readonly ttlSec: LayerConfig; @@ -128,11 +141,14 @@ export class DialCacheKeyConfig { requestLocal: false, shadow: { ramp: 0, + // `Required` keeps this kill-switch overlay exhaustive: leaves merge + // independently, so an omitted leaf would let an inherited `true` + // survive disabled(). mismatchLogging: { key: false, value: false, diff: false, - }, + } satisfies Required, }, ramp: { [CacheLayer.LOCAL]: 0, @@ -162,7 +178,9 @@ function cloneShadowConfig(config: ShadowConfig | undefined): ShadowConfig | und if (Object.hasOwn(config, "logMismatches")) { throw new TypeError('ShadowConfig.logMismatches was replaced by "shadow.mismatchLogging"'); } - const mismatchLogging = config.mismatchLogging; + // Own-property read: inherited groups are ignored, like everything the + // spread below copies. + const mismatchLogging = Object.hasOwn(config, "mismatchLogging") ? config.mismatchLogging : undefined; if (mismatchLogging === undefined) { return { ...config }; } diff --git a/src/dialcache.ts b/src/dialcache.ts index bbd3fad..ce10e3b 100644 --- a/src/dialcache.ts +++ b/src/dialcache.ts @@ -4,10 +4,12 @@ import { isDeepStrictEqual } from "node:util"; import { CacheLayer, DialCacheKeyConfig, + SHADOW_MISMATCH_LOGGING_LEAVES, type Awaitable, type CacheConfigProvider, type DialCacheConfig, type Logger, + type ShadowMismatchLoggingConfig, } from "./config.js"; import { DialCacheContext, getOrCreateRequestLocalCache, type RequestLocalCache } from "./context.js"; import { FallbackTimeoutError, UseCaseIsAlreadyRegisteredError, UseCaseNameIsReservedError } from "./errors.js"; @@ -42,6 +44,7 @@ import { type ResolvedLayerConfig, } from "./internal/runtime-config.js"; import { + SHADOW_LOG_DIFF_MAX_BYTES, previewShadowLogDiff, previewShadowLogJson, previewShadowLogKey, @@ -246,14 +249,14 @@ interface ShadowValidationPlan { } /** Resolved runtime content controls for one admitted shadow job's warning. */ -interface ShadowLogPlan { - readonly key: boolean; - readonly value: boolean; - readonly diff: boolean; -} +type ShadowLogPlan = Required; const SHADOW_LOG_PLAN_OFF: ShadowLogPlan = { key: false, value: false, diff: false }; +function shadowLogPlanActive(plan: ShadowLogPlan): boolean { + return Object.values(plan).some(Boolean); +} + /** Pre-rendered bounded JSON strings; raw compared values are not retained. */ interface ShadowMismatchLogDetails { readonly cachedValueJson?: string | null; @@ -860,7 +863,11 @@ export class DialCache { } const resolvedShadowConfig = shadowConfig as Record; - const shadowPercentage: unknown = resolvedShadowConfig.ramp; + // Own-property reads throughout runtime shadow config: neither admission + // nor warning content may be inherited from a prototype. + const shadowPercentage: unknown = Object.hasOwn(resolvedShadowConfig, "ramp") + ? resolvedShadowConfig.ramp + : undefined; if (shadowPercentage === undefined || shadowPercentage === 0) { return; } @@ -912,17 +919,19 @@ export class DialCache { key: DialCacheKey, shadowConfig: Record, ): ShadowLogPlan { - const configured = shadowConfig.mismatchLogging; + // A non-object group never reaches this read: the constructor and the + // runtime merge both reject malformed group shapes as config errors, like + // malformed layer maps. Only leaf values arrive unvalidated. + const configured = Object.hasOwn(shadowConfig, "mismatchLogging") + ? shadowConfig.mismatchLogging + : undefined; if (configured === undefined) { return SHADOW_LOG_PLAN_OFF; } - if (configured === null || typeof configured !== "object" || Array.isArray(configured)) { - this.recordError(key, CacheLayer.REMOTE, "config_resolution"); - return SHADOW_LOG_PLAN_OFF; - } const group = configured as Record; let sawInvalidLeaf = false; - const resolveLeaf = (leaf: unknown): boolean => { + const resolveLeaf = (name: keyof ShadowMismatchLoggingConfig): boolean => { + const leaf = Object.hasOwn(group, name) ? group[name] : undefined; if (leaf === undefined) { return false; } @@ -933,9 +942,9 @@ export class DialCache { return leaf; }; const plan: ShadowLogPlan = { - key: resolveLeaf(group.key), - value: resolveLeaf(group.value), - diff: resolveLeaf(group.diff), + key: resolveLeaf("key"), + value: resolveLeaf("value"), + diff: resolveLeaf("diff"), }; if (sawInvalidLeaf) { this.recordError(key, CacheLayer.REMOTE, "config_resolution"); @@ -1159,11 +1168,9 @@ export class DialCache { return "superseded"; } if (logPlan.value || logPlan.diff) { - try { - mismatchLogDetails = renderShadowMismatchLog(logPlan, plan, cachedValue, sourceValue); - } catch { - // Log rendering is best-effort and must not affect the outcome. - } + // Cannot throw: every hook call and preview inside fails closed + // to a null field. + mismatchLogDetails = renderShadowMismatchLog(logPlan, plan, cachedValue, sourceValue); } validatedValueAgeSeconds = shadowValueAgeSeconds(originalFrame.createdAtMs); return "mismatch"; @@ -1196,27 +1203,22 @@ export class DialCache { if (valueAgeSeconds !== undefined) { this.metrics?.observeShadowValueAge?.(labels, valueAgeSeconds); } - if (outcome !== "mismatch" || !(logPlan.key || logPlan.value || logPlan.diff)) { + if (outcome !== "mismatch" || !shadowLogPlanActive(logPlan)) { return; } - const warning = { + // Throw-free by construction: every preview fails closed to null and the + // logger is observer-isolated, so no belt-and-suspenders fallback exists. + // Built fresh rather than from `labels`, which a metrics adapter may have + // mutated after it was handed over above. + this.logger.warn("DialCache shadow validation mismatch", { cacheNamespace: key.namespace, useCase: key.useCase, keyType: key.keyType, outcome: "mismatch", - } as const; - try { - this.logger.warn("DialCache shadow validation mismatch", { - ...warning, - ...(logPlan.key ? { cacheKey: previewShadowLogKey(key.urn) } : {}), - ...mismatchLogDetails, - }); - return; - } catch { - // Warning detail construction is best-effort; preserve the metadata warning. - } - this.logger.warn("DialCache shadow validation mismatch", warning); + ...(logPlan.key ? { cacheKey: previewShadowLogKey(key.urn) } : {}), + ...mismatchLogDetails, + }); } private async resolveLocalLayerConfig( @@ -1511,7 +1513,7 @@ function snapshotDefaultConfig(config: DialCacheKeyConfig | null | undefined): D } const mismatchLogging = snapshot.shadow.mismatchLogging; if (mismatchLogging !== undefined) { - for (const leaf of ["key", "value", "diff"] as const) { + for (const leaf of SHADOW_MISMATCH_LOGGING_LEAVES) { const configured = mismatchLogging[leaf]; if (configured !== undefined && typeof configured !== "boolean") { throw new TypeError(`DialCache defaultConfig shadow.mismatchLogging.${leaf} must be a boolean`); @@ -1670,7 +1672,7 @@ function renderShadowMismatchLog( if (logPlan.diff) { if (plan.logDiff !== undefined) { try { - diffJson = previewShadowLogJson(plan.logDiff(cachedValue, sourceValue)); + diffJson = previewShadowLogJson(plan.logDiff(cachedValue, sourceValue), SHADOW_LOG_DIFF_MAX_BYTES); } catch { diffJson = null; } diff --git a/src/internal/runtime-config.ts b/src/internal/runtime-config.ts index 7152466..866f1e1 100644 --- a/src/internal/runtime-config.ts +++ b/src/internal/runtime-config.ts @@ -1,6 +1,7 @@ import { CacheLayer, DialCacheKeyConfig, + SHADOW_MISMATCH_LOGGING_LEAVES, type CacheConfigProvider, type LayerConfig, type ShadowConfig, @@ -170,8 +171,12 @@ function mergeShadowConfig( return undefined; } - const ramp = overlay?.ramp !== undefined ? overlay.ramp : defaults?.ramp; - const mismatchLogging = mergeMismatchLoggingConfig(defaults?.mismatchLogging, overlay?.mismatchLogging); + const overlayRamp = readOwn(overlay, "ramp"); + const ramp = overlayRamp !== undefined ? overlayRamp : readOwn(defaults, "ramp"); + const mismatchLogging = mergeMismatchLoggingConfig( + readOwn(defaults, "mismatchLogging"), + readOwn(overlay, "mismatchLogging"), + ); return { ...(ramp === undefined ? {} : { ramp }), @@ -190,10 +195,10 @@ function mergeMismatchLoggingConfig( return undefined; } - const merged: { -readonly [Leaf in keyof ShadowMismatchLoggingConfig]: boolean } = {}; - for (const leaf of ["key", "value", "diff"] as const) { - const overlayValue = overlay?.[leaf]; - const value = overlayValue !== undefined ? overlayValue : defaults?.[leaf]; + const merged: { -readonly [Leaf in keyof ShadowMismatchLoggingConfig]?: boolean } = {}; + for (const leaf of SHADOW_MISMATCH_LOGGING_LEAVES) { + const overlayValue = readOwn(overlay, leaf); + const value = overlayValue !== undefined ? overlayValue : readOwn(defaults, leaf); if (value !== undefined) { merged[leaf] = value; } @@ -201,6 +206,14 @@ function mergeMismatchLoggingConfig( return merged; } +// Own-property reads keep runtime shadow config immune to inherited values: +// prototype-carried leaves must never merge into an own `mismatchLogging` +// group (its failure direction is payload data reaching logs, unlike a TTL) +// and the same rule is applied to `ramp` so admission cannot be inherited. +function readOwn(source: T | undefined, key: Key): T[Key] | undefined { + return source !== undefined && Object.hasOwn(source, key) ? source[key] : undefined; +} + function assertShadowConfig(config: ShadowConfig | undefined): void { if (config !== undefined && (config === null || typeof config !== "object" || Array.isArray(config))) { throw new TypeError("DialCache shadow config must be an object"); diff --git a/src/internal/shadow-log-json.ts b/src/internal/shadow-log-json.ts index d245e7a..32e5c14 100644 --- a/src/internal/shadow-log-json.ts +++ b/src/internal/shadow-log-json.ts @@ -9,54 +9,65 @@ const UTF8_ENCODER = new TextEncoder(); const UTF8_DECODER = new TextDecoder("utf-8", { fatal: true }); const TRUNCATION_MARKER_BYTES = UTF8_ENCODER.encode(SHADOW_LOG_TRUNCATION_MARKER); -export function previewShadowLogKey(value: string): string { - return clampUtf8(value, SHADOW_LOG_KEY_MAX_BYTES); +export function previewShadowLogKey(value: string): string | null { + try { + return clampUtf8(value, SHADOW_LOG_KEY_MAX_BYTES); + } catch { + return null; + } } -export function previewShadowLogJson(value: unknown): string | null { +export function previewShadowLogJson( + value: unknown, + maxBytes: number = SHADOW_LOG_VALUE_MAX_BYTES, +): string | null { try { const json = JSON.stringify(value); - return json === undefined ? null : clampUtf8(json, SHADOW_LOG_VALUE_MAX_BYTES); + return json === undefined ? null : clampUtf8(json, maxBytes); } catch { return null; } } /** - * Bounded JSON of the structural differences between the two loggable inputs, - * oriented from the cached side to the source side: `oldValue` is cached, - * `value` is source. Plain-object and array roots diff recursively (cycle-safe); - * any other root pair collapses to one root-level change entry when the inputs - * are not identical. `[]` means the inputs held no visible difference. + * Bounded JSON of the differences between the two loggable forms, oriented + * from the cached side to the source side: `oldValue` is cached, `value` is + * source. Both inputs are first rendered to native JSON — the same forms + * `value` logging shows — so `toJSON` redaction and serializer normalization + * bound the diff exactly as they bound value logging. Identical loggable + * forms yield `[]`; roots of the same container kind diff recursively; any + * other root pair collapses to one root-level change entry. */ export function previewShadowLogDiff(cachedInput: unknown, sourceInput: unknown): string | null { try { - const entries = isDiffableRoot(cachedInput) && isDiffableRoot(sourceInput) - ? diff(cachedInput, sourceInput) - : rootDifference(cachedInput, sourceInput); - const json = JSON.stringify(entries); - return json === undefined ? null : clampUtf8(json, SHADOW_LOG_DIFF_MAX_BYTES); + const cachedJson = JSON.stringify(cachedInput); + const sourceJson = JSON.stringify(sourceInput); + if (cachedJson === sourceJson) { + return "[]"; + } + const cachedLoggable: unknown = cachedJson === undefined ? null : JSON.parse(cachedJson); + const sourceLoggable: unknown = sourceJson === undefined ? null : JSON.parse(sourceJson); + const entries = isSameContainerKind(cachedLoggable, sourceLoggable) + ? diff( + cachedLoggable as Record | unknown[], + sourceLoggable as Record | unknown[], + ) + : rootDifference(cachedLoggable, sourceLoggable); + return previewShadowLogJson(entries, SHADOW_LOG_DIFF_MAX_BYTES); } catch { return null; } } -function isDiffableRoot(value: unknown): value is Record | unknown[] { - if (Array.isArray(value)) { - return true; - } - if (value === null || typeof value !== "object") { - return false; +function isSameContainerKind(cached: unknown, source: unknown): boolean { + if (Array.isArray(cached) || Array.isArray(source)) { + return Array.isArray(cached) && Array.isArray(source); } - const proto: unknown = Object.getPrototypeOf(value); - return proto === Object.prototype || proto === null; + return typeof cached === "object" && cached !== null && typeof source === "object" && source !== null; } -function rootDifference(cachedInput: unknown, sourceInput: unknown): Difference[] { - if (Object.is(cachedInput, sourceInput)) { - return []; - } - return [{ type: "CHANGE", path: [], value: sourceInput, oldValue: cachedInput }]; +function rootDifference(cachedLoggable: unknown, sourceLoggable: unknown): Difference[] { + return [{ type: "CHANGE", path: [], value: sourceLoggable, oldValue: cachedLoggable }]; } function clampUtf8(value: string, maxBytes: number): string { diff --git a/test/dialcache-config-ramp.test.ts b/test/dialcache-config-ramp.test.ts index 322a9c3..bf9843d 100644 --- a/test/dialcache-config-ramp.test.ts +++ b/test/dialcache-config-ramp.test.ts @@ -500,6 +500,8 @@ describe("DialCache runtime config and ramp controls", () => { ["a null layer map", { ttlSec: null, ramp: {} }], ["an array shadow config", { ttlSec: {}, ramp: {}, shadow: [] }], ["the removed shadowRamp field", { ttlSec: {}, ramp: {}, shadowRamp: 100 }], + ["the removed shadow logMismatches field", { ttlSec: {}, ramp: {}, shadow: { logMismatches: true } }], + ["a non-object shadow mismatchLogging group", { ttlSec: {}, ramp: {}, shadow: { mismatchLogging: null } }], ["a null requestLocal value", { ttlSec: {}, ramp: {}, requestLocal: null }], ["a null coalesce value", { ttlSec: {}, ramp: {}, coalesce: null }], ] as const)("fails open instead of inheriting defaults when the provider returns %s", async (_name, runtimeConfig) => { diff --git a/test/dialcache-observability-internals.test.ts b/test/dialcache-observability-internals.test.ts index 5df3111..8713bbf 100644 --- a/test/dialcache-observability-internals.test.ts +++ b/test/dialcache-observability-internals.test.ts @@ -80,6 +80,22 @@ describe("DialCache observability internal compatibility paths", () => { } }); + it("merges only own mismatch logging leaves, ignoring prototype-carried values", async () => { + const defaultConfig = new DialCacheKeyConfig({ + ttlSec: { [CacheLayer.LOCAL]: 60 }, + ramp: { [CacheLayer.LOCAL]: 100 }, + shadow: { ramp: 20 }, + }); + const runtime = { + shadow: { mismatchLogging: Object.create({ value: true }) as { value?: boolean } }, + } as DialCacheKeyConfig; + + const merged = await fetchKeyConfig(async () => runtime, key(defaultConfig)); + + expect(merged?.shadow?.mismatchLogging).toEqual({}); + expect(Object.hasOwn(merged?.shadow?.mismatchLogging ?? {}, "value")).toBe(false); + }); + it("preserves omitted requestLocal and coalesce through a runtime merge", async () => { // The gates own the effective defaults, so the merge must not materialize // either boolean when both sides omit it. diff --git a/test/dialcache-shadow-confirmation.test.ts b/test/dialcache-shadow-confirmation.test.ts index 6ff9804..5a85e2e 100644 --- a/test/dialcache-shadow-confirmation.test.ts +++ b/test/dialcache-shadow-confirmation.test.ts @@ -421,7 +421,7 @@ describe("DialCache Redis shadow confirmation", () => { expect(serializer.dump).not.toHaveBeenCalled(); }); - it("falls back to a metadata warning when JSON detail construction throws", async () => { + it("fails closed per field when preview encoding fails", async () => { const cachedValue = { id: "123", version: 1 }; const sourceValue = { id: "123", version: 2 }; const payload = JSON.stringify(cachedValue); @@ -450,8 +450,8 @@ describe("DialCache Redis shadow confirmation", () => { await dialcache.enable(async () => await getUser()); await sourceStarted.promise; - // A persistent throw nulls both value previews at render time and then - // fails the key preview inside warning assembly, forcing the metadata path. + // A persistent throw nulls both value previews at render time and the key + // preview at emit time; the warning still emits with every field null. const encodeInto = vi.spyOn(TextEncoder.prototype, "encodeInto").mockImplementation(() => { throw new Error("preview unavailable"); }); @@ -468,6 +468,9 @@ describe("DialCache Redis shadow confirmation", () => { useCase: "ShadowMismatchJsonFailure", keyType: "user_id", outcome: "mismatch", + cacheKey: null, + cachedValueJson: null, + sourceValueJson: null, }, ); } finally { @@ -896,6 +899,90 @@ describe("DialCache Redis shadow confirmation", () => { expect(warn).not.toHaveBeenCalled(); }); + it("projects values while the diff hook receives raw values when both are enabled", async () => { + const useCase = "ShadowMismatchBothHooks"; + const payload = JSON.stringify({ id: "123", version: 1, secret: "cached-secret" }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const projector = vi.fn( + (value: { version: number }) => ({ version: value.version }), + ); + const logDiff = vi.fn( + (cached: { version: number }, source: { version: number }) => + ({ from: cached.version, to: source.version }), + ); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached( + async () => ({ id: "123", version: 2, secret: "source-secret" }), + { + ...trackedOptions(useCase, remoteConfig(100, 100, { value: true, diff: true })), + cacheKey: () => "123", + shadowMismatchLogValue: projector, + shadowMismatchLogDiff: logDiff, + }, + ); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + + expect(projector).toHaveBeenCalledTimes(2); + expect(logDiff).toHaveBeenCalledTimes(1); + expect(logDiff).toHaveBeenCalledWith( + { id: "123", version: 1, secret: "cached-secret" }, + { id: "123", version: 2, secret: "source-secret" }, + ); + expect(warn).toHaveBeenCalledTimes(1); + const warning = warn.mock.calls[0]?.[1] as Record; + expect(warning.cachedValueJson).toBe('{"version":1}'); + expect(warning.sourceValueJson).toBe('{"version":2}'); + expect(warning.cachedValueJson).not.toContain("secret"); + expect(warning.sourceValueJson).not.toContain("secret"); + expect(warning.diffJson).toBe('{"from":1,"to":2}'); + }); + + it("ignores prototype-inherited mismatch logging fields", async () => { + const useCase = "ShadowMismatchPollutedPrototype"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true })), + cacheKey: () => "123", + }); + + // Pollute only around admission (the logging plan resolves synchronously + // inside enable); wider pollution breaks vitest's own descriptor use. + (Object.prototype as Record).value = true; + (Object.prototype as Record).diff = true; + try { + await dialcache.enable(async () => await getUser()); + } finally { + delete (Object.prototype as Record).value; + delete (Object.prototype as Record).diff; + } + await waitForShadowEvents(metrics, 1); + + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch"]); + expect(warn).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cacheKey: `{urn:user_id:123}#${useCase}`, + }, + ); + }); + it("logs a null diff when shadowMismatchLogDiff throws", async () => { const useCase = "ShadowMismatchCustomDiffThrow"; const payload = JSON.stringify({ id: "123", version: 1 }); diff --git a/test/shadow-log-json.test.ts b/test/shadow-log-json.test.ts index 1312a00..00aeca3 100644 --- a/test/shadow-log-json.test.ts +++ b/test/shadow-log-json.test.ts @@ -37,16 +37,25 @@ describe("shadow mismatch log JSON", () => { expect(previewShadowLogJson(value)).toBeNull(); }); + it("honors an explicit byte budget", () => { + const preview = previewShadowLogJson({ text: "a".repeat(200) }, 64); + + expect(preview).not.toBeNull(); + expect(Buffer.byteLength(preview!)).toBeLessThanOrEqual(64); + expect(preview!.endsWith(SHADOW_LOG_TRUNCATION_MARKER)).toBe(true); + }); + it("byte-clamps keys and JSON without splitting UTF-8 sequences", () => { const key = `${"k".repeat(SHADOW_LOG_KEY_MAX_BYTES)}🙂`; const value = { text: "🙂".repeat(SHADOW_LOG_VALUE_MAX_BYTES) }; const keyPreview = previewShadowLogKey(key); const valuePreview = previewShadowLogJson(value); + expect(keyPreview).not.toBeNull(); expect(valuePreview).not.toBeNull(); - expect(Buffer.byteLength(keyPreview)).toBeLessThanOrEqual(SHADOW_LOG_KEY_MAX_BYTES); + expect(Buffer.byteLength(keyPreview!)).toBeLessThanOrEqual(SHADOW_LOG_KEY_MAX_BYTES); expect(Buffer.byteLength(valuePreview!)).toBeLessThanOrEqual(SHADOW_LOG_VALUE_MAX_BYTES); - expect(keyPreview.endsWith(SHADOW_LOG_TRUNCATION_MARKER)).toBe(true); + expect(keyPreview!.endsWith(SHADOW_LOG_TRUNCATION_MARKER)).toBe(true); expect(valuePreview!.endsWith(SHADOW_LOG_TRUNCATION_MARKER)).toBe(true); expect(keyPreview).not.toContain("�"); expect(valuePreview).not.toContain("�"); @@ -70,6 +79,41 @@ describe("shadow mismatch log JSON", () => { ]); }); + it("diffs the loggable forms, so toJSON redaction bounds the diff like value logging", () => { + class User { + constructor( + readonly id: number, + readonly apiKey: string, + ) {} + + toJSON(): { id: number } { + return { id: this.id }; + } + } + // Runtime shape: the cached side is deserialized JSON, the source is live. + const cached = { user: { id: 1 } }; + + expect(previewShadowLogDiff(cached, { user: new User(1, "SECRET-TOKEN") })).toBe("[]"); + const changed = previewShadowLogDiff(cached, { user: new User(2, "SECRET-TOKEN") }); + expect(changed).not.toContain("SECRET-TOKEN"); + expect(JSON.parse(changed!)).toEqual([ + { type: "CHANGE", path: ["user", "id"], value: 2, oldValue: 1 }, + ]); + }); + + it("does not emit phantom entries for serializer-normalized fields", () => { + // Runtime shape: the cached Date arrived as its ISO string; the live + // source still holds a Date for the same instant. + const diffJson = previewShadowLogDiff( + { updatedAt: "2026-07-31T00:00:00.000Z", n: 1 }, + { updatedAt: new Date("2026-07-31T00:00:00.000Z"), n: 2 }, + ); + + expect(JSON.parse(diffJson!)).toEqual([ + { type: "CHANGE", path: ["n"], value: 2, oldValue: 1 }, + ]); + }); + it("renders nested Date leaves as ISO strings in diff entries", () => { expect(JSON.parse(previewShadowLogDiff( { updatedAt: new Date("2026-07-31T00:00:00.000Z") }, @@ -94,12 +138,15 @@ describe("shadow mismatch log JSON", () => { ]); }); - it("returns an empty diff for equal inputs", () => { + it("returns an empty diff for identical loggable forms", () => { expect(previewShadowLogDiff({ id: "123" }, { id: "123" })).toBe("[]"); expect(previewShadowLogDiff("same", "same")).toBe("[]"); + // A Map renders as {} on both sides; the emptiness matches what value + // logging would show for the same inputs. + expect(previewShadowLogDiff({ m: {} }, { m: new Map([["k", 1]]) })).toBe("[]"); }); - it("collapses non-plain-object roots to one root-level change entry", () => { + it("collapses non-container and mixed-kind roots to one root-level change entry", () => { expect(JSON.parse(previewShadowLogDiff("cached", "source")!)).toEqual([ { type: "CHANGE", path: [], value: "source", oldValue: "cached" }, ]); @@ -117,6 +164,12 @@ describe("shadow mismatch log JSON", () => { oldValue: "2026-07-31T00:00:00.000Z", }, ]); + expect(JSON.parse(previewShadowLogDiff({ a: 1, b: 2 }, [1, 2])!)).toEqual([ + { type: "CHANGE", path: [], value: [1, 2], oldValue: { a: 1, b: 2 } }, + ]); + expect(JSON.parse(previewShadowLogDiff({}, [])!)).toEqual([ + { type: "CHANGE", path: [], value: [], oldValue: {} }, + ]); }); it("fails closed to null for cyclic inputs instead of throwing", () => { @@ -125,8 +178,7 @@ describe("shadow mismatch log JSON", () => { const source: { id: string; self?: unknown } = { id: "source" }; source.self = source; - // The traversal is cycle-safe, but the resulting entries reference the - // cyclic structures, so JSON rendering fails closed to null. + // The loggable-form rendering throws on cycles before any diffing. expect(previewShadowLogDiff(cached, source)).toBeNull(); }); From 09dac5b2d3b34520b43bc7dd49c745f69248cc92 Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Fri, 14 Aug 2026 22:34:58 -0700 Subject: [PATCH 4/9] fix(shadow): own-read config boundaries, fail-closed unknown leaves, and render-once own-key diff Review fixes for PR #138: - The shadow group itself is now an own-property read at the constructor, defaults-snapshot, and runtime-merge boundaries, so a prototype-inherited group can no longer activate logging policy (its leaves are own properties and passed every inner gate). - Unknown mismatchLogging fields fail closed: defaults reject them at registration, and a runtime override carrying one (a typo'd emergency shutoff like `vaule: false`) turns the whole logging group off with one config_resolution error instead of silently inheriting enabled leaves. The merge carries unknown own keys through so admission can see them. - Mismatch warnings render each side to native JSON exactly once and derive the value fields and the built-in diff from the same snapshot, so a stateful toJSON cannot put data in diffJson that value logging redacts. A side with no JSON rendering (top-level undefined, cycles, bigint, a thrown hook or projection) fails the diff closed to null instead of emitting a self-contradictory root entry. - The built-in diff is now a small own-key differ over the parsed JSON snapshots, replacing microdiff: prototype-carried data (enumerable Object.prototype or Array.prototype pollution) can never reach diffJson, and the microdiff runtime dependency is removed. Entry format, orientation, and array index-wise semantics are unchanged and remain pinned by tests. --- README.md | 6 +- package.json | 3 +- pnpm-lock.yaml | 8 - src/config.ts | 5 +- src/dialcache.ts | 77 ++++---- src/internal/runtime-config.ts | 27 ++- src/internal/shadow-log-json.ts | 166 +++++++++++++++--- test/dialcache-config-ramp.test.ts | 17 ++ .../dialcache-observability-internals.test.ts | 26 +++ test/dialcache-shadow-confirmation.test.ts | 35 ++++ test/shadow-log-json.test.ts | 124 +++++++++++-- 11 files changed, 393 insertions(+), 101 deletions(-) diff --git a/README.md b/README.md index 17babca..e7b4c60 100644 --- a/README.md +++ b/README.md @@ -221,13 +221,13 @@ The disabled baseline sets `requestLocal` to false, leaves the process-local and A provider result of `null` (or defensive `undefined`) applies no overrides. An empty `DialCacheKeyConfig` and omitted runtime fields also inherit the baseline. Top-level fields, cache-layer leaves, leaves inside `shadow`, and leaves inside `shadow.mismatchLogging` merge independently; an explicit `false` logging leaf overrides an inherited `true`. Use explicit values to override inherited policy: `requestLocal: false` disables request-local caching and a layer ramp of `0` disables that shared layer. `DialCacheKeyConfig.disabled()` is the complete new-cache-invocation kill switch in one call: request-local and shadow work off, shadow logging off, and both shared layers ramped to 0. It leaves `coalesce` unset: with every layer off there is no in-flight sharing to disable, and a use case ramped back up at runtime coalesces again unless it explicitly opts out. It does not cancel already-admitted work, and explicit maintenance operations such as `invalidateRemote()` remain available. To stop new cache-invocation Redis reads and fills while preserving other runtime settings, explicitly set both `ramp.remote` and `shadow.ramp` to `0`; the remote ramp alone stops serving but does not override an inherited nonzero shadow ramp. -DialCache validates `defaultConfig` when `cached()` registers a definition and whenever `getOrLoad()` is invoked: TTLs must be positive safe integers no greater than 31,536,000 seconds (a fixed 365-day duration), remote-read deadlines must be positive safe integers within their documented limit, layer and shadow ramps must be finite percentages from 0 to 100, layer maps, `shadow`, and `shadow.mismatchLogging` must be objects, and `requestLocal`, `coalesce`, and the `shadow.mismatchLogging` fields must be booleans when present. Invalid defaults are rejected immediately. +DialCache validates `defaultConfig` when `cached()` registers a definition and whenever `getOrLoad()` is invoked: TTLs must be positive safe integers no greater than 31,536,000 seconds (a fixed 365-day duration), remote-read deadlines must be positive safe integers within their documented limit, layer and shadow ramps must be finite percentages from 0 to 100, layer maps, `shadow`, and `shadow.mismatchLogging` must be objects, `requestLocal`, `coalesce`, and the `shadow.mismatchLogging` fields must be booleans when present, and `shadow.mismatchLogging` may not carry unknown fields. Invalid defaults are rejected immediately. Each registration or one-shot invocation captures an immutable internal snapshot of `defaultConfig`; mutating the supplied config or its maps later does not change that operation's baseline. Runtime policy changes belong in the provider's returned overlay. Runtime TTL and ramp leaves are used as supplied instead of falling back to valid default leaves. A TTL outside the same 1-to-31,536,000-second range disables that layer with `invalid_ttl`; a nonnumeric, non-finite, or out-of-range ramp disables it with `invalid_ramp`. Valid ramps include both `0` and `100`. Other layers can still run, and invalid leaves also record a `config_resolution` error so provider garbage is alertable separately from intentional ramp-downs. A malformed runtime config object, layer-map shape, `requestLocal` value, `coalesce` value, explicit `remoteReadTimeoutMs`, non-object `shadow.mismatchLogging` group, removed top-level `shadowRamp`, or removed `shadow.logMismatches` fails config resolution for the invocation, records `config_error`, and executes the fallback uncached without attempting Redis. The public `DialCacheKeyConfig` constructor and static defaults likewise reject both removed fields immediately; migrate `shadowRamp` to `shadow.ramp` and `shadow.logMismatches` to `shadow.mismatchLogging`. -An invalid runtime `shadow.ramp` does not affect the cache result or disable an otherwise valid Redis policy. If normal traversal reaches an otherwise shadow-eligible Redis path, DialCache skips shadow work and records a `config_resolution` error. An invalid runtime `shadow.mismatchLogging` field likewise preserves the cache result, Redis policy, shadow result, and shadow metric; an invalid field acts false while valid sibling fields still log. DialCache validates these diagnostic leaves only after the metrics hook, exact-key cohort, and capacity gates admit shadow work, then records one remote `config_resolution` error for that admitted resolution. A non-object `mismatchLogging` group is malformed config shape rather than an invalid field: like a malformed layer map, it fails resolution as `config_error` and the invocation runs uncached. Runtime shadow config is read by own properties only; prototype-inherited `ramp` or logging fields are ignored. +An invalid runtime `shadow.ramp` does not affect the cache result or disable an otherwise valid Redis policy. If normal traversal reaches an otherwise shadow-eligible Redis path, DialCache skips shadow work and records a `config_resolution` error. An invalid runtime `shadow.mismatchLogging` field likewise preserves the cache result, Redis policy, shadow result, and shadow metric; an invalid field acts false while valid sibling fields still log, and an unknown field fails the whole logging group closed instead — a typo'd override never silently inherits enabled leaves. DialCache validates these diagnostic leaves only after the metrics hook, exact-key cohort, and capacity gates admit shadow work, then records one remote `config_resolution` error for that admitted resolution. A non-object `mismatchLogging` group is malformed config shape rather than an invalid field: like a malformed layer map, it fails resolution as `config_error` and the invocation runs uncached. The `shadow` group and everything inside it are read by own properties only, at the constructor, defaults-snapshot, and runtime-merge boundaries alike; prototype-inherited policy never activates. `cacheConfigProvider` is called for every enabled cache invocation before DialCache performs any cache lookup. Keep it cheap, cache any remote/config-store reads inside the provider, and avoid work that would erase the benefit of a cache hit. @@ -602,7 +602,7 @@ Confirmed-mismatch logging is separately opt-in through the `shadow.mismatchLogg A byte-clipped field ends in `...[truncated]`, counted inside its cap. Every hook invocation and JSON step fails closed: a projector throw logs `null` for that side (and a `null` built-in diff), a diff-hook throw or unserializable diff logs `diffJson: null`, and native-JSON failure on one side leaves the other side attempted. DialCache never calls the configured serializer again for logging. -The built-in diff first renders both sides to native JSON — the same loggable forms `value: true` shows — so `toJSON` redaction and serializer normalization bound the diff exactly as they bound value logging, and a cached side deserialized to an ISO string never phantom-differs from a live source `Date` at the same instant. Identical loggable forms yield `[]`; with a projector that reads as "the difference is inside fields the projection hides", and structures native JSON flattens (a `Map` renders as `{}`) read the same way. Otherwise the [microdiff](https://github.com/AsyncBanana/microdiff) library emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. Loggable roots of the same container kind (both objects or both arrays) diff recursively, with array entries compared by index, so an element shift reports every later index; any other root pair — primitives, `null`, or mixed object/array kinds — collapses to one root-level change entry. Cyclic inputs fail closed to a `null` diff. The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures native JSON flattens. +The built-in diff renders each side to native JSON exactly once per warning — the same loggable forms `value: true` shows — and derives both the value fields and the diff from those single snapshots, so `toJSON` redaction and serializer normalization bound the diff exactly as they bound value logging, a stateful `toJSON` cannot make the two outputs disagree, and a cached side deserialized to an ISO string never phantom-differs from a live source `Date` at the same instant. A side with no JSON rendering — top-level `undefined`, cycles, `bigint`, a thrown hook, or a failed projection — fails the diff closed to `null`; the diff never attests anything about inputs value logging cannot show. Identical loggable snapshots yield `[]`; with a projector that reads as "the difference is inside fields the projection hides", and structures native JSON flattens (a `Map` renders as `{}`) read the same way. Otherwise DialCache's own bounded differ emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. It walks only own enumerable keys and array indices of the parsed JSON forms, so prototype-carried data can never reach `diffJson`. Nodes of the same container kind (both objects or both arrays) diff recursively, with array entries compared by index, so an element shift reports every later index; a pair of differing kinds — primitives, `null`, or mixed object/array — collapses to one change entry at its path, including the root. The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures native JSON flattens. Both hooks run only after terminal mismatch confirmation, inside detached shadow work, under the comparator's discipline: synchronous, deterministic, side-effect-free, non-mutating, and bounded, over borrowed references. Hook output feeds `JSON.stringify` directly. diff --git a/package.json b/package.json index d1bd5cf..9a5fc01 100644 --- a/package.json +++ b/package.json @@ -98,8 +98,7 @@ }, "dependencies": { "@types/node": "^24.10.1", - "lru-cache": "^11.5.2", - "microdiff": "^1.6.0" + "lru-cache": "^11.5.2" }, "devDependencies": { "@valkey/valkey-glide": "2.0.0", diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index d7b4bc1..47b5450 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -18,9 +18,6 @@ importers: lru-cache: specifier: ^11.5.2 version: 11.5.2 - microdiff: - specifier: ^1.6.0 - version: 1.6.0 devDependencies: '@valkey/valkey-glide': specifier: 2.0.0 @@ -1196,9 +1193,6 @@ packages: resolution: {integrity: sha512-hXdUTZYIVOt1Ex//jAQi+wTZZpUpwBj/0QsOzqegb3rGMMeJiSEu5xLHnYfBrRV4RH2+OCSOO95Is/7x1WJ4bw==} engines: {node: '>=10'} - microdiff@1.6.0: - resolution: {integrity: sha512-w7JWt8Bno6I8h0rEqlxr4lNG4UbT1FVtWo42wWosIiaJ+rP3pXh7shCYDnyqBrYx36LJ1CZ64p8A62aVp0sJpQ==} - minimatch@5.1.9: resolution: {integrity: sha512-7o1wEA2RyMP7Iu7GNba9vc0RWWGACJOCZBJX2GJWip0ikV+wcOsgVuY9uE8CPiyQhkGFSlhuSkZPavN7u1c2Fw==} engines: {node: '>=10'} @@ -2635,8 +2629,6 @@ snapshots: dependencies: semver: 7.8.5 - microdiff@1.6.0: {} - minimatch@5.1.9: dependencies: brace-expansion: 5.0.8 diff --git a/src/config.ts b/src/config.ts index 2e7272f..1488a21 100644 --- a/src/config.ts +++ b/src/config.ts @@ -94,7 +94,10 @@ export class DialCacheKeyConfig { } this.ttlSec = cloneLayerConfig(config.ttlSec, "ttlSec"); this.ramp = cloneLayerConfig(config.ramp, "ramp"); - const shadow = cloneShadowConfig(config.shadow); + // Own-property read: `shadow` carries the log-content controls, so a + // prototype-inherited group must not activate policy (its leaves would + // all be own properties and pass every later gate). + const shadow = cloneShadowConfig(Object.hasOwn(config, "shadow") ? config.shadow : undefined); if (shadow !== undefined) { this.shadow = shadow; } diff --git a/src/dialcache.ts b/src/dialcache.ts index ce10e3b..9214a13 100644 --- a/src/dialcache.ts +++ b/src/dialcache.ts @@ -45,9 +45,10 @@ import { } from "./internal/runtime-config.js"; import { SHADOW_LOG_DIFF_MAX_BYTES, - previewShadowLogDiff, previewShadowLogJson, previewShadowLogKey, + renderShadowMismatchJson, + type ShadowMismatchLogFields, } from "./internal/shadow-log-json.js"; type CacheKeyArgs = Record; @@ -257,13 +258,6 @@ function shadowLogPlanActive(plan: ShadowLogPlan): boolean { return Object.values(plan).some(Boolean); } -/** Pre-rendered bounded JSON strings; raw compared values are not retained. */ -interface ShadowMismatchLogDetails { - readonly cachedValueJson?: string | null; - readonly sourceValueJson?: string | null; - readonly diffJson?: string | null; -} - type ShadowValidationStart = | { readonly kind: "retained"; readonly frame: DecodedRedisFrame } | { @@ -929,6 +923,15 @@ export class DialCache { return SHADOW_LOG_PLAN_OFF; } const group = configured as Record; + for (const name of Object.keys(group)) { + if (!(SHADOW_MISMATCH_LOGGING_LEAVES as readonly string[]).includes(name)) { + // Fail the whole group closed: a typo'd runtime override must not + // silently inherit enabled leaves whose failure direction is payload + // data reaching logs. One error, logging off, cache untouched. + this.recordError(key, CacheLayer.REMOTE, "config_resolution"); + return SHADOW_LOG_PLAN_OFF; + } + } let sawInvalidLeaf = false; const resolveLeaf = (name: keyof ShadowMismatchLoggingConfig): boolean => { const leaf = Object.hasOwn(group, name) ? group[name] : undefined; @@ -1031,7 +1034,7 @@ export class DialCache { }; const elapsedBeforeStartMs = Math.max(performance.now() - deadlineStartedAtMs, 0); const remainingTimeoutMs = Math.max(plan.timeoutMs - elapsedBeforeStartMs, 0); - let mismatchLogDetails: ShadowMismatchLogDetails | undefined; + let mismatchLogDetails: ShadowMismatchLogFields | undefined; let validatedValueAgeSeconds: number | undefined; const validation = withMonotonicDeadline({ @@ -1190,7 +1193,7 @@ export class DialCache { key: DialCacheKey, outcome: ShadowValidationOutcome, logPlan: ShadowLogPlan = SHADOW_LOG_PLAN_OFF, - mismatchLogDetails?: ShadowMismatchLogDetails, + mismatchLogDetails?: ShadowMismatchLogFields, valueAgeSeconds?: number, ): void { const labels = { @@ -1454,7 +1457,9 @@ function snapshotDefaultConfig(config: DialCacheKeyConfig | null | undefined): D } const ttlSecConfig = config.ttlSec; const rampConfig = config.ramp; - const shadowConfig = config.shadow; + // Own-property read, mirroring the constructor: an inherited shadow group + // must not activate log-content policy. + const shadowConfig = Object.hasOwn(config, "shadow") ? config.shadow : undefined; const requestLocal = config.requestLocal; const coalesce = config.coalesce; const remoteReadTimeoutMs = config.remoteReadTimeoutMs; @@ -1519,6 +1524,13 @@ function snapshotDefaultConfig(config: DialCacheKeyConfig | null | undefined): D throw new TypeError(`DialCache defaultConfig shadow.mismatchLogging.${leaf} must be a boolean`); } } + // Defaults are the strict tier: a typo'd field fails at registration + // instead of silently inheriting or disabling logging at runtime. + for (const name of Object.keys(mismatchLogging)) { + if (!(SHADOW_MISMATCH_LOGGING_LEAVES as readonly string[]).includes(name)) { + throw new TypeError(`DialCache defaultConfig shadow.mismatchLogging has unknown field "${name}"`); + } + } } } @@ -1648,13 +1660,13 @@ function renderShadowMismatchLog( plan: ShadowValidationPlan, cachedValue: Value, sourceValue: Value, -): ShadowMismatchLogDetails { +): ShadowMismatchLogFields { let cachedLoggable: unknown = cachedValue; let sourceLoggable: unknown = sourceValue; let cachedLoggableOk = true; let sourceLoggableOk = true; - const needsProjection = plan.logValue !== undefined - && (logPlan.value || (logPlan.diff && plan.logDiff === undefined)); + const includeBuiltInDiff = logPlan.diff && plan.logDiff === undefined; + const needsProjection = plan.logValue !== undefined && (logPlan.value || includeBuiltInDiff); if (needsProjection && plan.logValue !== undefined) { try { cachedLoggable = plan.logValue(cachedValue); @@ -1668,30 +1680,23 @@ function renderShadowMismatchLog( } } - let diffJson: string | null | undefined; - if (logPlan.diff) { - if (plan.logDiff !== undefined) { - try { - diffJson = previewShadowLogJson(plan.logDiff(cachedValue, sourceValue), SHADOW_LOG_DIFF_MAX_BYTES); - } catch { - diffJson = null; - } - } else { - diffJson = cachedLoggableOk && sourceLoggableOk - ? previewShadowLogDiff(cachedLoggable, sourceLoggable) - : null; + const rendered: ShadowMismatchLogFields = logPlan.value || includeBuiltInDiff + ? renderShadowMismatchJson( + { available: cachedLoggableOk, value: cachedLoggable }, + { available: sourceLoggableOk, value: sourceLoggable }, + { value: logPlan.value, diff: includeBuiltInDiff }, + ) + : {}; + if (logPlan.diff && plan.logDiff !== undefined) { + let diffJson: string | null; + try { + diffJson = previewShadowLogJson(plan.logDiff(cachedValue, sourceValue), SHADOW_LOG_DIFF_MAX_BYTES); + } catch { + diffJson = null; } + return { ...rendered, diffJson }; } - - return { - ...(logPlan.value - ? { - cachedValueJson: cachedLoggableOk ? previewShadowLogJson(cachedLoggable) : null, - sourceValueJson: sourceLoggableOk ? previewShadowLogJson(sourceLoggable) : null, - } - : {}), - ...(diffJson === undefined ? {} : { diffJson }), - }; + return rendered; } // Frame stamps are epoch-based (Redis server time for tracked writes, writer diff --git a/src/internal/runtime-config.ts b/src/internal/runtime-config.ts index 866f1e1..f894191 100644 --- a/src/internal/runtime-config.ts +++ b/src/internal/runtime-config.ts @@ -114,7 +114,10 @@ function mergeKeyConfig( const remoteReadTimeoutMs = overlay?.remoteReadTimeoutMs !== undefined ? overlay.remoteReadTimeoutMs : defaultConfig?.remoteReadTimeoutMs; - const shadow = mergeShadowConfig(defaultConfig?.shadow, overlay?.shadow); + const shadow = mergeShadowConfig( + readOwn(defaultConfig ?? undefined, "shadow"), + readOwn(overlay, "shadow"), + ); return new DialCacheKeyConfig({ ttlSec: mergeLayerConfig(defaultConfig?.ttlSec, overlay?.ttlSec, "ttlSec"), @@ -195,7 +198,25 @@ function mergeMismatchLoggingConfig( return undefined; } - const merged: { -readonly [Leaf in keyof ShadowMismatchLoggingConfig]?: boolean } = {}; + // Unknown own keys survive the merge so admission can fail the whole group + // closed and record a config_resolution error. Rebuilding from known leaves + // alone would silently drop a typo'd override (e.g. `vaule: false`) while + // the inherited enabled leaves kept logging payload data. + const merged: Record = {}; + for (const source of [defaults, overlay]) { + if (source === undefined) { + continue; + } + for (const name of Object.keys(source)) { + if ((SHADOW_MISMATCH_LOGGING_LEAVES as readonly string[]).includes(name)) { + continue; + } + const value = (source as Record)[name]; + if (value !== undefined) { + merged[name] = value; + } + } + } for (const leaf of SHADOW_MISMATCH_LOGGING_LEAVES) { const overlayValue = readOwn(overlay, leaf); const value = overlayValue !== undefined ? overlayValue : readOwn(defaults, leaf); @@ -203,7 +224,7 @@ function mergeMismatchLoggingConfig( merged[leaf] = value; } } - return merged; + return merged as ShadowMismatchLoggingConfig; } // Own-property reads keep runtime shadow config immune to inherited values: diff --git a/src/internal/shadow-log-json.ts b/src/internal/shadow-log-json.ts index 32e5c14..5f88799 100644 --- a/src/internal/shadow-log-json.ts +++ b/src/internal/shadow-log-json.ts @@ -1,5 +1,3 @@ -import diff, { type Difference } from "microdiff"; - export const SHADOW_LOG_KEY_MAX_BYTES = 2 * 1024; export const SHADOW_LOG_VALUE_MAX_BYTES = 8 * 1024; export const SHADOW_LOG_DIFF_MAX_BYTES = 8 * 1024; @@ -9,6 +7,39 @@ const UTF8_ENCODER = new TextEncoder(); const UTF8_DECODER = new TextDecoder("utf-8", { fatal: true }); const TRUNCATION_MARKER_BYTES = UTF8_ENCODER.encode(SHADOW_LOG_TRUNCATION_MARKER); +/** One loggable side of a confirmed mismatch; unavailable when its projection failed. */ +export interface ShadowLoggableSide { + readonly available: boolean; + readonly value?: unknown; +} + +export interface ShadowMismatchLogFields { + readonly cachedValueJson?: string | null; + readonly sourceValueJson?: string | null; + readonly diffJson?: string | null; +} + +export interface ShadowLogDifferenceCreate { + readonly type: "CREATE"; + readonly path: readonly (string | number)[]; + readonly value: unknown; +} +export interface ShadowLogDifferenceRemove { + readonly type: "REMOVE"; + readonly path: readonly (string | number)[]; + readonly oldValue: unknown; +} +export interface ShadowLogDifferenceChange { + readonly type: "CHANGE"; + readonly path: readonly (string | number)[]; + readonly value: unknown; + readonly oldValue: unknown; +} +export type ShadowLogDifference = + | ShadowLogDifferenceCreate + | ShadowLogDifferenceRemove + | ShadowLogDifferenceChange; + export function previewShadowLogKey(value: string): string | null { try { return clampUtf8(value, SHADOW_LOG_KEY_MAX_BYTES); @@ -30,44 +61,121 @@ export function previewShadowLogJson( } /** - * Bounded JSON of the differences between the two loggable forms, oriented - * from the cached side to the source side: `oldValue` is cached, `value` is - * source. Both inputs are first rendered to native JSON — the same forms - * `value` logging shows — so `toJSON` redaction and serializer normalization - * bound the diff exactly as they bound value logging. Identical loggable - * forms yield `[]`; roots of the same container kind diff recursively; any - * other root pair collapses to one root-level change entry. + * Renders both loggable sides to native JSON exactly once and derives every + * requested built-in warning field from those two snapshots, so `toJSON` + * hooks run once per side and the diff provably compares the same forms that + * value logging shows. An unavailable or unrenderable side yields `null` for + * its value field and a `null` diff; equal snapshots yield `"[]"`. */ -export function previewShadowLogDiff(cachedInput: unknown, sourceInput: unknown): string | null { +export function renderShadowMismatchJson( + cached: ShadowLoggableSide, + source: ShadowLoggableSide, + include: { readonly value: boolean; readonly diff: boolean }, +): ShadowMismatchLogFields { + const cachedJson = renderLoggableJson(cached); + const sourceJson = renderLoggableJson(source); + return { + ...(include.value + ? { + cachedValueJson: cachedJson === null ? null : clampJson(cachedJson, SHADOW_LOG_VALUE_MAX_BYTES), + sourceValueJson: sourceJson === null ? null : clampJson(sourceJson, SHADOW_LOG_VALUE_MAX_BYTES), + } + : {}), + ...(include.diff ? { diffJson: builtInDiffJson(cachedJson, sourceJson) } : {}), + }; +} + +function renderLoggableJson(side: ShadowLoggableSide): string | null { + if (!side.available) { + return null; + } try { - const cachedJson = JSON.stringify(cachedInput); - const sourceJson = JSON.stringify(sourceInput); - if (cachedJson === sourceJson) { - return "[]"; - } - const cachedLoggable: unknown = cachedJson === undefined ? null : JSON.parse(cachedJson); - const sourceLoggable: unknown = sourceJson === undefined ? null : JSON.parse(sourceJson); - const entries = isSameContainerKind(cachedLoggable, sourceLoggable) - ? diff( - cachedLoggable as Record | unknown[], - sourceLoggable as Record | unknown[], - ) - : rootDifference(cachedLoggable, sourceLoggable); + const json = JSON.stringify(side.value); + return json === undefined ? null : json; + } catch { + return null; + } +} + +function clampJson(json: string, maxBytes: number): string | null { + try { + return clampUtf8(json, maxBytes); + } catch { + return null; + } +} + +/** + * Bounded JSON of the differences between the two rendered snapshots, + * oriented from the cached side to the source side: `oldValue` is cached, + * `value` is source. A side without a JSON rendering fails the diff closed to + * `null` — the diff never attests anything about inputs value logging cannot + * show. Identical snapshots yield `[]`. + */ +function builtInDiffJson(cachedJson: string | null, sourceJson: string | null): string | null { + if (cachedJson === null || sourceJson === null) { + return null; + } + if (cachedJson === sourceJson) { + return "[]"; + } + try { + const cached: unknown = JSON.parse(cachedJson); + const source: unknown = JSON.parse(sourceJson); + const entries: ShadowLogDifference[] = []; + appendJsonDifferences(cached, source, [], entries); return previewShadowLogJson(entries, SHADOW_LOG_DIFF_MAX_BYTES); } catch { return null; } } -function isSameContainerKind(cached: unknown, source: unknown): boolean { - if (Array.isArray(cached) || Array.isArray(source)) { - return Array.isArray(cached) && Array.isArray(source); +// Structural difference between two parsed-JSON values. Only own enumerable +// keys and array indices are visited: the inputs are JSON.parse output, and +// prototype-carried data must never reach the log. Same-kind containers +// recurse (arrays index-wise, so an element shift reports every later +// index); any other pair is one CHANGE entry at its path. +function appendJsonDifferences( + cached: unknown, + source: unknown, + path: readonly (string | number)[], + out: ShadowLogDifference[], +): void { + if (Array.isArray(cached) && Array.isArray(source)) { + const shared = Math.min(cached.length, source.length); + for (let index = 0; index < shared; index += 1) { + appendJsonDifferences(cached[index], source[index], [...path, index], out); + } + for (let index = shared; index < cached.length; index += 1) { + out.push({ type: "REMOVE", path: [...path, index], oldValue: cached[index] }); + } + for (let index = shared; index < source.length; index += 1) { + out.push({ type: "CREATE", path: [...path, index], value: source[index] }); + } + return; + } + if (isJsonObject(cached) && isJsonObject(source)) { + for (const name of Object.keys(cached)) { + if (Object.hasOwn(source, name)) { + appendJsonDifferences(cached[name], source[name], [...path, name], out); + } else { + out.push({ type: "REMOVE", path: [...path, name], oldValue: cached[name] }); + } + } + for (const name of Object.keys(source)) { + if (!Object.hasOwn(cached, name)) { + out.push({ type: "CREATE", path: [...path, name], value: source[name] }); + } + } + return; + } + if (cached !== source) { + out.push({ type: "CHANGE", path, value: source, oldValue: cached }); } - return typeof cached === "object" && cached !== null && typeof source === "object" && source !== null; } -function rootDifference(cachedLoggable: unknown, sourceLoggable: unknown): Difference[] { - return [{ type: "CHANGE", path: [], value: sourceLoggable, oldValue: cachedLoggable }]; +function isJsonObject(value: unknown): value is Record { + return typeof value === "object" && value !== null && !Array.isArray(value); } function clampUtf8(value: string, maxBytes: number): string { diff --git a/test/dialcache-config-ramp.test.ts b/test/dialcache-config-ramp.test.ts index bf9843d..bf39a06 100644 --- a/test/dialcache-config-ramp.test.ts +++ b/test/dialcache-config-ramp.test.ts @@ -72,6 +72,17 @@ describe("DialCache runtime config and ramp controls", () => { })).toThrow('ShadowConfig.logMismatches was replaced by "shadow.mismatchLogging"'); }); + it("ignores a prototype-inherited shadow group at the constructor boundary", () => { + const config = new DialCacheKeyConfig(Object.create({ + shadow: { + ramp: 100, + mismatchLogging: { value: true, diff: true }, + }, + }) as ConstructorParameters[0]); + + expect(config.shadow).toBeUndefined(); + }); + it("rejects a non-object shadow mismatchLogging group", () => { for (const mismatchLogging of [null, 5, "keys", [true]]) { expect(() => new DialCacheKeyConfig({ @@ -436,6 +447,12 @@ describe("DialCache runtime config and ramp controls", () => { TypeError, "shadow.mismatchLogging.value must be a boolean", ], + [ + "unknown shadow mismatch logging field", + new DialCacheKeyConfig({ shadow: { mismatchLogging: { vaule: true } as never } }), + TypeError, + 'shadow.mismatchLogging has unknown field "vaule"', + ], [ "removed shadow logMismatches", { ttlSec: {}, ramp: {}, shadow: { logMismatches: true } } as unknown as DialCacheKeyConfig, diff --git a/test/dialcache-observability-internals.test.ts b/test/dialcache-observability-internals.test.ts index 8713bbf..ef92c95 100644 --- a/test/dialcache-observability-internals.test.ts +++ b/test/dialcache-observability-internals.test.ts @@ -96,6 +96,32 @@ describe("DialCache observability internal compatibility paths", () => { expect(Object.hasOwn(merged?.shadow?.mismatchLogging ?? {}, "value")).toBe(false); }); + it("ignores a prototype-inherited shadow group in a runtime overlay", async () => { + const defaultConfig = new DialCacheKeyConfig({ + ttlSec: { [CacheLayer.REMOTE]: 60 }, + ramp: { [CacheLayer.REMOTE]: 100 }, + shadow: { + ramp: 20, + mismatchLogging: { key: true }, + }, + }); + // A provider result whose shadow policy lives on the prototype: every leaf + // inside it is an own property, so only the group boundary can reject it. + const overlay = Object.create({ + shadow: { + ramp: 100, + mismatchLogging: { value: true, diff: true }, + }, + }) as DialCacheKeyConfig; + + const merged = await fetchKeyConfig(async () => overlay, key(defaultConfig)); + + expect(merged?.shadow).toEqual({ + ramp: 20, + mismatchLogging: { key: true }, + }); + }); + it("preserves omitted requestLocal and coalesce through a runtime merge", async () => { // The gates own the effective defaults, so the merge must not materialize // either boolean when both sides omit it. diff --git a/test/dialcache-shadow-confirmation.test.ts b/test/dialcache-shadow-confirmation.test.ts index 5a85e2e..e70b5c0 100644 --- a/test/dialcache-shadow-confirmation.test.ts +++ b/test/dialcache-shadow-confirmation.test.ts @@ -2028,6 +2028,41 @@ describe("DialCache Redis shadow confirmation", () => { expect(warn).not.toHaveBeenCalled(); }); + it("fails the whole logging group closed when a runtime override carries an unknown field", async () => { + const useCase = "ShadowUnknownLoggingLeaf"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + // The emergency-shutoff typo: the operator meant `value: false`. The + // inherited `value: true` must not survive it silently. + cacheConfigProvider: async () => new DialCacheKeyConfig({ + shadow: { mismatchLogging: { vaule: false } as never }, + }), + logger: { + debug: () => undefined, + error: () => undefined, + warn, + }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true, value: true })), + cacheKey: () => "123", + }); + + expect(await dialcache.enable(async () => await getUser())).toEqual({ id: "123", version: 1 }); + await waitForShadowEvents(metrics, 1); + + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch"]); + expect(metrics.ordinaryEvents.filter(({ name: metricName, labels }) => + metricName === "error" + && labels.layer === CacheLayer.REMOTE + && labels.error === "config_resolution" + )).toHaveLength(1); + expect(warn).not.toHaveBeenCalled(); + }); + it("resolves an invalid mismatch logging leaf to off without suppressing valid leaves", async () => { const useCase = "ShadowInvalidLoggingLeaf"; const cachedValue = { id: "123", version: 1 }; diff --git a/test/shadow-log-json.test.ts b/test/shadow-log-json.test.ts index 00aeca3..1f974b2 100644 --- a/test/shadow-log-json.test.ts +++ b/test/shadow-log-json.test.ts @@ -5,11 +5,18 @@ import { SHADOW_LOG_KEY_MAX_BYTES, SHADOW_LOG_TRUNCATION_MARKER, SHADOW_LOG_VALUE_MAX_BYTES, - previewShadowLogDiff, previewShadowLogJson, previewShadowLogKey, + renderShadowMismatchJson, } from "../src/internal/shadow-log-json.js"; +const diffOf = (cached: unknown, source: unknown): string | null => + renderShadowMismatchJson( + { available: true, value: cached }, + { available: true, value: source }, + { value: false, diff: true }, + ).diffJson ?? null; + describe("shadow mismatch log JSON", () => { it("uses native JSON for the values supplied to the comparator", () => { expect(previewShadowLogJson({ @@ -62,7 +69,7 @@ describe("shadow mismatch log JSON", () => { }); it("diffs plain objects and arrays from the cached side to the source side", () => { - const diffJson = previewShadowLogDiff( + const diffJson = diffOf( { id: "123", version: 1, tags: ["a", "b"] }, { id: "123", version: 2, tags: ["a"] }, ); @@ -74,7 +81,7 @@ describe("shadow mismatch log JSON", () => { }); it("reports source-only fields as CREATE entries", () => { - expect(JSON.parse(previewShadowLogDiff({ a: 1 }, { a: 1, b: 2 })!)).toEqual([ + expect(JSON.parse(diffOf({ a: 1 }, { a: 1, b: 2 })!)).toEqual([ { type: "CREATE", path: ["b"], value: 2 }, ]); }); @@ -93,8 +100,8 @@ describe("shadow mismatch log JSON", () => { // Runtime shape: the cached side is deserialized JSON, the source is live. const cached = { user: { id: 1 } }; - expect(previewShadowLogDiff(cached, { user: new User(1, "SECRET-TOKEN") })).toBe("[]"); - const changed = previewShadowLogDiff(cached, { user: new User(2, "SECRET-TOKEN") }); + expect(diffOf(cached, { user: new User(1, "SECRET-TOKEN") })).toBe("[]"); + const changed = diffOf(cached, { user: new User(2, "SECRET-TOKEN") }); expect(changed).not.toContain("SECRET-TOKEN"); expect(JSON.parse(changed!)).toEqual([ { type: "CHANGE", path: ["user", "id"], value: 2, oldValue: 1 }, @@ -104,7 +111,7 @@ describe("shadow mismatch log JSON", () => { it("does not emit phantom entries for serializer-normalized fields", () => { // Runtime shape: the cached Date arrived as its ISO string; the live // source still holds a Date for the same instant. - const diffJson = previewShadowLogDiff( + const diffJson = diffOf( { updatedAt: "2026-07-31T00:00:00.000Z", n: 1 }, { updatedAt: new Date("2026-07-31T00:00:00.000Z"), n: 2 }, ); @@ -115,7 +122,7 @@ describe("shadow mismatch log JSON", () => { }); it("renders nested Date leaves as ISO strings in diff entries", () => { - expect(JSON.parse(previewShadowLogDiff( + expect(JSON.parse(diffOf( { updatedAt: new Date("2026-07-31T00:00:00.000Z") }, { updatedAt: new Date("2026-08-01T00:00:00.000Z") }, )!)).toEqual([ @@ -131,7 +138,7 @@ describe("shadow mismatch log JSON", () => { it("reports an element shift as index-wise changes", () => { // Documented noise: array entries compare by index, so a shift reports // every later index instead of one insertion. - expect(JSON.parse(previewShadowLogDiff(["a", "b", "c"], ["x", "a", "b"])!)).toEqual([ + expect(JSON.parse(diffOf(["a", "b", "c"], ["x", "a", "b"])!)).toEqual([ { type: "CHANGE", path: [0], value: "x", oldValue: "a" }, { type: "CHANGE", path: [1], value: "a", oldValue: "b" }, { type: "CHANGE", path: [2], value: "b", oldValue: "c" }, @@ -139,21 +146,21 @@ describe("shadow mismatch log JSON", () => { }); it("returns an empty diff for identical loggable forms", () => { - expect(previewShadowLogDiff({ id: "123" }, { id: "123" })).toBe("[]"); - expect(previewShadowLogDiff("same", "same")).toBe("[]"); + expect(diffOf({ id: "123" }, { id: "123" })).toBe("[]"); + expect(diffOf("same", "same")).toBe("[]"); // A Map renders as {} on both sides; the emptiness matches what value // logging would show for the same inputs. - expect(previewShadowLogDiff({ m: {} }, { m: new Map([["k", 1]]) })).toBe("[]"); + expect(diffOf({ m: {} }, { m: new Map([["k", 1]]) })).toBe("[]"); }); it("collapses non-container and mixed-kind roots to one root-level change entry", () => { - expect(JSON.parse(previewShadowLogDiff("cached", "source")!)).toEqual([ + expect(JSON.parse(diffOf("cached", "source")!)).toEqual([ { type: "CHANGE", path: [], value: "source", oldValue: "cached" }, ]); - expect(JSON.parse(previewShadowLogDiff({ id: "123" }, null)!)).toEqual([ + expect(JSON.parse(diffOf({ id: "123" }, null)!)).toEqual([ { type: "CHANGE", path: [], value: null, oldValue: { id: "123" } }, ]); - expect(JSON.parse(previewShadowLogDiff( + expect(JSON.parse(diffOf( new Date("2026-07-31T00:00:00.000Z"), new Date("2026-08-01T00:00:00.000Z"), )!)).toEqual([ @@ -164,14 +171,93 @@ describe("shadow mismatch log JSON", () => { oldValue: "2026-07-31T00:00:00.000Z", }, ]); - expect(JSON.parse(previewShadowLogDiff({ a: 1, b: 2 }, [1, 2])!)).toEqual([ + expect(JSON.parse(diffOf({ a: 1, b: 2 }, [1, 2])!)).toEqual([ { type: "CHANGE", path: [], value: [1, 2], oldValue: { a: 1, b: 2 } }, ]); - expect(JSON.parse(previewShadowLogDiff({}, [])!)).toEqual([ + expect(JSON.parse(diffOf({}, [])!)).toEqual([ { type: "CHANGE", path: [], value: [], oldValue: {} }, ]); }); + it("reports nested kind mismatches at their path", () => { + expect(JSON.parse(diffOf({ data: { a: 1 } }, { data: [1] })!)).toEqual([ + { type: "CHANGE", path: ["data"], value: [1], oldValue: { a: 1 } }, + ]); + }); + + it("fails the diff closed when either side has no JSON rendering", () => { + expect(diffOf(undefined, null)).toBeNull(); + expect(diffOf(null, undefined)).toBeNull(); + expect(diffOf(undefined, undefined)).toBeNull(); + expect(diffOf(undefined, { a: 1 })).toBeNull(); + }); + + it("renders null value fields and a null diff for an unavailable side", () => { + expect(renderShadowMismatchJson( + { available: false }, + { available: true, value: { id: "123" } }, + { value: true, diff: true }, + )).toEqual({ + cachedValueJson: null, + sourceValueJson: '{"id":"123"}', + diffJson: null, + }); + }); + + it("runs toJSON once per side and derives value and diff from the same snapshot", () => { + const makeSide = (id: number) => { + let calls = 0; + return { + calls: () => calls, + value: { + user: { + toJSON(): { id: number; calls: number } { + calls += 1; + return { id, calls }; + }, + }, + }, + }; + }; + const cached = makeSide(1); + const source = makeSide(2); + + const fields = renderShadowMismatchJson( + { available: true, value: cached.value }, + { available: true, value: source.value }, + { value: true, diff: true }, + ); + + // A second stringify per side would render calls: 2 somewhere; both + // outputs must come from the single calls: 1 snapshot. + expect(cached.calls()).toBe(1); + expect(source.calls()).toBe(1); + expect(fields.cachedValueJson).toBe('{"user":{"id":1,"calls":1}}'); + expect(fields.sourceValueJson).toBe('{"user":{"id":2,"calls":1}}'); + expect(JSON.parse(fields.diffJson!)).toEqual([ + { type: "CHANGE", path: ["user", "id"], value: 2, oldValue: 1 }, + ]); + }); + + it("keeps prototype-carried data out of the diff", () => { + const objectProto = Object.prototype as unknown as Record; + const arrayProto = Array.prototype as unknown as Record; + objectProto.polluted = "PROTOTYPE-ONLY"; + arrayProto.pollutedEntry = "PROTOTYPE-ONLY"; + try { + const diffJson = diffOf({ a: 1, list: ["x"] }, { a: 2, list: ["x"] }); + + expect(diffJson).not.toContain("PROTOTYPE-ONLY"); + expect(diffJson).not.toContain("polluted"); + expect(JSON.parse(diffJson!)).toEqual([ + { type: "CHANGE", path: ["a"], value: 2, oldValue: 1 }, + ]); + } finally { + delete objectProto.polluted; + delete arrayProto.pollutedEntry; + } + }); + it("fails closed to null for cyclic inputs instead of throwing", () => { const cached: { id: string; self?: unknown } = { id: "cached" }; cached.self = cached; @@ -179,15 +265,15 @@ describe("shadow mismatch log JSON", () => { source.self = source; // The loggable-form rendering throws on cycles before any diffing. - expect(previewShadowLogDiff(cached, source)).toBeNull(); + expect(diffOf(cached, source)).toBeNull(); }); it("returns null when the diff entries cannot be serialized", () => { - expect(previewShadowLogDiff({ n: 1n }, { n: 2n })).toBeNull(); + expect(diffOf({ n: 1n }, { n: 2n })).toBeNull(); }); it("byte-clamps the diff", () => { - const diffJson = previewShadowLogDiff( + const diffJson = diffOf( { text: "a".repeat(SHADOW_LOG_DIFF_MAX_BYTES) }, { text: "b".repeat(SHADOW_LOG_DIFF_MAX_BYTES) }, ); From 7aa731c31edbeeff4d0c8b30558fefe296e3a44a Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Fri, 14 Aug 2026 23:10:29 -0700 Subject: [PATCH 5/9] fix(shadow): serialize the built-in diff tree without inherited toJSON hooks The own-key differ kept prototype data out of the entries, but the finished entry tree was still handed to native JSON.stringify, whose inherited-toJSON lookup let a polluted or legacy Array.prototype.toJSON replace the whole diff. The diff tree is now serialized by a closed-domain walker that only gives primitives to native JSON, so toJSON runs solely while rendering user data into the side snapshots, never over the internally generated entries. --- README.md | 2 +- src/internal/shadow-log-json.ts | 24 +++++++++++++++++- test/shadow-log-json.test.ts | 44 +++++++++++++++++++++++++++++++++ 3 files changed, 68 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index e7b4c60..676a455 100644 --- a/README.md +++ b/README.md @@ -602,7 +602,7 @@ Confirmed-mismatch logging is separately opt-in through the `shadow.mismatchLogg A byte-clipped field ends in `...[truncated]`, counted inside its cap. Every hook invocation and JSON step fails closed: a projector throw logs `null` for that side (and a `null` built-in diff), a diff-hook throw or unserializable diff logs `diffJson: null`, and native-JSON failure on one side leaves the other side attempted. DialCache never calls the configured serializer again for logging. -The built-in diff renders each side to native JSON exactly once per warning — the same loggable forms `value: true` shows — and derives both the value fields and the diff from those single snapshots, so `toJSON` redaction and serializer normalization bound the diff exactly as they bound value logging, a stateful `toJSON` cannot make the two outputs disagree, and a cached side deserialized to an ISO string never phantom-differs from a live source `Date` at the same instant. A side with no JSON rendering — top-level `undefined`, cycles, `bigint`, a thrown hook, or a failed projection — fails the diff closed to `null`; the diff never attests anything about inputs value logging cannot show. Identical loggable snapshots yield `[]`; with a projector that reads as "the difference is inside fields the projection hides", and structures native JSON flattens (a `Map` renders as `{}`) read the same way. Otherwise DialCache's own bounded differ emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. It walks only own enumerable keys and array indices of the parsed JSON forms, so prototype-carried data can never reach `diffJson`. Nodes of the same container kind (both objects or both arrays) diff recursively, with array entries compared by index, so an element shift reports every later index; a pair of differing kinds — primitives, `null`, or mixed object/array — collapses to one change entry at its path, including the root. The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures native JSON flattens. +The built-in diff renders each side to native JSON exactly once per warning — the same loggable forms `value: true` shows — and derives both the value fields and the diff from those single snapshots, so `toJSON` redaction and serializer normalization bound the diff exactly as they bound value logging, a stateful `toJSON` cannot make the two outputs disagree, and a cached side deserialized to an ISO string never phantom-differs from a live source `Date` at the same instant. A side with no JSON rendering — top-level `undefined`, cycles, `bigint`, a thrown hook, or a failed projection — fails the diff closed to `null`; the diff never attests anything about inputs value logging cannot show. Identical loggable snapshots yield `[]`; with a projector that reads as "the difference is inside fields the projection hides", and structures native JSON flattens (a `Map` renders as `{}`) read the same way. Otherwise DialCache's own bounded differ emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. It walks only own enumerable keys and array indices of the parsed JSON forms, and serializes the finished entry tree without invoking inherited `toJSON` hooks, so prototype-carried data can never reach `diffJson`: `toJSON` runs only where it renders user data (the side snapshots, value fields, and custom hook output), never where it could reshape the internally generated entries. Nodes of the same container kind (both objects or both arrays) diff recursively, with array entries compared by index, so an element shift reports every later index; a pair of differing kinds — primitives, `null`, or mixed object/array — collapses to one change entry at its path, including the root. The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures native JSON flattens. Both hooks run only after terminal mismatch confirmation, inside detached shadow work, under the comparator's discipline: synchronous, deterministic, side-effect-free, non-mutating, and bounded, over borrowed references. Hook output feeds `JSON.stringify` directly. diff --git a/src/internal/shadow-log-json.ts b/src/internal/shadow-log-json.ts index 5f88799..26c3266 100644 --- a/src/internal/shadow-log-json.ts +++ b/src/internal/shadow-log-json.ts @@ -124,12 +124,34 @@ function builtInDiffJson(cachedJson: string | null, sourceJson: string | null): const source: unknown = JSON.parse(sourceJson); const entries: ShadowLogDifference[] = []; appendJsonDifferences(cached, source, [], entries); - return previewShadowLogJson(entries, SHADOW_LOG_DIFF_MAX_BYTES); + return clampJson(serializeJsonTree(entries), SHADOW_LOG_DIFF_MAX_BYTES); } catch { return null; } } +// Serializes the internally generated diff tree without handing any container +// to native JSON.stringify, so inherited `toJSON` hooks (for example a legacy +// or polluted `Array.prototype.toJSON`) can never replace or reshape the +// entries. `toJSON` runs only while rendering user data into the two side +// snapshots. The domain here is closed: entry objects and path arrays are +// built above, and every other member is JSON.parse output, so only null, +// booleans, finite numbers, strings, arrays, and plain objects appear. +function serializeJsonTree(value: unknown): string { + if (value === null || typeof value !== "object") { + // Primitives never consult toJSON; JSON.stringify only handles escaping. + return JSON.stringify(value); + } + if (Array.isArray(value)) { + return `[${value.map((member) => serializeJsonTree(member)).join(",")}]`; + } + const object = value as Record; + const members = Object.keys(object).map( + (name) => `${JSON.stringify(name)}:${serializeJsonTree(object[name])}`, + ); + return `{${members.join(",")}}`; +} + // Structural difference between two parsed-JSON values. Only own enumerable // keys and array indices are visited: the inputs are JSON.parse output, and // prototype-carried data must never reach the log. Same-kind containers diff --git a/test/shadow-log-json.test.ts b/test/shadow-log-json.test.ts index 1f974b2..ecca59d 100644 --- a/test/shadow-log-json.test.ts +++ b/test/shadow-log-json.test.ts @@ -258,6 +258,50 @@ describe("shadow mismatch log JSON", () => { } }); + it("serializes the diff without invoking an inherited Array.prototype.toJSON", () => { + const arrayProto = Array.prototype as unknown as Record; + let diffJson: string | null; + arrayProto.toJSON = () => ({ prototypeSecret: "PROTOTYPE-ONLY" }); + try { + // The entries root and every path are arrays; native serialization + // would hand the whole diff to the inherited hook. + diffJson = diffOf({ id: 1 }, { id: 2 }); + } finally { + delete arrayProto.toJSON; + } + + expect(diffJson).not.toContain("PROTOTYPE-ONLY"); + expect(JSON.parse(diffJson!)).toEqual([ + { type: "CHANGE", path: ["id"], value: 2, oldValue: 1 }, + ]); + }); + + it("runs an inherited Object.prototype.toJSON only while rendering the side snapshots", () => { + const objectProto = Object.prototype as unknown as Record; + let calls = 0; + let fields: ReturnType; + objectProto.toJSON = function (this: unknown) { + calls += 1; + return { hooked: calls }; + }; + try { + fields = renderShadowMismatchJson( + { available: true, value: { id: 1 } }, + { available: true, value: { id: 2 } }, + { value: false, diff: true }, + ); + } finally { + delete objectProto.toJSON; + } + + // Snapshot rendering honors native JSON semantics (once per side); the + // internally generated entry objects must not consult the hook again. + expect(calls).toBe(2); + expect(JSON.parse(fields.diffJson!)).toEqual([ + { type: "CHANGE", path: ["hooked"], value: 2, oldValue: 1 }, + ]); + }); + it("fails closed to null for cyclic inputs instead of throwing", () => { const cached: { id: string; self?: unknown } = { id: "cached" }; cached.self = cached; From c1433864dfd3116aafaba1cbc8958d5f8ff0d74c Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Sat, 15 Aug 2026 01:48:26 -0700 Subject: [PATCH 6/9] refactor(shadow): simplify built-in JSON diff --- README.md | 2 +- src/internal/shadow-log-json.ts | 67 ++++++++++++--------------------- test/shadow-log-json.test.ts | 46 +--------------------- 3 files changed, 27 insertions(+), 88 deletions(-) diff --git a/README.md b/README.md index 676a455..4eee7dd 100644 --- a/README.md +++ b/README.md @@ -602,7 +602,7 @@ Confirmed-mismatch logging is separately opt-in through the `shadow.mismatchLogg A byte-clipped field ends in `...[truncated]`, counted inside its cap. Every hook invocation and JSON step fails closed: a projector throw logs `null` for that side (and a `null` built-in diff), a diff-hook throw or unserializable diff logs `diffJson: null`, and native-JSON failure on one side leaves the other side attempted. DialCache never calls the configured serializer again for logging. -The built-in diff renders each side to native JSON exactly once per warning — the same loggable forms `value: true` shows — and derives both the value fields and the diff from those single snapshots, so `toJSON` redaction and serializer normalization bound the diff exactly as they bound value logging, a stateful `toJSON` cannot make the two outputs disagree, and a cached side deserialized to an ISO string never phantom-differs from a live source `Date` at the same instant. A side with no JSON rendering — top-level `undefined`, cycles, `bigint`, a thrown hook, or a failed projection — fails the diff closed to `null`; the diff never attests anything about inputs value logging cannot show. Identical loggable snapshots yield `[]`; with a projector that reads as "the difference is inside fields the projection hides", and structures native JSON flattens (a `Map` renders as `{}`) read the same way. Otherwise DialCache's own bounded differ emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. It walks only own enumerable keys and array indices of the parsed JSON forms, and serializes the finished entry tree without invoking inherited `toJSON` hooks, so prototype-carried data can never reach `diffJson`: `toJSON` runs only where it renders user data (the side snapshots, value fields, and custom hook output), never where it could reshape the internally generated entries. Nodes of the same container kind (both objects or both arrays) diff recursively, with array entries compared by index, so an element shift reports every later index; a pair of differing kinds — primitives, `null`, or mixed object/array — collapses to one change entry at its path, including the root. The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures native JSON flattens. +The built-in diff renders each side to native JSON exactly once per warning — the same loggable forms `value: true` shows — and derives both the value fields and the diff from those single snapshots, so `toJSON` redaction and serializer normalization bound the diff exactly as they bound value logging, a stateful `toJSON` cannot make the two outputs disagree, and a cached side deserialized to an ISO string never phantom-differs from a live source `Date` at the same instant. A side with no JSON rendering — top-level `undefined`, cycles, `bigint`, a thrown hook, or a failed projection — fails the diff closed to `null`; the diff never attests anything about inputs value logging cannot show. Identical loggable snapshots yield `[]`; with a projector that reads as "the difference is inside fields the projection hides", and structures native JSON flattens (a `Map` renders as `{}`) read the same way. Otherwise DialCache's own bounded differ emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. It walks only own enumerable keys and array indices of the parsed JSON forms. Nodes of the same container kind (both objects or both arrays) diff recursively, with array entries compared by index, so an element shift reports every later index; a pair of differing kinds — primitives, `null`, or mixed object/array — collapses to one change entry at its path, including the root. The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures native JSON flattens. Both hooks run only after terminal mismatch confirmation, inside detached shadow work, under the comparator's discipline: synchronous, deterministic, side-effect-free, non-mutating, and bounded, over borrowed references. Hook output feeds `JSON.stringify` directly. diff --git a/src/internal/shadow-log-json.ts b/src/internal/shadow-log-json.ts index 26c3266..cdeb25b 100644 --- a/src/internal/shadow-log-json.ts +++ b/src/internal/shadow-log-json.ts @@ -7,6 +7,9 @@ const UTF8_ENCODER = new TextEncoder(); const UTF8_DECODER = new TextDecoder("utf-8", { fatal: true }); const TRUNCATION_MARKER_BYTES = UTF8_ENCODER.encode(SHADOW_LOG_TRUNCATION_MARKER); +type JsonObject = { [key: string]: JsonValue }; +type JsonValue = null | boolean | number | string | JsonValue[] | JsonObject; + /** One loggable side of a confirmed mismatch; unavailable when its projection failed. */ export interface ShadowLoggableSide { readonly available: boolean; @@ -22,18 +25,18 @@ export interface ShadowMismatchLogFields { export interface ShadowLogDifferenceCreate { readonly type: "CREATE"; readonly path: readonly (string | number)[]; - readonly value: unknown; + readonly value: JsonValue; } export interface ShadowLogDifferenceRemove { readonly type: "REMOVE"; readonly path: readonly (string | number)[]; - readonly oldValue: unknown; + readonly oldValue: JsonValue; } export interface ShadowLogDifferenceChange { readonly type: "CHANGE"; readonly path: readonly (string | number)[]; - readonly value: unknown; - readonly oldValue: unknown; + readonly value: JsonValue; + readonly oldValue: JsonValue; } export type ShadowLogDifference = | ShadowLogDifferenceCreate @@ -120,73 +123,53 @@ function builtInDiffJson(cachedJson: string | null, sourceJson: string | null): return "[]"; } try { - const cached: unknown = JSON.parse(cachedJson); - const source: unknown = JSON.parse(sourceJson); + // Both strings came from successful native JSON rendering above, so this + // is the single boundary from arbitrary loggable values to the closed JSON + // domain consumed by the built-in differ. + const cached = JSON.parse(cachedJson) as JsonValue; + const source = JSON.parse(sourceJson) as JsonValue; const entries: ShadowLogDifference[] = []; appendJsonDifferences(cached, source, [], entries); - return clampJson(serializeJsonTree(entries), SHADOW_LOG_DIFF_MAX_BYTES); + return previewShadowLogJson(entries, SHADOW_LOG_DIFF_MAX_BYTES); } catch { return null; } } -// Serializes the internally generated diff tree without handing any container -// to native JSON.stringify, so inherited `toJSON` hooks (for example a legacy -// or polluted `Array.prototype.toJSON`) can never replace or reshape the -// entries. `toJSON` runs only while rendering user data into the two side -// snapshots. The domain here is closed: entry objects and path arrays are -// built above, and every other member is JSON.parse output, so only null, -// booleans, finite numbers, strings, arrays, and plain objects appear. -function serializeJsonTree(value: unknown): string { - if (value === null || typeof value !== "object") { - // Primitives never consult toJSON; JSON.stringify only handles escaping. - return JSON.stringify(value); - } - if (Array.isArray(value)) { - return `[${value.map((member) => serializeJsonTree(member)).join(",")}]`; - } - const object = value as Record; - const members = Object.keys(object).map( - (name) => `${JSON.stringify(name)}:${serializeJsonTree(object[name])}`, - ); - return `{${members.join(",")}}`; -} - // Structural difference between two parsed-JSON values. Only own enumerable -// keys and array indices are visited: the inputs are JSON.parse output, and -// prototype-carried data must never reach the log. Same-kind containers -// recurse (arrays index-wise, so an element shift reports every later -// index); any other pair is one CHANGE entry at its path. +// keys and array indices are visited, matching JSON object and array semantics. +// Same-kind containers recurse (arrays index-wise, so an element shift reports +// every later index); any other pair is one CHANGE entry at its path. function appendJsonDifferences( - cached: unknown, - source: unknown, + cached: JsonValue, + source: JsonValue, path: readonly (string | number)[], out: ShadowLogDifference[], ): void { if (Array.isArray(cached) && Array.isArray(source)) { const shared = Math.min(cached.length, source.length); for (let index = 0; index < shared; index += 1) { - appendJsonDifferences(cached[index], source[index], [...path, index], out); + appendJsonDifferences(cached[index]!, source[index]!, [...path, index], out); } for (let index = shared; index < cached.length; index += 1) { - out.push({ type: "REMOVE", path: [...path, index], oldValue: cached[index] }); + out.push({ type: "REMOVE", path: [...path, index], oldValue: cached[index]! }); } for (let index = shared; index < source.length; index += 1) { - out.push({ type: "CREATE", path: [...path, index], value: source[index] }); + out.push({ type: "CREATE", path: [...path, index], value: source[index]! }); } return; } if (isJsonObject(cached) && isJsonObject(source)) { for (const name of Object.keys(cached)) { if (Object.hasOwn(source, name)) { - appendJsonDifferences(cached[name], source[name], [...path, name], out); + appendJsonDifferences(cached[name]!, source[name]!, [...path, name], out); } else { - out.push({ type: "REMOVE", path: [...path, name], oldValue: cached[name] }); + out.push({ type: "REMOVE", path: [...path, name], oldValue: cached[name]! }); } } for (const name of Object.keys(source)) { if (!Object.hasOwn(cached, name)) { - out.push({ type: "CREATE", path: [...path, name], value: source[name] }); + out.push({ type: "CREATE", path: [...path, name], value: source[name]! }); } } return; @@ -196,7 +179,7 @@ function appendJsonDifferences( } } -function isJsonObject(value: unknown): value is Record { +function isJsonObject(value: JsonValue): value is JsonObject { return typeof value === "object" && value !== null && !Array.isArray(value); } diff --git a/test/shadow-log-json.test.ts b/test/shadow-log-json.test.ts index ecca59d..cacb63a 100644 --- a/test/shadow-log-json.test.ts +++ b/test/shadow-log-json.test.ts @@ -239,7 +239,7 @@ describe("shadow mismatch log JSON", () => { ]); }); - it("keeps prototype-carried data out of the diff", () => { + it("diffs only own JSON members", () => { const objectProto = Object.prototype as unknown as Record; const arrayProto = Array.prototype as unknown as Record; objectProto.polluted = "PROTOTYPE-ONLY"; @@ -258,50 +258,6 @@ describe("shadow mismatch log JSON", () => { } }); - it("serializes the diff without invoking an inherited Array.prototype.toJSON", () => { - const arrayProto = Array.prototype as unknown as Record; - let diffJson: string | null; - arrayProto.toJSON = () => ({ prototypeSecret: "PROTOTYPE-ONLY" }); - try { - // The entries root and every path are arrays; native serialization - // would hand the whole diff to the inherited hook. - diffJson = diffOf({ id: 1 }, { id: 2 }); - } finally { - delete arrayProto.toJSON; - } - - expect(diffJson).not.toContain("PROTOTYPE-ONLY"); - expect(JSON.parse(diffJson!)).toEqual([ - { type: "CHANGE", path: ["id"], value: 2, oldValue: 1 }, - ]); - }); - - it("runs an inherited Object.prototype.toJSON only while rendering the side snapshots", () => { - const objectProto = Object.prototype as unknown as Record; - let calls = 0; - let fields: ReturnType; - objectProto.toJSON = function (this: unknown) { - calls += 1; - return { hooked: calls }; - }; - try { - fields = renderShadowMismatchJson( - { available: true, value: { id: 1 } }, - { available: true, value: { id: 2 } }, - { value: false, diff: true }, - ); - } finally { - delete objectProto.toJSON; - } - - // Snapshot rendering honors native JSON semantics (once per side); the - // internally generated entry objects must not consult the hook again. - expect(calls).toBe(2); - expect(JSON.parse(fields.diffJson!)).toEqual([ - { type: "CHANGE", path: ["hooked"], value: 2, oldValue: 1 }, - ]); - }); - it("fails closed to null for cyclic inputs instead of throwing", () => { const cached: { id: string; self?: unknown } = { id: "cached" }; cached.self = cached; From 6443227c3ba4adbc89a34d53a3aeb339fd1f3ac8 Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Sat, 15 Aug 2026 12:05:17 -0700 Subject: [PATCH 7/9] feat(shadow): include the validated value age in mismatch warnings Every opted-in mismatch warning now carries cachedValueAgeSeconds, the same coarse mixed-clock age observeShadowValueAge records for the verdict, so a single log line distinguishes a seconds-old race from a days-old invalidation bug without consulting the histogram. --- README.md | 4 ++-- src/dialcache.ts | 4 ++++ test/dialcache-shadow-confirmation.test.ts | 21 +++++++++++++++++++-- 3 files changed, 25 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index 4eee7dd..eaf45d1 100644 --- a/README.md +++ b/README.md @@ -592,9 +592,9 @@ The effective serializer's `load` method therefore runs a second time for a samp Shadow metrics use the bounded outcomes `match`, `mismatch`, `superseded`, `filled`, `fill_blocked`, `fill_error`, `redis_error`, `source_error`, `deserialization_error`, `comparison_error`, `confirmation_error`, `timeout`, and `dropped`. `redis_error` applies to the initial shadow-only `C0` read; `confirmation_error` applies to `C1`; `fill_blocked` applies only when a tracked watermark rejects the write. A clean `C0` miss is an ordinary `miss{layer="remote_shadow"}` and terminates with a fill, source, or timeout outcome rather than a second shadow outcome for the miss itself. Labels never contain cache ids, values, payloads, Redis keys, or raw exception text. -A `match` or `mismatch` verdict additionally records the validated value's age through the optional `observeShadowValueAge` adapter hook: the observing process's epoch clock minus the validated frame's `createdAtMs` (the served `C0` frame, or the detached `C0` frame on a ramped-down path), in seconds, clamped at zero. The age is captured at verdict time, so a mismatch age lands one confirmation read after the comparison itself. A confirmed `mismatch` age therefore measures how long the stale value had been readable when validation caught it. Tracked frames are stamped with Redis server time and untracked frames with the writer's client clock, so the age mixes clocks and is coarse operational evidence rather than a precise measurement. Outcomes that deliver no verdict on a retained value — including `superseded`, `filled`, and every error or timeout outcome — record no age. The hook does not gate shadow eligibility; only `shadowValidation` does. +A `match` or `mismatch` verdict additionally records the validated value's age through the optional `observeShadowValueAge` adapter hook: the observing process's epoch clock minus the validated frame's `createdAtMs` (the served `C0` frame, or the detached `C0` frame on a ramped-down path), in seconds, clamped at zero. The age is captured at verdict time, so a mismatch age lands one confirmation read after the comparison itself. A confirmed `mismatch` age therefore measures how long the stale value had been readable when validation caught it. Tracked frames are stamped with Redis server time and untracked frames with the writer's client clock, so the age mixes clocks and is coarse operational evidence rather than a precise measurement. Outcomes that deliver no verdict on a retained value — including `superseded`, `filled`, and every error or timeout outcome — record no age. Opted-in mismatch warnings carry the same age as `cachedValueAgeSeconds`. The hook does not gate shadow eligibility; only `shadowValidation` does. -Confirmed-mismatch logging is separately opt-in through the `shadow.mismatchLogging` group; it never replaces the required `shadowValidation` metric or emits for a mismatch candidate that becomes `superseded`. One warning is emitted per confirmed mismatch when at least one group field is true, and it always carries `cacheNamespace`, `useCase`, `keyType`, and `outcome: "mismatch"`. Each enabled field adds one bounded piece of content, so warnings stay useful for values that must not reach logs whole: +Confirmed-mismatch logging is separately opt-in through the `shadow.mismatchLogging` group; it never replaces the required `shadowValidation` metric or emits for a mismatch candidate that becomes `superseded`. One warning is emitted per confirmed mismatch when at least one group field is true, and it always carries `cacheNamespace`, `useCase`, `keyType`, `outcome: "mismatch"`, and `cachedValueAgeSeconds` — the same coarse mixed-clock age the `observeShadowValueAge` hook records for the verdict, measuring how long the stale value had been readable when validation caught it. Each enabled field adds one bounded piece of content, so warnings stay useful for values that must not reach logs whole: - `key: true` adds `cacheKey`: the logical DialCache URN capped at 2 KiB, not the physical Redis storage key. - `value: true` adds `cachedValueJson` and `sourceValueJson`: native `JSON.stringify` of each compared side, capped at 8 KiB per side. When the use case defines `shadowMismatchLogValue`, each side is that projection's result instead of the raw value; the projector runs once per side. Without a projector the deserialized cached snapshot and raw source value are stringified as-is. diff --git a/src/dialcache.ts b/src/dialcache.ts index 9214a13..da4526a 100644 --- a/src/dialcache.ts +++ b/src/dialcache.ts @@ -1219,6 +1219,10 @@ export class DialCache { useCase: key.useCase, keyType: key.keyType, outcome: "mismatch", + // The same coarse mixed-clock age observeShadowValueAge records for + // this verdict: how long the stale value had been readable when + // validation caught it. Metadata-tier, so it rides on every warning. + ...(valueAgeSeconds === undefined ? {} : { cachedValueAgeSeconds: valueAgeSeconds }), ...(logPlan.key ? { cacheKey: previewShadowLogKey(key.urn) } : {}), ...mismatchLogDetails, }); diff --git a/test/dialcache-shadow-confirmation.test.ts b/test/dialcache-shadow-confirmation.test.ts index e70b5c0..44e19f6 100644 --- a/test/dialcache-shadow-confirmation.test.ts +++ b/test/dialcache-shadow-confirmation.test.ts @@ -362,6 +362,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase: "ShadowMismatchJson", keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: "{private-namespace:user_id:private-id}?tenant=private-tenant#ShadowMismatchJson", cachedValueJson: '{"id":"private-id","version":1}', sourceValueJson: '{"id":"private-id","version":2}', @@ -413,6 +414,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase: "ShadowMismatchRampedDownJson", keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: "{urn:user_id:123}?locale=en-US#ShadowMismatchRampedDownJson", cachedValueJson: '{"id":"123","version":1}', sourceValueJson: '{"id":"123","version":2}', @@ -468,6 +470,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase: "ShadowMismatchJsonFailure", keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: null, cachedValueJson: null, sourceValueJson: null, @@ -548,6 +551,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase, keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: `{urn:user_id:123}#${useCase}`, }, ); @@ -578,6 +582,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase, keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cachedValueJson: '{"id":"123","version":1}', sourceValueJson: '{"id":"123","version":2}', }, @@ -613,6 +618,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase, keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: `{urn:user_id:123}#${useCase}`, cachedValueJson: '{"version":1}', sourceValueJson: '{"version":2}', @@ -651,6 +657,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase, keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cachedValueJson: null, sourceValueJson: '{"version":2}', }, @@ -805,6 +812,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase, keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: `{urn:user_id:123}#${useCase}`, diffJson: null, }, @@ -978,6 +986,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase, keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: `{urn:user_id:123}#${useCase}`, }, ); @@ -1011,6 +1020,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase, keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: `{urn:user_id:123}#${useCase}`, diffJson: null, }, @@ -1066,9 +1076,12 @@ describe("DialCache Redis shadow confirmation", () => { ]); redis.frameCreatedAtMs = nowMs - 90_000; const metrics = new RecordingMetrics(); - const dialcache = createCache(redis, metrics); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { - ...trackedOptions("ShadowMismatchValueAge", remoteConfig(100)), + ...trackedOptions("ShadowMismatchValueAge", remoteConfig(100, 100, { key: true })), cacheKey: () => "123", }); @@ -1083,6 +1096,9 @@ describe("DialCache Redis shadow confirmation", () => { keyType: "user_id", outcome: "mismatch", }); + // The warning carries the exact age the metric observed. + expect(warn).toHaveBeenCalledTimes(1); + expect(warn.mock.calls[0]?.[1]).toMatchObject({ cachedValueAgeSeconds: 90 }); } finally { nowSpy.mockRestore(); } @@ -2102,6 +2118,7 @@ describe("DialCache Redis shadow confirmation", () => { useCase, keyType: "user_id", outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), cacheKey: `{urn:user_id:123}#${useCase}`, }, ); From fea4ae99c5b015cba1ca90858767a7e8fcf956e9 Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Sat, 15 Aug 2026 15:40:36 -0700 Subject: [PATCH 8/9] fix(shadow): fail closed on invalid log hooks Treat promise-like logging-hook results as unavailable and consume their settlements so detached shadow work cannot leak unhandled rejections. Preserve unknown runtime logging keys even when explicitly undefined so closed-schema admission rejects the whole group. --- README.md | 2 +- src/dialcache.ts | 75 +++++++++++------- src/internal/runtime-config.ts | 7 +- test/dialcache-shadow-confirmation.test.ts | 88 ++++++++++++++++++++-- test/shadow-log-json.test.ts | 4 +- 5 files changed, 135 insertions(+), 41 deletions(-) diff --git a/README.md b/README.md index eaf45d1..89f55df 100644 --- a/README.md +++ b/README.md @@ -600,7 +600,7 @@ Confirmed-mismatch logging is separately opt-in through the `shadow.mismatchLogg - `value: true` adds `cachedValueJson` and `sourceValueJson`: native `JSON.stringify` of each compared side, capped at 8 KiB per side. When the use case defines `shadowMismatchLogValue`, each side is that projection's result instead of the raw value; the projector runs once per side. Without a projector the deserialized cached snapshot and raw source value are stringified as-is. - `diff: true` adds `diffJson`, capped at 8 KiB: the `shadowMismatchLogDiff` result when the use case defines one (it receives the raw compared values), and otherwise a built-in structural diff — computed over the same loggable forms `value` uses, so a projector bounds the diff exactly as it bounds value logging. -A byte-clipped field ends in `...[truncated]`, counted inside its cap. Every hook invocation and JSON step fails closed: a projector throw logs `null` for that side (and a `null` built-in diff), a diff-hook throw or unserializable diff logs `diffJson: null`, and native-JSON failure on one side leaves the other side attempted. DialCache never calls the configured serializer again for logging. +A byte-clipped field ends in `...[truncated]`, counted inside its cap. Every hook invocation and JSON step fails closed: a projector throw or returned promise-like value logs `null` for that side (and a `null` built-in diff), a diff-hook throw, promise-like result, or unserializable output logs `diffJson: null`, and native-JSON failure on one side leaves the other side attempted. Promise-like settlements are consumed but never awaited, preserving the synchronous hook contract without unhandled rejections. DialCache never calls the configured serializer again for logging. The built-in diff renders each side to native JSON exactly once per warning — the same loggable forms `value: true` shows — and derives both the value fields and the diff from those single snapshots, so `toJSON` redaction and serializer normalization bound the diff exactly as they bound value logging, a stateful `toJSON` cannot make the two outputs disagree, and a cached side deserialized to an ISO string never phantom-differs from a live source `Date` at the same instant. A side with no JSON rendering — top-level `undefined`, cycles, `bigint`, a thrown hook, or a failed projection — fails the diff closed to `null`; the diff never attests anything about inputs value logging cannot show. Identical loggable snapshots yield `[]`; with a projector that reads as "the difference is inside fields the projection hides", and structures native JSON flattens (a `Map` renders as `{}`) read the same way. Otherwise DialCache's own bounded differ emits entries of `{ type: "CREATE" | "REMOVE" | "CHANGE", path, value, oldValue }` oriented from the cached side to the source side: `oldValue` is cached, `value` is source. It walks only own enumerable keys and array indices of the parsed JSON forms. Nodes of the same container kind (both objects or both arrays) diff recursively, with array entries compared by index, so an element shift reports every later index; a pair of differing kinds — primitives, `null`, or mixed object/array — collapses to one change entry at its path, including the root. The diff is rendering evidence, not the comparator's verdict: a custom comparator can ignore fields the diff still reports, and can compare structures native JSON flattens. diff --git a/src/dialcache.ts b/src/dialcache.ts index da4526a..7c4868a 100644 --- a/src/dialcache.ts +++ b/src/dialcache.ts @@ -48,6 +48,7 @@ import { previewShadowLogJson, previewShadowLogKey, renderShadowMismatchJson, + type ShadowLoggableSide, type ShadowMismatchLogFields, } from "./internal/shadow-log-json.js"; @@ -140,14 +141,16 @@ interface CacheOperationOptionsBase { * without it, opted-in warnings log the raw native-JSON forms. Runs once per * side after terminal mismatch confirmation, inside detached shadow work. * Must be synchronous, deterministic, side-effect-free, non-mutating, and - * bounded; inputs are borrowed snapshots. A throw logs `null` for that side. + * bounded; inputs are borrowed snapshots. A throw or returned promise-like + * value logs `null` for that side. */ readonly shadowMismatchLogValue?: (value: Value) => unknown; /** * Replaces the built-in structural diff for mismatch warnings that enable * `mismatchLogging.diff`. Receives the raw compared values, not the * `shadowMismatchLogValue` projections. Same execution constraints as - * `shadowMismatchLogValue`; a throw logs a `null` diff. + * `shadowMismatchLogValue`; a throw or returned promise-like value logs a + * `null` diff. */ readonly shadowMismatchLogDiff?: (cachedValue: Value, sourceValue: Value) => unknown; /** @@ -1665,44 +1668,58 @@ function renderShadowMismatchLog( cachedValue: Value, sourceValue: Value, ): ShadowMismatchLogFields { - let cachedLoggable: unknown = cachedValue; - let sourceLoggable: unknown = sourceValue; - let cachedLoggableOk = true; - let sourceLoggableOk = true; const includeBuiltInDiff = logPlan.diff && plan.logDiff === undefined; - const needsProjection = plan.logValue !== undefined && (logPlan.value || includeBuiltInDiff); - if (needsProjection && plan.logValue !== undefined) { - try { - cachedLoggable = plan.logValue(cachedValue); - } catch { - cachedLoggableOk = false; - } - try { - sourceLoggable = plan.logValue(sourceValue); - } catch { - sourceLoggableOk = false; - } - } + const logValue = plan.logValue; + const needsProjection = logValue !== undefined && (logPlan.value || includeBuiltInDiff); + const cachedLoggable: ShadowLoggableSide = needsProjection + ? runShadowLogHook(() => logValue(cachedValue)) + : { available: true, value: cachedValue }; + const sourceLoggable: ShadowLoggableSide = needsProjection + ? runShadowLogHook(() => logValue(sourceValue)) + : { available: true, value: sourceValue }; const rendered: ShadowMismatchLogFields = logPlan.value || includeBuiltInDiff ? renderShadowMismatchJson( - { available: cachedLoggableOk, value: cachedLoggable }, - { available: sourceLoggableOk, value: sourceLoggable }, + cachedLoggable, + sourceLoggable, { value: logPlan.value, diff: includeBuiltInDiff }, ) : {}; - if (logPlan.diff && plan.logDiff !== undefined) { - let diffJson: string | null; - try { - diffJson = previewShadowLogJson(plan.logDiff(cachedValue, sourceValue), SHADOW_LOG_DIFF_MAX_BYTES); - } catch { - diffJson = null; - } - return { ...rendered, diffJson }; + const logDiff = plan.logDiff; + if (logPlan.diff && logDiff !== undefined) { + const diff = runShadowLogHook(() => logDiff(cachedValue, sourceValue)); + return { + ...rendered, + diffJson: diff.available + ? previewShadowLogJson(diff.value, SHADOW_LOG_DIFF_MAX_BYTES) + : null, + }; } return rendered; } +function runShadowLogHook(hook: () => unknown): ShadowLoggableSide { + try { + const value = hook(); + if (isThenable(value)) { + // The hook contract is synchronous, but its `unknown` return type also + // accepts async functions. Ignore their output and consume rejection; + // awaiting here would silently turn this into a second async contract. + void Promise.resolve(value).catch(() => undefined); + return { available: false }; + } + return { available: true, value }; + } catch { + return { available: false }; + } +} + +function isThenable(value: unknown): value is PromiseLike { + return value !== null + && (typeof value === "object" || typeof value === "function") + && typeof (value as { readonly then?: unknown }).then === "function"; +} + // Frame stamps are epoch-based (Redis server time for tracked writes, writer // client clock for untracked), so the age uses the epoch clock and clamps // negative cross-clock skew to zero. A custom client that violates the decode diff --git a/src/internal/runtime-config.ts b/src/internal/runtime-config.ts index f894191..5b08043 100644 --- a/src/internal/runtime-config.ts +++ b/src/internal/runtime-config.ts @@ -211,10 +211,9 @@ function mergeMismatchLoggingConfig( if ((SHADOW_MISMATCH_LOGGING_LEAVES as readonly string[]).includes(name)) { continue; } - const value = (source as Record)[name]; - if (value !== undefined) { - merged[name] = value; - } + // Presence, not value, makes this field unknown. Preserve even an + // explicit `undefined` so admission can reject the closed schema. + merged[name] = (source as Record)[name]; } } for (const leaf of SHADOW_MISMATCH_LOGGING_LEAVES) { diff --git a/test/dialcache-shadow-confirmation.test.ts b/test/dialcache-shadow-confirmation.test.ts index 44e19f6..6d9a77b 100644 --- a/test/dialcache-shadow-confirmation.test.ts +++ b/test/dialcache-shadow-confirmation.test.ts @@ -665,6 +665,44 @@ describe("DialCache Redis shadow confirmation", () => { expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch"]); }); + it("fails rejected shadowMismatchLogValue promises closed without an unhandled rejection", async () => { + const useCase = "ShadowMismatchAsyncProjection"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const projector = vi.fn(async () => { + throw new Error("async projection unavailable"); + }); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { value: true, diff: true })), + cacheKey: () => "123", + shadowMismatchLogValue: projector, + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + await nextImmediate(); + + expect(projector).toHaveBeenCalledTimes(2); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), + cachedValueJson: null, + sourceValueJson: null, + diffJson: null, + }, + ); + }); + it("logs a structural diff of the raw values when no hooks are defined", async () => { const useCase = "ShadowMismatchBuiltInDiff"; const payload = JSON.stringify({ id: "123", version: 1, tags: ["a", "b"] }); @@ -1028,6 +1066,43 @@ describe("DialCache Redis shadow confirmation", () => { expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch"]); }); + it("fails a rejected shadowMismatchLogDiff promise closed without an unhandled rejection", async () => { + const useCase = "ShadowMismatchAsyncCustomDiff"; + const payload = JSON.stringify({ id: "123", version: 1 }); + const redis = new ScriptedRedis([() => payload, () => payload]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const logDiff = vi.fn(async () => { + throw new Error("async diff unavailable"); + }); + const dialcache = createCache(redis, metrics, { + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + const getUser = dialcache.cached(async () => ({ id: "123", version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { key: true, diff: true })), + cacheKey: () => "123", + shadowMismatchLogDiff: logDiff, + }); + + await dialcache.enable(async () => await getUser()); + await waitForShadowEvents(metrics, 1); + await nextImmediate(); + + expect(logDiff).toHaveBeenCalledOnce(); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), + cacheKey: `{urn:user_id:123}#${useCase}`, + diffJson: null, + }, + ); + }); + it.each([ { name: "missing", confirmation: null }, { @@ -2044,17 +2119,20 @@ describe("DialCache Redis shadow confirmation", () => { expect(warn).not.toHaveBeenCalled(); }); - it("fails the whole logging group closed when a runtime override carries an unknown field", async () => { - const useCase = "ShadowUnknownLoggingLeaf"; + it.each([ + ["false", false], + ["undefined", undefined], + ] as const)("fails the whole logging group closed when an unknown field is $0", async (suffix, value) => { + const useCase = `ShadowUnknownLoggingLeaf${suffix}`; const payload = JSON.stringify({ id: "123", version: 1 }); const redis = new ScriptedRedis([() => payload, () => payload]); const metrics = new RecordingMetrics(); const warn = vi.fn(); const dialcache = createCache(redis, metrics, { - // The emergency-shutoff typo: the operator meant `value: false`. The - // inherited `value: true` must not survive it silently. + // Presence alone makes this a closed-schema violation. Even undefined + // must survive the merge so inherited logging cannot remain enabled. cacheConfigProvider: async () => new DialCacheKeyConfig({ - shadow: { mismatchLogging: { vaule: false } as never }, + shadow: { mismatchLogging: { vaule: value } as never }, }), logger: { debug: () => undefined, diff --git a/test/shadow-log-json.test.ts b/test/shadow-log-json.test.ts index cacb63a..5d61d39 100644 --- a/test/shadow-log-json.test.ts +++ b/test/shadow-log-json.test.ts @@ -18,7 +18,7 @@ const diffOf = (cached: unknown, source: unknown): string | null => ).diffJson ?? null; describe("shadow mismatch log JSON", () => { - it("uses native JSON for the values supplied to the comparator", () => { + it("uses native JSON for log previews", () => { expect(previewShadowLogJson({ id: "123", updatedAt: new Date("2026-07-31T00:00:00.000Z"), @@ -268,7 +268,7 @@ describe("shadow mismatch log JSON", () => { expect(diffOf(cached, source)).toBeNull(); }); - it("returns null when the diff entries cannot be serialized", () => { + it("fails the diff closed for bigint inputs", () => { expect(diffOf({ n: 1n }, { n: 2n })).toBeNull(); }); From d15bdedce4221e8a41f50ee7d18dc700b82ae9f2 Mon Sep 17 00:00:00 2001 From: Lev Neiman Date: Sat, 15 Aug 2026 19:29:36 -0700 Subject: [PATCH 9/9] fix(config): ignore and report unknown fields Apply known config fields while ignoring unknown own keys across defaults and runtime overlays, including legacy shadow fields. Emit one bounded config_unknown_field error label per observed config without exposing field names or values. --- README.md | 9 +- scripts/test-package.mjs | 1 + src/config.ts | 118 +++++++++++++++++---- src/dialcache.ts | 45 ++++---- src/internal/runtime-config.ts | 28 +---- src/metrics.ts | 3 +- test/datadog.test.ts | 1 + test/dialcache-config-ramp.test.ts | 51 ++++----- test/dialcache-metrics.test.ts | 68 ++++++++++++ test/dialcache-shadow-confirmation.test.ts | 22 ++-- test/prometheus.test.ts | 1 + 11 files changed, 245 insertions(+), 102 deletions(-) diff --git a/README.md b/README.md index 89f55df..40282a7 100644 --- a/README.md +++ b/README.md @@ -221,13 +221,13 @@ The disabled baseline sets `requestLocal` to false, leaves the process-local and A provider result of `null` (or defensive `undefined`) applies no overrides. An empty `DialCacheKeyConfig` and omitted runtime fields also inherit the baseline. Top-level fields, cache-layer leaves, leaves inside `shadow`, and leaves inside `shadow.mismatchLogging` merge independently; an explicit `false` logging leaf overrides an inherited `true`. Use explicit values to override inherited policy: `requestLocal: false` disables request-local caching and a layer ramp of `0` disables that shared layer. `DialCacheKeyConfig.disabled()` is the complete new-cache-invocation kill switch in one call: request-local and shadow work off, shadow logging off, and both shared layers ramped to 0. It leaves `coalesce` unset: with every layer off there is no in-flight sharing to disable, and a use case ramped back up at runtime coalesces again unless it explicitly opts out. It does not cancel already-admitted work, and explicit maintenance operations such as `invalidateRemote()` remain available. To stop new cache-invocation Redis reads and fills while preserving other runtime settings, explicitly set both `ramp.remote` and `shadow.ramp` to `0`; the remote ramp alone stops serving but does not override an inherited nonzero shadow ramp. -DialCache validates `defaultConfig` when `cached()` registers a definition and whenever `getOrLoad()` is invoked: TTLs must be positive safe integers no greater than 31,536,000 seconds (a fixed 365-day duration), remote-read deadlines must be positive safe integers within their documented limit, layer and shadow ramps must be finite percentages from 0 to 100, layer maps, `shadow`, and `shadow.mismatchLogging` must be objects, `requestLocal`, `coalesce`, and the `shadow.mismatchLogging` fields must be booleans when present, and `shadow.mismatchLogging` may not carry unknown fields. Invalid defaults are rejected immediately. +DialCache validates known `defaultConfig` fields when `cached()` registers a definition and whenever `getOrLoad()` is invoked: TTLs must be positive safe integers no greater than 31,536,000 seconds (a fixed 365-day duration), remote-read deadlines must be positive safe integers within their documented limit, layer and shadow ramps must be finite percentages from 0 to 100, layer maps, `shadow`, and `shadow.mismatchLogging` must be objects, and `requestLocal`, `coalesce`, and the `shadow.mismatchLogging` fields must be booleans when present. Invalid known defaults are rejected immediately. Unknown own fields are ignored while every recognized field is retained; one `config_unknown_field` error metric is recorded when such a default is observed, without putting the field name or value in labels. Each registration or one-shot invocation captures an immutable internal snapshot of `defaultConfig`; mutating the supplied config or its maps later does not change that operation's baseline. Runtime policy changes belong in the provider's returned overlay. -Runtime TTL and ramp leaves are used as supplied instead of falling back to valid default leaves. A TTL outside the same 1-to-31,536,000-second range disables that layer with `invalid_ttl`; a nonnumeric, non-finite, or out-of-range ramp disables it with `invalid_ramp`. Valid ramps include both `0` and `100`. Other layers can still run, and invalid leaves also record a `config_resolution` error so provider garbage is alertable separately from intentional ramp-downs. A malformed runtime config object, layer-map shape, `requestLocal` value, `coalesce` value, explicit `remoteReadTimeoutMs`, non-object `shadow.mismatchLogging` group, removed top-level `shadowRamp`, or removed `shadow.logMismatches` fails config resolution for the invocation, records `config_error`, and executes the fallback uncached without attempting Redis. The public `DialCacheKeyConfig` constructor and static defaults likewise reject both removed fields immediately; migrate `shadowRamp` to `shadow.ramp` and `shadow.logMismatches` to `shadow.mismatchLogging`. +Runtime TTL and ramp leaves are used as supplied instead of falling back to valid default leaves. A TTL outside the same 1-to-31,536,000-second range disables that layer with `invalid_ttl`; a nonnumeric, non-finite, or out-of-range ramp disables it with `invalid_ramp`. Valid ramps include both `0` and `100`. Other layers can still run, and invalid leaves also record a `config_resolution` error so provider garbage is alertable separately from intentional ramp-downs. A malformed runtime config object, layer-map shape, `requestLocal` value, `coalesce` value, explicit `remoteReadTimeoutMs`, or non-object `shadow.mismatchLogging` group fails config resolution for the invocation, records `config_error`, and executes the fallback uncached without attempting Redis. Unknown own fields at the top level, in layer maps, in `shadow`, or in `shadow.mismatchLogging` are ignored while known fields still apply. That includes removed `shadowRamp` and `shadow.logMismatches` fields from older or mixed-version providers. Each observed config containing one or more unknown fields records one `config_unknown_field` error metric; arbitrary field names and values never become labels. -An invalid runtime `shadow.ramp` does not affect the cache result or disable an otherwise valid Redis policy. If normal traversal reaches an otherwise shadow-eligible Redis path, DialCache skips shadow work and records a `config_resolution` error. An invalid runtime `shadow.mismatchLogging` field likewise preserves the cache result, Redis policy, shadow result, and shadow metric; an invalid field acts false while valid sibling fields still log, and an unknown field fails the whole logging group closed instead — a typo'd override never silently inherits enabled leaves. DialCache validates these diagnostic leaves only after the metrics hook, exact-key cohort, and capacity gates admit shadow work, then records one remote `config_resolution` error for that admitted resolution. A non-object `mismatchLogging` group is malformed config shape rather than an invalid field: like a malformed layer map, it fails resolution as `config_error` and the invocation runs uncached. The `shadow` group and everything inside it are read by own properties only, at the constructor, defaults-snapshot, and runtime-merge boundaries alike; prototype-inherited policy never activates. +An invalid runtime `shadow.ramp` does not affect the cache result or disable an otherwise valid Redis policy. If normal traversal reaches an otherwise shadow-eligible Redis path, DialCache skips shadow work and records a `config_resolution` error. An invalid known runtime `shadow.mismatchLogging` field likewise preserves the cache result, Redis policy, shadow result, and shadow metric; that field acts false while valid sibling fields still log. Unknown fields are removed before the leaf-wise merge, so recognized sibling overrides and inherited recognized defaults remain effective. DialCache validates known diagnostic leaves only after the metrics hook, exact-key cohort, and capacity gates admit shadow work, then records one remote `config_resolution` error for that admitted resolution. A non-object `mismatchLogging` group is malformed config shape rather than an invalid field: like a malformed layer map, it fails resolution as `config_error` and the invocation runs uncached. The `shadow` group and everything inside it are read by own properties only, at the constructor, defaults-snapshot, and runtime-merge boundaries alike; prototype-inherited policy never activates or triggers unknown-field telemetry. `cacheConfigProvider` is called for every enabled cache invocation before DialCache performs any cache lookup. Keep it cheap, cache any remote/config-store reads inside the provider, and avoid work that would erase the benefit of a cache hit. @@ -888,12 +888,13 @@ Observer throws and rejections from returned promises or thenables are isolated ### Error categories -The `error` label reports where an operation failed rather than copying the thrown value's class or `Error.name`: +The `error` label reports a bounded operational category rather than copying a thrown value's class, `Error.name`, or config field name: | `error` | Meaning | | --- | --- | | `key_construction` | The cache-key selector or `DialCacheKey` construction failed | | `config_resolution` | Runtime or layer configuration, or ramp resolution, failed | +| `config_unknown_field` | A default or runtime key config carried one or more ignored unknown own fields | | `cache_read` | A local-cache or Redis read failed | | `cache_read_timeout` | A Redis read exceeded its effective remote-read deadline | | `cache_write` | A local-cache or Redis write failed; tracked Redis writes add a benign self-healing floor under same-key contention (see [Redis-backed TTL cache](#redis-backed-ttl-cache)) | diff --git a/scripts/test-package.mjs b/scripts/test-package.mjs index 6040f23..5245619 100644 --- a/scripts/test-package.mjs +++ b/scripts/test-package.mjs @@ -372,6 +372,7 @@ const legacyMissingConfigReason: DisabledReason = "missing_config"; const metricErrorKinds: Readonly> = { key_construction: true, config_resolution: true, + config_unknown_field: true, cache_read: true, cache_read_timeout: true, cache_write: true, diff --git a/src/config.ts b/src/config.ts index 1488a21..d38e7a1 100644 --- a/src/config.ts +++ b/src/config.ts @@ -41,6 +41,15 @@ export interface ShadowConfig { readonly mismatchLogging?: ShadowMismatchLoggingConfig; } +interface DialCacheKeyConfigInput { + readonly ttlSec?: LayerConfig; + readonly ramp?: LayerConfig; + readonly shadow?: ShadowConfig; + readonly requestLocal?: boolean; + readonly coalesce?: boolean; + readonly remoteReadTimeoutMs?: number; +} + // `satisfies Record` fails to compile when the interface gains // a field this set is missing, so every leaf loop stays exhaustive. const SHADOW_MISMATCH_LOGGING_LEAF_SET = { @@ -54,6 +63,58 @@ export const SHADOW_MISMATCH_LOGGING_LEAVES = Object.keys( SHADOW_MISMATCH_LOGGING_LEAF_SET, ) as readonly (keyof ShadowMismatchLoggingConfig)[]; +const KEY_CONFIG_FIELD_SET = { + ttlSec: true, + ramp: true, + shadow: true, + requestLocal: true, + coalesce: true, + remoteReadTimeoutMs: true, +} as const satisfies Record; +const KEY_CONFIG_FIELDS = Object.keys(KEY_CONFIG_FIELD_SET); +const SHADOW_CONFIG_FIELD_SET = { + ramp: true, + mismatchLogging: true, +} as const satisfies Record; +const SHADOW_CONFIG_FIELDS = Object.keys(SHADOW_CONFIG_FIELD_SET); +const UNKNOWN_KEY_CONFIG_FIELDS = Symbol("DialCacheKeyConfig.unknownFields"); + +interface UnknownFieldMarkedConfig { + readonly [UNKNOWN_KEY_CONFIG_FIELDS]?: true; +} + +/** Internal: reports unknown own string fields without exposing their names. */ +export function hasUnknownKeyConfigFields(config: unknown): boolean { + if (!isConfigObject(config)) { + return false; + } + if ( + Object.hasOwn(config, UNKNOWN_KEY_CONFIG_FIELDS) + && (config as UnknownFieldMarkedConfig)[UNKNOWN_KEY_CONFIG_FIELDS] === true + ) { + return true; + } + if (hasUnknownOwnFields(config, KEY_CONFIG_FIELDS)) { + return true; + } + + const ttlSec = readOwnUnknown(config, "ttlSec"); + const ramp = readOwnUnknown(config, "ramp"); + const shadow = readOwnUnknown(config, "shadow"); + if ( + hasUnknownOwnFields(ttlSec, Object.values(CacheLayer)) + || hasUnknownOwnFields(ramp, Object.values(CacheLayer)) + || hasUnknownOwnFields(shadow, SHADOW_CONFIG_FIELDS) + ) { + return true; + } + + const mismatchLogging = isConfigObject(shadow) + ? readOwnUnknown(shadow, "mismatchLogging") + : undefined; + return hasUnknownOwnFields(mismatchLogging, SHADOW_MISMATCH_LOGGING_LEAVES); +} + export class DialCacheKeyConfig { /** Per-layer TTLs in seconds, from 1 through 31,536,000 (365 days). */ readonly ttlSec: LayerConfig; @@ -78,20 +139,11 @@ export class DialCacheKeyConfig { */ readonly remoteReadTimeoutMs?: number; - constructor(config: { - ttlSec?: LayerConfig; - ramp?: LayerConfig; - shadow?: ShadowConfig; - requestLocal?: boolean; - coalesce?: boolean; - remoteReadTimeoutMs?: number; - }) { + constructor(config: DialCacheKeyConfigInput) { if (config === null || typeof config !== "object" || Array.isArray(config)) { throw new TypeError("DialCache key config must be an object"); } - if (Object.hasOwn(config, "shadowRamp")) { - throw new TypeError('DialCacheKeyConfig.shadowRamp was replaced by "shadow.ramp"'); - } + const hasUnknownFields = hasUnknownKeyConfigFields(config); this.ttlSec = cloneLayerConfig(config.ttlSec, "ttlSec"); this.ramp = cloneLayerConfig(config.ramp, "ramp"); // Own-property read: `shadow` carries the log-content controls, so a @@ -117,6 +169,9 @@ export class DialCacheKeyConfig { assertValidDeadlineMs(config.remoteReadTimeoutMs, "DialCache remoteReadTimeoutMs"); this.remoteReadTimeoutMs = config.remoteReadTimeoutMs; } + if (hasUnknownFields) { + Object.defineProperty(this, UNKNOWN_KEY_CONFIG_FIELDS, { value: true }); + } } static enabled(ttlSec: number): DialCacheKeyConfig { @@ -168,7 +223,14 @@ function cloneLayerConfig(config: LayerConfig | undefined, name: "ttlSec" | "ram if (config === null || typeof config !== "object" || Array.isArray(config)) { throw new TypeError(`DialCache ${name} config must be a layer map`); } - return { ...config }; + const clone: LayerConfig = {}; + for (const layer of Object.values(CacheLayer)) { + const value = Object.hasOwn(config, layer) ? config[layer] : undefined; + if (value !== undefined) { + clone[layer] = value; + } + } + return clone; } function cloneShadowConfig(config: ShadowConfig | undefined): ShadowConfig | undefined { @@ -178,19 +240,37 @@ function cloneShadowConfig(config: ShadowConfig | undefined): ShadowConfig | und if (config === null || typeof config !== "object" || Array.isArray(config)) { throw new TypeError("DialCache shadow config must be an object"); } - if (Object.hasOwn(config, "logMismatches")) { - throw new TypeError('ShadowConfig.logMismatches was replaced by "shadow.mismatchLogging"'); - } - // Own-property read: inherited groups are ignored, like everything the - // spread below copies. + const ramp = Object.hasOwn(config, "ramp") ? config.ramp : undefined; const mismatchLogging = Object.hasOwn(config, "mismatchLogging") ? config.mismatchLogging : undefined; if (mismatchLogging === undefined) { - return { ...config }; + return ramp === undefined ? {} : { ramp }; } if (mismatchLogging === null || typeof mismatchLogging !== "object" || Array.isArray(mismatchLogging)) { throw new TypeError("DialCache shadow mismatchLogging config must be an object"); } - return { ...config, mismatchLogging: { ...mismatchLogging } }; + const clonedLogging: Record = {}; + for (const leaf of SHADOW_MISMATCH_LOGGING_LEAVES) { + if (Object.hasOwn(mismatchLogging, leaf)) { + clonedLogging[leaf] = mismatchLogging[leaf]; + } + } + return { + ...(ramp === undefined ? {} : { ramp }), + mismatchLogging: clonedLogging as ShadowMismatchLoggingConfig, + }; +} + +function isConfigObject(value: unknown): value is Record { + return value !== null && typeof value === "object" && !Array.isArray(value); +} + +function hasUnknownOwnFields(value: unknown, knownFields: readonly string[]): boolean { + return isConfigObject(value) + && Object.keys(value).some((name) => !knownFields.includes(name)); +} + +function readOwnUnknown(source: Record, key: string): unknown { + return Object.hasOwn(source, key) ? source[key] : undefined; } /** diff --git a/src/dialcache.ts b/src/dialcache.ts index 7c4868a..bf6e963 100644 --- a/src/dialcache.ts +++ b/src/dialcache.ts @@ -5,6 +5,7 @@ import { CacheLayer, DialCacheKeyConfig, SHADOW_MISMATCH_LOGGING_LEAVES, + hasUnknownKeyConfigFields, type Awaitable, type CacheConfigProvider, type DialCacheConfig, @@ -380,10 +381,14 @@ export class DialCache { * values are shared by reference and must be treated as immutable. */ cached(fn: Fn, options: CachedOptions): CachedFn { + const hasUnknownDefaultFields = hasUnknownKeyConfigFields(options.defaultConfig); const defaultConfig = snapshotDefaultConfig(options.defaultConfig); const fallbackTimeoutMs = resolveFallbackTimeoutMs(options.fallbackTimeoutMs); const shadowComparator = resolveShadowComparator(options.shadowComparator); this.registerUseCase(options.useCase); + if (hasUnknownDefaultFields) { + this.recordUnknownConfigFields(options); + } return (...args: Parameters): Promise> => this.executeCacheOperation( @@ -405,10 +410,14 @@ export class DialCache { * shared by reference and must be treated as immutable. */ getOrLoad(load: () => Awaitable, options: GetOrLoadOptions): Promise { + const hasUnknownDefaultFields = hasUnknownKeyConfigFields(options.defaultConfig); const defaultConfig = snapshotDefaultConfig(options.defaultConfig); const fallbackTimeoutMs = resolveFallbackTimeoutMs(options.fallbackTimeoutMs); const shadowComparator = resolveShadowComparator(options.shadowComparator); this.assertUseCaseIsNotReserved(options.useCase); + if (hasUnknownDefaultFields) { + this.recordUnknownConfigFields(options); + } return this.executeCacheOperation( load, @@ -478,7 +487,11 @@ export class DialCache { let keyConfig: DialCacheKeyConfig | null; try { - keyConfig = await fetchKeyConfig(this.configProvider, key); + keyConfig = await fetchKeyConfig( + this.configProvider, + key, + () => this.recordError(key, NO_CACHE_LAYER, "config_unknown_field"), + ); } catch (error) { // Provider failure: fail open and run uncached, mirroring the per-layer config_error path. this.logger.warn("Could not resolve DialCache key config", error); @@ -926,15 +939,6 @@ export class DialCache { return SHADOW_LOG_PLAN_OFF; } const group = configured as Record; - for (const name of Object.keys(group)) { - if (!(SHADOW_MISMATCH_LOGGING_LEAVES as readonly string[]).includes(name)) { - // Fail the whole group closed: a typo'd runtime override must not - // silently inherit enabled leaves whose failure direction is payload - // data reaching logs. One error, logging off, cache untouched. - this.recordError(key, CacheLayer.REMOTE, "config_resolution"); - return SHADOW_LOG_PLAN_OFF; - } - } let sawInvalidLeaf = false; const resolveLeaf = (name: keyof ShadowMismatchLoggingConfig): boolean => { const leaf = Object.hasOwn(group, name) ? group[name] : undefined; @@ -1327,6 +1331,17 @@ export class DialCache { this.metrics?.error({ ...labelsFor(key, layer), error: kind, inFallback: false }); } + private recordUnknownConfigFields(options: { readonly useCase: string; readonly keyType: string }): void { + this.metrics?.error({ + cacheNamespace: this.namespace, + useCase: options.useCase, + keyType: options.keyType, + layer: NO_CACHE_LAYER, + error: "config_unknown_field", + inFallback: false, + }); + } + /** * Invalid runtime TTL/ramp leaves can only come from provider results, since * static defaults are validated before the operation executes. Count them as @@ -1459,9 +1474,6 @@ function snapshotDefaultConfig(config: DialCacheKeyConfig | null | undefined): D if (typeof config !== "object" || Array.isArray(config)) { throw new TypeError("DialCache defaultConfig must be an object"); } - if (Object.hasOwn(config, "shadowRamp")) { - throw new TypeError('DialCacheKeyConfig.shadowRamp was replaced by "shadow.ramp"'); - } const ttlSecConfig = config.ttlSec; const rampConfig = config.ramp; // Own-property read, mirroring the constructor: an inherited shadow group @@ -1531,13 +1543,6 @@ function snapshotDefaultConfig(config: DialCacheKeyConfig | null | undefined): D throw new TypeError(`DialCache defaultConfig shadow.mismatchLogging.${leaf} must be a boolean`); } } - // Defaults are the strict tier: a typo'd field fails at registration - // instead of silently inheriting or disabling logging at runtime. - for (const name of Object.keys(mismatchLogging)) { - if (!(SHADOW_MISMATCH_LOGGING_LEAVES as readonly string[]).includes(name)) { - throw new TypeError(`DialCache defaultConfig shadow.mismatchLogging has unknown field "${name}"`); - } - } } } diff --git a/src/internal/runtime-config.ts b/src/internal/runtime-config.ts index 5b08043..dcb6ed5 100644 --- a/src/internal/runtime-config.ts +++ b/src/internal/runtime-config.ts @@ -2,6 +2,7 @@ import { CacheLayer, DialCacheKeyConfig, SHADOW_MISMATCH_LOGGING_LEAVES, + hasUnknownKeyConfigFields, type CacheConfigProvider, type LayerConfig, type ShadowConfig, @@ -39,12 +40,16 @@ interface ResolveLayerConfigOptions { export async function fetchKeyConfig( configProvider: CacheConfigProvider, key: DialCacheKey, + onUnknownFields?: () => void, ): Promise { const defaultConfig = key.defaultConfig; const runtimeConfig = (await configProvider(key)) as DialCacheKeyConfig | null | undefined; if (runtimeConfig === null || runtimeConfig === undefined) { return defaultConfig; } + if (hasUnknownKeyConfigFields(runtimeConfig)) { + onUnknownFields?.(); + } return mergeKeyConfig(defaultConfig, runtimeConfig); } @@ -133,9 +138,6 @@ function assertKeyConfig(config: DialCacheKeyConfig | null | undefined): void { if (config !== null && config !== undefined && (typeof config !== "object" || Array.isArray(config))) { throw new TypeError("DialCache key config must be an object"); } - if (config !== null && config !== undefined && Object.hasOwn(config, "shadowRamp")) { - throw new TypeError('DialCacheKeyConfig.shadowRamp was replaced by "shadow.ramp"'); - } } function mergeLayerConfig( @@ -198,24 +200,7 @@ function mergeMismatchLoggingConfig( return undefined; } - // Unknown own keys survive the merge so admission can fail the whole group - // closed and record a config_resolution error. Rebuilding from known leaves - // alone would silently drop a typo'd override (e.g. `vaule: false`) while - // the inherited enabled leaves kept logging payload data. const merged: Record = {}; - for (const source of [defaults, overlay]) { - if (source === undefined) { - continue; - } - for (const name of Object.keys(source)) { - if ((SHADOW_MISMATCH_LOGGING_LEAVES as readonly string[]).includes(name)) { - continue; - } - // Presence, not value, makes this field unknown. Preserve even an - // explicit `undefined` so admission can reject the closed schema. - merged[name] = (source as Record)[name]; - } - } for (const leaf of SHADOW_MISMATCH_LOGGING_LEAVES) { const overlayValue = readOwn(overlay, leaf); const value = overlayValue !== undefined ? overlayValue : readOwn(defaults, leaf); @@ -238,9 +223,6 @@ function assertShadowConfig(config: ShadowConfig | undefined): void { if (config !== undefined && (config === null || typeof config !== "object" || Array.isArray(config))) { throw new TypeError("DialCache shadow config must be an object"); } - if (config !== undefined && Object.hasOwn(config, "logMismatches")) { - throw new TypeError('ShadowConfig.logMismatches was replaced by "shadow.mismatchLogging"'); - } } function assertMismatchLoggingConfig(config: ShadowMismatchLoggingConfig | undefined): void { diff --git a/src/metrics.ts b/src/metrics.ts index 998469f..67c1ea6 100644 --- a/src/metrics.ts +++ b/src/metrics.ts @@ -43,10 +43,11 @@ export type CompressionOutcome = | "read_over_limit"; /** Bounded reasons for skipping cache work; policy_disabled means a shared layer has no effective TTL. */ export type DisabledReason = "context" | "policy_disabled" | "invalid_ttl" | "invalid_ramp" | "ramped_down" | "config_error"; -/** Stable failure sites used instead of backend- or application-defined error names. */ +/** Stable operational categories used instead of backend- or application-defined error names. */ export type MetricErrorKind = | "key_construction" | "config_resolution" + | "config_unknown_field" | "cache_read" | "cache_read_timeout" | "cache_write" diff --git a/test/datadog.test.ts b/test/datadog.test.ts index fbb6b93..5ac1a45 100644 --- a/test/datadog.test.ts +++ b/test/datadog.test.ts @@ -93,6 +93,7 @@ const disabledReasons = Object.keys(DISABLED_REASONS) as DisabledReason[]; const ERROR_KINDS: Readonly> = { key_construction: true, config_resolution: true, + config_unknown_field: true, cache_read: true, cache_read_timeout: true, cache_write: true, diff --git a/test/dialcache-config-ramp.test.ts b/test/dialcache-config-ramp.test.ts index bf39a06..81acab9 100644 --- a/test/dialcache-config-ramp.test.ts +++ b/test/dialcache-config-ramp.test.ts @@ -66,10 +66,28 @@ describe("DialCache runtime config and ramp controls", () => { }); }); - it("rejects the removed shadow logMismatches flag", () => { - expect(() => new DialCacheKeyConfig({ - shadow: { logMismatches: true } as never, - })).toThrow('ShadowConfig.logMismatches was replaced by "shadow.mismatchLogging"'); + it("ignores unknown own fields while preserving every known config field", () => { + const config = new DialCacheKeyConfig({ + ttlSec: { [CacheLayer.LOCAL]: 60, edge: 120 } as never, + ramp: { [CacheLayer.LOCAL]: 100, edge: 50 } as never, + shadow: { + ramp: 25, + logMismatches: true, + futureShadowField: true, + mismatchLogging: { key: true, vaule: false }, + }, + requestLocal: true, + futureTopLevelField: true, + } as never); + + expect(config.ttlSec).toEqual({ [CacheLayer.LOCAL]: 60 }); + expect(config.ramp).toEqual({ [CacheLayer.LOCAL]: 100 }); + expect(config.shadow).toEqual({ + ramp: 25, + mismatchLogging: { key: true }, + }); + expect(config.requestLocal).toBe(true); + expect(Object.keys(config)).not.toContain("futureTopLevelField"); }); it("ignores a prototype-inherited shadow group at the constructor boundary", () => { @@ -376,11 +394,6 @@ describe("DialCache runtime config and ramp controls", () => { () => new DialCacheKeyConfig({ shadow: [] as never }), "DialCache shadow config must be an object", ], - [ - "the removed shadowRamp field", - () => new DialCacheKeyConfig({ shadowRamp: 100 } as never), - 'DialCacheKeyConfig.shadowRamp was replaced by "shadow.ramp"', - ], ])("rejects $0 in the public config constructor", (_name, construct, message) => { expect(construct).toThrow(message); }); @@ -447,18 +460,6 @@ describe("DialCache runtime config and ramp controls", () => { TypeError, "shadow.mismatchLogging.value must be a boolean", ], - [ - "unknown shadow mismatch logging field", - new DialCacheKeyConfig({ shadow: { mismatchLogging: { vaule: true } as never } }), - TypeError, - 'shadow.mismatchLogging has unknown field "vaule"', - ], - [ - "removed shadow logMismatches", - { ttlSec: {}, ramp: {}, shadow: { logMismatches: true } } as unknown as DialCacheKeyConfig, - TypeError, - 'logMismatches was replaced by "shadow.mismatchLogging"', - ], ["primitive config", 42 as unknown as DialCacheKeyConfig, TypeError, "must be an object"], ["array config", [] as unknown as DialCacheKeyConfig, TypeError, "must be an object"], [ @@ -473,12 +474,6 @@ describe("DialCache runtime config and ramp controls", () => { TypeError, "shadow must be an object", ], - [ - "removed shadowRamp", - { ttlSec: {}, ramp: {}, shadowRamp: 100 } as unknown as DialCacheKeyConfig, - TypeError, - 'shadowRamp was replaced by "shadow.ramp"', - ], [ "a null coalesce value", { ttlSec: {}, ramp: {}, coalesce: null } as unknown as DialCacheKeyConfig, @@ -516,8 +511,6 @@ describe("DialCache runtime config and ramp controls", () => { ["an array", []], ["a null layer map", { ttlSec: null, ramp: {} }], ["an array shadow config", { ttlSec: {}, ramp: {}, shadow: [] }], - ["the removed shadowRamp field", { ttlSec: {}, ramp: {}, shadowRamp: 100 }], - ["the removed shadow logMismatches field", { ttlSec: {}, ramp: {}, shadow: { logMismatches: true } }], ["a non-object shadow mismatchLogging group", { ttlSec: {}, ramp: {}, shadow: { mismatchLogging: null } }], ["a null requestLocal value", { ttlSec: {}, ramp: {}, requestLocal: null }], ["a null coalesce value", { ttlSec: {}, ramp: {}, coalesce: null }], diff --git a/test/dialcache-metrics.test.ts b/test/dialcache-metrics.test.ts index 15f5fa1..b2c68dc 100644 --- a/test/dialcache-metrics.test.ts +++ b/test/dialcache-metrics.test.ts @@ -80,6 +80,74 @@ const remoteOnly = () => const tick = (): Promise => new Promise((resolve) => setTimeout(resolve, 0)); describe("DialCache observability metrics", () => { + it("reports one bounded error while ignoring unknown static config fields", async () => { + const metrics = new RecordingMetrics(); + const defaultConfig = new DialCacheKeyConfig({ + ttlSec: { [CacheLayer.LOCAL]: 60, future: 1 } as never, + ramp: { [CacheLayer.LOCAL]: 100 }, + shadow: { + logMismatches: true, + mismatchLogging: { key: true, vaule: false }, + }, + shadowRamp: 100, + futureTopLevel: true, + } as never); + const dialcache = new DialCache({ metrics }); + let calls = 0; + const getUser = dialcache.cached(async (id: string) => ({ id, calls: ++calls }), { + keyType: "user_id", + useCase: "UnknownStaticConfigFields", + cacheKey: (id) => id, + defaultConfig, + }); + + await dialcache.enable(async () => await getUser("123")); + await dialcache.enable(async () => await getUser("123")); + + const warnings = events(metrics, "error", { + useCase: "UnknownStaticConfigFields", + layer: "noop", + error: "config_unknown_field", + inFallback: false, + }); + expect(warnings).toHaveLength(1); + expect(calls).toBe(1); + expect(JSON.stringify(warnings)).not.toMatch(/future|logMismatches|shadowRamp|vaule/); + }); + + it("reports once per runtime config while applying its known fields", async () => { + const metrics = new RecordingMetrics(); + const cacheConfigProvider = vi.fn(async () => ({ + ttlSec: { [CacheLayer.LOCAL]: 60, future: 1 }, + ramp: { [CacheLayer.LOCAL]: 100, future: 50 }, + shadow: { + logMismatches: true, + future: true, + mismatchLogging: { vaule: false }, + }, + future: true, + }) as unknown as DialCacheKeyConfig); + const dialcache = new DialCache({ metrics, cacheConfigProvider }); + let calls = 0; + const getUser = dialcache.cached(async (id: string) => ({ id, calls: ++calls }), { + keyType: "user_id", + useCase: "UnknownRuntimeConfigFields", + cacheKey: (id) => id, + }); + + await dialcache.enable(async () => await getUser("123")); + await dialcache.enable(async () => await getUser("123")); + + expect(cacheConfigProvider).toHaveBeenCalledTimes(2); + expect(calls).toBe(1); + expect(events(metrics, "error", { + useCase: "UnknownRuntimeConfigFields", + layer: "noop", + error: "config_unknown_field", + inFallback: false, + })).toHaveLength(2); + }); + it("consumes rejecting thenables returned by every metrics method without awaiting them", async () => { const then = vi.fn(( _onFulfilled: ((value: unknown) => unknown) | null | undefined, diff --git a/test/dialcache-shadow-confirmation.test.ts b/test/dialcache-shadow-confirmation.test.ts index 6d9a77b..c72e603 100644 --- a/test/dialcache-shadow-confirmation.test.ts +++ b/test/dialcache-shadow-confirmation.test.ts @@ -2122,15 +2122,13 @@ describe("DialCache Redis shadow confirmation", () => { it.each([ ["false", false], ["undefined", undefined], - ] as const)("fails the whole logging group closed when an unknown field is $0", async (suffix, value) => { + ] as const)("ignores an unknown logging field set to $0 while preserving known fields", async (suffix, value) => { const useCase = `ShadowUnknownLoggingLeaf${suffix}`; const payload = JSON.stringify({ id: "123", version: 1 }); const redis = new ScriptedRedis([() => payload, () => payload]); const metrics = new RecordingMetrics(); const warn = vi.fn(); const dialcache = createCache(redis, metrics, { - // Presence alone makes this a closed-schema violation. Even undefined - // must survive the merge so inherited logging cannot remain enabled. cacheConfigProvider: async () => new DialCacheKeyConfig({ shadow: { mismatchLogging: { vaule: value } as never }, }), @@ -2151,10 +2149,22 @@ describe("DialCache Redis shadow confirmation", () => { expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch"]); expect(metrics.ordinaryEvents.filter(({ name: metricName, labels }) => metricName === "error" - && labels.layer === CacheLayer.REMOTE - && labels.error === "config_resolution" + && labels.layer === "noop" + && labels.error === "config_unknown_field" )).toHaveLength(1); - expect(warn).not.toHaveBeenCalled(); + expect(warn).toHaveBeenCalledWith( + "DialCache shadow validation mismatch", + { + cacheNamespace: "urn", + useCase, + keyType: "user_id", + outcome: "mismatch", + cachedValueAgeSeconds: expect.any(Number), + cacheKey: `{urn:user_id:123}#${useCase}`, + cachedValueJson: '{"id":"123","version":1}', + sourceValueJson: '{"id":"123","version":2}', + }, + ); }); it("resolves an invalid mismatch logging leaf to off without suppressing valid leaves", async () => { diff --git a/test/prometheus.test.ts b/test/prometheus.test.ts index bcfebbc..da28555 100644 --- a/test/prometheus.test.ts +++ b/test/prometheus.test.ts @@ -40,6 +40,7 @@ const CONFIGURED_TIMER_BUCKETS = [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0. const METRIC_ERROR_KINDS: Readonly> = { key_construction: true, config_resolution: true, + config_unknown_field: true, cache_read: true, cache_read_timeout: true, cache_write: true,