32 KiB

Raw Blame History

G-036 Root-cause the Tcl 9 console+udp worker-thread event-loop wedge; minimal repro for possible upstream reporting

Status: achieved 2026-07-08 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: (reworked 2026-07-08 after the root cause was found) the wedge mechanism is identified and written up in the detail file - DONE: bundled tcludp 1.0.12's Windows per-thread UDP_ExitProc closes the process-global synchronization events, proven by dump handle-table analysis plus a live CloseHandle breakpoint and confirmed by the upstream 1.0.12->1.0.13 diff, which already fixes it (so no upstream report is required; the standalone minimal repro originally required here is waived as moot by the user); the tcl9 kits bundle tcludp >= 1.0.13 with the in-context batch harness baseline resolved - DONE 2026-07-08 (run-2 syslog workers alive vs the 4/4-wedged 1.0.12 baseline); REMAINING: a has_bug-style detection in the punkshell check machinery (in the vein of punk::lib::check::has_tclbug_* / punk::console::check::has_bug_*, surfaced through the same reporting as 'help tcl'/'help console') reports the vulnerable combination - simple version-based detection (loaded/bundled tcludp < 1.0.13 on Tcl 9 Windows) is sufficient, no behavioural probe needed; loose-end decisions (punk8win 8.6 kit's udp 1.0.12 swap; optional upstream tickets for residual tcludp trunk weaknesses) recorded in the detail file when made.

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

exit/quit unwind the repl completely (both teardown phases finish, repl::start returns exit 0).
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.
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).
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
- main thread closing stdin and ADOPTING the CONIN$ channel into the stdin std-channel slot (channel name becomes 'stdin'), SetStdHandle, and an active gets-on-readable reader armed - i.e. the same visible stdin arrangement the restarted repl has ('adopt' probe variant, 2026-07-08)

Upstream reconnaissance (2026-07-08, TEMP_REFERENCE fossil checkouts: Tcl core trunk-side branch @ 2026-07-07, tcludp trunk @ 2026-07-05):

core-9-0-branch has had NO tclWinConsole.c change since 9.0.2 beyond an include-hygiene commit (2025-10-24) - the wedge, if in the console driver, is likely still present in 9.0.x maintenance. Trunk has console-channel activity by apnadkarni (2025-12-29 metakey-notification change + revert; branch apn-winconsole-noreadahead) worth reading.
Current tclWinConsole.c architecture confirms a credible wedge surface: process-global gConsoleLock, a console-handle list SHARED ACROSS ALL Tcl THREADS, per-handle SRWLOCKs, reader/writer threads coordinated via CONDITION_VARIABLEs (consoleThreadCV / interpThreadCV "for awakening interp thread(s)"), and Tcl_ThreadAlert fan-out to interested channel-owning threads. A missed CV wakeup leaves an interp thread blocked inside a console-driver call - matching the observed "blocked not spinning, timers and thread::sends unserviced".
Sharpened worker-side ingredient hypothesis: a fresh thread's std channels initialize on its FIRST channel creation (udp_open, or a -file log open) - with the process stdin handle pointing at the console (post SetStdHandle), that first channel creation attaches the worker to the shared console machinery. Fits the data exactly: run-2 workers that never create any channel (-file {} -syslog {}) survive; channel-creating ones wedge; run-1 workers (stdin handle = dead pipe at creation) are immune. NOT yet reproduced by probes, so at least one more live-shell ingredient is still missing (candidates below).

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

[round 1 done 2026-07-08, see Notes] Capture native thread stacks of a wedged in-context specimen. Pipeline proven: spawn specimen via the hidden-console repro (post-fix, punkshout/punksherr still wedge in run 2 - their syslog comes from the logging config), procdump64 -accepteula -ma <pid> <dmp> (c:/cmdfiles/SysinternalsSuite), then WinDbgX -y srv*C:\symbols*https://msdl.microsoft.com/download/symbols -z <dmp> -c "~*k 30; .logclose; q" -logo <txt> (winget Microsoft.WinDbg; cdb is ACL-buried in WindowsApps but WinDbgX accepts classic scripted args). ROUND-1 LIMITATION: on the committed (fix-applied, uninstrumented) tree, workers carry no heartbeat timers, so a wedged worker is stack-indistinguishable from an idle one (all show the notifier MsgWaitForMultipleObjectsEx wait).
NEXT: re-add the shellthread instrumentation (listings below), spawn a specimen whose diag identifies the wedged worker tids (the tidXXXX hex in diag lines = dump thread Ids), dump, then read the wedged thread's exact stack, its MsgWait timeout argument (5th arg, on the stack frame - a permanently-zero or INFINITE timeout each discriminate a theory), and per-thread CPU (spin vs block decides the tcludp packetNum poll-mode theory below).
Read tcludp SocketThread's alert path and the packetNum consumption paths fully against the round-2 evidence; then reduce to a minimal repro.
Write up the mechanism here.
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).
Upstream filing (Tcl core or tcludp) is the user's manual decision and step.

