ci: add per-script timing to script-test target

[ralphbean]

Summary

• Wraps each make script-test invocation in a run-timed macro that emits ::debug:: GitHub Actions annotations with elapsed seconds
• Hidden by default; visible when re-running a job with the "Enable debug logging" checkbox
• Local profiling shows post-prioritize-test.sh dominates at ~213s of ~225s total — everything else is ≤8s

Test plan

• make script-test passes locally
• CI passes on this branch
• Re-run the CI job with "Enable debug logging" to confirm timing lines appear

🤖 Generated with Claude Code

[qodo-code-review]

PR Summary by Qodo

Add per-script timing debug logs to make script-test
✨ Enhancement ⚙️ Configuration changes 🕐 Less than 10 minutes

Description

• Adds a run-timed Make macro to measure elapsed seconds per script invocation.
• Wraps all script-test commands to emit ::debug:: GitHub Actions timing annotations.
• Keeps timing output hidden unless CI debug logging is enabled.

Diagram

graph TD
  A["CI runner / developer"] --> B["make script-test"] --> C["Makefile: run-timed"] --> D["bash/python scripts"] --> E["::debug:: timing logs"]

Loading

High-Level Assessment

The following are alternative approaches to this PR:

1. Use `time`/GNU `time` directly

• ➕ Very standard timing mechanism; easy to recognize in logs
• ➕ Can provide richer metrics (user/sys time, max RSS) with GNU time
• ➖ Output formatting varies across platforms/shells and may be noisier
• ➖ Harder to keep output hidden by default without extra plumbing

2. Use bash `SECONDS` or `date` inline per command

• ➕ No Make macro complexity; straightforward for a small number of commands
• ➕ Can customize formatting per command easily
• ➖ Duplicates boilerplate across many lines (harder to maintain)
• ➖ More likely to drift/inconsistently format across commands

3. Move orchestration into a dedicated script (single harness)

• ➕ Centralizes timing, logging, and error handling in one place
• ➕ Easier to add aggregation/summaries (slowest N, totals) later
• ➖ Adds a new file and indirection; heavier change than necessary
• ➖ Shifts behavior away from Makefile conventions used elsewhere

Recommendation: The Make macro approach is the best fit here: it minimizes duplication, keeps behavior consistent across all commands, and avoids external dependencies while integrating cleanly with GitHub Actions ::debug:: visibility controls. The main thing to watch is shell/make quoting, but the current pattern is simple and maintainable.

Files changed (1) +18 / -11

Other (1) +18 / -11

MakefileTime and annotate each 'script-test' script invocation +18/-11

Time and annotate each 'script-test' script invocation

• Introduces a 'run-timed' macro that captures start/end timestamps and emits a GitHub Actions '::debug::' line with elapsed seconds. Updates the 'script-test' target to execute every bash/python test script through this macro for per-script timing visibility in CI when debug logging is enabled.

Makefile

[github-actions]

Site preview

Preview: https://83f075da-site.fullsend-ai.workers.dev

Commit: 048f53d5e6a726165e8123c2cf74bab28f4d8329

[qodo-code-review]

Code Review by Qodo

🐞 Bugs (0) 📘 Rule violations (0) 📜 Skill insights (0)

Context used

✅ Compliance rules (platform): 51 rules

✅ Skills: writing-user-docs, writing-adrs

1. Test failures masked ✓ Resolved 🐞 Bug ≡ Correctness

Description

run-timed always exits with the status of the trailing printf, so a failing wrapped script
(non-zero exit) won’t fail make script-test and CI can incorrectly pass. This is a correctness
regression compared to invoking each test directly as a recipe line.

Code

Makefile[R109-112]

+	@start=$$(date +%s); \
+	$(1); \
+	elapsed=$$(($$(date +%s) - $$start)); \
+	printf '::debug::script-test timing: %s completed in %ds\n' '$(1)' "$$elapsed"

Relevance

⭐⭐⭐ High

Team previously accepted fixes preventing swallowed failures/error propagation (e.g., remove `||
true`, preserve errors).

PR-#286
PR-#1487
PR-#1711

ⓘ Recommendations generated based on similar findings in past PRs

Evidence

The macro currently runs the test command and then prints timing without capturing/restoring the
test command’s exit code; CI runs make script-test; the script tests are designed to exit non-zero
on failure, but that signal would be lost.

Makefile[108-126]
.github/workflows/lint.yml[39-48]
internal/scaffold/fullsend-repo/scripts/post-triage-test.sh[450-454]

Agent prompt

The issue below was found during a code review. Follow the provided context and guidance below and implement a solution

### Issue description
The `run-timed` macro runs `$(1)` and then unconditionally runs `elapsed=...` and `printf ...`, causing the overall recipe exit status to be that of `printf` (typically 0). As a result, `make script-test` can succeed even when the wrapped test command fails.

### Issue Context
`make script-test` is invoked in CI, so masking failures undermines the CI signal.

