diff --git a/CHANGELOG.md b/CHANGELOG.md index 25b7acee..04375d8e 100644 --- a/CHANGELOG.md +++ b/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 `-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 ` 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/.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 `.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) diff --git a/project-bin/exec.sh b/project-bin/exec.sh index 62479d19..e3121ba4 100755 --- a/project-bin/exec.sh +++ b/project-bin/exec.sh @@ -80,6 +80,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 @@ -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 .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 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 ]