Findings round 1: native stacks + tcludp source (2026-07-08)

Uninstrumented specimen dump (15 threads): 11 threads in the Tcl notifier's win32u!NtUserMsgWaitForMultipleObjectsEx (event loops - workers indistinguishable wedged vs idle without timers); one thread parked in SleepConditionVariableSRW inside static Tcl (consistent with a console reader thread on its CV); twapi's GetMessage thread; and - notable - one thread living entirely inside tcl9udp1012.dll blocked in WaitForSingleObjectEx: tcludp runs its own global helper thread on Windows.

tcludp generic/udp_tcl.c (trunk 2026-07-05) Windows architecture - a rich wedge surface that is udp-specific by construction (matching "only udp-using workers wedge"):

sockListLock is an auto-reset EVENT used as a lock (CreateEvent auto-reset initially signaled; acquire = WaitForSingleObject INFINITE, release = SetEvent). No ownership, no recursion, lost-SetEvent = every udp-owning thread blocks INFINITE at its next event-loop pass (setup/check procs take it every pass) - deaf to timers and thread::send, blocked not spinning. Fingerprint-compatible.
One global SocketThread: acquire lock -> build fd_set skipping sockets with packetNum>0 or threadId NULL -> release -> if no sockets, park INFINITE on waitForSock event (the observed WaitForSingleObjectEx park) -> else select with 50ms timeout -> on readable: packetNum++ and (presumably - to verify) Tcl_ThreadAlert to the owning interp thread.
UDP_CheckProc (every event-loop pass of every udp-owning thread) recvfroms each owned socket unconditionally under the lock. Socket is non-blocking (ioctlsocket FIONBIO at open), so no blocking-read wedge - THAT theory is dead. But on error (e.g. WSAECONNRESET from our ICMP port-unreachable datagrams to 127.0.0.1:514-with-no-listener) it just frees the buffer: packetNum is apparently NOT decremented on the error path (decrement lives in the consumed-packet read path, ~line 1035).
UdpSetupProc: while packetNum>0 for an owned socket, forces Tcl_SetMaxBlockTime({0,0}) - ZERO block time - on EVERY pass. A packetNum stuck >0 (ICMP-flagged socket whose "packet" can never be consumed as data) therefore locks the owning thread's event loop into permanent zero-timeout poll mode. How that manifests under the Tcl 9 Windows notifier (busy spin? degenerate wait that starves timer/alert dispatch? interaction with the console-attached notifier mode?) is the round-2 question - note the separately-observed one-core-spinning orphaned interactive punk902z (dead console) may be this same packetNum poll mode showing as a spin in a different notifier state.
Tcl 8.6 immunity and console-dependence remain to be explained by whichever mechanism survives round 2 (8.6 vs 9 notifier differences, and console-attached notifier behaviour, are the candidate discriminators).

Dump artifact: %TEMP%/punk_wedge.dmp (244MB, round-1 specimen) + %TEMP%/punk_wedge_stacks.txt.

Findings round 2: object-level proof of the wedge mechanism (2026-07-08)

