From f118bb0f358829613a7db6265f07ee8b3c6c01db Mon Sep 17 00:00:00 2001 From: MendixMau Date: Fri, 16 Oct 2026 10:17:56 +0800 Subject: [PATCH] fix(exec): per-step seconds in the run summary and BUILD-LOG, gate seconds kept on a failed gate Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 1 + project-bin/exec.sh | 18 +++++- tests/wave2/test-exec-step-times.sh | 94 +++++++++++++++++++++++++++++ 3 files changed, 112 insertions(+), 1 deletion(-) create mode 100644 tests/wave2/test-exec-step-times.sh diff --git a/CHANGELOG.md b/CHANGELOG.md index 2334398a..bab781a8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,7 @@ Sections dated before 2026-09-19 predate the cycle and stay as they are. Named m ## Unreleased - fix(conformance-check): read ledger rows whose pointer cell is bare (no backticks) and treat status `planned` as not-built; a ledger whose acceptance text is also bare prose is still not measured (acceptance must hold a backticked SHOW/DESCRIBE), but it now exits 2 with a FAULT that says rows were found and the text is prose, instead of "shape changed or glob matched nothing" (TK-006, partial: that ledger shape is diagnosed, not fixed) — field report TK-006 +- fix(exec): **`exec.sh` now prints and logs per-step seconds, and a run whose gate fails logs its gate seconds too.** The BUILD-LOG row carried only the run total, so nobody could say where a 28 to 41 s exec went. `step_done` marks guards, check, snapshot, baseline, exec, gate, lint and score (one `date +%s` each) and the run summary and the BUILD-LOG detail print `steps: guards Ns check Ns ...`. The gate mark is taken straight after the mxbuild run, before any pass or fail branch, because the rolled-back runs (47 of 238 rows, the costliest 20%, in the lab) would otherwise lose exactly the seconds worth seeing. New `tests/wave2/test-exec-step-times.sh` covers a passing and a failing gate; both BUILD-LOG cells fail on master. Split out of #409 so both arms of the test-strategy A/B log the same `steps:` cell — a five-app lab project (Mendix 11.15, mxcli v0.26.0) - fix(app-restart): **a secret with spaces in quotes is masked whole, and `Pwd` and `Credential` join the secret words.** Follow-up to #403: `--constant "Mod.ApiKey=two words"` and `--db-password 'two words'` printed everything after the first word (the quoted-flag case leaked before #403 too). `mask()` now masks each argument before quoting it for display, so the whole quoted value goes; the executed command is untouched, and a real-launch test proves the started app receives the raw argv; an env assignment at the start of a `--cmd` string keeps the whole command visible; the per-argument seds only run for arguments holding a secret word. The substring match still over-masks names like `Monkey` (Key) and `Turkey`; that is display only, kept, and pinned by a test. `tests/wave2/test-app-restart.sh` gains 22 cases, 8 of them failing on master. — review of #403 - fix(install-manifest): **a clean toolkit checkout passes its own `project-bin/` manifest self-check, so adopters no longer see the "named by NEITHER list" warning at the top of every sync.** `coverage-check-all.sh` (found by `review-module.sh` through its `_tool` lookup in the toolkit clone) and `ts-sync.sh` (UNPROVEN and SUPERSEDED per its header) join `MXTK_PROJECT_BIN_NOINSTALL` with reasons. New `tests/wave2/test-manifest-clean-checkout.sh` fails, rather than warns, when a `project-bin/` file is in neither list. — joshuamoesa (#381) - fix(sync-project): **the "Baseline-only skills cited" warning no longer fires on the toolkit's own wiring block, and no longer sizes a section that does not exist.** The check grepped all of `CLAUDE.md` for `skills/learned-mdl-preflight.md` / `skills/query-the-model.md`, and `wire-agents.sh`'s `mxtk:wiring` block cites the first, so every sync flagged the toolkit's own text; with no "mxcli-project-toolkit Integration" heading it then printed a whole-file word count as "heading to EOF". The wiring block is now stripped before the grep, and the warning is raised only when the heading exists. `tests/wave2/test-sync-dup-heading-exit.sh` T4 flips (no heading: no warning) and gains T7-T9. — joshuamoesa (#382) diff --git a/project-bin/exec.sh b/project-bin/exec.sh index a4c85a76..8f8cb4a3 100755 --- a/project-bin/exec.sh +++ b/project-bin/exec.sh @@ -78,6 +78,13 @@ # MXTK_SCAN_OVERRIDE="" (the user only: run despite a blocking STOP-row scan hit, #349) set -e _T0=$(date +%s) +# Per-step seconds (2026-10-16): the BUILD-LOG row used to carry only the total, so nobody could +# say where an exec's time went (check, baseline, exec, gate, lint, score). step_done +# adds " s" since the previous mark; the run summary and the BUILD-LOG detail print it. +# The gate mark sits right after the mxbuild run, before any pass/fail branch, so a rolled-back +# run (the costliest ones) logs its gate seconds too. +_TLAST=$_T0; STEP_TIMES="" +step_done() { _tn=$(date +%s); STEP_TIMES="${STEP_TIMES:+$STEP_TIMES }$1 $((_tn - _TLAST))s"; _TLAST=$_tn; } # ── Change class (advisory, added 2026-10-13) ──────────────────────────────── # Tags each run `ui-only` or `logic`, so the run summary can say which TEST LANE applies @@ -440,7 +447,7 @@ HDR2 # The gate cell is read from GATE_STATE rather than passed in, so no caller # can omit it — a blank cell in this table reads as "fine", which is the exact # false-green the gate exists to prevent. - _detail="$2${CHANGE_CLASS:+ · change: $CHANGE_CLASS}${CR_ID:+ · cr: $CR_ID}${SCAN_NOTE:+ · $SCAN_NOTE}${HV_NOTE:+ · $HV_NOTE}$_EXEC_APPROVAL_SUFFIX" + _detail="$2${CHANGE_CLASS:+ · change: $CHANGE_CLASS}${CR_ID:+ · cr: $CR_ID}${SCAN_NOTE:+ · $SCAN_NOTE}${HV_NOTE:+ · $HV_NOTE}$_EXEC_APPROVAL_SUFFIX${STEP_TIMES:+ · steps: $STEP_TIMES}" printf '| %s | `%s` | %s | %s | %s |\n' \ "$(date '+%Y-%m-%dT%H:%M:%S%z')" "$LOG_NAME" \ "${GATE_STATE:-not-run}" "$1" "$_detail" >> "$BUILD_LOG" @@ -928,8 +935,10 @@ run_lint_gate() { # One place decides the applied-row wording, so both mxbuild-clean branches agree. log_applied() { # $1 = mxbuild detail run_lint_gate + step_done lint LINT_RC_FOR_LEDGER="$LINT_RC" take_score + if [ "$SCORED" = 1 ]; then step_done score; fi if [ "$LINT_RC" -eq 1 ]; then log_build "⚠️ applied, LINT ROSE" "$1; $LINT_DETAIL" elif [ "$LINT_RC" -eq 3 ]; then @@ -947,6 +956,7 @@ log_applied() { # $1 = mxbuild detail # a passing build. SKIP_CHECK=1 for the rare script mxcli's parser rejects but # the model accepts (log why, in the script). PMXCLI="$(find_project_mxcli 2>/dev/null || true)" +step_done guards if [ "$PATCH_MODE" = "1" ]; then echo "→ --patch: no pre-exec mxcli check (not MDL). The mxbuild gate below is this write's only check." elif [ "${SKIP_CHECK:-0}" != "1" ] && [ -n "$PMXCLI" ]; then @@ -1007,8 +1017,10 @@ if [ ! -x "$MXBUILD" ] || [ ! -x "$JAVA_EXE" ]; then fi fi +step_done check echo "→ Snapshotting model..." ./bin/snapshot-mpr.sh +step_done snapshot # The snapshot just taken. A --patch run hands it to the script as MXPATCH_BACKUP_DIR, so the # .bak that bin/mxpatch.py keeps of each unit it rewrites lands beside the snapshot, OUTSIDE # the model tree, and is pruned with it. Until 2026-10-15 it was .mxunit.bak inside @@ -1396,6 +1408,7 @@ fi # was already applied. The result was live, ungated, unlogged model changes, # arrived at by the guard chain exiting through the one path with no guards on # it. A failed exec is precisely when the gate matters most. +step_done baseline echo "→ Executing $SCRIPT..." EXEC_STATUS=0 if [ "$PATCH_MODE" = "1" ]; then @@ -1520,6 +1533,7 @@ if [ "$EXEC_STATUS" -ne 0 ]; then echo " failing statement is already in the model. Running the gate anyway." fi +step_done exec echo "" echo "→ Running mxbuild model check (catches BSON corruption before SP opens)..." echo " (mxbuild: $MXBUILD)" @@ -1550,6 +1564,7 @@ if [ -x "$MXBUILD" ] && [ -x "$JAVA_EXE" ]; then MXBUILD_EXIT="$MXTK_MXBUILD_EXIT" MXBUILD_OUT="$MXTK_MXBUILD_OUT" MXB_WHY="${MXTK_MXBUILD_WHY:-}" + step_done gate if [ -f "$ERRORS_FILE" ] && [ -s "$ERRORS_FILE" ]; then CE_COUNT=$(err_count "$ERRORS_FILE") @@ -1928,6 +1943,7 @@ echo "✓ Script applied to $MPR_BASE." echo "" _EL=$(( $(date +%s) - _T0 )) echo " elapsed: ${_EL}s (check + snapshot + exec + mxbuild gate)" +if [ -n "$STEP_TIMES" ]; then echo " steps: $STEP_TIMES"; fi [ -n "$CHANGE_CLASS" ] && echo " change class: $CHANGE_CLASS — test lane: $(change_lane)" # A budget, not a gate: a normal run is 30-90 s on a healthy machine. Past 4 minutes the # usual cause is the machine (Defender scanning every fork, OneDrive, a slow disk), and diff --git a/tests/wave2/test-exec-step-times.sh b/tests/wave2/test-exec-step-times.sh new file mode 100644 index 00000000..7c4d4e9a --- /dev/null +++ b/tests/wave2/test-exec-step-times.sh @@ -0,0 +1,94 @@ +#!/usr/bin/env bash +# Fixture for exec.sh's per-step seconds (2026-10-16). +# +# usage: bash tests/wave2/test-exec-step-times.sh [/path/to/exec.sh] +# +# WHY. A BUILD-LOG row carried only the run total, so nobody could say where an exec's time +# went (a five-app lab project: 28-41 s per exec, split unknown). exec.sh now marks each step +# and prints "steps: guards Ns check Ns snapshot Ns baseline Ns exec Ns gate Ns lint Ns" in +# the summary and in the BUILD-LOG detail. The gate mark is taken right after the mxbuild run, +# so a run whose gate FAILS (and is rolled back) logs its gate seconds as well: those are the +# costliest runs, about 20% of execs in the lab, and the first version lost exactly them. +# +# The run case reuses test-exec-hash-verify.sh's stub project; its mxcli replays the verbatim +# v0.26.0 `mxcli fix hashes` / `fix --help` captures (fixtures/mxpatch/, fixtures/property-sets/). +# The mxbuild stub reports one Error problem when the model file contains BREAK. +# +# Positive control: against master's exec.sh the steps line and both BUILD-LOG cells fail; the +# exit-code and elapsed guards pass. +set -uo pipefail + +TOOLKIT="$(cd "$(dirname "$0")/../.." && pwd)" +EXEC_SH="${1:-$TOOLKIT/project-bin/exec.sh}" +case "$EXEC_SH" in /*) ;; *) EXEC_SH="$PWD/$EXEC_SH" ;; esac +WORK="$(mktemp -d "${TMPDIR:-/tmp}/exec-st.XXXXXX")"; trap 'rm -rf "$WORK"' EXIT +PASS=0; FAIL=0 +ok() { PASS=$((PASS+1)); printf ' ok %s\n' "$1"; } +bad() { FAIL=$((FAIL+1)); printf ' FAIL %s\n' "$1"; [ -n "${2:-}" ] && printf '%s\n' "$2" | sed 's/^/ /'; return 0; } +echo "== subject: $EXEC_SH" + +echo "== a run prints and logs the step seconds ==" +FX="$TOOLKIT/tests/wave2/fixtures/mxpatch"; PSFX="$TOOLKIT/tests/wave2/fixtures/property-sets" +P="$WORK/proj"; mkdir -p "$P/bin" "$P/mprcontents/84/77" "$WORK/jdk/bin" +printf 'not a real model\n' > "$P/Fixture.mpr" +printf 'bson\n' > "$P/mprcontents/84/77/84776610-13b2-48cb-a265-d5e984d63129.mxunit" +cp "$TOOLKIT/project-bin/_common.sh" "$TOOLKIT/project-bin/restore-mpr.sh" "$P/bin/" +cp "$EXEC_SH" "$P/bin/exec.sh"; chmod +x "$P/bin/"*.sh +cat > "$P/bin/snapshot-mpr.sh" <<'SNAP' +#!/usr/bin/env bash +set -e +cd "$(dirname "$0")/.." +D=".mpr-snapshots/$(date +%Y%m%d-%H%M%S)-$$-$RANDOM" +mkdir -p "$D"; cp Fixture.mpr "$D/Fixture.mpr"; cp -r mprcontents "$D/mprcontents" +echo "Snapshot saved: $D" +SNAP +chmod +x "$P/bin/snapshot-mpr.sh" +printf '#!/usr/bin/env bash\necho "written by the patch" >> "$1"\n' > "$P/patch.sh" +cat > "$P/mxcli" <<'MXCLI' +#!/usr/bin/env bash +case "$1 ${2:-}" in + "fix --help") cat "$PSFX/fix-help-v0.26.0.txt"; exit 0 ;; + "fix hashes") cat "$FX/verify-clean-v0.26.0.out"; cat "$FX/verify-clean-v0.26.0.err" >&2; exit "$(cat "$FX/verify-clean-v0.26.0.exit")" ;; +esac +exit 0 +MXCLI +cat > "$WORK/mxbuild" <<'MXB' +#!/usr/bin/env bash +BAD=0 +for a in "$@"; do case "$a" in *.mpr) grep -q BREAK "$a" 2>/dev/null && BAD=1 ;; esac; done +for a in "$@"; do case "$a" in --write-errors=*) + if [ "$BAD" = 1 ]; then printf '{"problems":[{"severity":"Error","errorCode":"CE0117","message":"type mismatch"}]}' > "${a#--write-errors=}" + else printf '{"problems":[]}' > "${a#--write-errors=}"; fi ;; esac; done +[ "$BAD" = 1 ] && exit 1 +exit 0 +MXB +printf '#!/usr/bin/env bash\nexit 0\n' > "$WORK/jdk/bin/java" +chmod +x "$P/mxcli" "$WORK/mxbuild" "$WORK/jdk/bin/java" +( cd "$P" && git init -q . && git add -A && git -c user.email=t@t -c user.name=t commit -qm fixture ) >/dev/null 2>&1 +export FX PSFX +mkdir -p "$WORK/tmp" +( cd "$P" && TMPDIR="$WORK/tmp" SKIP_BASELINE=1 SP_RESTART=0 MXTK_NO_INSTALL=1 \ + MXBUILD_PATH="$WORK/mxbuild" JAVA_HOME="$WORK/jdk" ./bin/exec.sh --patch patch.sh ) > "$WORK/out" 2>&1; RC=$? +[ "$RC" -eq 0 ] && ok "run exit 0" || bad "run rc=$RC" "$(tail -20 "$WORK/out")" +STEPS="$(grep '^ steps: ' "$WORK/out")" +printf '%s\n' "$STEPS" | grep -qE '^ steps: guards [0-9]+s check [0-9]+s snapshot [0-9]+s baseline [0-9]+s exec [0-9]+s gate [0-9]+s lint [0-9]+s' \ + && ok "summary: steps line in pipeline order" || bad "summary steps" "$(grep -n 'elapsed\|steps' "$WORK/out")" +grep -q '^ elapsed: ' "$WORK/out" && ok "elapsed total still printed" || bad "no elapsed line" +ROW="$(tail -1 "$P/docs/BUILD-LOG.md" 2>/dev/null)" +printf '%s\n' "$ROW" | grep -qE '✅ applied .* · steps: guards [0-9]+s check [0-9]+s .*gate [0-9]+s lint [0-9]+s' \ + && ok "BUILD-LOG detail carries the steps cell" || bad "BUILD-LOG steps" "$ROW" + +echo "== a run whose gate FAILS still logs the gate seconds ==" +printf '#!/usr/bin/env bash\necho BREAK >> "$1"\n' > "$P/break.sh"; chmod +x "$P/break.sh" +( cd "$P" && git add -A && git -c user.email=t@t -c user.name=t commit -qm after-first ) >/dev/null 2>&1 +( cd "$P" && TMPDIR="$WORK/tmp" SKIP_BASELINE=1 SP_RESTART=0 MXTK_NO_INSTALL=1 \ + MXBUILD_PATH="$WORK/mxbuild" JAVA_HOME="$WORK/jdk" ./bin/exec.sh --patch break.sh ) > "$WORK/out2" 2>&1; RC2=$? +[ "$RC2" -ne 0 ] && ok "failing run exits non-zero" || bad "failing run exited 0" "$(tail -20 "$WORK/out2")" +ROW2="$(tail -1 "$P/docs/BUILD-LOG.md" 2>/dev/null)" +printf '%s\n' "$ROW2" | grep -qE 'gate failed|rolled back|not verified|unverified|blocked' \ + && ok "the last BUILD-LOG row is the failed one" || bad "last row is not a failure row" "$ROW2" +printf '%s\n' "$ROW2" | grep -qE 'steps: guards [0-9]+s check [0-9]+s snapshot [0-9]+s baseline [0-9]+s exec [0-9]+s gate [0-9]+s' \ + && ok "failed row carries steps including gate" || bad "failed row lacks gate seconds" "$ROW2" + +echo; echo "PASS=$PASS FAIL=$FAIL" +[ "$FAIL" -eq 0 ]