Skip to content

Phase 5b: logging facade and redaction — tests and doubles - #70

Merged
Wahbeh-Mohammad merged 5 commits into
mainfrom
19-phase-5b-logging-and-redaction-tests
Sep 18, 2026
Merged

Wahbeh-Mohammad merged 5 commits into
mainfrom
19-phase-5b-logging-and-redaction-tests

Conversation

@Wahbeh-Mohammad

Copy link
Copy Markdown
Contributor

Part of #19. Eighth PR of the nine-PR phase-5 stack — the tests for phase 5b's code PR below it. Targets that PR's branch; the phase record is the next PR up.

What lands

18 files, +3,887 / −17: fifteen suites under gems/dexpace-core/test/dexpace/instrumentation/ mirroring lib/ one file per file (render.rb and emitter.rb are private_constants asserted through Event and the two steps and say so; diagnostics_test.rb is the full rewrite of 5c's minimal mirror), plus the two doubles the design's testing strategy names and the matrix-fact suite:

  • RecordingSink — a real in-memory _Sink with per-severity enablement, recording every entry it is handed exactly as handed, so an assertion that a credential never reached the sink is an assertion about the sink's own record.
  • DiagnosticContext.preserve — the save-and-restore block over Fiber storage that 5c's floor-aware FiberStorageFacts helpers do not cover. Both top-level, the tree's convention (P5-98).
  • 5c's Dexpace::RecordingSpan/RecordingTracer/RecordingTracerFactory/RecordingMeter, AllocationDelta and FiberStorageFacts, and 5a's FakeClock/FakeConfigSource, consumed unchanged — except allocation_delta.rb, which now reports the figure two consecutive measurements agree on (round 2's floor flake, R2-4; 5c's suites re-run green). Phase 2's FakeTransport/FakeAsyncTransport(settle_later:) and 4c's ForkingProbe drive the steps through real pipelines; no FakeFuture or fake cursor exists.

Every file's header names the requirement IDs it exercises; every class inherits DexpaceTestCase; every thread is joined; nothing uses assert_nothing_raised; GC.stat appears only inside the allocation assertions; no 5b test reads real ENV — every slot read goes through FakeConfigSource seams installed with Dexpace.configure and reset in teardown, and the reviewers ran the whole core suite under hostile HTTPS_PROXY/LOG_LEVEL/LOG_PREVIEW_BYTES/MAX_MATERIALIZED_BYTES/MAX_TRACKED_CONTEXTS (every 5b suite green; the four failures are pre-existing 3b/4b ceiling readers, phase 10 inbound bullet 42).

What the suites prove rather than restate:

  • OBS-1 as identity and as a number — assert_same(Event::INERT, …) across severities, and a two-loop GC.stat delta of exactly 0.0 per call over the inert chain with the arguments precomputed under # frozen_string_literal: true (R8).
  • The redaction surface, input by input — userinfo replaced with an allow-list naming the user; the default query allow-list exactly {api-version}; Token matched case-insensitively and %73ig decoded before matching; ?sig with no =, &&sig=x&, %zz=1 (a bad name is unmatchable, the value ***), a trailing ? preserved, a fragment ? not a query, an opaque mailto: with a query tail; /cb?code=S → /cb?***; '', ' ', http://[::1, a NUL, 10 KiB of ? → the sentinel, never a raise; the header-value route with userinfo on the relative, surgery and sentinel-fallback routes, leading OWS, <…>, quotes, parentheses, %20, +, @, NBSP, U+2028, obs-text and a doubled URL all losing the credential, a multi-valued Location redacted per value; the four RFC 3986 non-authority spellings kept verbatim and named as such; Authorization, Proxy-Authorization, Cookie, Set-Cookie, X-Api-Key redacted at #field and the diagnostic names kept; a credential in the logger's global context and in a Fiber[] key redacted at Logger.build and at #emit.
  • OBS-6/OBS-7 — a BasicObject, a raising #inspect, an anonymous StandardError subclass, a 20 KiB multibyte string straddling the 8 KiB boundary — all render, byte-sliced, with a nil-safe class name.
  • OBS-8 — 16 threads emitting once; a sink that re-enters the logger from #info not deadlocking (the mutex is released before the sink call).
  • OBS-10/OBS-24, floor-aware — the fold carries exactly the two default keys and skips a nil-valued one; a snapshot reinstalled in another thread and restored afterwards including on raise; a snapshot-introduced key absent after restore on 3.3+ and present-and-nil on 3.2.11, asserted through FiberStorageFacts; the async failure event bridged across a settling thread (round 1's surviving mutation, now a case).
  • OBS-20/OBS-30 through a real Pipeline — a raising sink returning the transport's response with two http.instrumentation.log diagnostics; a raising diagnostic swallowed; a raising tracer inside the same step propagating; on the async path a throwing meter reaching the settler on a later settlement and failing the request on an inline one, add and finish exactly once in all six level/settlement combinations (round 2's R2-3).
  • OBS-34–OBS-39 — the span and both instruments at NONE with no event; the HEADERS payload with every credential header redacted and url.full scrubbed; BODY with preview_bytes from the configuration (16 configured, 8192 unset), text previewed, octet-stream as the binary marker, a charset with no converter falling back, a chunked body putting no size field on either event (BODY-35, round 1's other surviving mutation), the wire bytes untouched; http.response.duration_ms from a FakeClock advanced by hand; every Keys and Events constant present in the manifest.
  • OBS-35 — the key required, the tiers in order through FakeConfigSource seams, an unrecognised level falling back, DEFAULT is NONE.
  • The four wirings — close_quietly(bad, logger:) emitting http.instrumentation.close and returning nil, onto: still attaching, neither still silent; Hooks.notify with three raising hooks raising the first with two on the trail and two http.instrumentation.hook events; Proxy.resolve(config, logger:) on a malformed HTTPS_PROXY yielding nil, one WarningCaptured warning and one http.instrumentation.config event, with the credential in neither channel for the quoted, bracketed and doubled spellings (R3-1's eight parsed-path spellings are the open case); LOG_PREVIEW_BYTES frozen with LOG_LEVEL untouched.
  • The matrix facts, pinned on every row — the five floor-straddling facts of the design plus 5c's two (Fiber[:k] = nil retaining on 3.2, Fiber["k"] raising on 3.2/3.3), fact 3 stating each row's expected map (round 0's R0-1: the first cut was order-dependent on the floor).

Verification

  • bundle exec rake on Ruby 4.0.6 at this tip: exit 0, all seventeen gates green — test:gems 2,050 runs / 58,450 assertions, line coverage 99.98%; honest RuboCop 401 files clean.
  • The matrix set on 3.2.11, 3.3.12 and 3.4.10 with a fresh lock: 0 failures; three extra seeds on 4.0.6 and one on 3.2.11 with identical run counts; the OBS-1 allocation assertion 0/30 whole-file and 0/30 alone on the floor after round 2's repair.
  • Four reviewers applied 47, 53, 56 and 56 single-edit mutations across the rounds; every one caught at the final tip, ten on 3.2.11 as well (the OBS-8 latch race probabilistically there — R3-3).

Known follow-ups from the final review (not blocking)

  • R3-3 (nit) — event_test.rb:100: the OBS-8 race test's four-thread Queue gate catches an unsynchronised latch only probabilistically on 3.2.11; a sixteen-thread barrier released on one signal would make it deterministic.
  • R3-1 (on the code PR) needs its eight parsed-path proxy spellings asserted here once the belt is per-run; R3-2 needs a FakeClock-advanced caller-callback case at HEADERS and BODY asserting the histogram and the log duration agree and exclude it.
  • diagnostics_test.rb changes in both this PR and the code PR: 5c's pin repaired to four constants and three functions on the code branch (the suite must be green there), the full 5b mirror here.

@Wahbeh-Mohammad
Wahbeh-Mohammad force-pushed the 19-phase-5b-logging-and-redaction branch from fc93a29 to e8e2431 Compare September 18, 2026 08:56
@Wahbeh-Mohammad
Wahbeh-Mohammad force-pushed the 19-phase-5b-logging-and-redaction-tests branch from 36952b4 to a40dbc5 Compare September 18, 2026 08:56
@Wahbeh-Mohammad
Wahbeh-Mohammad force-pushed the 19-phase-5b-logging-and-redaction branch from e8e2431 to 5771ec7 Compare September 18, 2026 09:04
@Wahbeh-Mohammad
Wahbeh-Mohammad force-pushed the 19-phase-5b-logging-and-redaction-tests branch from a40dbc5 to 60d3e68 Compare September 18, 2026 09:04
@Wahbeh-Mohammad
Wahbeh-Mohammad force-pushed the 19-phase-5b-logging-and-redaction branch from 5771ec7 to 1e1c7b9 Compare September 18, 2026 09:12
@Wahbeh-Mohammad
Wahbeh-Mohammad force-pushed the 19-phase-5b-logging-and-redaction-tests branch from 60d3e68 to f5a9941 Compare September 18, 2026 09:12
@Wahbeh-Mohammad
Wahbeh-Mohammad changed the base branch from 19-phase-5b-logging-and-redaction to main September 18, 2026 09:17
Add fourteen suites under test/dexpace/instrumentation/ -- twelve
mirrors of the phase-5b files plus the floor-straddling matrix facts as
a standing test and the four downstream wirings -- and rewrite 5c's
diagnostics mirror as this phase's, asserting the fold, the snapshot
bridge across a real thread boundary, and what the 3.2 floor makes of a
restored key, floor-aware through FiberStorageFacts. The two steps are
driven through the real Pipeline and AsyncPipeline over phase 2's
transport fakes and Completer, with 5c's recording tracer factory and
meter and 5a's FakeClock, and every configuration a suite consults is
built over FakeConfigSource seams so the process environment is never
read.

Add two top-level doubles under test/support/: RecordingSink, a real
in-memory sink with per-severity enablement, and DiagnosticContext, the
save-and-restore block for Fiber storage.

Every "never throws" claim is asserted on the substituted value; the
inert event is measured at zero allocations per chained call; and the
four tests the guard pass found missing are here: a sink that re-enters
the logger from inside its own write, the async path's header
redaction, a recording cursor whose fork raises, and the headers level
with a cap supplied. Forty-eight single-edit mutations of lib/ are
caught by these suites on 4.0.6 and 3.2.11.
Review round 0's findings, each with the suite that now runs red on
its revert. The redactor suite gains the three inputs that leaked
through Redactor#header_value -- a network-path reference on the
relative route, an authority the parser rejects on the surgery route,
and a userinfo on the exploding-policy fallback -- plus the `%zz`
parameter name that used to sentinel the whole URL and the opaque
URI's query-shaped tail (P5-100, P5-101). The step suite drives four
hostile Location values through a real pipeline at HEADERS and asserts
the credential in no payload. The event suite gains a HeaderGateTest
class: a credential header written straight into Event#field is
REDACTED, dropped in omit mode, and the name gate runs before the
URL-value redactor (P5-102).

Fact 3 of logging_matrix_facts_test.rb was order-dependent on the 3.2
floor: every teardown's `Fiber[OTHER] = nil` is retained there, so
`storage == prior` held for any test but the first and the assertion
"exact iff = nil deletes" failed on 12 of 13 orders. The expected map
is now stated for the row -- `prior` where `= nil` deletes,
`prior.merge(OTHER => nil)` on the floor -- which is the same map
whether or not the residue was already present. Green on 3.2.11 with
seeds 9818, 1 and 42 and standalone; the old spelling reproduces the
failure on seed 9818.
Twelve cases for review round 1 of phase 5b. The proxy resolver's
warning and its config diagnostic are driven with nine
credential-bearing malformed HTTPS_PROXY values -- the no-port,
out-of-range, non-numeric, space-in-host, no-host, double-@,
scheme-less, network-path and query-carrying spellings -- asserting the
placeholder in both channels and the credential in neither, and the
not-a-URI message named once without the parser's text (R1-1,
P5-103). The two ambient sources meet the reserved-key table: a
url.full, an Authorization and a Location in the logger's global
context are redacted once at build and the caller's Hash is untouched;
the unfiltered and the listed fold redact the same keys; omit mode
drops a non-allow-listed header from either source (R1-2, P5-104). A
Location with a leading SP, HTAB, VT, NUL or a trailing high byte
loses its userinfo through the redactor and through the step at
HEADERS over an inbound Headers built with the space, while the four
non-authority spellings are written back as given (R1-3, P5-105).
charset=utf-7 and iso-2022-jp-2 decode as UTF-8 at Preview.render and
the step at BODY still emits the http.response event (R1-4, P5-106).

The two mutations that survived round 1 now fail: a settlement failed
from a Thread whose own Fiber storage differs emits the failure event
under the caller's captured trace.id and span.id and restores the
settler's keys (R1-5); a chunked request and response body of declared
length -1 put no size field on either event at HEADERS (R1-6).

Three suites are split under Metrics/ClassLength: the redactor's
surgery-route cases move to SurgeryRouteTest, the step's header cases
to HeaderRedactionTest, and WritingTransport moves into the step
suite's shared Fixtures.
The surgery route: every prefix review round 2 named before a real
authority -- RFC 3986 Appendix C's delimiters, quotes, parentheses, a
word, an encoded space, `+`, `@`, a backslash, an NBSP, a line
separator, the BINARY obs-text spellings -- and a doubled proxy URL,
through Redactor#header_value, through a real pipeline at HEADERS over
inbound Headers, and through Proxy.resolve with a quoted, bracketed or
doubled HTTPS_PROXY (P5-107). The P5-105 assertion that a non-whitespace
prefix is written back verbatim is gone; the not-an-authority list is
now what the parser accepts without one and the backslash spellings, and
a path that spells a second authority is asserted as OBS-14's path.

Per-value redaction: two Locations through the step and an Array through
Event#field, each value redacted before the ", " join (P5-108).

The async step under a throwing meter at every level: a later settlement
raises into the settler while the caller still receives the response,
an inline settlement fails the request, and the counter and the span
finish are counted at exactly one each way (P5-109).

AllocationDelta#allocations_per_call returns the figure two consecutive
measurements agree on: on the 3.2.11 floor a one-time cost of 7 or 28
objects can land inside a measured block after the warm-up, once per
process and test-order dependent, so a single measurement came back
negative in roughly one whole-file run in fifteen and the exact zero
assertion failed it (R2-4). A change to 5c's support file; its five
allocation suites re-run green and the M02 guard still runs red.
The redactor suite's not-an-authority list gains a path-absolute
reference (`/http://user:secret@h/p`, which the parser accepts as a
path and the relative route writes back) and a `/ /` that is not a
`//` (P5-100, P5-107): both surfaced by re-running review round 2's
battery against the repaired redactor, and both are what RFC 3986
decides rather than what the surgery pattern reaches.
@Wahbeh-Mohammad
Wahbeh-Mohammad force-pushed the 19-phase-5b-logging-and-redaction-tests branch from f5a9941 to 5e420e6 Compare September 18, 2026 09:17
@Wahbeh-Mohammad
Wahbeh-Mohammad merged commit 9bfc3dd into main Sep 18, 2026
5 checks passed
@Wahbeh-Mohammad
Wahbeh-Mohammad deleted the 19-phase-5b-logging-and-redaction-tests branch September 18, 2026 09:25
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