Instrumented traffic-enabled specimen (syslog force-toggle in shellfilter::run to make the runtag log worker send datagrams again): run-2's three syslog workers completed init then wedged in <1s, blocked not spinning (~30-47ms CPU, Wait state). Their dump stacks all show WaitForSingleObjectEx inside tcl9udp1012 called from the Tcl event loop - the WaitForSingleObject(sockListLock, INFINITE) in tcludp's per-thread event-source procs (disassembly confirms both worker wait sites load the sockListLock static; run-1's two surviving syslog workers block at the sibling call site). The SocketThread's park site loads the waitForSock static immediately after a SetEvent(sockListLock) - it released properly.

Handle-table proof: the sockListLock static holds handle 0x38c which the dump's handle data shows is now an IoCompletion object, and waitForSock (0x37c) shows as a manual-reset event, set - tcludp only ever creates auto-reset events. Both tcludp global event objects were CloseHandle'd mid-session (waiters keep an object alive but no handle remains to ever signal it; the freed handle VALUES were recycled by unrelated code). Every udp-loaded thread that touches the event-source procs after that blocks forever. 16-thread census: no thread holds the lock doing work; the previously-terminated run-1 shellfilter-run worker (the only udp thread that died mid-session, in the run-1->run-2 transition) is the prime closer suspect - ExitSockets (the only code closing these handles, registered via Tcl_CreateExitHandler in every Udp_Init) apparently runs during that thread's teardown.

Downstream picture is now complete: closed-lock wedge -> udp-loaded workers freeze -> punkshell's old synchronous teardown send to a frozen worker -> the original exit/quit hang (mitigated). "Console dependence" dissolved: the CONIN$ restart was simply the only scenario where a udp-loaded worker died mid-session. Tcl 8.6 immunity presumably = its finalize-at-thread-death path not running the process exit handler (to verify; also check which tcludp version the 8.6 kit bundles).

Minimal-repro attempts that did NOT reproduce (probe 'die' variants, consoleless script mode): a released udp-loaded worker; a terminate-mimic (open socket + datagrams + close + self thread::release -wait, verified thread death); same with the full punk package env (packagepreference + shellthread). So the ExitSockets trigger needs something more from the live shell. Next candidates:

terminate via thread::send -async <tid> <script> <resultvar> (the real shutdown_free_threads form - result delivery during thread death may take a different teardown path)
thread::cancel (the codethread is cancelled in the same transition window)
Decisive regardless: live-attach WinDbgX during the run transition with a conditional breakpoint on KERNELBASE!CloseHandle for the lock handle value (read the statics early via the running process) - catches the closer with a full stack. Or a debug tcludp build with logging in ExitSockets (needs a compiler).

Round-2 artifacts: %TEMP%/punk_wedge2.dmp + _stacks/_disasm/_h2 logs.

Findings round 3: ROOT CAUSE - tcludp 1.0.12 UDP_ExitProc closes process-global events at thread exit (2026-07-08)

Live-attach WinDbgX with a conditional breakpoint on KERNELBASE!CloseHandle for the sockListLock handle value (read from the tcludp statics at attach) caught the closer red-handed. Trap script (run via WinDbgX -p <pid> -c "$$><script.txt" -logo <log>, attached during a long-lived piped phase so the bp arms before the transition; statics at tcl9udp1012+0x8800/+0x8818 for the 1.0.12 DLL; note || is not valid in .if conditions):

r $t0 = poi(tcl9udp1012+0x8800)
r $t1 = poi(tcl9udp1012+0x8818)
.printf "tcludp sockListLock handle: %p  waitForSock handle: %p\n", @$t0, @$t1
bp KERNELBASE!CloseHandle ".if (@rcx == @$t0) {.printf \"*** CloseHandle on sockListLock %p ***\n\", @rcx; ~.; k 30; .logclose; qd} .else {gc}"
g

It caught the closer: the CloseHandle is invoked from Tcl's thread-exit-handler walker in a dying Thread-extension worker, with no udp frame visible (tail-call). The fossil diff tcludp-1_0_12 -> current names it exactly - tcludp 1.0.12's Windows per-thread exit handler:

/* UDP_ExitProc - called at thread exit */
void UDP_ExitProc(ClientData clientData) {
    Tcl_DeleteEventSource(UDP_SetupProc, UDP_CheckProc, NULL);
    CloseHandle(waitForSock);     <- process-global
    CloseHandle(sockListLock);    <- process-global
}

So in the bundled tcludp 1.0.12, the FIRST udp-loaded thread to exit closes the process-wide lock/wake events. Threads already waiting keep waiting on the orphaned object forever (no handle left to signal it); later waiters wait on whatever kernel object RECYCLED the handle value (the round-2 dump's IoCompletion) and block forever; if the value happens to be unrecycled, WaitForSingleObject fails fast and execution limps on silently - which is exactly why the standalone die-worker probes stayed green (little handle churn after the close) while punkshell's run-2 startup (heavy handle churn immediately after the transition-time worker death) wedged 4/4.

Full causal account of the original symptom:

Piped-stdin run 1 creates a syslog log worker (udp loaded, socket opened).
At the run-1 -> run-2 transition, punkshell's between-runs teardown terminates that worker (pre-fix via unsubscribe/shutdown path; post-fix shutdown_free_threads still terminates free workers between runs) -> UDP_ExitProc closes the globals.
Run-2's syslog workers load udp (event-source procs registered), their first event-loop passes block forever in WaitForSingleObject(sockListLock) on a recycled handle.
exit/quit's synchronous teardown send to the wedged worker froze the shell (mitigated in shellthread 1.6.3 / shellfilter 0.2.4).

Upstream status: already fixed. The 1.0.12 -> 1.0.13/trunk rewrite (tcludp-1-0-13 tagged 2026-06-27; "Code Not Thread-Safe" ticket closed 2026-07-05) replaces UDP_ExitProc with UdpThreadExitProc (per-thread: deletes the event source only) + ExitSockets (process exit handler: closes the events). No upstream report needed for the killer bug.

Remedy for punkshell: upgrade the bundled tcludp to 1.0.13+ (kits bundle tcl9udp1012.dll = 1.0.12). Re-verify with the in-context batch harness after the upgrade (baseline: punk902z run-2 syslog workers wedged 4/4 -> expect 4/4 alive).

Upgrade DONE and VERIFIED 2026-07-08 (project 0.4.3): tcludp 1.0.13 placed in src/vendorlib_tcl9/win32-x86_64 and copied manually into punk9win.vfs/lib_tcl9 and punk9win_for_tkruntime.vfs/lib_tcl9 (udp1.0.12 removed); rebuilt kit reports package require udp = 1.0.13; regression batch (hidden-console, syslog force-toggled, same conditions as the wedged baseline): run-2 syslog workers ALL ALIVE across runs. The manual vfs copy was needed because make.tcl libs/vfscommonupdate/project do not propagate vendorlib_tcl platform libs into kit vfs lib_tcl trees - gap recorded as goal G-037. punk8win.vfs (8.6) still bundles udp 1.0.12 - same buggy code, immunity unexplained (pending decision whether to swap in 1.0.13's udp1013t.dll for the 8.x kit too).

Detection (2026-07-08 - the final acceptance item, goal flipped to achieved)

punk::lib 0.3.0 adds the check pair in ::punk::lib::check:

libbug_udp_threadexit_applies {udpversion platform tclversion} - pure classifier (facts in, verdict out; covered by a combination-matrix test in src/tests/modules/punk/lib/testsuites/lib/checkbugs.test). Vulnerable = udp version non-empty and < 1.0.13, platform windows, Tcl >= 9 (8.6 excluded per this goal's acceptance - its apparent immunity remains unexplained, see Context).
has_libbug_udp_threadexit - gathers live facts: [package provide udp] when loaded, otherwise the best available registered version discovered WITHOUT loading the binary (an unsatisfiable package require udp 999999 triggers the index scan, then [package versions udp]). Returns the standard buginfo dict (bug/description/level medium/libversion) plus a full url reference (https://core.tcl-lang.org/tcludp - tcludp is not a tcl-core tktview target).

Surfacing: help tcl (punk 0.2.1 helptopic::tcl handler) scans has_libbug_* alongside has_tclbug_* and renders the url key when present (bugref remains the tcl-core tktview shorthand). Verified: current punk902z kit (udp 1.0.13) reports bug=0 with no warning; a simulated triggered has_libbug_* check renders the warning block with description and url; checkbugs.test also pins the buginfo dict contract across all existing check procs.

Loose ends / optional follow-ups (record decisions here when made):

DECIDED + DONE 2026-07-08: punk8win.vfs (8.6 kits punksys/punkbi) swapped from udp 1.0.12 to tcludp 1.0.13 - the 1.0.13 folder is dual-generation (udp1013t.dll for 8.x selected by its pkgIndex) so the same vendorlib_tcl9 source serves lib_tcl8. Applied via the new G-037 vfslibs propagation step (declaration in src/runtime/vendorlib_vfs.toml removes the superseded udp1.0.12). The 8.6 apparent immunity remains unexplained but is now moot for punkshell kits (same fixed code everywhere).
Check why 8.6 appeared immune (different exit-handler ordering, or fast-fail luck) - academic now that all kits carry 1.0.13.
Residual weaknesses still present in tcludp trunk, candidates for polite upstream tickets: auto-reset-event-used-as-lock (lost-SetEvent risk, no ownership); packetNum not decremented on the recvfrom error path (ICMP port-unreachable leaves packetNum>0 -> permanent Tcl_SetMaxBlockTime({0,0}) poll mode for the owning thread and the socket excluded from select forever); get_tag_config-style INFINITE waits with no watchdog.
The latent hazard class in punkshell remains mitigated (teardown never blocks on a wedged worker) regardless of the upgrade.

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:

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

# 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 [adopt|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.

# 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 punkshell's actual restart: close stdin so the CONIN$ channel is ADOPTED into the
# stdin std-channel slot, then read it like the repl reader does
if {"adopt" in $::argv} {
    if {[catch {
        close stdin
        set ::conin [open {CONIN$} r]
        package require twapi
        set h [twapi::get_tcl_channel_handle $::conin in]
        twapi::SetStdHandle -10 $h
        chan configure $::conin -blocking 0
        chan event $::conin readable [list apply {{c} {
            if {[gets $c line] < 0 && [eof $c]} {chan event $c readable {}}
        }} $::conin]
        d "stdin closed, CONIN\$ adopted as '$::conin' (stdin slot), SetStdHandle done, reader armed"
    } err]} {
        d "adopt setup FAILED: $err"
    }
}

# 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

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

32 KiB Raw Blame History