Browse Source

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
'==== <name> <description> 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):
- '---- <name> start' lines (-verbose start - runtests.tcl always passes
  it) track the current test name.
- A line '==== <name> ...' 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
master
Julian Noble 6 days ago
parent
commit
08804abfc4
  1. 98
      src/modules/punk/tcltestrun-999999.0a1.0.tm
  2. 4
      src/modules/punk/tcltestrun-buildversion.txt
  3. 216
      src/tests/runner/testsuites/parser/parsetestrun.test

98
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 "---- <name> 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
# ==== <name> <description> FAILED
#and trims only the description's ENDS, so a description containing
#embedded newlines makes the banner span physical lines: the first line
#starts "==== <name> " (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 "<stdout><$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 "<stdout><$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 "<stdout><$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
}
# ---- <testname_words> 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 "<stdout><$pkg> $ln" \n
continue
}
if {[string match "Tests ended at*" $ln]} {
#review - what outputs this?
#puts stdout "<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 ====<space> and trailing <space>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
#"==== <current test name> " 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 "<stdout><$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 "<stdout><$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 "<stdout><$pkg> $ln" \n
continue ;#skip to next line.

4
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 '---- <name> 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

216
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 "==== <name> <description> 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 "---- <name> 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
# "==== <name> 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
#"==== <currentname> ..." 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
Loading…
Cancel
Save