From 08804abfc41d08354ade2d7326ed9cb336954624 Mon Sep 17 00:00:00 2001 From: Julian Noble Date: Mon, 3 Aug 2026 23:52:21 +1000 Subject: [PATCH] punk::tcltestrun 0.4.0: G-161 multi-line failure-banner parsing + result_expected capture fix parse_testrun previously required a failing test's opening banner '==== FAILED' to be one physical line: a description with embedded newlines spans lines (single tcltest puts, ends-only trim), the opener never matched, the closing banner was misread as an opener and the parser wedged in failure-capture state - every later event including the summary line was swallowed and the file degraded to warn/missing-cleanupTests with no failure detail. Now (G-161, settled on start-event anchoring + bounded banner buffering): - '---- start' lines (-verbose start - runtests.tcl always passes it) track the current test name. - A line '==== ...' for the current test that does not end ' FAILED' opens a banner-continuation stage (exact prefix compare, no glob), buffered until the ' FAILED'-terminated line completes the banner; recognisable event lines (took/PASSED/SKIPPED/start/summary) or a 100-line bound abandon capture and reprocess the line normally, and a stray '==== Contents of test case:' completes the banner instead of wedging. - Streams without start events, and every single-line parse path (including the emulated-banner confounder heuristics), behave exactly as before - pinned by the new characterization suite. Also fixes result_expected capture (G-161 acceptance surface): the '---- Result should have been' opener always arrives while the result_was capture is active, and the active-capture reset branch fell through past the opener elseif - result_expected was absent from every FAILED report (verified in the current full-suite baselines) and the expected-value lines leaked into test_body. The active branch now transitions result_was -> result_expected directly. New synthetic characterization suite src/tests/runner/testsuites/parser/parsetestrun.test (6 tests: multi-line fidelity incl summary flow, single-line regression shape, multi-line ERROR capture, anchored false-open abandonment, historic confounder pin, no-start-events fallback pin) green on tclsh90 (9.0.3) and native tclsh 8.6. Streams mirror real tcltest emission (verified against a live tcltest 2.5 capture). E2E fixture suite + bootsupport promotion follow in this arc. Assisted-by: harness=claude; primary-model=claude-fable-5; api-location=anthropic.com --- src/modules/punk/tcltestrun-999999.0a1.0.tm | 98 +++++++- src/modules/punk/tcltestrun-buildversion.txt | 4 +- .../testsuites/parser/parsetestrun.test | 216 ++++++++++++++++++ 3 files changed, 315 insertions(+), 3 deletions(-) create mode 100644 src/tests/runner/testsuites/parser/parsetestrun.test diff --git a/src/modules/punk/tcltestrun-999999.0a1.0.tm b/src/modules/punk/tcltestrun-999999.0a1.0.tm index f2323180..c254445f 100644 --- a/src/modules/punk/tcltestrun-999999.0a1.0.tm +++ b/src/modules/punk/tcltestrun-999999.0a1.0.tm @@ -36,7 +36,12 @@ tcl::namespace::eval punk::tcltestrun { "Parse a dict containing stderr and stdout keys into testresult summary data."\ -help\ "Parse a dict containing stderr and stdout keys into testresult summary data. - The dict is expected to be in the format returned by shellrun::runx from execution of a tcltest script" + The dict is expected to be in the format returned by shellrun::runx from execution of a tcltest script. + Intended for streams produced with tcltest -verbose {body pass skip start error line usec} (the + runtests.tcl configuration). Failing tests whose descriptions contain embedded newlines (multi-line + opening banners) are parsed with full fidelity when the stream carries -verbose start events; without + start events such banners are not recognised and parsing degrades to the historic single-line-only + behaviour." @leaders @opts @values -min 1 -max 2 @@ -81,12 +86,63 @@ tcl::namespace::eval punk::tcltestrun { set test_case_pass [dict create] #dict set test_case_pass microseconds 0 set test_case_time [dict create] + #most recently started test name, from "---- start" lines (-verbose start). + #Anchor for multi-line opening-banner recognition (G-161): without start events the + #parser retains its historic single-line-banner-only behaviour. + set current_start_name "" switch -- $what { stdout { foreach ln [split $chunk \n] { set ln_trimright [string trimright $ln] incr i set fail_stage [dict get $test_case_fail stage] + if {$fail_stage eq "banner"} { + #G-161: accumulating the remainder of a multi-line opening banner. + #tcltest emits the opening banner as ONE puts of + # ==== FAILED + #and trims only the description's ENDS, so a description containing + #embedded newlines makes the banner span physical lines: the first line + #starts "==== " (recognised by the anchored entry point below) and + #the final line always ends " FAILED" (the description's last line is + #non-whitespace-terminated, so the space before FAILED is guaranteed). + if {[string match "* FAILED" $ln_trimright]} { + #banner complete - same state as a single-line opener + dict append test_case_fail test_openingtext "\n[string range $ln_trimright 0 end-7]" + dict set test_case_fail stage open + dict unset test_case_fail banner_lines + dict append results out "<$pkg> $ln" \n + continue + } elseif {[string match "==== Contents of test case:*" $ln]} { + #terminator line missed (pathological description content) - treat the + #banner as complete and take the open->contents transition so the + #parser cannot wedge waiting for a line that already went past + dict set test_case_fail stage contents + dict unset test_case_fail banner_lines + dict append results out "<$pkg> $ln" \n + continue + } elseif {[string match "++++ * took *" $ln_trimright] + || [string match "++++ * PASSED" $ln_trimright] + || [string match "++++ * SKIPPED: *" $ln_trimright] + || [string match "---- * start" $ln_trimright] + || [string match "*:*Total*Passed*Skipped*Failed*" $ln] + || [dict get $test_case_fail banner_lines] >= 100} { + #a recognisable event line (or an implausibly long banner) while + #accumulating: this was not a banner after all - abandon capture and + #reprocess the current line through normal handling below. + #Already-buffered lines were ordinary output; they remain in 'out' + #where they were appended as they streamed. + dict set test_case_fail stage "" + dict set test_case_fail test_openingtext "" + dict unset test_case_fail banner_lines + set fail_stage "" + #deliberate fall-through - no continue + } else { + dict append test_case_fail test_openingtext "\n$ln" + dict incr test_case_fail banner_lines + dict append results out "<$pkg> $ln" \n + continue + } + } if {$fail_stage eq ""} { #not within a test case failure section, so we can parse summary lines and other output normally. @@ -124,6 +180,17 @@ tcl::namespace::eval punk::tcltestrun { continue } + # ---- start (-verbose start; the runner always enables it) + # Track the most recently started test: the anchor that lets a multi-line + # opening banner be recognised by name prefix (G-161). The name may itself + # contain spaces and even the word "start", so anchor on the LAST " start". + if {[string match "---- * start" $ln_trimright]} { + set start_pos [string last " start" $ln_trimright] + set current_start_name [string range $ln_trimright 5 [expr {$start_pos - 1}]] + dict append results out "<$pkg> $ln" \n + continue + } + if {[string match "Tests ended at*" $ln]} { #review - what outputs this? #puts stdout "<$pkg> $ln" @@ -153,6 +220,19 @@ tcl::namespace::eval punk::tcltestrun { dict set test_case_fail stage open set line_inner [string range $ln 5 end-7] ;#trim leading ==== and trailing FAILED dict set test_case_fail test_openingtext $line_inner + } elseif {$current_start_name ne "" && [string match "==== *" $ln] + && [string equal -length [string length "$current_start_name "] "$current_start_name " [string range $ln 5 end]]} { + #G-161: entry point to a MULTI-LINE opening banner - a line starting + #"==== " that does not end " FAILED" is the first + #physical line of a banner whose description contains embedded newlines + #(single tcltest puts; see the banner stage above for the terminator). + #Anchoring on the current started test's name (exact prefix compare, no + #glob) means ordinary output cannot open banner capture, and streams + #without -verbose start events never take this branch - their parsing + #is unchanged. + dict set test_case_fail stage banner + dict set test_case_fail test_openingtext [string range $ln 5 end] + dict set test_case_fail banner_lines 1 } dict append results out "<$pkg> $ln" \n @@ -232,7 +312,20 @@ tcl::namespace::eval punk::tcltestrun { # Result capture for FAILED (non-error) tests: grab "---- Result was:" and "---- Result should have been" blocks. if {$fail_stage eq "contents"} { if {[dict exists $test_case_fail result_stage] && [dict get $test_case_fail result_stage] ne ""} { - if {[string match "---- *" $ln] || [string match "==== * FAILED" $ln_trimright] || [string match "++++ *" $ln]} { + if {[string match "---- Result should have been*" $ln]} { + # Direct transition result_was -> result_expected. The two blocks are + # adjacent single puts, so this opener always arrives while the + # result_was capture is still ACTIVE. Before G-161 the line merely + # reset the active capture and the fall-through skipped the opener + # elseif below: result_expected was never captured (absent from every + # report) and the expected-value lines leaked into test_body. + dict set test_case_fail result_stage "result_expected" + if {![dict exists $test_case_fail result_expected]} { + dict set test_case_fail result_expected "" + } + dict append results out "<$pkg> $ln" \n + continue + } elseif {[string match "---- *" $ln] || [string match "==== * FAILED" $ln_trimright] || [string match "++++ *" $ln]} { dict set test_case_fail result_stage "" # fall through to normal handling below (do not continue) } else { @@ -304,6 +397,7 @@ tcl::namespace::eval punk::tcltestrun { dict unset test_case_fail result_was dict unset test_case_fail result_expected dict unset test_case_fail result_stage + dict unset test_case_fail banner_lines dict append results out "<$pkg> $ln" \n continue ;#skip to next line. diff --git a/src/modules/punk/tcltestrun-buildversion.txt b/src/modules/punk/tcltestrun-buildversion.txt index 33b18cd5..9fba7333 100644 --- a/src/modules/punk/tcltestrun-buildversion.txt +++ b/src/modules/punk/tcltestrun-buildversion.txt @@ -1,6 +1,8 @@ -0.3.1 +0.4.0 #First line must be a semantic version number #all other lines are ignored. +#0.4.0 - parse_testrun (G-161): multi-line opening-banner tolerance. A failing test whose description contains embedded newlines (tcltest emits the banner as ONE puts spanning physical lines) is now parsed with full fidelity - failure entry with name/description/result_was/result_expected - and every later event including the summary line keeps flowing. Recognition anchors on '---- start' events (-verbose start, which runtests.tcl always passes) plus bounded banner-continuation buffering, abandoned at the next recognisable event line so banner-ish ordinary output cannot swallow events. Streams without start events, and all single-line parse paths (including the emulated-banner confounder heuristics), behave exactly as before. +#0.4.0 - parse_testrun fix (G-161): result_expected was NEVER captured - the '---- Result should have been' opener always arrives while the result_was capture is active, and the active-capture reset branch fell through PAST the opener elseif, so every FAILED record lacked result_expected and the expected-value lines leaked into test_body. The active-capture branch now transitions result_was -> result_expected directly. #0.3.1 - fix: tm_path_additional_ifneeded exclude list missed the G-155 _build->_mint staging rename - staged pods in _mint were registered as bogus _mint::* modules; now -exclude-paths {**/_build/*** **/_mint/***} (full option name, ***-tail pruning form; _build kept for legacy checkouts) #0.3.0 - breaking: tm_path_additional_ifneeded now requires project_root as a 2nd parameter to fix out-of-scope $project_root bug that caused 'no such variable' errors whenever #modpod modules were found #0.3.0 - fix: #modpod version pattern is now extracted dynamically from directory name instead of hardcoded, preventing build-system version replacement from breaking pattern matching in built bootsupport copies diff --git a/src/tests/runner/testsuites/parser/parsetestrun.test b/src/tests/runner/testsuites/parser/parsetestrun.test new file mode 100644 index 00000000..d9b1c5c4 --- /dev/null +++ b/src/tests/runner/testsuites/parser/parsetestrun.test @@ -0,0 +1,216 @@ +# -*- tcl -*- +# Synthetic captured-output suite for punk::tcltestrun::parse_testrun (G-161): +# multi-line opening-banner tolerance. tcltest prints a failing test's opening +# banner as ONE puts of "==== FAILED" and trims only the +# description's ENDS, so a description with embedded newlines makes the banner +# span physical lines. parse_testrun 0.4.0+ recognises the spanned banner by +# anchoring on the "---- start" event (-verbose start, which the runner +# always passes) and buffering continuation lines until the " FAILED"-ending +# terminator - reporting such failures with full fidelity (name, description, +# result_was/result_expected) while every later event including the summary +# line keeps flowing. Streams WITHOUT start events retain the historic +# single-line-banner-only behaviour, as do all single-line parse paths +# (confounding-output heuristics unchanged - pinned here). +# +# Streams below mirror real tcltest emission shapes (tcltest.tcl failure +# block): blank separator, the -verbose line "error: test failed:" line (which +# also spans lines for a multi-line description), the opening banner, +# "==== Contents of test case:", body, "---- Result was:" / +# "---- Result should have been (exact matching):" blocks, the closing +# "==== FAILED" line, and the tab-separated cleanupTests summary line. +# +# Run: tclsh src/tests/runtests.tcl -report compact -show-passes 0 -include-paths runner/testsuites/parser parsetestrun.test + +package require tcltest +package require punk::tcltestrun 0.4.0- +package require punk::ansi ;#parse_testrun's stderr branch uses punk::ansi::ansistring + +namespace eval ::testspace { + namespace import ::tcltest::* + + variable took_usec "took 42 \u00b5s" ;#microseconds unit as emitted by tcltest -verbose usec + + proc parsed {stdout_lines} { + #run a fabricated stdout stream (list of lines) through parse_testrun the + #way runtests.tcl does (stderr/exitcode keys present) + set stream [join $stdout_lines \n] + return [punk::tcltestrun::parse_testrun [dict create stdout $stream stderr "" exitcode 0] synthfixture] + } + + proc summary_facts {r} { + #compact comparable extract of the summary + event-set fields + set facts [list] + lappend facts detected [dict get $r summaryline_detected] + lappend facts totals [dict get $r summaryline_total]/[dict get $r summaryline_passed]/[dict get $r summaryline_skipped]/[dict get $r summaryline_failed] + lappend facts fails [dict size [dict get $r testcase_fails]] + lappend facts passes [dict size [dict get $r testcase_passes]] + lappend facts skips [dict size [dict get $r testcase_constraintskips]] + return $facts + } + + #added 2026-08-03 (agent, G-161) + test parsetestrun-multiline-1.0 {multi-line-description failure parses with full fidelity and later events plus summary keep flowing} -body { + set desc [join {{first descriptive line} {second descriptive line} {third descriptive line}} \n] + variable took_usec + set lines [list] + lappend lines "---- t-multi-1.0 start" + lappend lines "" "" + lappend lines "C:/fab/synth.test:5: error: test failed: t-multi-1.0 first descriptive line" + lappend lines "second descriptive line" + lappend lines "third descriptive line" + lappend lines "==== t-multi-1.0 first descriptive line" + lappend lines "second descriptive line" + lappend lines "third descriptive line FAILED" + lappend lines "==== Contents of test case:" + lappend lines "" + lappend lines " set x got" + lappend lines " set x" + lappend lines "" + lappend lines "---- Result was:" + lappend lines "got" + lappend lines "---- Result should have been (exact matching):" + lappend lines "want" + lappend lines "==== t-multi-1.0 FAILED" + lappend lines "" + lappend lines "---- t-pass-1.1 start" + lappend lines "++++ t-pass-1.1 $took_usec" + lappend lines "++++ t-pass-1.1 PASSED" + lappend lines "++++ t-skip-1.2 SKIPPED: knownBug" + lappend lines "synth.test:\tTotal\t3\tPassed\t1\tSkipped\t1\tFailed\t1" + set r [parsed $lines] + set facts [summary_facts $r] + set f [dict get $r testcase_fails t-multi-1.0] + lappend facts status [dict get $f test_status] + lappend facts desc_ok [string equal [dict get $f test_description] $desc] + lappend facts was_ok [string equal [dict get $f result_was] "got\n"] + lappend facts expected_ok [string equal [dict get $f result_expected] "want\n"] + lappend facts body_ok [string match "*set x got*" [dict get $f test_body]] + #the expected-value lines must not leak into test_body (the pre-G-161 + #result_expected capture defect routed them there) + lappend facts body_noleak [expr {![string match "*want*" [dict get $f test_body]]}] + lappend facts pass_usec [dict get $r testcase_passes t-pass-1.1 microseconds] + lappend facts skip_reason [dict get $r testcase_constraintskips t-skip-1.2 reason] + set facts + } -result {detected 1 totals 3/1/1/1 fails 1 passes 1 skips 1 status FAILED desc_ok 1 was_ok 1 expected_ok 1 body_ok 1 body_noleak 1 pass_usec 42 skip_reason knownBug} + + #added 2026-08-03 (agent, G-161) + test parsetestrun-singleline-2.0 {single-line-description failure keeps its existing report shape} -body { + variable took_usec + set lines [list] + lappend lines "---- t-single-2.0 start" + lappend lines "" "" + lappend lines "==== t-single-2.0 one plain single-line description FAILED" + lappend lines "==== Contents of test case:" + lappend lines "" + lappend lines " set y actual" + lappend lines "" + lappend lines "---- Result was:" + lappend lines "actual" + lappend lines "---- Result should have been (exact matching):" + lappend lines "wanted" + lappend lines "==== t-single-2.0 FAILED" + lappend lines "---- t-pass-2.1 start" + lappend lines "++++ t-pass-2.1 $took_usec" + lappend lines "++++ t-pass-2.1 PASSED" + lappend lines "synth.test:\tTotal\t2\tPassed\t1\tSkipped\t0\tFailed\t1" + set r [parsed $lines] + set facts [summary_facts $r] + set f [dict get $r testcase_fails t-single-2.0] + lappend facts status [dict get $f test_status] + lappend facts desc [dict get $f test_description] + lappend facts was_ok [string equal [dict get $f result_was] "actual\n"] + lappend facts expected_ok [string equal [dict get $f result_expected] "wanted\n"] + set facts + } -result {detected 1 totals 2/1/0/1 fails 1 passes 1 skips 0 status FAILED desc {one plain single-line description} was_ok 1 expected_ok 1} + + #added 2026-08-03 (agent, G-161) + test parsetestrun-multiline-error-3.0 {multi-line-description ERROR-status failure captures returncode and errorInfo} -body { + set lines [list] + lappend lines "---- t-err-3.0 start" + lappend lines "" "" + lappend lines "==== t-err-3.0 erroring test whose description" + lappend lines "spans two lines FAILED" + lappend lines "==== Contents of test case:" + lappend lines "" + lappend lines " error boom" + lappend lines "" + lappend lines "---- Test generated error; Return code was: 1" + lappend lines "---- Return code should have been one of: 0 2" + lappend lines "---- errorInfo: boom" + lappend lines " while executing" + lappend lines "\"error boom\"" + lappend lines "---- errorCode: NONE" + lappend lines "==== t-err-3.0 FAILED" + lappend lines "synth.test:\tTotal\t1\tPassed\t0\tSkipped\t0\tFailed\t1" + set r [parsed $lines] + set facts [summary_facts $r] + set f [dict get $r testcase_fails t-err-3.0] + lappend facts status [dict get $f test_status] + lappend facts desc_ok [string equal [dict get $f test_description] "erroring test whose description\nspans two lines"] + #errorcode/errorinfo carry a historic leading space ("---- errorCode: " is + #16 chars, the capture ranges from index 15) - tolerated, not pinned + lappend facts returncode [dict get $f returncode] + lappend facts errorcode [string trim [dict get $f errorcode]] + lappend facts errorinfo_ok [string match "*boom*while executing*" [dict get $f errorinfo]] + set facts + } -result {detected 1 totals 1/0/0/1 fails 1 passes 0 skips 0 status ERROR desc_ok 1 returncode 1 errorcode NONE errorinfo_ok 1} + + #added 2026-08-03 (agent, G-161) - a test's own output emitting an anchored + #"==== ..." line (no FAILED terminator) must not swallow the + #following events: banner capture abandons at the next recognisable event + #line and reprocesses it normally + test parsetestrun-falseopen-4.0 {anchored banner-like output line for a passing test abandons capture at the next event line} -body { + variable took_usec + set lines [list] + lappend lines "---- t-conf-4.0 start" + lappend lines "==== t-conf-4.0 emulated banner-ish output from the test body" + lappend lines "more ordinary output" + lappend lines "++++ t-conf-4.0 $took_usec" + lappend lines "++++ t-conf-4.0 PASSED" + lappend lines "synth.test:\tTotal\t1\tPassed\t1\tSkipped\t0\tFailed\t0" + set r [parsed $lines] + set facts [summary_facts $r] + lappend facts pass_usec [dict get $r testcase_passes t-conf-4.0 microseconds] + set facts + } -result {detected 1 totals 1/1/0/0 fails 0 passes 1 skips 0 pass_usec 42} + + #added 2026-08-03 (agent, G-161) - characterization of the PRE-EXISTING + #single-line confounder cost, unchanged by G-161: an emulated single-line + #banner in ordinary output still opens failure-capture state and swallows + #subsequent events (historic heuristic behaviour preserved) + test parsetestrun-confounder-5.0 {emulated single-line banner in output still opens failure capture exactly as before} -body { + set lines [list] + lappend lines "---- t-conf-5.0 start" + lappend lines "==== bogus-test emulated single-line banner FAILED" + lappend lines "++++ t-conf-5.0 PASSED" + lappend lines "synth.test:\tTotal\t1\tPassed\t1\tSkipped\t0\tFailed\t0" + set r [parsed $lines] + summary_facts $r + } -result {detected 0 totals 0/0/0/0 fails 0 passes 0 skips 0} + + #added 2026-08-03 (agent, G-161) - without -verbose start events there is no + #anchor: the historic limitation stands (multi-line banner unrecognised, the + #closing banner misread as an opener, later events and summary swallowed). + #Documents the tolerance boundary rather than desired behaviour. + test parsetestrun-nostart-6.0 {stream without start events keeps the historic single-line-only parsing} -body { + set lines [list] + lappend lines "==== t-nostart-6.0 first descriptive line" + lappend lines "second descriptive line FAILED" + lappend lines "==== Contents of test case:" + lappend lines "" + lappend lines " set z 1" + lappend lines "" + lappend lines "---- Result was:" + lappend lines "1" + lappend lines "---- Result should have been (exact matching):" + lappend lines "2" + lappend lines "==== t-nostart-6.0 FAILED" + lappend lines "++++ t-pass-6.1 PASSED" + lappend lines "synth.test:\tTotal\t2\tPassed\t1\tSkipped\t0\tFailed\t1" + set r [parsed $lines] + summary_facts $r + } -result {detected 0 totals 0/0/0/0 fails 0 passes 0 skips 0} + + cleanupTests +} +namespace delete ::testspace