software-factory: run observability — timing instrumentation + QUnit test timeout#5245
Conversation
A factory:go run otherwise emits a flat wall of text with no timing, so there's no way to attribute where the wall-clock went. Wrap logger() to prepend [HH:MM:SS.mmm +Δms] to each line; the delta is the gap to the previous line on any channel. Disable with FACTORY_LOG_TIMESTAMPS=0. CS-11572 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Time the three buckets that dominate a run — agent turns, the validation pipeline, and workspace syncs — per issue, and log a per-issue line plus a grand-total table at the end. The unattributed remainder (total minus the three buckets) is scheduler + index-poll overhead, surfaced explicitly. Also introduces SyncHaltError, exported for the --halt-on-sync-error flag: the loop's per-step try/catch blocks rethrow it so a halt isn't swallowed. CS-11572, CS-11575 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
A hung in-browser test page (boot error, hanging test, never-resolving promise) used to block the full 300s with only Playwright's opaque "Timeout 300000ms exceeded". Default to 60s (override via FACTORY_TEST_TIMEOUT_MS), replace the timeout error with a diagnostic that names the likely cause, and log the run duration at info level. CS-11573 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
On a failed workspace sync the loop normally recovers via a pull on the next iteration — but that pull mutates local state and can mask the realm/index inconsistency that the failure caused. The opt-in flag logs the failure loudly and throws (SyncHaltError) before any recovery pull, freezing realm + index state at the point of failure for inspection. CS-11575 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
The +Δms delta advanced its baseline even for lines the logger suppressed at the active level, so a hidden debug call between two info lines made the next visible line's delta measure from an invisible point. Gate the baseline update on whether the line will actually emit, mirroring @cardstack/logger's own level check (instance _level vs severity order). Verified the library's native timestamp feature is unwired in 0.2.1 (config.timestamps is never passed to the Logger constructor), so this wrapper is the only source of timestamps — no double-stamping. CS-11572 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
The timing instrumentation (per-line timestamps, per-phase durations, and the end-of-run summary table) is now off by default so normal runs emit clean output. The factory CLI turns it on under --debug: - logger timestamps become a runtime flag (default off, FACTORY_LOG_TIMESTAMPS still pins it either way) flipped via setLogTimestampsEnabled; - the issue loop only prints per-phase durations / the summary when config.debug is set, threaded from the CLI's --debug. CS-11572 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Remove the halt-on-sync-error debug flag (and SyncHaltError). It was speculative forensics for an intermittent atomic-upload 500 that hasn't recurred, and it can't really do its job: a flag for a rare failure only helps if it's already on when the failure hits, and leaving it on trades away the resilient pull-recovery that lets runs self-heal. Sync-failure forensics are better served by richer always-on logging (follow-up), without sacrificing resilience. CS-11575 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
There was a problem hiding this comment.
Pull request overview
Adds debug-gated observability to software-factory runs so slow/opaque factory:go executions can be attributed to concrete phases (agent, validation, sync), with optional per-line timestamp/delta prefixes.
Changes:
- Add logger support for per-line
[HH:MM:SS.mmm +Δms]prefixes, enabled via--debug(orFACTORY_LOG_TIMESTAMPSoverride). - Collect and (under
debug) emit per-issue phase timings and an end-of-run attribution summary in the issue loop. - Add a configurable QUnit completion timeout (default 60s) with a more actionable timeout error message.
Reviewed changes
Copilot reviewed 5 out of 5 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
| packages/software-factory/src/test-run-execution.ts | Adds configurable QUnit timeout + improved diagnostics and duration formatting. |
| packages/software-factory/src/logger.ts | Wraps loggers to optionally prefix emitted lines with wall-clock + delta timestamps; adds runtime toggle. |
| packages/software-factory/src/issue-loop.ts | Tracks agent/validation/sync wall time per issue and prints per-issue + grand-total timing summary under debug. |
| packages/software-factory/src/factory-issue-loop-wiring.ts | Wires debug flag into the issue loop configuration. |
| packages/software-factory/src/cli/factory-entrypoint.ts | Enables timestamp prefixes and debug-level logging when --debug is passed. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| let timeoutMs = qunitTimeoutMs(); | ||
| try { | ||
| await page.waitForFunction( | ||
| () => (window as any).__qunitResults?.runEnd !== null, | ||
| null, | ||
| { timeout: timeoutMs }, | ||
| ); | ||
| } catch { | ||
| // Playwright's native message ("Timeout 60000ms exceeded") doesn't say | ||
| // what timed out or how long we actually waited. Replace it with a | ||
| // diagnostic that names the likely cause and is greppable. | ||
| let waited = Date.now() - start; | ||
| throw new Error( | ||
| `QUnit suite did not reach runEnd within ${timeoutMs}ms (waited ${waited}ms). ` + | ||
| `The page never set __qunitResults.runEnd — likely an Ember boot error, ` + | ||
| `a hanging test, or a never-resolving promise. Re-run with --debug to see ` + | ||
| `browser console output, or raise FACTORY_TEST_TIMEOUT_MS for a heavier suite.`, | ||
| ); | ||
| } |
There was a problem hiding this comment.
(Written by Claude on Matic's behalf.)
Fixed in 30b8430. The catch now only rewrites Playwright's TimeoutError (err.name === 'TimeoutError'); any other error (execution context destroyed, page crash, etc.) is rethrown unchanged so it surfaces as-is. I also moved the waited baseline to a waitStart taken immediately before page.waitForFunction, so it measures the wait alone rather than the function's full wall clock (which included server startup, browser launch, and navigation).
| log.info( | ||
| `QUnit completed in ${fmtMs(durationMs)}: ${qunitResults.runEnd?.testCounts?.total ?? 0} test(s)`, | ||
| ); |
There was a problem hiding this comment.
(Written by Claude on Matic's behalf.)
Good catch — reverted to debug in 30b8430. The QUnit completed in … line stays gated like the rest of the observability output; its duration still surfaces under --debug via the timing summary, so a normal run stays clean. Updated the PR description bullet to match.
…n log debug-gated Per review on #5245: - Only rewrite Playwright TimeoutError into the diagnostic; rethrow any other error (execution context destroyed, page crash) unchanged so it isn't masked as a timeout. - Measure `waited` from the start of the wait, not function entry (which included server/browser startup + navigation). - Revert the "QUnit completed" line info → debug so normal runs stay clean. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 30b843019c
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| // Run the agent — it calls tools during its turn | ||
| let agentStartMs = Date.now(); | ||
| let result = await agent.run(context, tools); | ||
| let agentMs = Date.now() - agentStartMs; |
There was a problem hiding this comment.
When the agent self-validates with a realm-touching run_* tool, those tools call syncWorkspace before running (via syncWorkspaceForToolRun in factory-tool-builder.ts), and that happens inside agent.run(...). Measuring the whole call here records those tool syncs as agentMs, while syncMs only captures the loop-owned syncs routed through timedSync, so debug timing summaries can tell operators the model was slow when sync/index work was actually the cost.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
(Written by Claude on Matic's behalf.)
Good catch — fixed in 1c0297d. Every syncWorkspace() call (the loop's own syncs and the realm-touching run_* tool syncs that fire inside agent.run via syncWorkspaceForToolRun) now goes through one shared stopwatch in the wiring, exposed to the loop as getSyncElapsedMs(). The loop reads sync time from deltas of that counter and subtracts the tool-sync delta elapsed during agent.run from agentMs — so tool-triggered sync time lands in syncMs, not agentMs. Added a regression test asserting a 500ms tool-triggered sync shows up in syncMs while agentMs stays 0.
…ent time Per review on #5245: realm-touching run_* tools sync the workspace before executing (syncWorkspaceForToolRun), inside agent.run. The old timing measured the whole agent.run as agentMs and only counted loop-owned syncs (via timedSync) as syncMs — so the debug summary could blame the model for sync/index work. Time every syncWorkspace() call through one shared stopwatch in the wiring and expose getSyncElapsedMs() to the loop. The loop now reads sync time from deltas of that counter (per-issue and grand total) and subtracts the tool-sync delta that elapses during agent.run from agentMs. Drops the loop-local timedSync. Adds a regression test asserting a tool-triggered sync lands in syncMs and not agentMs. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Adds detailed timing benchmark log output for the factory when
--debugis provided. It's used for seeing where the time went (AI agent / syncing / validations) that helps with making decisions where to optimize the time needed for a software factory run.