From 421ba922731cbc2cbfe9dffd2e611efe77ff98d6 Mon Sep 17 00:00:00 2001 From: Julian Noble Date: Wed, 8 Jul 2026 01:27:41 +1000 Subject: [PATCH] add goal G-036: tcl9 console+udp worker event-loop wedge root-cause + minimal repro Index entry recorded active per user. The detail file carries the full investigation record: diagnosis chain of the piped-stdin exit/quit hang, evidence and scoring caveats, ruled-out repro ingredients, remaining candidates, and inline tooling listings (standalone probe script and the hidden-console batch scorer with its 2026-07-08 baseline: punk902z run-2 syslog workers wedged 4/4, punksys 8.6 alive 4/4). Upstream reporting is the user's manual step, gated on re-verifying against a Tcl 9 built from current core sources. Assisted-by: harness=claude; primary-model=claude-fable-5; api-location=anthropic.com --- GOALS.md | 6 + goals/G-036-tcl9-udp-console-worker-wedge.md | 286 +++++++++++++++++++ 2 files changed, 292 insertions(+) create mode 100644 goals/G-036-tcl9-udp-console-worker-wedge.md diff --git a/GOALS.md b/GOALS.md index 57f14cb9..1c4afac0 100644 --- a/GOALS.md +++ b/GOALS.md @@ -257,3 +257,9 @@ Scope: src/tests/modules/punk/libunknown/testsuites/ (characterization suite), s Detail: goals/G-035-mixed-tm-pkgindex-provision.md Goal: the behaviour when the same package is provided both as a .tm module and as a pkgIndex.tcl-based library - same or differing versions, under the standard package unknown, punk::libunknown and punk::packagepreference - is characterised by committed tests, and the currently informal working rule ("avoid mixing provision forms for one package - unexpected behaviour even with libunknown's improvements") is either substantiated with the specific failure modes named in AGENTS.md guidance, or retired if the characterisation shows the machinery now handles mixing predictably. Acceptance: a committed test suite (extending src/tests/modules/punk/libunknown/testsuites/) characterises at least: same name+version provided via .tm and via pkgIndex.tcl (which registration wins, and whether it is deterministic across scan-trigger orderings) under the standard scanner, under punk::libunknown, and with punk::packagepreference active; differing versions across the two forms (version selection integrity including package prefer latest, and whether the losing form's registration lingers); re-registration effects (package forget then re-require crossing forms); surprising-but-accepted behaviours are pinned with GAP/known-quirk comments (the fossilmove characterization pattern), outright bugs fixed or filed as goals; the resulting do/don't guidance lands in src/modules/AGENTS.md and src/lib/AGENTS.md naming the characterised failure modes (or explicitly lifting the avoid-mixing rule if unwarranted). + +### G-036 [active] Root-cause the Tcl 9 console+udp worker-thread event-loop wedge; minimal repro for possible upstream reporting +Scope: src/modules/shellthread-999999.0a1.0.tm, src/bootsupport/modules/shellthread-1.6.2.tm, src/modules/shellfilter-999999.0a1.0.tm (as characterised - no product-code changes required by this goal; the punkshell mitigations are separate fixes) +Detail: goals/G-036-tcl9-udp-console-worker-wedge.md +Goal: the Tcl 9-only wedge - a worker thread that has used a tcludp syslog socket stops servicing its event queue (timers, thread::send) when the punkshell process is console-attached, the proximate trigger of the piped-stdin exit/quit hang - is root-caused to a named component (Tcl 9 Windows console driver, tcludp, Thread extension, or a specific interaction) with the smallest demonstrating repro, so the user can decide on and manually file an upstream report. +Acceptance: a repro reduced to the smallest ingredient set demonstrates the wedge on Tcl 9 Windows and its absence on Tcl 8.6 under identical conditions (target: plain Tcl + Thread + tcludp with no punk modules; if a punk component proves essential, the repro thereby pins which one); the wedge mechanism is identified and written up in the detail file (which wait never returns and why - e.g. via native thread stacks of a wedged specimen); before any upstream report the repro is re-verified against a Tcl 9 built from current core sources (per G-005 build capability - the shipped kit's 9.0.2 may carry an already-fixed bug), with the outcome recorded in the detail file; upstream filing itself is the user's manual step and not gated on this goal; the in-context batch harness (hidden-console piped-stdin runs scoring worker heartbeats, listings in the detail file) is retained as the regression check, with the 2026-07-08 baseline (punk902z run-2 syslog workers wedged 4/4, punksys alive 4/4) reproduced before and resolved after any fix. diff --git a/goals/G-036-tcl9-udp-console-worker-wedge.md b/goals/G-036-tcl9-udp-console-worker-wedge.md new file mode 100644 index 00000000..8139f1b3 --- /dev/null +++ b/goals/G-036-tcl9-udp-console-worker-wedge.md @@ -0,0 +1,286 @@ +# G-036 Root-cause the Tcl 9 console+udp worker-thread event-loop wedge; minimal repro for possible upstream reporting + +Status: active +Scope: src/modules/shellthread-999999.0a1.0.tm, src/bootsupport/modules/shellthread-1.6.2.tm, src/modules/shellfilter-999999.0a1.0.tm (as characterised - no product-code changes required by this goal; the punkshell mitigations are separate fixes) +Acceptance: a repro reduced to the smallest ingredient set demonstrates the wedge on Tcl 9 Windows and its absence on Tcl 8.6 under identical conditions (target: plain Tcl + Thread + tcludp with no punk modules; if a punk component proves essential, the repro thereby pins which one); the wedge mechanism is identified and written up in the detail file (which wait never returns and why - e.g. via native thread stacks of a wedged specimen); before any upstream report the repro is re-verified against a Tcl 9 built from current core sources (per G-005 build capability - the shipped kit's 9.0.2 may carry an already-fixed bug), with the outcome recorded in the detail file; upstream filing itself is the user's manual step and not gated on this goal; the in-context batch harness (hidden-console piped-stdin runs scoring worker heartbeats, listings in the detail file) is retained as the regression check, with the 2026-07-08 baseline (punk902z run-2 syslog workers wedged 4/4, punksys alive 4/4) reproduced before and resolved after any fix. + +## Context + +Investigated 2026-07-07/08 from a user-visible symptom: piping a small script into shell mode +(`'puts test' | punk902z shell` from pwsh), pressing Enter at the first interactive prompt +(after the app-layer CONIN$ restart), then typing `exit` at the dim `P%` prompt intermittently +froze the shell - the `exit` had no effect, one further command (e.g. `pwd`) echoed but never +ran, then echo stopped entirely and only ctrl-c killed the process. + +Diagnosis chain (all confirmed by timestamped instrumentation; see Notes for instrumented sites): + +1. `exit`/`quit` unwind the repl completely (both teardown phases finish, `repl::start` returns + `exit 0`). +2. `shellfilter::run`'s tail then calls `::shellfilter::log::close` for the `shellfilter-run` + log tag -> `shellthread::manager::unsubscribe` -> a **bare synchronous `thread::send`** + (settings-reset when returning the worker to the free list) to that tag's worker thread. +3. That worker had silently stopped servicing its event queue ~1-2s after birth: scheduled + `after` heartbeats never fired and queued async `send_info` events were never processed. + The sync send therefore blocks the main thread forever -> dead event loop -> all repl + symptoms downstream (the echoed-then-dead `pwd` line is the console driver's cooked read + buffering one line that nobody consumes; no further read is posted so echo stops). +4. Only `exit`/`quit` touch that worker synchronously - every other command is unaffected, + matching the observed "only exit/quit lock up". `exit` at the first prompt usually wins the + race because the sync send happens ~600ms after the worker's first syslog write, before the + wedge sets in; the Enter-then-exit detour adds the seconds the wedge needs. + +The wedge itself - a worker thread event loop that stops processing timers and cross-thread +sends - is the residual unknown this goal exists to resolve. The punkshell hang is mitigated +separately (unsubscribe robustness + un-hardcoding the syslog default), but syslog-to-localhost +must remain a *supported* configuration, so the wedge must be understood, not just avoided. + +## Evidence so far (2026-07-08, Windows 11, punk902z = Tcl 9.0.2, punksys = Tcl 8.6, tcludp 1.0.12, workers load bootsupport shellthread 1.6.2) + +Established by heartbeat scoring (each worker schedules `after` heartbeats at init; a worker +with zero heartbeats that was not legitimately torn down is wedged): + +- Wedged workers are exactly those configured with `-syslog 127.0.0.1:514` (they open a tcludp + socket and send datagrams on first log write). Workers without syslog never wedge. +- **Tcl 9 only**: hidden-console batch (4 runs per shell, judging the post-restart run-2 + workers, which live on): punk902z wedged 4/4; punksys (8.6) alive 4/4. One earlier punk902z + hidden-console run came up clean, so treat it as near-deterministic, not absolute. +- **Console required**: the same piped run with no console attached (harness/service context) + never wedges - 8s-delayed-exit runs completed cleanly with heartbeats throughout. +- Nothing listens on UDP 514 locally, so every datagram draws an ICMP port-unreachable. +- CPU of a hung specimen stays near zero -> the wedged threads are blocked, not spinning. +- Scoring caveat: each shell's run-1 workers are torn down in the run-1 -> run-2 transition + before their heartbeats come due - their hb=0 is normal, judge run-2 workers only. +- Diag-file caveat: the shared append-mode diag file loses/garbles occasional lines under + concurrent writers; single missing lines are not evidence, multi-line absences are. + +Ingredients ruled out by standalone probes (all clean under a hidden console on Tcl 9): + +- udp_open + datagram send in a worker thread (plain probe) +- + twapi loaded with a console-control handler registered in the main thread +- + the punk worker package environment (punk::packagepreference + shellthread 1.6.2) +- + 30 datagrams and a later send on the ICMP-flagged socket +- + CONIN$ opened in the main thread with a readable handler armed +- + twapi::SetStdHandle(-10, console) before worker creation + +Untested ingredients (next candidates): + +- Real console *use*: main thread actually reading CONIN$ (gets/read pumping, as the repl + reader does), console *output* channels (all probes redirected stdout/stderr to files), + punk::console SetConsoleMode changes (VT input/output flags, raw/line flips) +- The shellfilter tee stack: tcl::chan::fifo2 reflected channels + thread::transfer to pipe + workers (cross-thread reflected-channel forwarding blocks in the owner thread's event loop) +- The repl codethread; sheer thread/channel count +- Anomaly to re-examine: probe workers created *from the codethread* inside a live shell wedged + even without udp (both udp and control probes silent) - possibly artifact, possibly a lead + +Suggested tools for the mechanism write-up: native stacks of a wedged specimen (procdump / +windbg on the hung punk902z), then map the blocked wait to tclWinConsole.c (Tcl 9 rewrite: +per-handle reader/writer threads + gConsoleLock) or tcludp's Windows event source. + +## Approach + +1. Complete the minimal repro by adding the untested ingredients one at a time to the standalone + probe (console read pumping and console output channels first - they are what the live shell + has and every clean probe lacked). +2. If no single addition wedges, capture native thread stacks of a wedged in-context specimen + (spawn via the hidden-console repro below; it idles indefinitely) and work backwards from the + blocked wait. +3. Write up the mechanism here; reduce the repro accordingly. +4. Re-verify against a Tcl 9 built from current core sources before any upstream report (the + kit's 9.0.2 may carry an already-fixed bug). Building Tcl 9 from source is G-005 territory; + this step waits on that capability (or a manually obtained current build). +5. Upstream filing (Tcl core or tcludp) is the user's manual decision and step. + +## Alternatives considered + +- Mitigate-only (make the sync send robust, default syslog off) - rejected as the *whole* + answer: syslog-to-localhost must remain supported, and a worker that silently stops logging + is still a bug in a supported configuration. The mitigations proceed independently. +- Reporting upstream from the current evidence without a minimal repro - rejected: the wedge + needs a named mechanism and a repro a maintainer can run; and it must first be shown to exist + on current Tcl 9 sources, not just the shipped 9.0.2 kit. + +## Notes + +### Session instrumentation (temporary, all sites marked `#DIAG`) + +In the working tree during the investigation; remove once the mitigations are verified: + +- `src/modules/punk/repl-999999.0a1.0.tm` - lifecycle diag markers (start/vwait/teardowns, + exit/quit writers, eval status-poll), deferred-reader arming via diag proc, and the EOF-branch + `after 1 reopen_stdin` widened to `after 500` (race-determinism experiment; revert). +- `src/modules/shellfilter-999999.0a1.0.tm` - `rundiag` markers through `shellfilter::run`'s + teardown tail (flushes, stack removals, log close). +- `src/modules/shellthread-999999.0a1.0.tm` - `unsubdiag` markers in unsubscribe/write_log/ + new_worker/shutdown paths; init_script completion marker + 2s/5s heartbeats. +- `src/bootsupport/modules/shellthread-1.6.2.tm` - `wdiag` markers in the worker procs the + worker threads actually run (init, send_info, _initsock, terminate, bgerror). Note the + version split: main thread runs the 999999 dev module, workers load bootsupport 1.6.2. +- `src/lib/app-punkshell/punkshell.tcl` - markers at do_shell return, thread shutdown/release, + and every `::exit` call site. + +Diag output appends to `%TEMP%\punkshell_rundiag.txt` (file first, stderr echo second, so the +record survives a wedged stderr). + +### In-context repro (the regression check) + +Pipe a short script into shell mode with a console attached but stdin file-redirected; the pipe +EOF triggers app-punkshell's CONIN$ restart and the restarted run's syslog workers wedge: + +```powershell +Set-Content $env:TEMP\punkin2.txt "puts test" +Start-Process cmd.exe -WindowStyle Hidden -ArgumentList '/c', + 'c:\repo\jn\shellspy\bin\punk902z.exe src shell < %TEMP%\punkin2.txt > %TEMP%\punkout.txt 2>&1' +# wait ~15s, then judge run-2 workers' heartbeats in %TEMP%\punkshell_rundiag.txt and kill the process +``` + +Interactively: `'puts test' | punk902z src shell`, Enter at the first prompt, `exit` at the dim +prompt -> hang (main thread blocked in the unsubscribe sync send). + +### Batch scorer - wedgebatch.ps1 + +```powershell +# Batch wedge-detector: run each shell N times under a hidden console with piped +# 'puts test' (pipe EOF -> CONIN$ restart), wait for heartbeat window, then score +# each syslog-configured worker (shellfilter-run/punkshout/punksherr) by whether +# its heartbeats fired. Judge run-2 workers only (run-1 workers are torn down in +# the run transition before heartbeats come due - their hb=0 is a false positive). +$diag = "$env:TEMP\punkshell_rundiag.txt" +foreach ($exe in @('punksys','punk902z')) { + for ($i = 1; $i -le 4; $i++) { + Remove-Item $diag -ErrorAction SilentlyContinue + $null = Start-Process -FilePath 'cmd.exe' -ArgumentList '/c', "c:\repo\jn\shellspy\bin\$exe.exe src shell < %TEMP%\punkin2.txt > %TEMP%\punkout_batch.txt 2>&1" -WindowStyle Hidden -PassThru + Start-Sleep -Seconds 15 + Get-Process $exe -ErrorAction SilentlyContinue | Stop-Process -Force -Confirm:$false + Start-Sleep -Milliseconds 500 + if (-not (Test-Path $diag)) { Write-Output "$exe run$i : NO DIAG FILE (src instrumentation not loaded?)"; continue } + $content = Get-Content $diag + $created = $content | Select-String "CREATED new worker (tid\S+) for tag '(shellfilter-run|punkshout|punksherr)'" + if (-not $created) { Write-Output "$exe run$i : no syslog-worker creation lines found"; continue } + foreach ($m in $created) { + $tid = $m.Matches[0].Groups[1].Value + $tag = $m.Matches[0].Groups[2].Value + $hb = ($content | Select-String "$tid\) heartbeat").Count + $verdict = if ($hb -ge 1) { "alive (hb=$hb)" } else { "WEDGED (hb=0)" } + Write-Output "$exe run$i : $tag $tid -> $verdict" + } + } +} +Write-Output "batch done" +``` + +2026-07-08 baseline output: punksys run-2 workers alive 4/4 (hb=2 each); punk902z run-2 workers +(shellfilter-run, punkshout, punksherr) WEDGED 4/4. + +### Standalone probe - udpthread_test.tcl (all variants clean so far) + +Run: `punk902z src script udpthread_test.tcl [conin] [setstd] [twapi]` - directly (consoleless) +or via hidden console (`Start-Process cmd.exe -WindowStyle Hidden -ArgumentList '/c','...exe src +script ...tcl conin setstd > out 2>&1'`). Diag appends to `%TEMP%\udpthread_diag.txt`. + +```tcl +# Minimal repro probe: does a udp_open + send inside a worker thread wedge that +# thread's event loop when the process has a console attached? +# Two workers: 'udp' (punk pkg env + udp socket + 30 datagrams + late send on the +# ICMP-flagged socket) and 'ctrl' (no udp). Both schedule heartbeats. +package require Thread + +set diagfile [file join $::env(TEMP) udpthread_diag.txt] +proc d {msg} { + set f [open $::env(TEMP)/udpthread_diag.txt a] + puts $f "[clock milliseconds] (main) $msg" + close $f +} +d "=== run start (tcl [info patchlevel]) argv:'$::argv' ===" + +# mimic the restarted repl: main thread opens CONIN$ and arms a readable handler +if {"conin" in $::argv} { + if {[catch { + set ::conin [open {CONIN$} r] + chan configure $::conin -blocking 0 + chan event $::conin readable {list} + d "CONIN\$ opened as $::conin, readable handler armed ([chan configure $::conin])" + if {"setstd" in $::argv} { + package require twapi + set h [twapi::get_tcl_channel_handle $::conin in] + twapi::SetStdHandle -10 $h + d "SetStdHandle -10 done: process stdin handle now the console" + } + } err]} { + d "CONIN\$ setup FAILED: $err" + } +} + +# mimic punk::repl::init_signal_handlers - twapi console control handler in main thread +if {"twapi" in $::argv} { + if {[catch { + package require twapi + proc ::probe_ccc {args} {return 0} + twapi::set_console_control_handler ::probe_ccc + d "twapi console control handler registered (twapi [package provide twapi])" + } err]} { + d "twapi setup FAILED: $err" + } +} + +set workerbody { + proc wd {msg} { + set f [open $::env(TEMP)/udpthread_diag.txt a] + puts $f "[clock milliseconds] (%NAME% [thread::id]) $msg" + close $f + } + wd "worker up" + if {"%NAME%" eq "udp"} { + if {[catch { + set ::auto_path [list %AP%] + ::tcl::tm::add {*}[lreverse [list %MP%]] + package require punk::packagepreference + punk::packagepreference::install + package require Thread + package require shellthread + wd "punk env loaded (shellthread [package provide shellthread])" + package require udp + wd "udp package [package provide udp] loaded" + set s [udp_open] + chan configure $s -buffering none -translation binary + chan configure $s -remote [list 127.0.0.1 514] + for {set i 0} {$i < 30} {incr i} { + puts -nonewline $s "udpthread-test-datagram-$i [string repeat x 120]" + } + wd "30 datagrams sent to 127.0.0.1:514" + after 1500 [list apply {{s} { + catch {puts -nonewline $s "late-datagram [string repeat y 120]"} e + wd "late datagram send result: '$e'" + }} $s] + } err]} { + wd "udp setup FAILED: $err" + } + } + after 1000 {wd "heartbeat 1s"} + after 2000 {wd "heartbeat 2s"} + after 5000 {wd "heartbeat 5s"} + after 8000 {wd "heartbeat 8s"} +} + +foreach name {udp ctrl} { + set tid [thread::create -preserved] + thread::send -async $tid [string map [list %NAME% $name %AP% $::auto_path %MP% [tcl::tm::list]] $workerbody] + d "created worker '$name' $tid" +} + +after 10000 {set ::done 1} +vwait ::done +d "=== main exiting ===" +exit 0 +``` + +### Related + +- Session memory: `piped-stdin-exit-hang` (agent memory dir) mirrors this state. +- Adjacent prior art: the Tcl 8.6 console parked-read work (console 0.7.1 / repl 0.2.2) - same + neighbourhood (Windows console driver vs event-driven readers), different mechanism. +- Mitigations proceeding separately (not this goal): shellthread `unsubscribe` must not use a + bare synchronous `thread::send` (async, or async + vwait-with-timeout as + `shutdown_free_threads` already does); `shellfilter::run` must honor its `-syslog` option + instead of the hardcoded `127.0.0.1:514` in `log::open` (debug leftover - the correct call + sits commented out beside it).