From 7f88a6a8b29e7803ad5b17e7c1b5f6b2fb8456d9 Mon Sep 17 00:00:00 2001 From: David Cozens Date: Wed, 17 Jun 2026 14:52:08 +0100 Subject: [PATCH] ci: capture BDD-target stderr to diagnose and stop the mTLS flake MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The BDD target is spawned with stderr=PIPE but nothing reads it — only stdout is teed by the reader thread. The target's error handler writes every error event to stderr, so under a retrying TLS/mTLS handshake failure (the ~1ms service loop retries thousands of times in the 10s oracle wait) the undrained pipe fills; on Windows the next write blocks the target inside Service, stalling it for the rest of the scenario and producing the intermittent "oracle received 0 of N messages" flake. The discarded stderr also meant we couldn't tell a real TLS failure from an environmental one. - _start_stderr_reader drains the target's stderr into a 16KB sliding buffer (mirrors _start_stdout_reader, shares its idempotency guard). Draining removes the pipe-full stall. - after_step dumps both stdout (GUEST:) and stderr (ERR:) on failure, so the client-side cause (handshake timeout / cert rejected / connection refused / fatal exit) is visible in the behave log. - scripts/repro-mtls-flake.ps1 loops the @mtls scenario on a native Windows box (optional -Stress load), saving failing-run logs, to confirm the hypothesis before any library/timeout change. Test-side only — no production/library change. DEVLOG entry added. Co-Authored-By: Claude Opus 4.8 (1M context) --- Bdd/features/environment.py | 25 ++++-- Bdd/features/steps/syslog_steps.py | 38 +++++++++ DEVLOG.md | 39 +++++++++ scripts/repro-mtls-flake.ps1 | 128 +++++++++++++++++++++++++++++ 4 files changed, 222 insertions(+), 8 deletions(-) create mode 100644 scripts/repro-mtls-flake.ps1 diff --git a/Bdd/features/environment.py b/Bdd/features/environment.py index cd920c2e..772f4875 100644 --- a/Bdd/features/environment.py +++ b/Bdd/features/environment.py @@ -195,23 +195,32 @@ def before_scenario(context, scenario): def after_step(context, step): """On step failure, dump the recent BDD-target stdout (FreeRTOS guest - UART output for the QEMU target) so [solidsyslog] error lines and - printf diagnostics are visible in the behave log. _solidsyslog_stdout_log - is the 16 KB sliding buffer the reader thread maintains; if the target - didn't go through _start_stdout_reader (Linux/Windows path), this is a - no-op.""" + UART output for the QEMU target) and stderr (the error handler's + [solidsyslog] / BDD-TARGET error lines) so diagnostics are visible in the + behave log. The _solidsyslog_{stdout,stderr}_log are 16 KB sliding buffers + the reader threads maintain; if the target didn't go through + _start_stdout_reader (so neither buffer exists), this is a no-op. + + stderr is the channel that carries the client-side TLS/mTLS failure reason + (handshake timeout vs cert rejected vs connection refused vs fatal exit), + so it is what distinguishes a real bug from an environmental flake.""" if step.status != "failed": return if not hasattr(context, "interactive_process"): return process = context.interactive_process - log = getattr(process, "_solidsyslog_stdout_log", None) + _dump_target_log(process, "_solidsyslog_stdout_log", "stdout", "GUEST") + _dump_target_log(process, "_solidsyslog_stderr_log", "stderr", "ERR") + + +def _dump_target_log(process, attr, channel, prefix): + log = getattr(process, attr, None) if not log: return text = bytes(log).decode("utf-8", errors="replace") - print(f"--- last {len(log)} bytes of BDD target stdout ---", file=sys.stderr, flush=True) + print(f"--- last {len(log)} bytes of BDD target {channel} ---", file=sys.stderr, flush=True) for line in text.splitlines(): - print(f" GUEST: {line}", file=sys.stderr, flush=True) + print(f" {prefix}: {line}", file=sys.stderr, flush=True) print("--- end ---", file=sys.stderr, flush=True) diff --git a/Bdd/features/steps/syslog_steps.py b/Bdd/features/steps/syslog_steps.py index a7b5afea..8786b265 100644 --- a/Bdd/features/steps/syslog_steps.py +++ b/Bdd/features/steps/syslog_steps.py @@ -335,6 +335,44 @@ def _reader(): process._solidsyslog_byte_queue.put(None) threading.Thread(target=_reader, daemon=True).start() + _start_stderr_reader(process) + + +def _start_stderr_reader(process): + """Drain process.stderr into a capped buffer for after_step diagnostics. + + The BDD target's error handler (BddTargetStderrErrorHandler.c) writes + every SolidSyslog error event to stderr. The prompt protocol only reads + stdout, so without this drain the stderr PIPE is never emptied: under a + retrying failure (e.g. a transient TLS/mTLS handshake error spun by the + ~1ms service loop) it fills, and on Windows the next write blocks the + target mid-Service — stalling it for the rest of the scenario and + producing the "oracle received 0 of N" flake. Draining both prevents the + stall and captures the client-side error so failures are diagnosable + instead of silent. Started by _start_stdout_reader, so it shares the same + idempotency guard. + + Reads in chunks (no byte-queue) because nothing parses stderr — it is + diagnostics only. + """ + if process.stderr is None: + return + + process._solidsyslog_stderr_log = bytearray() + fd = process.stderr.fileno() + + def _reader(): + while True: + data = os.read(fd, 4096) + if not data: + break + log = process._solidsyslog_stderr_log + log += data + # Cap at 16 KB — recent context only. + if len(log) > 16384: + del log[: len(log) - 16384] + + threading.Thread(target=_reader, daemon=True).start() def wait_for_prompt(process, timeout=120): diff --git a/DEVLOG.md b/DEVLOG.md index b410debb..28aad392 100644 --- a/DEVLOG.md +++ b/DEVLOG.md @@ -1,5 +1,44 @@ # Dev Log +## 2026-06-17 — capture BDD-target stderr (mTLS flake diagnosis) + +Chased the `bdd-windows-otel` mTLS flake that put `main` red after the S30 CMake +epic. A full-workflow re-run of `9605afa` went green (`46 scenarios passed`), and +the failing path (Windows mTLS = OpenSSL over Winsock) was untouched by S30.02/03, +so the merge wasn't the cause. But "it's just a flake" wasn't satisfying — the +signature didn't fit a slow handshake. + +### Findings +- The service thread retries `SolidSyslog_Service` in a ~1 ms loop, so within the + 10 s oracle-wait the sender retries thousands of times. Staying at **0 of 1** + for the whole window means the target **stalled or died**, not "was slow." +- The target is spawned with `stderr=PIPE` (`target_driver.py`) but **nothing reads + it** — only stdout is teed (`_start_stdout_reader`). The error handler + (`BddTargetStderrErrorHandler.c`) writes every error event to stderr. +- Hypothesis: under a transient TLS/mTLS handshake failure the error handler spams + the undrained stderr pipe; on Windows the pipe fills (~4–64 KB) and the next + write **blocks the target inside `Service`** → stall → `0 of N`. Intermittent + because it only bites if the handshake hasn't succeeded before the pipe fills. + mTLS is the chattiest/heaviest handshake, which fits why it's the one that flakes. +- Crucially we **couldn't tell flake from real bug** because the client-side error + was discarded. + +### Change (test-side only — no library/production change) +- `_start_stderr_reader` drains the target's stderr into a 16 KB sliding buffer + (mirrors the stdout reader; started from `_start_stdout_reader` under the same + idempotency guard). Draining removes the pipe-full stall. +- `after_step` now dumps both stdout (`GUEST:`) and stderr (`ERR:`) on failure, so + any future failure shows the exact client-side cause (handshake timeout vs cert + rejected vs connection refused vs fatal `_Exit`). +- `scripts/repro-mtls-flake.ps1` loops the `@mtls` scenario on a native Windows box + (optional `-Stress` load) and saves failing-run logs — to confirm the hypothesis + and decide whether any library/timeout change is actually warranted. + +### Decisions +- Held off on any production change (e.g. the 200 ms connect timeout, error-spew + throttling) until the captured stderr says what's actually failing. Fix the + diagnosis gap first, then let evidence drive any library change. + ## 2026-06-10 — S30.03 generate the integration manifest from CMake E30's anti-drift story. The non-CMake file/include/`-D` manifest is now generated diff --git a/scripts/repro-mtls-flake.ps1 b/scripts/repro-mtls-flake.ps1 new file mode 100644 index 00000000..ae620163 --- /dev/null +++ b/scripts/repro-mtls-flake.ps1 @@ -0,0 +1,128 @@ +<# +.SYNOPSIS + Loop the Windows @mtls BDD scenario to reproduce the intermittent + "oracle received 0 of 1 messages" flake and capture the client-side cause. + +.DESCRIPTION + Mirrors the bdd-windows-otel CI job locally on a native Windows box: + starts otelcol-contrib with the BDD config, waits for the UDP 5514 / + TCP 6514 / TCP 6515 listeners, then runs `behave` against the chosen tag + in a loop. Each iteration's full output is kept; failing iterations are + saved to Bdd/output/repro/iter-.log so the captured BDD-target stderr + (added in ci/bdd-capture-target-stderr) is available to tell a real TLS + failure (handshake timeout / cert rejected / fatal exit) from an + environmental flake. + + Prerequisites: + * The Windows BDD target is built, e.g.: + cmake --preset msvc-debug + cmake --build --preset msvc-debug --target SolidSyslogBddTarget + * behave is installed (pip install behave) and on PATH. + * Run from anywhere — the script resolves the repo root itself. + +.PARAMETER Iterations + Number of behave runs. Default 50. + +.PARAMETER Tags + behave --tags expression. Default '@mtls'. Use '@tls or @mtls' to widen, + or the full Windows filter to exercise everything. + +.PARAMETER Stress + Spawn background CPU-burner threads for the duration to bias the runner + toward the loaded conditions under which the flake appears. + +.EXAMPLE + powershell -ExecutionPolicy Bypass -File scripts\repro-mtls-flake.ps1 -Iterations 100 -Stress +#> +[CmdletBinding()] +param( + [int] $Iterations = 50, + [string] $Tags = '@mtls', + [switch] $Stress +) + +$ErrorActionPreference = 'Stop' + +# Repo root = parent of this script's scripts/ directory. +$repoRoot = Split-Path -Parent $PSScriptRoot +Set-Location $repoRoot + +$env:BDD_TARGET = 'windows' +$env:EXAMPLE_BINARY = 'build/msvc-debug/Bdd/Targets/Debug/SolidSyslogBddTarget.exe' +$env:RECEIVED_LOG = 'Bdd/output/received.jsonl' +$env:ORACLE_FORMAT = 'otel-jsonl' + +if (-not (Test-Path $env:EXAMPLE_BINARY)) { + throw "BDD target not found at $($env:EXAMPLE_BINARY). Build it first: cmake --preset msvc-debug; cmake --build --preset msvc-debug --target SolidSyslogBddTarget" +} + +$otelBin = Join-Path $repoRoot 'Bdd/otel/bin/otelcol-contrib.exe' +$otelConfig = Join-Path $repoRoot 'Bdd/otel/config.yaml' +if (-not (Test-Path $otelBin)) { + throw "otelcol-contrib not found at $otelBin. Run Bdd/otel/Install-OtelCollector.ps1 first." +} + +$outDir = Join-Path $repoRoot 'Bdd/output/repro' +New-Item -ItemType Directory -Force -Path $outDir | Out-Null + +function Wait-OraclePorts { + $deadline = (Get-Date).AddSeconds(30) + while ((Get-Date) -lt $deadline) { + $udp = Get-NetUDPEndpoint -LocalPort 5514 -ErrorAction SilentlyContinue + $tcp4 = Get-NetTCPConnection -LocalPort 6514 -State Listen -ErrorAction SilentlyContinue + $tcp5 = Get-NetTCPConnection -LocalPort 6515 -State Listen -ErrorAction SilentlyContinue + if ($udp -and $tcp4 -and $tcp5) { return $true } + Start-Sleep -Milliseconds 300 + } + return $false +} + +$stressJobs = @() +$otel = $null +try { + Write-Host "Starting otelcol-contrib oracle..." -ForegroundColor Cyan + taskkill /F /IM otelcol-contrib.exe 2>$null | Out-Null + $otel = Start-Process -FilePath $otelBin -ArgumentList "--config=$otelConfig" ` + -RedirectStandardOutput (Join-Path $outDir 'otelcol.out') ` + -RedirectStandardError (Join-Path $outDir 'otelcol.err') ` + -PassThru -NoNewWindow + + if (-not (Wait-OraclePorts)) { + throw "Oracle did not bind 5514/6514/6515 within 30s. See $outDir/otelcol.err" + } + Write-Host "Oracle listening on 5514/6514/6515." -ForegroundColor Green + + if ($Stress) { + $n = [Environment]::ProcessorCount + Write-Host "Spawning $n CPU-burner jobs for load..." -ForegroundColor Yellow + $stressJobs = 1..$n | ForEach-Object { + Start-Job { while ($true) { $x = 1; for ($i = 0; $i -lt 1000000; $i++) { $x = ($x * 7 + 13) % 1000003 } } } + } + } + + $fail = 0 + for ($i = 1; $i -le $Iterations; $i++) { + $log = Join-Path $outDir ("iter-{0:D3}.log" -f $i) + # Fresh oracle file each run so counts start from zero. + Remove-Item $env:RECEIVED_LOG -ErrorAction SilentlyContinue + $output = & behave --tags=$Tags --no-capture Bdd/features/ 2>&1 + $ok = ($LASTEXITCODE -eq 0) + if ($ok) { + Write-Host ("[{0,3}/{1}] PASS" -f $i, $Iterations) -ForegroundColor Green + } else { + $fail++ + $output | Out-File -FilePath $log -Encoding utf8 + Write-Host ("[{0,3}/{1}] FAIL -> {2}" -f $i, $Iterations, $log) -ForegroundColor Red + } + } + + Write-Host "" + Write-Host ("Done: {0} failures in {1} runs." -f $fail, $Iterations) -ForegroundColor Cyan + if ($fail -gt 0) { + Write-Host "Inspect the failing logs for 'ERR:' lines (BDD target stderr) to see the client-side TLS cause." -ForegroundColor Cyan + } +} +finally { + if ($stressJobs) { $stressJobs | Remove-Job -Force -ErrorAction SilentlyContinue } + taskkill /F /IM otelcol-contrib.exe 2>$null | Out-Null +}