fix(exec): per-step seconds in the run summary and BUILD-LOG, gate seconds kept on a failed gate (409a)

CHANGELOG.md

@@ -22,6 +22,7 @@ Sections dated before 2026-09-19 predate the cycle and stay as they are. Named m
 - fix(journey-runner): **a journey file without a string `id` now warns naming the file and uses its basename as the id, so captures are named `<basename>-stepN.png` instead of `undefined-stepN.png`; two journeys ending up with the same id (explicit, or a basename that collides with an explicit id) are refused with exit 2 before the browser opens, naming both files.** The only new refusal is a duplicate id; existing id-less journey files keep running. `journey-examples.md` field table updated ([#383](https://github.com/MendixMau/mxcli-project-toolkit/issues/383)) — joshuamoesa
 - fix(lint-gate): **a ratchet rise now lists the findings that are NEW, not three arbitrary members of the rule.** The baseline keeps a multiset of findings (rule, module, document, message) next to the counts; on a rise the gate prints the surplus per rule, up to three per rule (the rest in `.claude/loop/lint-last.json`), labelled as new or changed findings next to the net rise. An old counts-only baseline falls back to the first three and says they are not necessarily new. Not done here: pre-exec snapshot attribution, a per-slice growth cap, a slice-close lint check (the rest of [#239](https://github.com/MendixMau/mxcli-project-toolkit/issues/239)). Test: `tests/wave2/test-lint-gate-new-findings.sh` — MendixMau (#239)
 - 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)
 - new(testing): **`project-bin/affected-tests.sh <script.mdl>` computes the unit tests and journeys a change owes (advisory, exit 0), and `exec.sh --subjects` lists the elements a script writes.** `testing-shape.md` §3 defined the per-change subject set in prose only. The script takes the subjects from `exec.sh --subjects`, gets their transitive callers (pages included on mxcli v0.26.0) from ONE batched `SHOW CALLERS OF ... TRANSITIVE` call, and prints the `.test.mdl` and `journeys/<Module>.journey.json` files owed at the moment's scope from the PROJECT.md `## Test strategy` row (defaults when absent), plus run lines; it never runs a model-writing test and says `callers NOT MEASURED` when it has no model. Caller depth for unit tests is `--depth N` or `MXTK_AFFECTED_DEPTH`, default 1. Three selection gaps found in the lab are closed here: a `journeys unmapped N of M` row counts the journey files that name-based selection can never reach (12 of 20 held no qualified name), a journey that names a transitive caller is selected, and an entity, association, enumeration, access, module, module role, user role or constant subject prints a `data NOT MEASURED` row instead of silently owing only its own module. exec.sh prints the `affected tests:` hint on every MDL run. Nothing in the docs is binding yet; the doc and default changes are the separate held PR. Golden callers output captured from mxcli v0.26.0 on a scratch copy of an empty 11.12 app (`tests/wave2/fixtures/affected-tests/CAPTURE.txt`). The unmapped count treats a file in `journeys/` as mapped only when it is named `<Module>.journey.json`. Callers are read fresh on every call: mxcli rebuilds its catalog when the .mpr changed (captured in `CAPTURE-FRESHNESS.txt`). Split out of #409 — 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)

project-bin/exec.sh

@@ -80,6 +80,13 @@
 #            MXTK_SCAN_OVERRIDE="<reason>" (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 <name>
+# adds "<name> <s>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
@@ -483,7 +490,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"
@@ -971,8 +978,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
@@ -990,6 +999,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
@@ -1050,8 +1060,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 <unit>.mxunit.bak inside
@@ -1439,6 +1451,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
@@ -1563,6 +1576,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)"
@@ -1593,6 +1607,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")
@@ -1971,6 +1986,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

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 ]