Skip to content

feat: group shadow config and log mismatch JSON - #113

Merged
lan17 merged 6 commits into
mainfrom
codex/shadow-config-logging
Jul 31, 2026
Merged

feat: group shadow config and log mismatch JSON#113
lan17 merged 6 commits into
mainfrom
codex/shadow-config-logging

Conversation

@lan17

@lan17 lan17 commented Jul 31, 2026

Copy link
Copy Markdown
Owner

Summary

  • Replace the flat shadowRamp key policy with a grouped shadow policy.
  • Add one default-off shadow.logMismatches switch that logs the logical key plus native JSON for the cached and source values on a confirmed mismatch.
  • Preserve the required metrics.shadowValidation activation gate, confirmation read, and fail-open observer behavior.
  • Reuse the existing logger; no new logger abstraction, metric, dependency, formatter callback, or textual-diff model is introduced.

API and migration

Before:

new DialCacheKeyConfig({
  shadowRamp: 10,
});

After:

new DialCacheKeyConfig({
  shadow: {
    ramp: 10,
    logMismatches: true,
  },
});

This is an intentional MVP breaking change. The public DialCacheKeyConfig constructor, static defaults, and raw runtime-provider results reject shadowRamp with a migration error. At runtime, that config-resolution failure safely executes the uncached fallback rather than inheriting defaults. Migrate the field to shadow.ramp.

Runtime defaults and per-key overrides merge shadow.ramp and shadow.logMismatches independently. DialCacheKeyConfig.disabled() explicitly sets the shadow ramp to 0 and mismatch logging to false.

Mismatch behavior

shadow.logMismatches Confirmed mismatch behavior
omitted or false Record the existing shadow metric only
true Record the metric and emit one warning with the key and both JSON strings
flowchart LR
  C0["Cached value A"] --> Compare["Compare A with source value B"]
  B["Source value B"] --> Compare
  Compare -->|match| Metric["Record match metric"]
  Compare -->|candidate mismatch| C1["Confirmation read"]
  C1 -->|missing or changed| Superseded["Record superseded metric"]
  C1 -->|same payload| Mismatch["Record mismatch metric"]
  Mismatch -->|logMismatches| Warn["Warn with key, cachedValueJson, sourceValueJson"]
Loading

The warning is emitted only for terminal mismatch: the cached Redis payload observed before comparison must still be byte-identical on the confirmation read. Matches, superseded comparisons, timeouts, dropped work, and errors remain metric-only.

The warning fields are:

  • cacheNamespace, useCase, keyType, and outcome: "mismatch"
  • cacheKey: the logical DialCache URN, capped at 2 KiB of UTF-8
  • cachedValueJson: native JSON for the deserialized cached comparator input, capped at 8 KiB
  • sourceValueJson: native JSON for the source comparator input, capped at 8 KiB

Byte-clipped fields end in ...[truncated] within their cap. Each value is stringified independently. If JSON.stringify throws or returns undefined, that field is null and the other side is still attempted. DialCache does not call serializer.dump again or compute a diff.

Safety and operational limits

  • Logging is default-off and does not activate shadow work without metrics.shadowValidation.
  • JSON is built only after terminal mismatch confirmation; raw compared-value references are never passed to the logger.
  • Invalid runtime shadow.logMismatches records config_resolution, suppresses the warning, and preserves cache and shadow outcomes.
  • JSON/key construction failure degrades safely; logger throws and rejected promises or thenables remain isolated from cache behavior.
  • Truncation is not redaction. Keys and values may contain sensitive data, so logging requires an approved logger and data-handling policy.
  • Native JSON semantics are intentional: getters and toJSON methods may run, unsupported values may be omitted or normalized, and cycles or bigint make that side null.
  • The 8 KiB caps apply after JSON.stringify returns. They bound emitted fields, not input traversal, hook execution, synchronous event-loop time, or the intermediate JSON string; enable logging only for trusted, reasonably bounded values.

Validation

Validated from main@9f6c933b69c33ac2f52c2931e581f953fe99a5c0 with Node 22.22.0:

  • corepack pnpm check — typecheck, 405 unit tests with coverage, build, and packed ESM/CommonJS consumer checks
  • corepack pnpm test:integration — 93 Redis, Valkey, and cluster tests
  • corepack pnpm audit --prod — no known vulnerabilities
  • git diff --check
  • Bounded post-simplification review — no correctness findings; both P3 simplicity/documentation findings addressed

