diff --git a/design/2026-10-24-shadow-mismatch-paths.md b/design/2026-10-24-shadow-mismatch-paths.md index 38570168..65d85349 100644 --- a/design/2026-10-24-shadow-mismatch-paths.md +++ b/design/2026-10-24-shadow-mismatch-paths.md @@ -2,7 +2,7 @@ - **Status:** Implemented - **Issue:** #243, which tracked the work after the TypeScript reference; #242 completes it -- **Pull requests:** #242 +- **Pull requests:** #242, #250 - **Baseline:** `main` at `b4e4fba`, the commit the record was written against - **Supersedes:** the design in pull request #138, which is unmerged; the decisions it carries are listed under [Carried decisions](#carried-decisions) @@ -998,3 +998,29 @@ Reviewed and approved by the maintainer on #138; carried unchanged: `kernel/shadow.qnt` with logging off. `kernel/shadow.qnt` keeps the captured `Logging` leaves, `LOGGING_OFF`, `logs` and the diff levels, and does not import the new module. +- **2026-10-28, #250, TypeScript:** at the maintainer's request in session + that day ("how we can leverage setImmediete and some other optimizations to + make sure we are not taking as long and also we are not blocking event + loop and also that its still correct"), the warning returns to the event + loop after each native rendering or parse of a side whose rendering is at + least 65,536 UTF-16 code units long; each such step, the walk and the hook + still run without a break. The replay histories' values are shorter than + that, so they replay the warning as one step, and native tests cover the + breaks. The warning also holds the job's shadow capacity slot until it + reaches the logger, as Go and Rust do, so Failure handling's "TypeScript + and Python render after the slot is released" no longer holds for + TypeScript; the slot stays a port detail. With the default + `JsonSerializer`, the walk reads the cached value that `JSON.parse` of the + payload produced instead of parsing that side's rendering again, comparing + a number beyond double range as the `null` the rendering writes. The two + hold the same JSON, so the output D3 and step 1 of the computation describe + is unchanged; only a comparator that mutates the cached value, which its + contract forbids, can make the diff name members that `cachedValueJson` + does not show, or fail the warning with `render_error`. The walk also skips + members and items whose values are identical before sorting, and a + built-in `diffJson` side is rendered only as far as its 1 KiB clamp reads. + The vectors, the existing tests and a seeded fuzz against `main` at + `bae1e5e` agree on every output. On one Apple-silicon Mac, with the + default `JsonSerializer`, a 7.3 MB object of 150,000 string members took + about 0.11 s per warning at `diff: "paths"`, against 0.14 s on `main`, in + steps of at most about 0.03 s, and 0.05 s for the value fields alone. diff --git a/docs/shadow-validation.md b/docs/shadow-validation.md index 7867bf39..cc6cb26f 100644 --- a/docs/shadow-validation.md +++ b/docs/shadow-validation.md @@ -305,7 +305,8 @@ holding the shadow slot after timeout. Scheduling and shadow deadline timers are unreferenced and do not keep an otherwise idle Node process alive. Detachment uses the event loop, not a worker; synchronous source, codec, comparator and logger work still consumes it, as do -mismatch-warning rendering and `shadowMismatchDiff`. +mismatch-warning rendering and `shadowMismatchDiff`. A mismatch warning keeps +the job's capacity until it reaches the logger. @@ -692,10 +693,20 @@ const getUser = dialcache.cached(fetchUser, { }); ``` -Rendering, the walk, and the hook run on the event loop after the job releases -its capacity slot. On one Apple-silicon Mac, a 6.3 MB object of 150,000 members -took about 0.12 seconds per warning at `diff: "paths"`, against 0.06 seconds for -the value fields alone. +Rendering, the walk, and the hook run on the event loop after the verdict and +hold the job's shadow capacity until the warning reaches the logger, so while +one is built, further jobs for the same key and jobs beyond capacity report +`dropped`. After each `JSON.stringify` or `JSON.parse` of a side whose rendering +is at least 65,536 characters long, the warning returns to the event loop, so +other work runs between those steps; each of them, the walk and the hook still +run without a break. With the default `JsonSerializer`, the walk reads the +cached value as it was decoded instead of parsing its rendering again, so a +comparator that mutates the cached value, which its contract forbids, can make +the diff name members that `cachedValueJson` does not show, or fail the +warning with `render_error`. On one Apple-silicon Mac, with the default +`JsonSerializer`, a 7.3 MB object of 150,000 string members took about 0.11 +seconds per warning at `diff: "paths"`, in steps of at most about 0.03 seconds, +against 0.05 seconds for the value fields alone. diff --git a/docs/upgrading.md b/docs/upgrading.md index e740c418..75544480 100644 --- a/docs/upgrading.md +++ b/docs/upgrading.md @@ -243,9 +243,18 @@ characters. `DialCacheKeyConfig.disabled()` now turns logging off with `shadow.mismatchLogging: { value: false, diff: "off" }` in place of -`shadow.logMismatches: false`. On one Apple-silicon Mac, a 6.3 MB object of -150,000 members took about 0.12 seconds per warning at `diff: "paths"`, against -0.06 seconds for the value fields alone. +`shadow.logMismatches: false`. On one Apple-silicon Mac, with the default +`JsonSerializer`, a 7.3 MB object of 150,000 string members took about 0.11 +seconds per warning at `diff: "paths"`, against 0.05 seconds for the value +fields alone. + +A warning now holds the job's shadow capacity until it reaches the logger, as +in Go and Rust; earlier releases released it before building the warning. So +while a warning is built, further jobs for the same key and jobs beyond +`shadowMaxInFlight` report `dropped`. For a side whose rendering is at least +65,536 characters long, the warning returns to the event loop after each +`JSON.stringify` and `JSON.parse` of it, in steps of at most about 0.03 seconds +on that object. diff --git a/formal/catalogs/feature-coverage.json b/formal/catalogs/feature-coverage.json index f1f96edc..e620ac0d 100644 --- a/formal/catalogs/feature-coverage.json +++ b/formal/catalogs/feature-coverage.json @@ -1547,19 +1547,19 @@ "test": "byte-clamps keys and JSON without splitting UTF-8 sequences", "path": "typescript/test/shadow-log-json.test.ts", "scope": "Asserts that the TypeScript binding byte-clamps keys and JSON without splitting UTF-8 sequences.", - "sha256": "2dab2b5558563125f731410b170a41c8c216ff28d54a012b3744ce387c99213f" + "sha256": "e14254c394cef87dc3ab5cd71a40550738dc8dba4eda5a35903b6dcb7e64664b" }, { "test": "catches user JSON hook failures", "path": "typescript/test/shadow-log-json.test.ts", "scope": "Asserts that the TypeScript binding catches user JSON hook failures.", - "sha256": "2dab2b5558563125f731410b170a41c8c216ff28d54a012b3744ce387c99213f" + "sha256": "e14254c394cef87dc3ab5cd71a40550738dc8dba4eda5a35903b6dcb7e64664b" }, { "test": "returns null independently for values that native JSON cannot serialize", "path": "typescript/test/shadow-log-json.test.ts", "scope": "Asserts that the TypeScript binding returns null independently for values that native JSON cannot serialize.", - "sha256": "2dab2b5558563125f731410b170a41c8c216ff28d54a012b3744ce387c99213f" + "sha256": "e14254c394cef87dc3ab5cd71a40550738dc8dba4eda5a35903b6dcb7e64664b" } ], "go": [ diff --git a/formal/catalogs/go-parity.json b/formal/catalogs/go-parity.json index 245317b4..276e230c 100644 --- a/formal/catalogs/go-parity.json +++ b/formal/catalogs/go-parity.json @@ -10,8 +10,8 @@ "inputs": { "semanticCasesSha256": "380273598e1d956a3f9fce270cc84424b342e456139b279bd56576bd3b837f65", "executionSha256": "eaf117c3e8630013cc8df0524f84af440c470f42e8711ab4dd07b931161c784f", - "sourceAuditDispositionsSha256": "c95ce03c30df574246e5943e2d69e084ed809b5d3e2a3d0f0abf5a2123bc8aaa", - "featureCoverageSha256": "3f33092274a0046c2d793790b1b4999021021e018f47ae65c15d3a0313776fd2", + "sourceAuditDispositionsSha256": "308073255328096e21c27cfa90e73e6d9e39bf9e2aad15e73abd10a390480230", + "featureCoverageSha256": "e494cdc5c0d26f495de2fe780b5c43d2e028d252cfaa6e8a10c544b6d58d1584", "coverageWitnessesSha256": "745cebececddbfa97912621ada94072d648e8e60e8b3eb013b91eefd16f352a1", "profilesSha256": "888a522f8ad97862ebcb0b5fe363ec7bec60367fa42c60e1623141814b1991b3" }, @@ -21,7 +21,7 @@ "withoutRequiredGeneratedWitnesses": [], "wireCases": 23, "sourceFiles": 28, - "sourceDeclarations": 878, + "sourceDeclarations": 887, "casesWithScheduledChecks": 272, "requiredWitnesses": 535, "casesWithQuintRegressionReplay": 198, @@ -3499,7 +3499,7 @@ }, { "path": "typescript/src/dialcache.ts", - "sha256": "88e1e9bdf70bba085f4c8f2861cfac89ec021a5af318e21dc94e9f54c75b583c", + "sha256": "04d7eda97dd9da30e3d7fe97117de4f69e4ad7d43ecd8ff1ba9f2b2a61118e6c", "candidateGoFiles": [ "go/cache.go", "go/bindings.go", @@ -3511,7 +3511,7 @@ ], "mappingReview": { "status": "reviewed-mapping-not-execution", - "rationale": "The public orchestration is divided into Cache lifecycle, Cached registration, GetOrLoad execution, source/read deadlines and detached shadow work. GetOrLoad snapshots inputs before awaiting policy; singleFlight owns leaders/followers. Go contexts, generics, returned errors and recovered callback panics replace TypeScript overloads, promises and exceptions; default diagnostic logging lives in an internal package, while public logger callbacks and inspection remain root-package bindings. The warning's leaves come from the invocation's ResolvedShadow, Operation.MismatchDiff replaces the built-in walk, and warnShadowMismatch emits one shadowMismatchLogging event; a Warn panic is the Go logger_error.", + "rationale": "The public orchestration is divided into Cache lifecycle, Cached registration, GetOrLoad execution, source/read deadlines and detached shadow work. GetOrLoad snapshots inputs before awaiting policy; singleFlight owns leaders/followers. Go contexts, generics, returned errors and recovered callback panics replace TypeScript overloads, promises and exceptions; default diagnostic logging lives in an internal package, while public logger callbacks and inspection remain root-package bindings. The warning's leaves come from the invocation's ResolvedShadow, Operation.MismatchDiff replaces the built-in walk, and warnShadowMismatch emits one shadowMismatchLogging event; a Warn panic is the Go logger_error. Both ports hold the job's shadow capacity until the warning is logged; TypeScript returns to the event loop between the native JSON steps of a long side, where Go builds the warning on the job's goroutine.", "nativeAdaptations": [ "B01", "B02", @@ -3918,7 +3918,7 @@ }, { "path": "typescript/src/internal/redis-cache.ts", - "sha256": "6fd0f9d16289efd66d60cfdf538d44fb520301a45634f72c5aaaaf4f79deae79", + "sha256": "3c6e14bc665a7807870752d8a346144efa4e7b892a4d4087465a33cce78b4143", "candidateGoFiles": [ "go/engine.go", "go/shadow.go", @@ -3927,7 +3927,7 @@ ], "mappingReview": { "status": "reviewed-mapping-not-execution", - "rationale": "Serving, retained stale recovery, compression, timestamp validation and local publication are in execution methods; detached shadow validation is separate. A raw semantic read is normalized before serving, elapsed deadlines retain acquired snapshots, and both tracked refill timestamp checks precede a complete frame write.", + "rationale": "Serving, retained stale recovery, compression, timestamp validation and local publication are in execution methods; detached shadow validation is separate. A raw semantic read is normalized before serving, elapsed deadlines retain acquired snapshots, and both tracked refill timestamp checks precede a complete frame write. loadsParsedJson, which lets the TypeScript warning walk the JSON serializer's decoded value, is a TypeScript speed-up with no Go counterpart.", "nativeAdaptations": [ "B02", "B03" @@ -4116,7 +4116,7 @@ }, { "path": "typescript/src/internal/shadow-log-json.ts", - "sha256": "ddab3366b00b83f19c796f3e457b9a12dc422e61f3f2b1b1d1c41731785687d5", + "sha256": "d87c767194f855013cf2626e77abe82e7106e9d1145b9d51337a098f669e2bdb", "candidateGoFiles": [ "go/metrics.go", "go/codec.go", @@ -4124,7 +4124,7 @@ ], "mappingReview": { "status": "reviewed-mapping-not-execution", - "rationale": "Warning content renders each compared value once with the Go JSON compatibility writer; the built-in walk runs over the parsed renderings with the same member order, array rule, root cases, depth cap (deep equality past it) and caps, materializing only the kept pointers up to their clamp, and the MismatchDiff hook's entries take the same clamps. Byte-bounded UTF-8 output uses the same truncation marker; a failure nulls only the fields it feeds and cannot suppress the verdict or caller result. Native type representation is a codec binding (B03): Go's decoder fails a rendering nested past 10,000 levels as hook_error. Hook entry sides honor json.Marshaler at every depth, as TypeScript sides honor toJSON, while the codec stored encoding reaches MarshalJSON only through a struct.", + "rationale": "Warning content renders each compared value once with the Go JSON compatibility writer; the built-in walk runs over the parsed renderings with the same member order, array rule, root cases, depth cap (deep equality past it) and caps, materializing only the kept pointers up to their clamp, and the MismatchDiff hook's entries take the same clamps. TypeScript's walk reads the JSON serializer's decoded cached value in place of a second parse, skips identical members and items, and renders a built-in side only as far as its clamp reads; the output is the same. Byte-bounded UTF-8 output uses the same truncation marker; a failure nulls only the fields it feeds and cannot suppress the verdict or caller result. Native type representation is a codec binding (B03): Go's decoder fails a rendering nested past 10,000 levels as hook_error. Hook entry sides honor json.Marshaler at every depth, as TypeScript sides honor toJSON, while the codec stored encoding reaches MarshalJSON only through a struct.", "nativeAdaptations": [ "B03", "X01", diff --git a/formal/catalogs/mutations.json b/formal/catalogs/mutations.json index c09130dc..93a3f3c6 100644 --- a/formal/catalogs/mutations.json +++ b/formal/catalogs/mutations.json @@ -1992,8 +1992,8 @@ "edits": [ { "path": "typescript/src/dialcache.ts", - "before": "if (operationFinished && pendingRedisReads.size === 0) {", - "after": "if (operationFinished) {" + "before": "if (operationFinished && !warningPending && pendingRedisReads.size === 0) {", + "after": "if (operationFinished && !warningPending) {" } ], "requiredDetections": [ @@ -2153,8 +2153,8 @@ "edits": [ { "path": "typescript/src/internal/shadow-log-json.ts", - "before": " if (kind !== jsonKind(right) || kind === \"primitive\") {\n if (left !== right) {", - "after": " if (kind !== jsonKind(right)) {\n return;\n }\n if (kind === \"primitive\") {\n if (left !== right) {" + "before": " if (kind !== jsonKind(right) || kind === \"primitive\") {\n if (jsonLeaf(left) !== jsonLeaf(right)) {", + "after": " if (kind !== jsonKind(right)) {\n return;\n }\n if (kind === \"primitive\") {\n if (jsonLeaf(left) !== jsonLeaf(right)) {" } ], "requiredDetections": [ @@ -2180,7 +2180,7 @@ "id": "M68", "case": "W10.mismatch-paths", "description": "Treat an absent compared value as a value with no JSON rendering", - "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts renderShadowMismatchLog counts any side without a rendering as a render failure, the top-level undefined included; Go go/shadow_log.go renderRoot reports an Absent root as failed; Rust rust/src/shadow_log.rs rendered_side maps the absent marker to a side with no rendering. An absent side against a present one therefore logs null difference fields with render_error instead of one entry at \"\" carrying the present side (D13). TypeScript and Go also fail the value fields this way, while Rust's value fields keep their absent handling. The shadow profile has no absent value, so only the absent-side vectors reach the rule.", + "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts shadowMismatchLogSteps counts any side without a rendering as a render failure, the top-level undefined included; Go go/shadow_log.go renderRoot reports an Absent root as failed; Rust rust/src/shadow_log.rs rendered_side maps the absent marker to a side with no rendering. An absent side against a present one therefore logs null difference fields with render_error instead of one entry at \"\" carrying the present side (D13). TypeScript and Go also fail the value fields this way, while Rust's value fields keep their absent handling. The shadow profile has no absent value, so only the absent-side vectors reach the rule.", "typescript": { "edits": [ { @@ -2212,13 +2212,13 @@ "id": "M69", "case": "C60.logging-outcomes", "description": "Fall back to the built-in walk when the mismatch diff hook fails", - "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts renderShadowMismatchLog, Go go/shadow_log.go renderShadowMismatchLog and Rust rust/src/shadow_log.rs render_mismatch_log keep the hook_error outcome when the shadowMismatchDiff hook fails but then walk both renderings, unless a rendering already failed, and log the walk's paths, count and entries. The warning therefore carries difference fields the use case's hook did not produce instead of null ones (D6). Each port renders the sides for the fallback itself, since with a hook and value off the warning renders neither.", + "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts shadowMismatchLogSteps, Go go/shadow_log.go renderShadowMismatchLog and Rust rust/src/shadow_log.rs render_mismatch_log keep the hook_error outcome when the shadowMismatchDiff hook fails but then walk both renderings, unless a rendering already failed, and log the walk's paths, count and entries. The warning therefore carries difference fields the use case's hook did not produce instead of null ones (D6). Each port renders the sides for the fallback itself, since with a hook and value off the warning renders neither.", "typescript": { "edits": [ { "path": "typescript/src/internal/shadow-log-json.ts", "before": " diff = runShadowMismatchHook(hook, cachedValue, sourceValue);\n diffFailed = diff === null;", - "after": " diff = runShadowMismatchHook(hook, cachedValue, sourceValue);\n diffFailed = diff === null;\n if (diff === null && !renderFailed) {\n diff = walkRenderedJson(renderJson(cachedValue), renderJson(sourceValue));\n }" + "after": " diff = runShadowMismatchHook(hook, cachedValue, sourceValue);\n diffFailed = diff === null;\n if (diff === null && !renderFailed) {\n diff = yield* walkRenderedJson(renderJson(cachedValue), renderJson(sourceValue), undefined);\n }" } ], "requiredDetections": [ @@ -2245,7 +2245,7 @@ "id": "M70", "case": "C60.outcome-precedence", "description": "Run the mismatch diff hook when diff is off", - "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts renderShadowMismatchLog, Go go/shadow_log.go renderShadowMismatchLog and Rust rust/src/shadow_log.rs render_mismatch_log call the shadowMismatchDiff hook when the captured diff leaf is off and record its failure as the warning's failure. A warning that logs only the value fields therefore reports hook_error from a hook that should never have run, outranking the render_error or logged outcome it owes.", + "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts shadowMismatchLogSteps, Go go/shadow_log.go renderShadowMismatchLog and Rust rust/src/shadow_log.rs render_mismatch_log call the shadowMismatchDiff hook when the captured diff leaf is off and record its failure as the warning's failure. A warning that logs only the value fields therefore reports hook_error from a hook that should never have run, outranking the render_error or logged outcome it owes.", "typescript": { "edits": [ { @@ -2311,7 +2311,7 @@ "id": "M72", "case": "C60.outcome-precedence", "description": "Report render_error over hook_error when both fail", - "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts renderShadowMismatchLog, Go go/shadow_log.go renderShadowMismatchLog and Rust rust/src/shadow_log.rs render_mismatch_log check the render failure before the difference-computation failure when they name the warning's failure. A failing shadowMismatchDiff hook beside a side with no JSON rendering therefore reports render_error, as the warning's loggingOutcome and the shadowMismatchLogging event, instead of hook_error.", + "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts shadowMismatchLogSteps, Go go/shadow_log.go renderShadowMismatchLog and Rust rust/src/shadow_log.rs render_mismatch_log check the render failure before the difference-computation failure when they name the warning's failure. A failing shadowMismatchDiff hook beside a side with no JSON rendering therefore reports render_error, as the warning's loggingOutcome and the shadowMismatchLogging event, instead of hook_error.", "typescript": { "edits": [ { @@ -2410,7 +2410,7 @@ "id": "M75", "case": "C60.warning-field-groups", "description": "Log the difference entries with their values at diff paths", - "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts renderShadowMismatchLog, Go go/shadow_log.go renderShadowMismatchLog and Rust rust/src/shadow_log.rs render_mismatch_log treat every diff level above off as values, so a warning at diff paths also carries diffJson with each entry's cached and source sides. The paths level, which a cache of user data can leave on in production, therefore logs values.", + "rationale": "TypeScript typescript/src/internal/shadow-log-json.ts shadowMismatchLogSteps, Go go/shadow_log.go renderShadowMismatchLog and Rust rust/src/shadow_log.rs render_mismatch_log treat every diff level above off as values, so a warning at diff paths also carries diffJson with each entry's cached and source sides. The paths level, which a cache of user data can leave on in production, therefore logs values.", "typescript": { "edits": [ { diff --git a/formal/catalogs/source-audit.json b/formal/catalogs/source-audit.json index 69623d06..75e8691f 100644 --- a/formal/catalogs/source-audit.json +++ b/formal/catalogs/source-audit.json @@ -283,7 +283,7 @@ }, { "path": "docs/shadow-validation.md", - "sha256": "e318acf6936ad4c9126363eff2c803d00a20596f92a00c543e645cb6ca765c34", + "sha256": "0d3939165eb2e9f598b3f9dd73416bbf02e51687dd4016081de4f28bad7607cc", "entries": [ {"title":"Shadow validation","contracts":["C47"]}, {"title":"What a check establishes","contracts":["C50","C51"]}, @@ -319,7 +319,7 @@ }, { "path": "docs/upgrading.md", - "sha256": "f35d61a95ac2f9ad9dcc5d1f86c5b151b1260f7e7679f75a161777cbe39e8e84", + "sha256": "025578fcc08746c0e943bc6c4a98ffb33f46a4a9479c33ef65e49798a9531740", "entries": [ {"title":"Upgrading","contracts":["E05"]}, {"title":"Tracked protocol cutover","contracts":["E05","W09"]}, @@ -758,7 +758,7 @@ }, { "path": "typescript/test/dialcache-shadow-confirmation.test.ts", - "sha256": "db7d43c1428fbf4a84bcde1dc3876a1b56508b26309c25faf99d4ae95d7145a1", + "sha256": "eb7c7a0cc6a6a9caf0ddfaa509b88b20192400d83a7f30b0802f3f1b9291228f", "entries": [ {"title":"skips confirmation when the served Redis payload semantically matches SoT","contracts":["C50"]}, {"title":"confirms a mismatch only when C1 is byte-identical to the served C0","contracts":["C51"]}, @@ -774,6 +774,9 @@ {"title":"logs the exact value age the verdict observed as cachedValueAgeSeconds","contracts":["C57","C60"]}, {"title":"logs the documented GetUser example at diff $diff","contracts":["C60","X01"]}, {"title":"emits one logged event per confirmed mismatch after its verdict and none for a match","contracts":["C60","X01"]}, + {"title":"returns to the event loop while it builds a long warning and holds the shadow slot until it logs","contracts":["C54","C60","B02"]}, + {"title":"frees the shadow slot when the deadline rejects a confirmed mismatch as it settles","contracts":["C54","C60","B02"]}, + {"title":"walks a custom serializer's value from its rendering","contracts":["C60","B03"]}, {"title":"rejects %s as shadowMismatchDiff where each API captures it","contracts":["B01"]}, {"title":"logs shadowMismatchDiff entries in place of the built-in walk through %s()","contracts":["C60"]}, {"title":"logs null diff fields and hook_error without touching the verdict when the hook $name","contracts":["C30","C60"]}, @@ -1080,7 +1083,7 @@ }, { "path": "typescript/test/shadow-log-json.test.ts", - "sha256": "2dab2b5558563125f731410b170a41c8c216ff28d54a012b3744ce387c99213f", + "sha256": "e14254c394cef87dc3ab5cd71a40550738dc8dba4eda5a35903b6dcb7e64664b", "entries": [ {"title":"uses native JSON for the values supplied to the comparator","contracts":["B03","X01"]}, {"title":"returns null independently for values that native JSON cannot serialize","contracts":["B03","X01"]}, @@ -1094,6 +1097,8 @@ {"title":"clamps each pointer to 512 bytes without splitting UTF-8 sequences","contracts":["W10","X01"]}, {"title":"builds each kept pointer only as far as its clamp reads, however long the member names above it","contracts":["W10","X01"]}, {"title":"replaces each side over 1 KiB with its clamped JSON text","contracts":["W10","X01"]}, + {"title":"renders a long built-in side only as far as its clamp reads","contracts":["X01","X02"]}, + {"title":"reports equal-length array items that differ in JSON type","contracts":["W10","C60"]}, {"title":"caps the walk at 32 reference tokens however deep the difference lies","contracts":["W10","C60","X01"]}, {"title":"compares equal containers past the depth cap regardless of member order and depth","contracts":["W10","C60","X01"]}, {"title":"renders exactly the fields requested by %s","contracts":["C60"]}, @@ -1107,6 +1112,9 @@ {"title":"clamps diffJson to 8 KiB with the truncation marker","contracts":["X01"]}, {"title":"fails every field %s requests closed to null, in rendering order","contracts":["C60"]}, {"title":"clamps each built-in diffJson side to 1 KiB","contracts":["X01"]}, + {"title":"yields after each native rendering or parse of a long side and never for short ones","contracts":["B02","X02"]}, + {"title":"logs what a second parse of its rendering logs for %s","contracts":["W10","C60","B03"]}, + {"title":"is recognized only from a serializer that loads as JsonSerializer does","contracts":["B03","X02"]}, {"title":"takes the entries from the hook and never runs the built-in walk","contracts":["C60"]}, {"title":"renders neither root side when the hook supplies the entries and value is off","contracts":["C60","B03"]}, {"title":"fails closed with hook_error and no fallback when the hook %s","contracts":["C60","B02"]}, diff --git a/formal/guides/course/13-catalogs-and-ledgers.md b/formal/guides/course/13-catalogs-and-ledgers.md index 463dd5ed..0c65f837 100644 --- a/formal/guides/course/13-catalogs-and-ledgers.md +++ b/formal/guides/course/13-catalogs-and-ledgers.md @@ -97,7 +97,7 @@ You will edit a tracked guide and undo it at the end. ```text { sources: 50, - tests: 633, + tests: 641, sections: 216, reviewedGuides: 19, guideSections: 195 diff --git a/typescript/src/dialcache.ts b/typescript/src/dialcache.ts index dfbb2fcc..0c2899ee 100644 --- a/typescript/src/dialcache.ts +++ b/typescript/src/dialcache.ts @@ -55,7 +55,7 @@ import { import { failedShadowMismatchLogFields, previewShadowLogKey, - renderShadowMismatchLog, + shadowMismatchLogSteps, type ShadowMismatchLogContent, type ShadowMismatchLogPlan, } from "./internal/shadow-log-json.js"; @@ -287,6 +287,7 @@ interface ShadowValidationPlan { interface ShadowMismatchDetails { readonly logPlan: ShadowMismatchLogPlan; readonly cachedValue: unknown; + readonly cachedIsParsedJson: boolean; readonly sourceValue: unknown; readonly mismatchDiff: ShadowMismatchDiff | undefined; } @@ -1074,6 +1075,9 @@ export class DialCache { ): void { const pendingRedisReads = new Set>(); let operationFinished = false; + // A confirmed mismatch keeps the slot until its warning is built, so the + // warnings in flight stay within shadowMaxInFlight. + let warningPending = false; let released = false; let signalShadowTimeout = (): void => undefined; const shadowTimeoutSignal = new Promise((resolve) => { @@ -1090,7 +1094,7 @@ export class DialCache { } }; const maybeRelease = (): void => { - if (operationFinished && pendingRedisReads.size === 0) { + if (operationFinished && !warningPending && pendingRedisReads.size === 0) { release(); } }; @@ -1271,7 +1275,14 @@ export class DialCache { return "superseded"; } if (logPlan !== null) { - mismatchDetails = { logPlan, cachedValue, sourceValue, mismatchDiff: plan.mismatchDiff }; + mismatchDetails = { + logPlan, + cachedValue, + cachedIsParsedJson: redisCache.loadsParsedJson(key), + sourceValue, + mismatchDiff: plan.mismatchDiff, + }; + warningPending = true; } validatedValueAgeSeconds = shadowValueAgeSeconds(originalFrame.createdAtMs); return "mismatch"; @@ -1282,15 +1293,23 @@ export class DialCache { }); void validation.then( - (outcome) => this.recordShadowValidation(key, outcome, mismatchDetails, validatedValueAgeSeconds), + async (outcome) => { + this.recordShadowValidation(key, outcome, validatedValueAgeSeconds); + // Only a confirmed mismatch with logging on carries details. + if (mismatchDetails !== undefined) { + await this.warnShadowMismatch(key, mismatchDetails, validatedValueAgeSeconds); + } + }, () => this.recordShadowValidation(key, "timeout"), - ); + ).then(() => { + warningPending = false; + maybeRelease(); + }); } private recordShadowValidation( key: DialCacheKey, outcome: ShadowValidationOutcome, - mismatchDetails?: ShadowMismatchDetails, valueAgeSeconds?: number, ): void { const labels = { @@ -1303,22 +1322,20 @@ export class DialCache { if (valueAgeSeconds !== undefined) { this.metrics?.observeShadowValueAge?.(labels, valueAgeSeconds); } - // Only a confirmed mismatch with logging on carries details. - if (mismatchDetails !== undefined) { - this.warnShadowMismatch(key, mismatchDetails, valueAgeSeconds); - } } /** * Emits the confirmed-mismatch warning and its one `shadowMismatchLogging` * event. Runs after the verdict was recorded and never changes it; any * construction failure logs less, never more, and nothing reaches the caller. + * After each native JSON rendering or parse of a long side, which blocks the + * event loop for as long as the side is large, it returns to the event loop. */ - private warnShadowMismatch( + private async warnShadowMismatch( key: DialCacheKey, details: ShadowMismatchDetails, valueAgeSeconds: number | undefined, - ): void { + ): Promise { const metadata = { cacheNamespace: key.namespace, useCase: key.useCase, @@ -1330,12 +1347,19 @@ export class DialCache { let content: ShadowMismatchLogContent; try { cacheKey = previewShadowLogKey(key.urn); - content = renderShadowMismatchLog( + const steps = shadowMismatchLogSteps( details.logPlan, details.cachedValue, details.sourceValue, details.mismatchDiff, + details.cachedIsParsedJson, ); + let step = steps.next(); + while (step.done !== true) { + await yieldUnreferencedImmediate(); + step = steps.next(); + } + content = step.value; } catch { // Last resort: nothing may escape into the detached verdict handler. content = { fields: failedShadowMismatchLogFields(details.logPlan), failure: "render_error" }; diff --git a/typescript/src/internal/redis-cache.ts b/typescript/src/internal/redis-cache.ts index 90935e38..b758bb07 100644 --- a/typescript/src/internal/redis-cache.ts +++ b/typescript/src/internal/redis-cache.ts @@ -237,6 +237,14 @@ export class RedisCache { return await this.deserializePayload(key, payload, REMOTE_SHADOW_CACHE_LAYER); } + /** + * Whether the key's serializer loads as the built-in JSON serializer does, + * so a decoded value is a fresh `JSON.parse` tree or the absent value. + */ + loadsParsedJson(key: DialCacheKey): boolean { + return this.serializerFor(key).load === JsonSerializer.prototype.load; + } + /** * Start a measured Redis read for detached shadow work. * diff --git a/typescript/src/internal/shadow-log-json.ts b/typescript/src/internal/shadow-log-json.ts index 1c5bdf2b..2e1b6914 100644 --- a/typescript/src/internal/shadow-log-json.ts +++ b/typescript/src/internal/shadow-log-json.ts @@ -11,6 +11,15 @@ export const SHADOW_MISMATCH_SIDE_MAX_BYTES = 1024; export const SHADOW_MISMATCH_MAX_DEPTH = 32; export const SHADOW_LOG_TRUNCATION_MARKER = "...[truncated]"; +/** + * A side rendered shorter than this, in UTF-16 code units, renders, parses and + * walks in about a millisecond or less, so returning to the event loop after + * its steps would only delay the warning. The TypeScript replays rely on it: + * their harness drains one zero-time tick per input, in which a chain of + * immediates cannot finish. + */ +const LONG_RENDERING_LENGTH = 64 * 1024; + 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); @@ -71,6 +80,22 @@ export function previewShadowLogKey(value: string): string { return clampUtf8(value, SHADOW_LOG_KEY_MAX_BYTES); } +/** Runs `shadowMismatchLogSteps` to the end without pausing. */ +export function renderShadowMismatchLog( + plan: ShadowMismatchLogPlan, + cachedValue: unknown, + sourceValue: unknown, + hook?: ShadowMismatchEntriesHook, + cachedIsParsedJson = false, +): ShadowMismatchLogContent { + const steps = shadowMismatchLogSteps(plan, cachedValue, sourceValue, hook, cachedIsParsedJson); + let step = steps.next(); + while (step.done !== true) { + step = steps.next(); + } + return step.value; +} + /** * Builds the content fields the plan requests for one confirmed mismatch. * Each side is rendered to native JSON at most once, and every built-in field @@ -80,16 +105,29 @@ export function previewShadowLogKey(value: string): string { * the top-level `undefined` a negative-cache entry stores, is not a failure: * its value field is `null`, and the built-in reports the other side whole at * the root. + * + * Each `yield` follows one native JSON rendering or parse of a long side, + * which cannot be interrupted, so a caller can return to the event loop + * between them. `cachedIsParsedJson` says the cached value is the JSON + * serializer's `JSON.parse` of the payload. It holds the JSON its rendering + * parses back to, so the built-in walk reads it instead of a second parse. */ -export function renderShadowMismatchLog( +export function* shadowMismatchLogSteps( plan: ShadowMismatchLogPlan, cachedValue: unknown, sourceValue: unknown, - hook?: ShadowMismatchEntriesHook, -): ShadowMismatchLogContent { + hook: ShadowMismatchEntriesHook | undefined, + cachedIsParsedJson: boolean, +): Generator { const renderSides = plan.value || (plan.diff !== "off" && hook === undefined); const cachedJson = renderSides ? renderJson(cachedValue) : null; + if (isLongRendering(cachedJson)) { + yield; + } const sourceJson = renderSides ? renderJson(sourceValue) : null; + if (isLongRendering(sourceJson)) { + yield; + } let diffFailed = false; let renderFailed = renderSides && ((cachedJson === null && cachedValue !== undefined) || (sourceJson === null && sourceValue !== undefined)); @@ -102,7 +140,7 @@ export function renderShadowMismatchLog( diff = runShadowMismatchHook(hook, cachedValue, sourceValue); diffFailed = diff === null; } else if (!renderFailed) { - diff = walkRenderedJson(cachedJson, sourceJson); + diff = yield* walkRenderedJson(cachedJson, sourceJson, cachedIsParsedJson ? cachedValue as JsonValue : undefined); } if (diff === null) { @@ -114,7 +152,7 @@ export function renderShadowMismatchLog( } else { let diffJson: string | null = null; if (withValues) { - diffJson = renderDiffJson(diff.entries); + diffJson = renderDiffJson(diff.entries, hook === undefined ? boundJsonEntry : boundEntry); renderFailed ||= diffJson === null; } diffFields = { @@ -164,8 +202,7 @@ export function failedShadowMismatchLogFields(plan: ShadowMismatchLogPlan): Shad */ export function diffShadowMismatchJson(cached: JsonValue, source: JsonValue): ShadowMismatchJsonDiff { const diff = walkJson(cached, source); - // JSON values always render, so every entry bounds. - return { count: diff.count, entries: diff.entries.map((entry) => boundEntry(entry)!) }; + return { count: diff.count, entries: diff.entries.map(boundJsonEntry) }; } /** Entries before the pointer and side clamps, from the walk or the hook. */ @@ -180,20 +217,41 @@ interface RawMismatchEntry { readonly source?: unknown; } -/** `null` is an absent side; a side that failed to render never reaches here. */ -function walkRenderedJson(cachedJson: string | null, sourceJson: string | null): RawMismatchDiff { +/** + * `null` is an absent side; a side that failed to render never reaches here. + * `cachedTree`, when given, is the JSON serializer's parse of the payload that + * `cachedJson` renders: the same JSON, except that a number beyond double + * range is an infinity (see `jsonLeaf`). + */ +function* walkRenderedJson( + cachedJson: string | null, + sourceJson: string | null, + cachedTree: JsonValue | undefined, +): Generator { if (cachedJson === sourceJson) { return { entries: [], count: 0 }; } - // Each string came from successful native JSON rendering, so this is the - // single boundary from arbitrary values to the closed JSON domain. + // Each string came from successful native JSON rendering, so parsing it is + // a boundary from arbitrary values to the closed JSON domain. if (cachedJson === null) { return { entries: [{ path: "", source: JSON.parse(sourceJson!) as JsonValue }], count: 1 }; } + const cached = cachedTree === undefined ? JSON.parse(cachedJson) as JsonValue : cachedTree; if (sourceJson === null) { - return { entries: [{ path: "", cached: JSON.parse(cachedJson) as JsonValue }], count: 1 }; + return { entries: [{ path: "", cached }], count: 1 }; + } + if (cachedTree === undefined && isLongRendering(cachedJson)) { + yield; + } + const source = JSON.parse(sourceJson) as JsonValue; + if (isLongRendering(sourceJson)) { + yield; } - return walkJson(JSON.parse(cachedJson) as JsonValue, JSON.parse(sourceJson) as JsonValue); + return walkJson(cached, source); +} + +function isLongRendering(json: string | null): boolean { + return json !== null && json.length >= LONG_RENDERING_LENGTH; } function walkJson(cached: JsonValue, source: JsonValue): ShadowMismatchJsonDiff { @@ -211,7 +269,7 @@ function walkJson(cached: JsonValue, source: JsonValue): ShadowMismatchJsonDiff const walk = (left: JsonValue, right: JsonValue): void => { const kind = jsonKind(left); if (kind !== jsonKind(right) || kind === "primitive") { - if (left !== right) { + if (jsonLeaf(left) !== jsonLeaf(right)) { report({ cached: left, source: right }); } return; @@ -230,18 +288,38 @@ function walkJson(cached: JsonValue, source: JsonValue): ShadowMismatchJsonDiff return; } for (let index = 0; index < leftItems.length; index += 1) { - tokens.push(index); - walk(leftItems[index]!, rightItems[index]!); - tokens.pop(); + const leftItem = leftItems[index]!; + const rightItem = rightItems[index]!; + if (leftItem !== rightItem) { + tokens.push(index); + walk(leftItem, rightItem); + tokens.pop(); + } } return; } const leftMembers = left as JsonObject; const rightMembers = right as JsonObject; - const names = Object.keys(leftMembers); - for (const name of Object.keys(rightMembers)) { - if (!Object.hasOwn(leftMembers, name)) { + // Equal primitives report nothing, so only the other members are sorted + // and visited; sorting a subset keeps its relative order. + const names: string[] = []; + let shared = 0; + for (const name of Object.keys(leftMembers)) { + if (!Object.hasOwn(rightMembers, name)) { names.push(name); + } else { + shared += 1; + if (leftMembers[name] !== rightMembers[name]) { + names.push(name); + } + } + } + const rightNames = Object.keys(rightMembers); + if (shared < rightNames.length) { + for (const name of rightNames) { + if (!Object.hasOwn(leftMembers, name)) { + names.push(name); + } } } // The default sort order is UTF-16 code units. @@ -273,7 +351,7 @@ function jsonValuesEqual(cached: JsonValue, source: JsonValue): boolean { return false; } if (kind === "primitive") { - if (left !== right) { + if (jsonLeaf(left) !== jsonLeaf(right)) { return false; } } else if (kind === "array") { @@ -303,6 +381,13 @@ function jsonValuesEqual(cached: JsonValue, source: JsonValue): boolean { return true; } +// A cached payload another port wrote can hold a number literal beyond double +// range, such as 1e400. JSON.parse reads it as an infinity, which renders as +// null. +function jsonLeaf(value: JsonValue): JsonValue { + return typeof value === "number" && !Number.isFinite(value) ? null : value; +} + function jsonKind(value: JsonValue): "array" | "object" | "primitive" { if (Array.isArray(value)) { return "array"; @@ -377,10 +462,13 @@ function runShadowMismatchHook( * Renders entries with their bounded sides; a side with no JSON rendering * makes the whole field `null`, and later sides are not rendered. */ -function renderDiffJson(entries: readonly RawMismatchEntry[]): string | null { +function renderDiffJson( + entries: readonly RawMismatchEntry[], + bound: (entry: RawMismatchEntry) => ShadowMismatchJsonEntry | null, +): string | null { const bounded: ShadowMismatchJsonEntry[] = []; for (const entry of entries) { - const next = boundEntry(entry); + const next = bound(entry); if (next === null) { return null; } @@ -390,10 +478,9 @@ function renderDiffJson(entries: readonly RawMismatchEntry[]): string | null { } /** - * The one clamp rule for built-in and hook entries: the pointer is clamped, - * and each present side is rendered once and kept as JSON, or as its clamped - * text when the rendering exceeds the side cap. `null` when a side has no - * JSON rendering. + * The clamp rule for hook entries: the pointer is clamped, and each present + * side is rendered once and kept as JSON, or as its clamped text when the + * rendering exceeds the side cap. `null` when a side has no JSON rendering. */ function boundEntry(entry: RawMismatchEntry): ShadowMismatchJsonEntry | null { const bounded: { path: string; cached?: JsonValue; source?: JsonValue } = { path: clampPointer(entry.path) }; @@ -412,6 +499,73 @@ function boundEntry(entry: RawMismatchEntry): ShadowMismatchJsonEntry | null { return bounded; } +/** + * `boundEntry`'s rule for a built-in entry, whose sides are JSON values: a + * side that fits is kept as it is, and one that does not is rendered only as + * far as the clamp reads. + */ +function boundJsonEntry(entry: RawMismatchEntry): ShadowMismatchJsonEntry { + return { + path: clampPointer(entry.path), + ...(Object.hasOwn(entry, "cached") ? { cached: boundJsonSide(entry.cached as JsonValue) } : {}), + ...(Object.hasOwn(entry, "source") ? { source: boundJsonSide(entry.source as JsonValue) } : {}), + }; +} + +function boundJsonSide(value: JsonValue): JsonValue { + const json = jsonPrefix(value, SHADOW_MISMATCH_SIDE_MAX_BYTES); + const clamped = clampUtf8(json, SHADOW_MISMATCH_SIDE_MAX_BYTES); + return clamped === json ? value : clamped; +} + +/** + * The JSON text of `value`, or a prefix of it longer than `limit` code units. + * Each code unit is at least one UTF-8 byte, so such a prefix overflows a + * `limit`-byte clamp, which keeps the same leading bytes from it as from the + * whole text. A string or member name is cut to `limit + 1` code units before + * quoting, so any escape the cut changes lies past `limit`. Each nesting level + * adds a code unit, so the recursion is at most `limit` deep. + */ +function jsonPrefix(value: JsonValue, limit: number): string { + const pieces: string[] = []; + let length = 0; + const emit = (piece: string): boolean => { + pieces.push(piece); + length += piece.length; + return length > limit; + }; + const quote = (text: string): string => JSON.stringify(text.length > limit ? text.slice(0, limit + 1) : text); + const write = (item: JsonValue): boolean => { + if (item === null || typeof item !== "object") { + return emit(typeof item === "string" ? quote(item) : JSON.stringify(item)); + } + if (Array.isArray(item)) { + if (emit("[")) { + return true; + } + for (let index = 0; index < item.length; index += 1) { + if ((index > 0 && emit(",")) || write(item[index]!)) { + return true; + } + } + return emit("]"); + } + if (emit("{")) { + return true; + } + let first = true; + for (const name of Object.keys(item)) { + if ((!first && emit(",")) || emit(`${quote(name)}:`) || write((item as JsonObject)[name]!)) { + return true; + } + first = false; + } + return emit("}"); + }; + write(value); + return pieces.join(""); +} + function clampPointer(path: string): string { return clampUtf8(path, SHADOW_MISMATCH_PATH_MAX_BYTES); } diff --git a/typescript/test/dialcache-shadow-confirmation.test.ts b/typescript/test/dialcache-shadow-confirmation.test.ts index 3dccb8ab..91aaee46 100644 --- a/typescript/test/dialcache-shadow-confirmation.test.ts +++ b/typescript/test/dialcache-shadow-confirmation.test.ts @@ -1008,6 +1008,138 @@ describe("DialCache Redis shadow confirmation", () => { } }); + it("returns to the event loop while it builds a long warning and holds the shadow slot until it logs", async () => { + const useCase = "ShadowMismatchLongWarning"; + const cached = { id: "long", blob: "x".repeat(64 * 1024), version: 1 }; + const payload = JSON.stringify(cached); + const redis = new ScriptedRedis([ + () => payload, + () => payload, + () => JSON.stringify({ id: "during", version: 1 }), + () => JSON.stringify({ id: "after", version: 1 }), + ]); + const metrics = new RecordingMetrics(); + const order: string[] = []; + const dialcache = createCache(redis, metrics, { + shadowMaxInFlight: 1, + logger: { debug: () => undefined, error: () => undefined, warn: () => order.push("warning") }, + }); + const getUser = dialcache.cached(async (id: string) => id === "long" ? { ...cached, version: 2 } : { id, version: 1 }, { + ...trackedOptions(useCase, remoteConfig(100, 100, { mismatchLogging: { diff: "paths" } })), + cacheKey: (id) => id, + }); + const recordVerdict = metrics.shadowValidation.bind(metrics); + let during: Promise | undefined; + metrics.shadowValidation = (labels) => { + recordVerdict(labels); + if (labels.outcome === "mismatch") { + setImmediate(() => order.push("immediate")); + during = dialcache.enable(async () => await getUser("during")); + } + }; + const parse = vi.spyOn(JSON, "parse"); + + try { + await dialcache.enable(async () => await getUser("long")); + await waitForMismatchLoggingEvents(metrics, 1); + await during; + await waitForShadowEvents(metrics, 2); + expect(order).toEqual(["immediate", "warning"]); + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch", "dropped"]); + // The served read and the shadow job each decode the payload; the walk + // reads that decoded value instead of parsing its identical rendering. + expect(parse.mock.calls.filter(([text]) => text === payload)).toHaveLength(2); + } finally { + parse.mockRestore(); + } + + await dialcache.enable(async () => await getUser("after")); + await waitForShadowEvents(metrics, 3); + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["mismatch", "dropped", "match"]); + }); + + it("frees the shadow slot when the deadline rejects a confirmed mismatch as it settles", async () => { + let nowMs = 0; + let confirmed = false; + const nowSpy = vi.spyOn(performance, "now").mockImplementation(() => nowMs); + try { + const useCase = "ShadowMismatchLateSettlement"; + const payload = JSON.stringify({ id: "late", version: 1 }); + const redis = new ScriptedRedis([ + () => payload, + () => { + confirmed = true; + return payload; + }, + () => JSON.stringify({ id: "after", version: 1 }), + ]); + const metrics = new RecordingMetrics(); + const warn = vi.fn(); + const dialcache = createCache(redis, metrics, { + shadowMaxInFlight: 1, + logger: { debug: () => undefined, error: () => undefined, warn }, + }); + // The warning details read the serializer's load after the job's last + // deadline check, so the deadline passes before the settled job is checked. + const serializer: Serializer<{ readonly id: string; readonly version: number }> = { + dump: (value) => JSON.stringify(value), + get load() { + if (confirmed) { + nowMs = 1_000; + } + return (value: string | Buffer) => JSON.parse(String(value)) as { readonly id: string; readonly version: number }; + }, + }; + const getUser = dialcache.cached(async (id: string) => ({ id, version: id === "late" ? 2 : 1 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { mismatchLogging: { diff: "paths" } })), + cacheKey: (id) => id, + fallbackTimeoutMs: 10, + serializer, + }); + + await dialcache.enable(async () => await getUser("late")); + await waitForShadowEvents(metrics, 1); + confirmed = false; + nowMs = 2_000; + await dialcache.enable(async () => await getUser("after")); + await waitForShadowEvents(metrics, 2); + + expect(metrics.shadowEvents.map(({ outcome }) => outcome)).toEqual(["timeout", "match"]); + expect(warn).not.toHaveBeenCalled(); + } finally { + nowSpy.mockRestore(); + } + }); + + it("walks a custom serializer's value from its rendering", async () => { + // A serializer that revives dates hands the comparator Date members, but + // the walk, like the value fields, reads what they render as. + const useCase = "ShadowMismatchRevivingSerializer"; + const at = "2026-10-28T00:00:00.000Z"; + const payload = JSON.stringify({ at, 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 reviving: Serializer<{ readonly at: Date; readonly version: number }> = { + dump: (value) => JSON.stringify(value), + load: (value) => { + const loaded = JSON.parse(String(value)) as { readonly at: string; readonly version: number }; + return { ...loaded, at: new Date(loaded.at) }; + }, + }; + const getEvent = dialcache.cached(async () => ({ at: new Date(at), version: 2 }), { + ...trackedOptions(useCase, remoteConfig(100, 100, { mismatchLogging: { diff: "paths" } })), + cacheKey: () => "123", + serializer: reviving, + }); + + await dialcache.enable(async () => await getEvent()); + await waitForMismatchLoggingEvents(metrics, 1); + + expect(warn.mock.calls[0]?.[1]).toMatchObject({ mismatchPaths: ["/version"], mismatchPathCount: 1 }); + }); + it.each([ ["null", null], ["a string", "paths"], diff --git a/typescript/test/shadow-log-json.test.ts b/typescript/test/shadow-log-json.test.ts index f5383931..88c8a0c7 100644 --- a/typescript/test/shadow-log-json.test.ts +++ b/typescript/test/shadow-log-json.test.ts @@ -2,19 +2,24 @@ import { readFileSync } from "node:fs"; import { describe, expect, it, vi } from "vitest"; +import { DialCacheKey, JsonSerializer, type Serializer } from "../src/index.js"; +import { RedisCache } from "../src/internal/redis-cache.js"; import { SHADOW_LOG_KEY_MAX_BYTES, SHADOW_LOG_TRUNCATION_MARKER, SHADOW_LOG_VALUE_MAX_BYTES, SHADOW_MISMATCH_PATH_MAX_BYTES, + SHADOW_MISMATCH_SIDE_MAX_BYTES, diffShadowMismatchJson, failedShadowMismatchLogFields, previewShadowLogKey, renderShadowMismatchLog, + shadowMismatchLogSteps, type JsonValue, type ShadowMismatchJsonEntry, type ShadowMismatchLogPlan, } from "../src/internal/shadow-log-json.js"; +import { FakeRedis } from "./fake-redis.js"; const VALUE_ONLY: ShadowMismatchLogPlan = { value: true, diff: "off" }; const PATHS_ONLY: ShadowMismatchLogPlan = { value: false, diff: "paths" }; @@ -256,6 +261,32 @@ describe("shadow mismatch log JSON", () => { ], count: 5, }); + // "[" and the first item fill exactly 1 KiB, and the rest overflows it. + const filled = ["x".repeat(1021), "y"]; + expect(diffShadowMismatchJson(filled, [])).toStrictEqual({ + entries: [{ path: "", cached: `${JSON.stringify(filled).slice(0, 1010)}${SHADOW_LOG_TRUNCATION_MARKER}`, source: [] }], + count: 1, + }); + }); + + it("renders a long built-in side only as far as its clamp reads", () => { + const cached = { list: Array.from({ length: 100_000 }, (_, index) => index), blob: "x".repeat(1 << 20) }; + const stringify = vi.spyOn(JSON, "stringify"); + try { + const { entries } = diffShadowMismatchJson(cached, { list: [], blob: "y" }); + + expect(entries.map(({ path }) => path)).toStrictEqual(["/blob", "/list"]); + const rendered = stringify.mock.results.map(({ value }) => (typeof value === "string" ? value.length : 0)); + expect(rendered.length).toBeLessThan(2 * SHADOW_MISMATCH_SIDE_MAX_BYTES); + expect(Math.max(...rendered)).toBeLessThanOrEqual(SHADOW_MISMATCH_SIDE_MAX_BYTES + 3); + } finally { + stringify.mockRestore(); + } + }); + + it("reports equal-length array items that differ in JSON type", () => { + expect(renderShadowMismatchLog(PATHS_ONLY, [1, 0, ""], ["1", false, 0]).fields.mismatchPaths) + .toStrictEqual(["/0", "/1", "/2"]); }); it("caps the walk at 32 reference tokens however deep the difference lies", () => { @@ -490,6 +521,72 @@ describe("shadow mismatch log JSON", () => { { path: "/blob", cached: `"${"x".repeat(1009)}${SHADOW_LOG_TRUNCATION_MARKER}`, source: "y" }, ]); }); + + it("yields after each native rendering or parse of a long side and never for short ones", () => { + const yields = (cached: unknown, source: unknown, cachedIsParsedJson: boolean): number => { + const steps = shadowMismatchLogSteps(PATHS_ONLY, cached, source, undefined, cachedIsParsedJson); + let count = 0; + while (steps.next().done !== true) { + count += 1; + } + return count; + }; + const long = (version: number) => ({ blob: "x".repeat(64 * 1024), version }); + // A string whose rendering, quotes included, is `length` code units. + const rendered = (length: number) => "x".repeat(length - 2); + + expect(yields(long(1), long(2), false)).toBe(4); + // The walk reads the serializer's tree instead of parsing the rendering. + expect(yields(long(1), long(2), true)).toBe(3); + expect(yields(long(1), { version: 2 }, false)).toBe(2); + expect(yields({ version: 1 }, { version: 2 }, false)).toBe(0); + expect(yields(rendered(64 * 1024), rendered(64 * 1024 - 1), false)).toBe(2); + }); + }); + + describe("a cached value the JSON serializer parsed", () => { + // Payloads as another port can write them: a number literal beyond double + // range parses as an infinity, which renders as null. + it.each([ + ["an overflowing member", '{"big":1e400,"n":1}', { big: null, n: 2 }, ["/n"]], + ["overflowing items in a root of another kind", "[1e400,-1e400,1]", "x", [""]], + [ + "an overflow past the depth cap", + JSON.stringify({ deep: nestMembers(40, 0), n: 1 }).replace(":0", ":1e400"), + { deep: nestMembers(40, null), n: 2 }, + ["/n"], + ], + ["an own __proto__ member", '{"__proto__":1,"a":1}', JSON.parse('{"__proto__":1,"a":2}') as unknown, ["/a"]], + ])("logs what a second parse of its rendering logs for %s", (_name, payload, source, paths) => { + const cached: unknown = JSON.parse(payload); + for (const plan of [PATHS_ONLY, VALUES_ONLY, EVERYTHING]) { + const content = renderShadowMismatchLog(plan, cached, source, undefined, true); + + expect(content).toStrictEqual(renderShadowMismatchLog(plan, cached, source)); + expect(content.fields.mismatchPaths).toStrictEqual(paths); + } + }); + + it("is recognized only from a serializer that loads as JsonSerializer does", () => { + class KeepsLoad extends JsonSerializer {} + class OverridesLoad extends JsonSerializer { + override async load(value: string | Buffer): Promise { + return await super.load(value); + } + } + const custom: Serializer = { dump: (value) => JSON.stringify(value), load: (value) => JSON.parse(String(value)) }; + const loadsParsedJson = (configured: Serializer | undefined, perKey: Serializer | null): boolean => new RedisCache({ + redis: { client: new FakeRedis(), ...(configured === undefined ? {} : { serializer: configured }) }, + metrics: null, + }).loadsParsedJson(new DialCacheKey({ keyType: "user_id", id: "1", useCase: "ShadowParsedJson", serializer: perKey })); + + expect(loadsParsedJson(undefined, null)).toBe(true); + expect(loadsParsedJson(new JsonSerializer(), null)).toBe(true); + expect(loadsParsedJson(undefined, new KeepsLoad())).toBe(true); + expect(loadsParsedJson(custom, new JsonSerializer())).toBe(true); + expect(loadsParsedJson(undefined, new OverridesLoad())).toBe(false); + expect(loadsParsedJson(custom, null)).toBe(false); + }); }); describe("mismatch diff hook", () => {