Profiling results publish script with improved checks - #5923
Profiling results publish script with improved checks#5923marc-casavant wants to merge 3 commits into
Conversation
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
There was a problem hiding this comment.
Approving — both findings are nits confined to a diagnostic hint line (dead grep alternative, and dash echo escape-interpretation risk) that don't affect the refuse/prune/exit-code control flow this PR is actually about.
Extended reasoning...
Overview
This PR touches two CI shell scripts: scripts/ci/publish-profiling-results.sh (adds missing-status-file detection, a new PROF_PUBLISH_PRUNE_UNCLEAN mode, and diagnostic log excerpting) and start_valgrind_profiling.sh (improves the signal/exit-status diagnostic messages). No production/server code paths are touched — this is CI infrastructure for profiling runs only.
Security risks
None of substance. Inputs are CI-internal (exit status files, local log files written by the same pipeline), not attacker-controlled in any meaningful trust boundary. The two inline findings are diagnostic-quality issues (a grep pattern that can never match its target string, and use of echo instead of printf for log-derived content under dash, which could mangle a hint line if it contains a backslash) — both only affect a stderr hint line, not the actual refuse-to-publish/prune/exit-code decisions, which are driven by the exit-status file logic that is unaffected by either bug.
Level of scrutiny
Low-to-moderate is appropriate: this is CI tooling for a profiling pipeline, not a runtime code path, and a bug here at worst produces a confusing CI log message rather than corrupting results or misfiring the actual pass/fail gate (verified: the unclean-detection, prune, and exit(1) logic in publish-profiling-results.sh is independent of the flagged echo/grep lines). The change is well-commented and the core logic (missing-status detection, prune mode, signal-name mapping) is straightforward and mirrors the existing pattern in the file.
Other factors
No prior reviews exist on this PR (fresh timeline). The sibling script already demonstrates the correct printf-based pattern for exactly the case flagged in one of the nits, so the fix is well precedented and low-risk to apply in a follow-up. Given both findings are self-described nits with no control-flow impact, I'm approving rather than deferring.
| if [ -n "$diag" ]; then | ||
| echo " freeradius.log: ${diag}" >&2 | ||
| else | ||
| diag=$(grep -E -m1 "Assertion|FATAL|out of memory|impossible happened|Fatal error" "$dir/valgrind.log" 2>/dev/null || true) |
There was a problem hiding this comment.
🟡 The valgrind.log fallback grep at publish-profiling-results.sh:123 looks for the literal substring "impossible happened" to catch VEX/valgrind internal panics, but real valgrind panic text is "the 'impossible' happened" (quote/backtick between the words), so this alternative can never match and the exact failure mode it was added for prints no diagnostic. Suggest changing the pattern to something like "impossible.*happened" so it matches the real output.
Extended reasoning...
The bug: Line 123's fallback diagnostic greps valgrind.log with grep -E -m1 "Assertion|FATAL|out of memory|impossible happened|Fatal error" when freeradius.log didn't already contain one of the primary markers. The impossible happened alternative was clearly added to surface VEX-internal panics (valgrind bugging out on the instrumented binary itself), but real valgrind/VEX panic text always has a quote or backtick between the two words: vex: the \impossible''' happened:and%s: the '''impossible''' happened:. I confirmed this directly against stringsoutput on/usr/libexec/valgrind/callgrind-amd64-linux` in this environment — every occurrence of the phrase carries that quote/space, so the literal contiguous substring "impossible happened" never appears in real output. The alternative is dead code for the one case it exists to catch.
Why this isn't a duplicate of the refuted PANIC-casing finding (bug_001): In that case the redundant PANIC alternative was harmless because CAUGHT SIGNAL in the primary freeradius.log grep already matches first for every real-world case PANIC would have covered — so PANIC being unreachable changed nothing. Here I checked the sibling alternatives against the actual valgrind binary: assertion failures print Assertion '%s' failed. (matches 'Assertion'), fatal errors print Valgrind: FATAL: (matches 'FATAL'), and OOM prints 'out of memory' (matches). None of those fire for a genuine VEX vpanic() — a VEX internal panic is the only failure mode this fallback branch was written to surface, and it's also the one alternative that can never fire. So unlike bug_001, this dead pattern is not merely redundant with a sibling that already covers the case — it's the sole coverage for exactly the case named in the surrounding logic, and that coverage silently does nothing.
Concrete walkthrough: Suppose valgrind's VEX layer hits an internal error while profiling freeradius (e.g. an unhandled instruction). Valgrind aborts and writes vex: the \impossible''' happened: ...tovalgrind.log, then exits non-zero. start_valgrind_profiling.shrecords the exit status;publish-profiling-results.shcorrectly detects the run as unclean via thevalgrind-exit-statusfile (this part is unaffected — the refuse-to-publish / prune logic and the CI exit code both work correctly). The script printsexplain_statusfor the raw exit code, then falls into the freeradius.log/valgrind.log diagnostic block.freeradius.loghas none of ASSERT FAILED/CAUGHT SIGNAL/_EXIT/PANIC (freeradius itself didn't do anything wrong — valgrind died), so it falls to thevalgrind.loggrep. That grep runs against a log containing the VEX panic line, matches none of the five alternatives (the panic line has a quote where the pattern expects a bare space), anddiagcomes back empty, so novalgrind.log: ...` hint line is ever printed. A CI engineer investigating the failure gets the generic exit-status explanation but no pointer into the log for this specific, actionable case — exactly the gap the surrounding comment says this diagnostic exists to close.
Impact / why it's a nit and not blocking: This grep only controls whether an extra hint line is echoed to CI stderr — it does not affect the refuse-to-publish decision, the prune behavior, or the exit code, all of which are driven by the exit-status/missing-status logic earlier in the script. A VEX-panic run is still correctly flagged unclean and still correctly refused or pruned; the only loss is a convenience diagnostic line for a rare failure mode (valgrind bugging out on itself, as opposed to freeradius crashing). Fix is a one-line pattern tweak, e.g. grep -E -m1 "Assertion|FATAL|out of memory|impossible.*happened|Fatal error" or matching just impossible'.
On the refutation: The refuter's functional-impact argument is correct as far as it goes — nothing in the publish/refuse/prune control flow depends on this grep — and I agree that alone wouldn't justify blocking merge. But that's exactly why this is filed as nit rather than normal, not a reason to drop it entirely: it's a real, verified dead pattern with a trivial fix, and (unlike bug_001) it's the sole diagnostic path for the specific failure mode it was written to name, so leaving it as-is means CI logs stay silent on that one case indefinitely.
There was a problem hiding this comment.
The pattern was changed from impossible happened to 'impossible' happened (commit 2f4325a), but this only fixes the assert-style message and still misses the VEX internal panic — the exact case this alternative exists to catch.
Verified against strings /usr/libexec/valgrind/callgrind-amd64-linux, there are three real message formats:
"%s: %s:%d (%s): the 'impossible' happened." <- matches new pattern (straight quotes both sides)
"%s: the 'impossible' happened:" <- matches new pattern (straight quotes both sides)
"vex: the `impossible' happened:" <- does NOT match (backtick before 'impossible', not a straight quote)
The new grep alternative '\''impossible'\'' happened requires a leading straight quote immediately before "impossible", so it matches the two M_ASSERT-style panic strings but still can never match the VEX-level panic line (vex: the \impossible' happened:`), which is the specific VEX-internal-panic failure mode called out in the surrounding comment as the reason this alternative was added.
Suggest broadening to something that doesn't anchor on the character before "impossible", e.g. impossible.*happened (as originally suggested) or [''']impossible' happened` to explicitly allow either quote style.
| echo " freeradius.log: ${diag}" >&2 | ||
| else | ||
| diag=$(grep -E -m1 "Assertion|FATAL|out of memory|impossible happened|Fatal error" "$dir/valgrind.log" 2>/dev/null || true) | ||
| [ -n "$diag" ] && echo " valgrind.log: ${diag}" >&2 |
There was a problem hiding this comment.
🟡 In publish-profiling-results.sh this script runs under #!/bin/sh (dash on the CI runners), whose echo builtin interprets backslash escapes by default — so echo "...: ${diag}" at lines 121/124 can mangle or truncate the diagnostic line (a trailing \c drops the rest of the line and its newline) since $diag is untrusted, grep-captured log content that can contain backslashes (e.g. LDAP DN escapes, DOMAIN\\user). The sibling script touched by this same PR (start_valgrind_profiling.sh) already avoids this exact issue by using printf '%s\n' "$var" for variable content — the same pattern should be used here, e.g. printf ' freeradius.log: %s\n' "${diag}" >&2.
Extended reasoning...
The bug: publish-profiling-results.sh declares #!/bin/sh, which on the FreeRADIUS CI runners resolves to dash. Unlike bash, dash's echo builtin interprets backslash escape sequences unconditionally (XSI-style behavior, no -e needed) — POSIX explicitly leaves this implementation-defined, and dash chooses to always expand escapes. The new diagnostic lines added by this PR are:
echo " freeradius.log: ${diag}" >&2
...
echo " valgrind.log: ${diag}" >&2$diag is not a fixed string — it is captured via grep -E -m1 ... "$dir/freeradius.log" (or valgrind.log), i.e. arbitrary, attacker/environment-controlled log content (assert messages, panic messages, signal-related text). FreeRADIUS fault messages routinely embed backslashes: LDAP DN/filter escaping uses sequences like \\28/\\29, and Windows/NTLM/Kerberos identities appear as DOMAIN\\user. If such a backslash sequence lands in the matched line, dash's echo will reinterpret it as an escape rather than printing it literally.
Concrete proof (verified by two independent verifiers running dash):
$ dash -c 'diag="some text\\ctrailing"; echo "line: ${diag}"'
line: some textThe \\c sequence causes dash's echo to suppress all further output including the trailing newline — the diagnostic is truncated mid-line and the next echo's output gets concatenated onto the same terminal/log line. Other sequences like \\n or \\t insert literal control characters into the CI log instead of printing the log line as-is.
Why nothing today prevents this: the value flows straight from grep output into echo with no sanitization, and there is no guarantee the shell interpreting the script is a POSIX/bash-only echo — the shebang is #!/bin/sh, and CI runners for this repo use dash for /bin/sh.
Established precedent in this very PR: start_valgrind_profiling.sh, modified by this same PR, already prints variable/log-derived content ($CTRL_OUT) via printf '%s\n' "$CTRL_OUT" specifically to sidestep this exact class of shell-dependent echo behavior. The new diagnostic code in publish-profiling-results.sh doesn't follow that established, safer pattern.
Impact: this is diagnostic output written to stderr in the CI log only — it does not influence the unclean-detection logic, the prune/refuse-to-publish decision, or the exit code, all of which are driven by the valgrind-exit-status file contents, not this echoed string. Worst case is a garbled or truncated hint line in the CI log, occasionally running into the next line's output, which makes the diagnostic harder to read right when someone is debugging a CI failure — mildly self-defeating for a change whose whole purpose is improving diagnostics, but not something that breaks the pipeline.
Fix: swap both echo calls for printf, matching the sibling script's pattern:
printf ' freeradius.log: %s\n' "${diag}" >&2
...
printf ' valgrind.log: %s\n' "${diag}" >&2
There was a problem hiding this comment.
Beyond the inline findings from this run, I also checked the PROF_PUBLISH_PRUNE_UNCLEAN env var mentioned in the PR description: it isn't actually implemented anywhere in the diff — pruning of unclean test directories happens unconditionally, not gated behind that variable. The description overstates what's configurable, but the unconditional-prune behavior itself matches the rest of the script and isn't a functional bug.
Extended reasoning...
Ruled-out check only: the PR description advertises a PROF_PUBLISH_PRUNE_UNCLEAN toggle for enabling pruning of unclean results, but grepping the diff and the full modified publish-profiling-results.sh shows no reference to that variable — the new unclean-pruning loop runs unconditionally for every invocation. This is a documentation/description accuracy issue rather than a code bug (the code is internally consistent, it just does more than the description says), so it doesn't change the verdict on the already-filed inline nits.
| echo "${VALGRIND_STATUS}" > /etc/prof-results/valgrind-exit-status | ||
|
|
||
| if [ "${VALGRIND_STATUS}" -ne 0 ]; then | ||
| # Over 128 means a signal. 139 is SIGSEGV, which is how valgrind exiting on | ||
| # its 8 MB brk segment ceiling presents; valgrind.log names the real reason | ||
| # on the line above its backtrace. | ||
| # Over 128 means a signal. Valgrind passes the profiled server's exit | ||
| # status through (verified: freeradius's own _EXIT(134) matched the 134 | ||
| # recorded here on the e26e348 ldap run), so a signal status usually | ||
| # means FREERADIUS died of that signal - an assert or crash logged in |
There was a problem hiding this comment.
🟡 The comment above this block (start_valgrind_profiling.sh:119-124) still says the publish step 'refuses to upload an unclean run' — this same PR rewrote publish-profiling-results.sh so it now only prunes the unclean test's own directory and publishes the clean remainder, refusing the whole run only when every test is unclean. The PR updated the parallel comments in publish-profiling-results.sh itself but missed this sibling description of the same cross-script contract.
Extended reasoning...
The bug: The comment at start_valgrind_profiling.sh:119-124 explains why VALGRIND_STATUS is written to valgrind-exit-status, stating: "the status has to survive to the publish step, which reads this file and refuses to upload an unclean run." That description was accurate before this PR — the old publish-profiling-results.sh did an all-or-nothing exit 1 whenever any test's status file was non-zero.
What changed under it: This exact PR rewrites publish-profiling-results.sh to no longer refuse the whole run. It now loops over unclean entries, prints a WARNING: pruning tests... message, and rm -rfs only each unclean test's own directory (for entry in $unclean; do rm -rf "${entry%:*}"; done), then proceeds to tar and publish whatever clean directories remain. The script only exit 1s if every test was pruned (the new check if [ -n "$unclean" ] inside the ! [ -s "$file_list" ] branch). So for the common case — one flaky/crashed test among several — the run is no longer refused; it's partially published.
Why existing code doesn't catch this: Nothing enforces comment/behavior consistency automatically; this is purely a documentation-drift issue caught by manual review. The PR author clearly tracked this same contract change in the sibling file: the header doc-comment in publish-profiling-results.sh changed from "Fails without publishing when any test's valgrind-exit-status is non-zero" to "Prunes any test whose valgrind-exit-status is non-zero or missing... The clean remainder is published", and the inline comment above the unclean loop changed from "Refuse to publish a run valgrind did not finish cleanly" to "Never publish a test valgrind did not finish cleanly... unclean tests are pruned... and the rest publish normally." Both of those were deliberately kept in sync. The comment in the sibling script describing the same cross-script contract was simply missed.
Impact: None on runtime behavior — this is a comment inside start_valgrind_profiling.sh, which only records $VALGRIND_STATUS to the status file; the stale text doesn't change what gets recorded or how the publish step behaves. The impact is purely on a future reader: someone debugging why a partially-unclean profiling run still got some data published might read this comment, believe the whole run should have been refused, and waste time looking for a bug in the prune logic that doesn't exist.
Step-by-step proof:
- Suppose a multi-server CI job runs 3 profiling tests; test B's freeradius process crashes under valgrind (SIGSEGV), tests A and C finish cleanly.
start_valgrind_profiling.shruns in each container; for B it writes a non-zeroVALGRIND_STATUS(e.g. 139) to/etc/prof-results/valgrind-exit-status, exactly as the comment at line 119-124 describes.publish-profiling-results.shruns once over the combinedprof-results/tree. It finds B's status file is non-zero, adds it to$unclean, prints the warning + diagnostic for B, andrm -rfs only B's directory.- A's and C's directories are untouched.
$file_listis non-empty (A and C's files), so the script proceeds totar, mint an OIDC token, andPOSTthe tarball — the run is published, just without B's data. - Reading the comment at lines 119-124 of
start_valgrind_profiling.sh, a reader would conclude step 4 shouldn't have happened ("refuses to upload an unclean run") — but it did, correctly, per the new intended behavior.
Fix: Reword the trailing clause, e.g.: "...so the status has to survive to the publish step, which prunes this test's directory if the run was unclean rather than publishing truncated data. The status is recorded for clean runs too, so an absent file means 'the wrapper did not get this far' rather than 'the run was fine'." matching the phrasing already used in the updated publish-profiling-results.sh comments.
1 participant
Two scripts used when profiling have been updated.
publish-profiling-results.sh:
The script won't upload results if Valgrind didn't finish properly and it now now checks if the status file is missing. If the file is missing, the results aren't pushed to the results container. They previously would.
The script also has a new PROF_PUBLISH_PRUNE_UNCLEAN env variable that can be set. If set, the script deletes all unclean results and pushes the good ones to the container. Useful when we need to test new features in the result store container.
start_valgrind_profiling.sh
The script now has better diagnostic messages that fire when valgrind exits abnormally (on a signal / non-zero status) which are helpful when determining why certain tests have failed in CI.