@lan17
lan17 marked this pull request as ready for review July 31, 2026 03:37
@lan17

lan17 commented Jul 31, 2026

Copy link
Copy Markdown
Owner Author

Review

I checked out the branch and verified behavior empirically rather than reading only. Baseline: 414 tests pass, tsc --noEmit clean.

I also fuzzed the previewer (~2,500 generated values, every prefix length of multibyte strings, proxies, cycles, null-prototype records, lone surrogates) — the byte accounting is genuinely correct. Reserving the marker by shrinking contentLimit on first truncation, and trimming back to a complete UTF-8 sequence boundary, both hold. Caps never exceeded, nothing threw, no lone surrogates leaked, and ...[truncated] is present whenever truncated is set. The no-user-code discipline is real too: proxies are screened before getPrototypeOf, accessors are rendered from descriptors without reading them.

Now the problems.

1. A throw during detail construction kills the process (High — introduced by this PR)

shadowMismatchLogDetails(...) is called inside the argument expression to this.logger.warn(...) (dialcache.ts#L1151), so it evaluates before safeLogger is entered — the wrapper the PR body cites as the isolation mechanism doesn't cover it. And recordShadowValidation runs from void validation.then(onFulfilled, onRejected) (dialcache.ts#L1122); a throw in onFulfilled is not caught by onRejected, and there is no .catch.

I mocked the preview module to throw and confirmed: the metric records mismatch, then unhandledRejection: preview blew up. Node terminates on that by default. An opt-in logging feature can take down the process from a detached path.

This is a regression, not pre-existing: on main, recordShadowValidation only touched safe-wrapped metrics and had no throwable expression. Related asymmetry — previewShadowLogValue has a top-level try/catch, but previewShadowLogKey has none, and unavailablePreview() calls finish() outside any try (shadow-log-preview.ts#L109). A throw is unlikely in practice; the point is that the severity is process death, and the fix is a try/catch around the logging block after the metric emission.

2. A stale runtime shadowRamp takes the whole use case fully uncached (High, operational)

Verified with a provider returning { shadowRamp: 50 }: fetchKeyConfig throws → disabled{config_error} + config_resolution → fallback runs uncached. 0 Redis reads, source called 3/3 times, and the LOCAL layer is lost too — not just shadow work.

The PR body says the field is "explicitly rejected with a migration error instead of being silently ignored," which reads like a constructor-time developer error. On the runtime-overlay path it is a total cache bypass. Flag stores deploy independently of library versions, so a flag store still serving shadowRamp after the upgrade is the likely rollout order — that is a latency and load cliff onto the source of truth.

Keep the hard throw in the DialCacheKeyConfig constructor (developer-visible, fails at cached() registration — that part is good). On the runtime overlay, record config_resolution and ignore the legacy leaf instead of failing the whole resolution. At minimum the migration notes should state the blast radius. To be clear: the incompat itself is fine — this is about the runtime failure mode, not the API change.

3. A logging-flag typo pages you at full request volume (Medium)

With shadow: { ramp: 1, logMismatches: "yes" } over 20 calls: 20 config_resolution errors, 0 shadow outcomes. And with both flags malformed, one key emits 2 errors — the count scales with how many fields you fat-fingered, not with failed resolutions.

So a typo in a purely diagnostic flag produces the same error{layer="remote", error="config_resolution"} signal, at 100% of traffic, as a genuinely broken Redis ramp. The README documents the placement, but the alerting consequence is worth rethinking: collapse to one error per resolution, and consider gating logging-flag validation behind the cohort/metrics gates so its volume matches its impact.

4. The previews are opaque for exactly the values that usually diverge (Medium)

Date, Map, Set, Buffer, and class instances all render [Object]. Two different Dates produce byte-identical previews:

{"updatedAt": [Object]}...[truncated]

Timestamps are among the most common shadow-divergence causes, and the feature cannot show them — which undercuts the stated purpose. utilTypes.isDate(v) + Date.prototype.valueOf.call(v) uses the intrinsic, so a subclass override cannot run; that respects the no-user-code rule. Same for isMap/isSet sizes.

5. 190 ms synchronous event-loop stall on pathological plain records (Medium)

Measured: 1k keys → 0.7 ms, 100k → 13.8 ms, 1M → 190 ms — all producing the same 346-char preview. renderRecord's for...in materializes V8's full enum cache before the 32-entry break. Arrays are fine (2M elements → 0.24 ms) because renderArray indexes directly.

The README mentions this only as an inspection caveat ("may inspect more keys than DialCache renders"). The real cost is a latency stall on the shared event loop, in a library sold on tail latency. Worth saying so explicitly.

6. The new module is below the repo's own coverage thresholds, masked by the aggregate (Low)

shadow-log-preview.ts is 89.36% stmts / 86.72% branches / 89.24% lines against thresholds of 95/90/95. Thresholds are global, so CI is green at 95.96/93.13/95.99 — the newest and most safety-critical file is the least covered in src/internal after local-cache.ts.

Uncovered lines are precisely the defensive paths: utf8SequenceLength's 2-, 3-, and 4-byte branches (366/369/372) — the core "don't split a multibyte character" logic; escapeCharacter's \\, \b, \f, \r, \t cases; both [unavailable] fallbacks plus unavailablePreview() entirely; renderRecord's missing-descriptor path. My fuzzing hit these and they are correct, but the suite here does not reach them.

Nits

  • warning (dialcache.ts#L1145) rebuilds labels with a hardcoded outcome: "mismatch"; {...labels} is equivalent since that is already established, and still a distinct object.
  • shadow: { logMismatches: true } with no ramp is silently inert — verified no error, no shadow work. A config that can never do anything.
  • Any structural marker permanently shrinks the budget by 14 bytes and appends a global suffix, so { a: new Date() } becomes {"a": [Object]}...[truncated]. Documented as "structurally shortened," just reads oddly when nothing was byte-clipped.

What's right

Worth stating, because several of these are the parts that are easy to get wrong: the metric object and logger metadata are separate, and there is a test with a deliberately mutating metrics adapter proving one observer cannot taint the other's payload. Details are captured only after terminal confirmation, superseded candidates do not log, disabled() kills all three leaves, per-leaf merge independence works (verified an overlay carrying only logMismatches preserves an inherited ramp), and serializer.dump is never called for logging. Malformed static defaultConfig fails fast at registration — that is the right call, and it is why finding #3 is confined to the runtime path.

My read: #1 and #2 should block; #3#5 are worth fixing before this ships to a real use case, since they all bite during the exact incident the feature exists to diagnose.

@lan17

lan17 commented Jul 31, 2026

Copy link
Copy Markdown
Owner Author

Re-review — 393db5c "fix: harden shadow mismatch logging"

427 tests pass (was 414), tsc --noEmit clean, build clean. I re-ran every probe from the first pass plus new ones for the new code paths. All six findings are addressed. One of my original criticisms was wrong and I owe a correction on it.

Verified fixed

#1 — process crash. recordShadowValidation now wraps detail construction in try/catch and falls through to the metadata warning. Re-ran the mocked-throw probe: 0 unhandled rejections, metric still mismatch, exactly one warn with metadata only. (callObserver swallows both sync throws and rejections, so safeLogger.warn cannot throw — the catch can only ever fire on shadowMismatchLogDetails, which also makes the theoretical double-log case unreachable.)

#2 — legacy shadowRamp cache bypass. mergeKeyConfig now uses assertKeyConfigShape for the overlay and reports the legacy leaf through a callback instead of throwing. Verified: disabled: [] (no more config_error), source called 1x across 3 calls so the LOCAL layer still caches, Redis still consulted, one config_resolution per resolution. The public constructor still throws on shadowRamp. This is exactly the split I suggested.

#3 — error volume. resolveShadowLogging moved below the metrics-hook, cohort, and capacity gates, with both flags collapsed into one invalidLogging emission. Both flags malformed: 2 -> 1 error. 20 out-of-cohort calls: 20 -> 0 errors.

#4 — opaque previews. Date, Map, Set, and typed arrays now render legibly through captured intrinsics. Different Dates are distinguishable (Date(2020-01-01T00:00:00.000Z)), Buffers hex-preview (Buffer(5 bytes) [68 65 6c 6c 6f]). I specifically checked the traps:

  • An EvilDate subclass overriding toISOString/valueOf is not invoked — verified called: false.
  • Pooled Buffer windowing is correct. Buffer.from("BBBB") landed at byteOffset: 22912 inside a 65536-byte pool and previewed exactly [42 42 42 42], with no neighbouring pool bytes leaked. That was my biggest worry here and it is right.
  • A detached ArrayBuffer degrades to [unavailable] without throwing; SharedArrayBuffer views work.

#5 — event-loop stall. Not fixed in code (still ~163 ms for a 1M-key record), but now documented accurately as a latency caveat: "can block the shared Node.js event loop and cause a tail-latency spike... Keep detailed logging disabled for untrusted or unbounded record shapes." That was the actual ask — the previous wording framed it only as an inspection concern.

#6 — coverage. shadow-log-preview.ts: 89.4% -> 98.0% stmts / 96.8% branches, now above the repo's own thresholds rather than hiding behind the global aggregate. The new tests hit the exact paths I named: 2/3/4-byte UTF-8 rollback, every escape sequence, detached buffers, intrinsic overrides.

Correction: I was wrong about the string guard

The new MAX_STRING_INPUT_CODE_UNITS = 64 Ki guard renders long strings as [String length=N code units] with no content. I was going to flag that as a diagnostic regression for no benefit, because I measured flat cost across 10k/30k/65k code-unit strings (0.211 / 0.186 / 0.188 ms per call) and concluded writeQuotedString was already output-bounded.

That measurement was invalid: String.prototype.repeat produces a flat sequential string, so it never exercised the case the README's "rope" rationale is about. Testing actual ConsString ropes built by concatenation:

rope size first codePointAt(0)
1 Mchar 0.31 ms
8 Mchar 2.54 ms
32 Mchar 9.16 ms

And encodeInto from a 32 Mchar rope into a 2 KiB destination costs 9.81 ms while reading only 2048 code units — it pays the full flatten plus an O(n) allocation. So the guard is justified and correctly placed. The residual tradeoff is that a large flat string (a 100 KB JSON blob) also loses its whole preview rather than its first 8 KiB — a real but minor cost, and the conservative default is defensible.

Residual, non-blocking

  • Map/Set show size only. new Map([["a",1]]) and new Map([["zzz",999]]) both render Map(1) — same size, different contents, identical preview. Unavoidable without invoking iterators, which the design deliberately refuses, and the README now states contents are omitted. Worth knowing that a Map-valued divergence still is not diagnosable.
  • completeUtf8PrefixLength dropped the utf8SequenceLength ternary for a bare return sequenceStart. That is provably equivalent: when bytes[proposedLength] is a continuation byte, every byte in (sequenceStart, proposedLength] is one too, so the sequence always overruns and the old ternary could only pick sequenceStart. Re-fuzzed to confirm — caps hold at every prefix length across 500 random structures, no throws, no lone surrogates, marker always present when truncated.
  • previewShadowLogValue no longer has its own try/catch, so isolation now lives solely in recordShadowValidation. Correct for this caller; any future caller inherits the throw risk.
  • Module-load-time Object.getOwnPropertyDescriptor(...)!.get! for Map.size and the typed-array getters would throw at import on a runtime missing them, taking down the whole library rather than just logging. Node >= 22 always has them, so this is theoretical.
  • runtime-config.ts:131assertKeyConfig's shadowRamp throw for defaultConfig is now unreachable, since snapshotDefaultConfig rejects it at registration. Harmless redundant guard.

This clears both blockers and the three medium findings. LGTM.

@lan17

lan17 commented Jul 31, 2026

Copy link
Copy Markdown
Owner Author

Follow-up: consider replacing the custom previewer with bounded JSON.stringify

The code as it stands is correct — I verified that separately and my LGTM holds. This is about carrying cost, not correctness, and it's worth raising before another team adopts the library rather than after.

shadow-log-preview.ts is 470 lines, 6 limit constants, and 13 distinct opaque markers, to render a debug log line. I went looking for what that machinery actually buys over much simpler options and measured it.

The bounded walk does not buy what it looks like it buys

The custom walk bounds the output, but not the enumeration, and enumeration is the dominant cost. JSON.stringify with a replacer that aborts once over budget lands within noise of it:

approach 200k-key record 200k-elem array intermediate string
naive JSON.stringify + slice 100 ms 60 ms 8–13 MB
JSON.stringify + aborting replacer 34 ms 0.2 ms none
current custom walk ~35 ms (163 ms at 1M keys) ~0 ms none

JSON.stringify enumerates all own keys upfront, so wide records cost O(n) either way — the same V8 enum-cache materialization as the current for...in. That cost is irreducible in JS, which means the 470 lines are buying fidelity, not safety.

For reference, util.inspect with getters: false, customInspect: false invokes no user code at all (verified: getters, toJSON, iterators, and proxy traps all stay untriggered) and its defaults already bound depth, arrays at 100, and strings at 10,000. Its one unbounded dimension is object key count.

Suggested shape

Asymmetric, because the cached side is free. At the mismatch point we still hold flight.cachedPayload, which is already a flat serialized string or Buffer:

  • Buffer → <binary N bytes>, do not decode
  • string → .slice(0, SHADOW_LOG_VALUE_MAX_BYTES)

That is O(cap), invokes no user code, and is the actual stored bytes. Only the source side is a live object, and it can use a bounded stringify:

const ABORT = Symbol("abort");
let budget = 16_384;
JSON.stringify(v, (_k, val) => {
  if (budget <= 0) throw ABORT;
  budget -= typeof val === "string" ? val.length + 3 : 8;
  return val;
});

Skip binary on both sides — otherwise a Buffer renders as {"type":"Buffer","data":[104,101,...]}, which is both useless and large. Worth widening that skip to all Uint8Array, not just Buffer.

The naive stringify-then-slice variant is the one thing to avoid: 3x slower and it builds an 8–13 MB string per mismatch per side before discarding 99.9% of it. The aborting replacer is what makes this viable.

What we would give up — deliberately

Each of these I confirmed by test, so they should be a conscious call rather than a surprise:

  • Getters and toJSON get invoked. This is the one hard guarantee lost. It matters less than it first appears, since putForShadow already calls serializer.dump(sourceValue) on the fill path, so source values are already serialized in normal operation. But it downgrades "never touches user code" from an invariant to best-effort, and a lazy getter with side effects would fire on a logging path.
  • Map and Set render as {}. Total loss — worse than today's Map(1), and much worse than util.inspect's Map(2) { 'a' => 1 }.
  • bigint and cycles throw, losing the whole preview rather than one field. The current code degrades to [Circular] and continues.
  • NaN/Infinity become null, -0 becomes 0. Silently wrong, and numeric divergence is precisely what this feature diagnoses. Worth one replacer branch to emit "NaN" as a string.
  • undefined, functions, and symbol-keyed fields vanish silently.

Two caveats that stay caveats either way: with a custom non-JSON serializer the two previews end up in different formats and stop being eyeball-comparable (fine for the default JSON serializer), and the wide-record enumeration stall persists, so the README's "keep detailed logging disabled for unbounded record shapes" guidance still applies.

Net

Roughly 25–40 lines replacing 470, deleting the Utf8PreviewWriter, the UTF-8 boundary arithmetic, completeUtf8PrefixLength, all 13 markers, typedArrayBrand's 13 branches, renderDate/renderCollectionSize/renderTypedArray, the escape table, and five of the six limit constants. Same wide-record cost, same byte bound where it matters.

Separately and independent of the above, two config simplifications worth folding in:

  • logMismatches + logMismatchDetails encode four states, one of which (details: true, base: false) is silently inert. A single logMismatches: "off" | "metadata" | "detailed" makes the invalid state unrepresentable and removes the flag reconciliation, the two validation branches, and the collapsed-error logic added in 393db5c.
  • Shadow config is validated in three places with three slightly different rule sets: cloneShadowConfig (shape only, no range), snapshotDefaultConfig (range plus booleans), and scheduleShadowValidation/resolveShadowLogging (range plus booleans again, with its own copy of the 0–100 bounds). Worth collapsing to one boundary.

Happy to be talked out of any of this — the fidelity argument for the current renderer is real, I just do not think it is worth 470 lines pre-adoption.

@lan17 lan17 changed the title feat: group shadow config and add mismatch logging feat: group shadow config and log mismatch JSON Jul 31, 2026
@lan17
lan17 merged commit 2bc5308 into main Jul 31, 2026
6 checks passed
@lan17
lan17 deleted the codex/shadow-config-logging branch July 31, 2026 22:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant