ci: capture BDD-target stderr to diagnose and stop the mTLS flake

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)
 
 

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):

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

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-<NN>.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
+}