### Fix Focus Areas
- Makefile[108-126]

### Suggested fix
Capture and return the wrapped command’s exit status while still emitting the timing line, e.g.:

```make
define run-timed
  @start=$$(date +%s); \
  status=0; \
  $(1) || status=$$?; \
  elapsed=$$(($$(date +%s) - $$start)); \
  printf '::debug::script-test timing: %s completed in %ds\n' '$(1)' "$$elapsed"; \
  exit $$status
endef
```

This preserves failures (status != 0) while still logging timings.

ⓘ Copy this prompt and use it to remediate the issue with your preferred AI generation tools

---

[fullsend-ai-review]

🤖 Finished Review · ✅ Success · Started 7:23 PM UTC · Completed 7:31 PM UTC
Commit: 1facad7 · View workflow run →

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.

📢 Thoughts on this report? Let us know!

[fullsend-ai-review]

Looks good to me

Previous run

Review

Findings

Critical

• [error handling gap] Makefile:108 — The run-timed macro silently swallows test failures. The expanded shell command joins the test invocation ($(1)) and the timing bookkeeping with ; (semicolons), so the exit code of the entire recipe line is that of the last command (printf), which always succeeds. If a test script exits non-zero, Make will not see the failure, will not abort, and CI will pass green. In the original code, each test was its own recipe line whose exit code Make checked directly.
  Remediation: Capture the exit code before the timing bookkeeping and re-exit with it. For example:

  define run-timed
  	@start=$$(date +%s); \\
  	$(1); \\
  	rc=$$?; \\
  	elapsed=$$(($$(date +%s) - $$start)); \\
  	printf '::debug::script-test timing: %s completed in %ds\n' '$(1)' "$$elapsed"; \\
  	exit $$rc
  endef

  This preserves timing output even on failure while still propagating the original exit code to Make.

---

Labels: PR modifies the Makefile CI test target (script-test)

[fullsend-ai-review]

See the review comment for full details.

[fullsend-ai-review]

[critical] error handling gap

The run-timed macro silently swallows test failures. The expanded shell command joins the test invocation ($(1)) and the timing bookkeeping with ; (semicolons), so the exit code of the entire recipe line is that of the last command (printf), which always succeeds. If a test script exits non-zero, Make will not see the failure, will not abort, and CI will pass green. In the original code, each test was its own recipe line whose exit code Make checked directly.

Suggested fix: Capture the exit code and re-exit with it after printing timing. For example: $(1); rc=$$?; elapsed=...; printf ...; exit $$rc

[fullsend-ai-review]

🤖 Finished Review · ✅ Success · Started 11:47 AM UTC · Completed 11:55 AM UTC
Commit: 048f53d · View workflow run →

[fullsend-ai-retro]

🤖 Finished Retro · ✅ Success · Started 12:19 PM UTC · Completed 12:24 PM UTC
Commit: 048f53d · View workflow run →

[fullsend-ai-retro]

Retro: PR #2530 — ci: add per-script timing to script-test target

What happened

Ralph Bean opened this PR on Jun 22 with a run-timed Make macro to emit ::debug:: timing annotations for each script-test invocation. Both automated reviewers (qodo-code-review[bot] and fullsend-ai-review[bot]) independently caught a critical bug: the macro swallowed non-zero exit codes because the recipe's exit status was that of the trailing printf (always 0). The fullsend review bot correctly issued CHANGES_REQUESTED. A fix commit was pushed on Jun 24, and the bot re-approved.

Workflow quality

• Review quality: Excellent. Both bots identified a genuine, potentially CI-breaking bug. The fullsend review bot's inline comment was specific and included a concrete fix suggestion.
• Rework rate: 1 iteration. The fix commit directly addressed the flagged issue — clean rework cycle.
• Token cost: Some waste from cancelled runs. 5 review runs were triggered between 11:43–11:56 UTC on Jun 24 (around the fix commit push), all completing setup steps before being cancelled at the "Run review agent" step. This is wasted compute but is already tracked by multiple existing issues (Add concurrency group to dispatch-review job in fullsend.yaml #981, Debounce review dispatch on rapid synchronize events #1014, Enable cancel-in-progress for review dispatches on the same PR #1357, Deduplicate review runs on rapid successive pushes #1418, Deduplicate review runs when PR is rebased multiple times in quick succession #1422, Deduplicate review dispatches for the same HEAD SHA #1452).
• Time to resolution: ~40 hours. The gap between the initial review (Jun 22 19:31) and the fix commit (Jun 24 11:44) was human-paced, not agent-paced — no improvement opportunity for the platform.

Proposals

No new proposals. The only systemic issue observed (cancelled/redundant review runs on rapid pushes) is already well-covered by existing open issues, particularly #1357 (enable cancel-in-progress for review dispatches) and #1418 (deduplicate review runs on rapid successive pushes).

This was a well-functioning workflow — the review agents delivered genuine value by catching a bug that could have silently broken CI.