Browse Source
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.commaster
2 changed files with 292 additions and 0 deletions
@ -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). |
||||||
Loading…
Reference in new issue