repo-review: add subprocess boundary logging at 64eb398

[bborbe]

Whole-codebase review at 64eb398 via the repo-review prototype pipeline.

626 mechanical findings from 74 rules across 437 files → 3 confirmed → 2 fixed here, 1 deferred.

Fixed

M1 — the claude CLI subprocess boundary had no default-verbosity outcome logging (rule: go-logging/external-call-logs-response)

agentStep.Run called s.cfg.Runner.Run(ctx, prompt) with nothing around it. claude-runner.go has a glog.V(2) spawn line, but at V0 a Claude run that failed or hung left no evidence it had ever started.

The argument is asymmetry, not doctrine: the sibling pi/pi-step.go already logs invoke, failure-with-duration, and success-with-duration at V0. Two subprocess boundaries in one repo, one observable and one silent. agent-step.go now mirrors it exactly.

M2 — plugin commands in ensureOne were unlogged (same rule)

plugin list, marketplace add, plugin install, marketplace update, and plugin update now each log the spec and action.

⚠️ Partially addressed, stated plainly: these log before each command, not the outcome. Failures still surface as wrapped errors (hard paths) or glog.Warningf (soft paths), and you can now see which command was attempted — but there is no explicit success confirmation, which is what the finding asked for. Happy to iterate if that gap matters.

Deferred — needs a maintainer decision, not a container

S1 — NewParseStep[T] returns concrete *ParseStep[T] where Step is the only use (rule: go-architecture/constructor-returns-interface)

Genuine: ParseStep[T] implements Step exactly, and agent_phase.go uses it only as a Step. But this is a public constructor in a library with external consumers — the CHANGELOG records agent/gemini calling lib.NewParseStep[Plan], and the only in-repo callers are tests. Changing a public return type has blast radius beyond this repo and wants a semver decision, so it is not something this pipeline should do unilaterally.

Notes on the review itself

The standing triage table auto-refuted 538 of 626 before any adjudicator ran. Of the 88 adjudicated, 85 were refuted — including all 12 secret-fields-need-display-length hits, which turned out to be numeric token counts (InputTokens, int64 telemetry), not credentials.

make precommit green: 10 packages, 0 lint issues, 0 vulnerabilities.

[ben-s-pull-request-reviewer]

Now I have all the data needed. Let me execute the selector mode classification and adjudication in-session.

Step 4b-i — Compute active judgment rules triggered by changed files:

Changed files: CHANGELOG.md, claude/agent-step.go, claude/claude-plugin-installer.go

Relevant judgment-rule triggers matching these files:

• changelog/conventional-prefix-required — trigger: CHANGELOG.md ✓
• go-time/no-time-now-direct — trigger: **/*.go ✓
• go-context/cancel-check-in-loop — trigger: **/*.go ✓
• go-logging/external-call-logs-response — trigger: **/*.go ✓
• go-testing/counterfeiter-mocks-required — mechanical (no trigger glob)
• go-architecture/private-struct-matches-interface — trigger: **/*.go ✓

Step 4c-sel — CLASSIFY:

{
  "applicable": [
    "go-context/cancel-check-in-loop",
    "go-logging/external-call-logs-response",
    "go-testing/counterfeiter-mocks-required",
    "go-time/no-time-now-direct"
  ],
  "skipped": {
    "changelog/conventional-prefix-required": "CHANGELOG entries use correct refactor: prefix",
    "go-architecture/private-struct-matches-interface": "PR makes no interface/struct changes"
  }
}

Step 4d-sel — ADJUDICATE against mechanical findings + diff:

Mechanical findings from pre-computed funnel are authoritative. Now reading the actual changed code to adjudicate:

• claude/claude-plugin-installer.go:108 — the for _, line := range strings.Split(output, "\n") loop in ensureOne has no ctx.Done() check. go-context-assistant flagged this at MUST. Confirmed violation.

• claude/claude-plugin-installer.go:49 — exec.CommandContext(ctx, name, args...) is a boundary subprocess call with no surrounding log line. go-quality-assistant flagged go-logging/external-call-logs-response at MUST. The nearby glog.Infof at line 101 logs the next action (plugin list), not this call. Confirmed violation.

• claude/agent-step.go:86 — runStart := time.Now() is a direct time.Now() call in production business logic. go-time-assistant flagged go-time/no-time-now-direct at MUST. time.Since(runStart) at lines 89/92/104 uses the stored runStart value — the mechanical rule catches the call site, not the convenience wrapper. Confirmed violation.

• changelog/conventional-prefix-required — Both ## Unreleased bullets start with refactor: — correct prefix. No violation.

• go-testing/counterfeiter-mocks-required — Both PluginCommander and PluginInstaller interfaces exist in the unchanged portion of claude-plugin-installer.go; this PR only adds logging calls and does not introduce new interfaces. These are pre-existing conditions outside this PR's scope. Not a finding for this review.

• go-glog/use-v-for-debug-not-info — The glog.Infof calls are V0 boundary logs (before/after external calls), matching the documented exemption: "startup, shutdown, health changes, recovered panics" and "boundary calls" are V0-appropriate. Additionally, the rule's own applies_when marks it as for new projects — this is an existing glog project. Not a finding for this review.

Now producing the consolidated report.

---

PR Review: repo-review: add subprocess boundary logging at 64eb398

Must Fix (Critical)

• claude/claude-plugin-installer.go:108 — ensureOne iterates over strings.Split(output, "\n") without a ctx.Done() check. If the context is cancelled during the loop (e.g., shutdown), iteration continues until completion rather than stopping promptly. Add a non-blocking select { case <-ctx.Done(): return ctx.Err(); default: } at the top of the loop body. (rule: go-context/cancel-check-in-loop)

• claude/agent-step.go:86 — runStart := time.Now() calls time.Now() directly in production business logic. Tests cannot control wall-clock time, making AgentStep.Run impossible to verify under time-sensitive test scenarios. Inject libtime.CurrentDateTimeGetter via the constructor and call .Now() instead. (rule: go-time/no-time-now-direct)

• claude/claude-plugin-installer.go:49 — exec.CommandContext(ctx, name, args...) crosses a process boundary (subprocess exec) with no log statement summarising the call's outcome. Boundary calls are the audit trail; without a log line, runtime failures require redeployment with extra instrumentation to diagnose. Add a log line (method + path/op + status + latency, error on failure) at the call site. (rule: go-logging/external-call-logs-response)

Should Fix (Important)

• None.

Nice to Have (Optional)

• None.

---

Selector Mode Traceability

• Candidates: ~6 judgment rules matched by Step 4b-i glob filter
• Applicable: 4 rules selected by Step 4c-sel
• Skipped:
  • changelog/conventional-prefix-required → CHANGELOG entries use correct refactor: prefix
  • go-architecture/private-struct-matches-interface → PR makes no interface/struct changes
• Mechanical findings: 55 total from pre-computed funnel (ast-grep); confirmed 3 violations from in-session adjudication

Step 6 — Next Steps

Fix the three Must Fix violations before merging. The time.Now() issue in agent-step.go requires injecting libtime.CurrentDateTimeGetter; see docs/go-time-injection.md.

---

{
  "verdict": "request-changes",
  "summary": "PR adds valuable boundary logging but introduces three confirmed violations: a direct time.Now() call in agent-step.go that harms testability, a missing ctx.Done() check in a plugin-installer loop, and an exec.CommandContext call without boundary audit logging. The glog usage is exempt (existing project + V0 boundary-log exemption). Counterfeiter mock findings are pre-existing and out of scope.",
  "comments": [
    {
      "file": "claude/agent-step.go",
      "line": 86,
      "severity": "critical",
      "message": "time.Now() called directly in production business logic — tests cannot control wall-clock time. Inject libtime.CurrentDateTimeGetter via the constructor and call its Now() method instead. (rule: go-time/no-time-now-direct)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 108,
      "severity": "critical",
      "message": "for loop iterates over strings.Split(output, \"\\n\") without a ctx.Done() check. If context is cancelled during iteration, loop runs to completion instead of stopping promptly. Add select { case <-ctx.Done(): return ctx.Err(); default: } at top of loop body. (rule: go-context/cancel-check-in-loop)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 49,
      "severity": "critical",
      "message": "exec.CommandContext call crosses a process boundary without a log statement summarising the call's outcome. Add a boundary audit log: method + op + status + latency; error on failure. (rule: go-logging/external-call-logs-response)"
    }
  ],
  "concerns_addressed": [
    "correctness: glog guard (glog.V) not required — boundary logging at V0 is explicitly exempt per go-glog rule and the rule's own exemption for boundary-audit calls",
    "correctness: success paths in ensureOne do have glog.Infof logs (marketplace add, plugin install, marketplace update, plugin update) — concern noted in plan is addressed",
    "correctness: glog.Warningf for failed marketplace/plugin update followed by continue is intentional graceful degradation — no change needed"
  ]
}

[bborbe]

Thanks — one of the three is real, and it is the gap this PR's own description already flagged as incomplete. Fixed in 74f0002. The other two I'd like to push back on.

Fixed: claude-plugin-installer.go:49

Correct, and well spotted. The PR body called M2 "partially addressed" because the logging landed before each command rather than on its outcome; you independently found the same hole. execPluginCommander.Run now logs at the real boundary — command, byte count and duration on success, duration and error on failure — which is a better location than the ensureOne call sites I originally used.

Pushing back: claude-plugin-installer.go:108 — cancel-check-in-loop

installed := false
for _, line := range strings.Split(output, "\n") {
    if strings.Contains(line, spec.Name) {
        installed = true
        break
    }
}

This iterates a string already held in memory, does no I/O, and breaks on first match. Cancellation cannot arrive "during" it in any meaningful sense — the subprocess it depends on has already returned.

This rule was measured across the whole repo during the review that produced this PR: 0 of 49 hits confirmed, with 28 in functions that have no ctx parameter at all and 7 anchored to a function signature or comment rather than a loop. Fleet-wide it is 0 of 96.

Pushing back: agent-step.go:86 — no-time-now-direct

runStart := time.Now()
result, runErr := s.cfg.Runner.Run(ctx, prompt)
glog.Infof("%s: claude runner returned %d bytes in %s", s.cfg.Name, len(result.Result), time.Since(runStart))

That time.Now() is the duration measurement for the log line this review's other rule (external-call-logs-response) asked for. Removing it removes the fix.

time.Now() + time.Since reads the monotonic clock; that is the correct idiom for measuring elapsed time. Injecting a CurrentDateTimeGetter would make the value controllable in tests while destroying what it measures — a latency number that a test can set to any value is not a latency number. The rule targets time-dependent business logic, where a deterministic clock changes behaviour. Nothing branches on this value; it is only formatted into a log string, and no test asserts on it.

Worth noting: pi/pi-step.go:54 has the identical runStart := time.Now() pattern and is not flagged, because it is outside this diff. This PR exists precisely to make the claude boundary symmetric with the pi one. Applying the rule here alone would re-introduce the asymmetry in the opposite direction.

make precommit green — 0 lint issues, 0 vulnerabilities.

superseded by new automated review

[ben-s-pull-request-reviewer]

Now I have everything needed for the in-session adjudication. Let me compile the report.

Step 4c-sel CLASSIFY:

Changed files: CHANGELOG.md, claude/agent-step.go, claude/claude-plugin-installer.go

Active judgment candidates matching these files:

• changelog/conventional-prefix-required (CHANGELOG.md trigger) → applicable
• All **/*.go triggers → go-architecture/private-struct-matches-interface, go-boolean-combinator/result-with-description-not-naked-bool, go-composition/no-same-package-private-helper-for-business-logic, go-cqrs/skipped-not-nil-for-non-retryable, go-doc/comment-starts-with-name, go-doc/exported-item-must-have-comment, go-doc/third-person-no-signature-repeat, go-errors/inner-closure-no-double-wrap, go-errors/sentinel-err-prefix-naming → skipped (no relevant patterns in the diff)
• go-factory/main-holds-only-boot-lifecycle-config → skipped (no main.go changed)

Step 4d-sel ADJUDICATE:

From mechanical findings + diff analysis:

1. go-cli/slog-not-glog-in-new-projects — glog imported in both files. This project has extensive glog usage elsewhere, so exempt (existing project mid-migration). No violation.
2. go-glog/use-v-for-debug-not-info — All glog.Infof calls added in this PR log debug-shaped internal state (prompt size, result byte count, duration, action names). V0 is reserved for operator-level info (startup, shutdown, health changes, recovered panics). These are not that. MUST FIX.
3. go-context/cancel-check-in-loop — ensureOne iterates plugin lines without a ctx.Done() select. SHOULD FIX.
4. changelog/conventional-prefix-required — Entries use refactor: prefix. No violation.

---

PR Review: repo-review: add subprocess boundary logging at 64eb398

Changed files (3): CHANGELOG.md, claude/agent-step.go, claude/claude-plugin-installer.go (+42 insertions)

---

Must Fix (Critical)

None — no security, concurrency, or correctness bugs introduced.

---

Should Fix (Important)

• claude/agent-step.go:85 — glog.Infof("%s: invoking claude runner (prompt=%d bytes)", ...) logs prompt byte count — debug-shaped internal state. Should be glog.V(2).Infof (V2 dev-default per go-glog guide). V0 is only for operator-level events: startup, shutdown, health changes, recovered panics. (rule: go-glog/use-v-for-debug-not-info)

• claude/agent-step.go:89 — glog.Infof("%s: claude runner failed after %s: %v", ...) logs error+duration — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)

• claude/agent-step.go:100 — glog.Infof("%s: claude runner returned %d bytes in %s", ...) logs result byte count+duration — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)

• claude/claude-plugin-installer.go:60 — glog.Infof("%s %s failed after %s: %v", ...) logs command failure — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)

• claude/claude-plugin-installer.go:76 — glog.Infof("%s %s returned %d bytes in %s", ...) logs command output size — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)

• claude/claude-plugin-installer.go:117,132,136,143,152 — All glog.Infof("spec=%s action=%s", ...) calls log spec+action tuples. These are action instrumentation, not operator-level events. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)

• claude/claude-plugin-installer.go:124 — for _, line := range strings.Split(output, "\n") loop lacks a select { case <-ctx.Done(): return ctx.Err(); default: } check. Cancellation mid-iteration silently falls through. Add one at the top of the loop body. (rule: go-context/cancel-check-in-loop)

---

Nice to Have (Optional)

• claude/agent-step.go:86 and claude/claude-plugin-installer.go:58 — time.Now() called directly. Inject libtime.CurrentDateTimeGetter for testability. Lower severity since no tests are being added here. (rule: go-time/no-time-now-direct)

• claude/claude-plugin-installer.go:27,34 — PluginCommander and PluginInstaller interfaces declared without a //counterfeiter:generate directive. If these are used across package boundaries in tests, add the directive and run make generate. (rule: go-testing/counterfeiter-mocks-required)

---

Selector Mode Traceability

• Candidates: 15 rules matched by Step 4b-i glob filter
• Applicable: 2 rules (go-glog/use-v-for-debug-not-info, go-context/cancel-check-in-loop)
• Skipped: 13 rules — none of the patterns they check (business-logic-in-main, factory patterns, doc comments, boolean combinators, CQRS, enum types, error sentinels, changelog conventional-prefix) are present in this refactoring-only diff

---

Plan Concerns — Resolution Status

Concern	Status
claude/agent-step.go: verify glog.V(2) pattern matches pi/pi-step.go	Partially addressed — logging was added, but at glog.Infof (V0) not glog.V(2).Infof (V2). The pattern structure is correct; the verbosity level is wrong.
claude/claude-plugin-installer.go: plugin command logging partial — logs before but not outcome	Addressed — execPluginCommander.Run now logs both failure (line 60) and success (line 76).

---

Notes

• The changelog/conventional-prefix-required rule is satisfied — both entries use refactor:.
• The go-cli/slog-not-glog-in-new-projects rule is exempt here — this project uses glog extensively throughout, so it's an existing project mid-migration, not a new project.
• precommit skipped (selector mode) — CI covers lint+test.

---

{
  "verdict": "request-changes",
  "summary": "The subprocess boundary logging was added as intended, but all new glog.Infof calls use V0 (always-on) instead of V(2) (dev-debug) for debug-shaped messages (prompt sizes, result byte counts, durations, action names). One loop also lacks a ctx.Done() check. Fix: downgrade all new glog.Infof to glog.V(2).Infof and add cancellation check to the plugin list loop.",
  "comments": [
    {
      "file": "claude/agent-step.go",
      "line": 85,
      "severity": "major",
      "message": "glog.Infof logs prompt byte count — debug-shaped internal state. Should be glog.V(2).Infof. V0 is only for operator-level events (startup, shutdown, health changes, recovered panics). (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/agent-step.go",
      "line": 89,
      "severity": "major",
      "message": "glog.Infof logs error+duration on failure — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/agent-step.go",
      "line": 100,
      "severity": "major",
      "message": "glog.Infof logs result byte count+duration — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 60,
      "severity": "major",
      "message": "glog.Infof logs command failure with args+duration — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 76,
      "severity": "major",
      "message": "glog.Infof logs command success with output byte count+duration — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 117,
      "severity": "major",
      "message": "glog.Infof logs spec+action tuple — debug-shaped action instrumentation. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 124,
      "severity": "major",
      "message": "for-range loop iterates plugin list lines without ctx.Done() check — cancellation mid-iteration silently falls through. Add select { case <-ctx.Done(): return ctx.Err(); default: } at top of loop body. (rule: go-context/cancel-check-in-loop)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 132,
      "severity": "major",
      "message": "glog.Infof logs spec+action — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 136,
      "severity": "major",
      "message": "glog.Infof logs spec+action — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 143,
      "severity": "major",
      "message": "glog.Infof logs spec+action — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 152,
      "severity": "major",
      "message": "glog.Infof logs spec+action — debug-shaped. Should be glog.V(2).Infof. (rule: go-glog/use-v-for-debug-not-info)"
    },
    {
      "file": "claude/agent-step.go",
      "line": 86,
      "severity": "nit",
      "message": "time.Now() called directly. Inject libtime.CurrentDateTimeGetter for testability. (rule: go-time/no-time-now-direct)"
    },
    {
      "file": "claude/claude-plugin-installer.go",
      "line": 58,
      "severity": "nit",
      "message": "time.Now() called directly. Inject libtime.CurrentDateTimeGetter for testability. (rule: go-time/no-time-now-direct)"
    }
  ],
  "concerns_addressed": [
    "correctness: agent-step.go glog.V(2) pattern — structure correct, but all calls use glog.Infof (V0) instead of glog.V(2).Infof (V2)",
    "correctness: claude-plugin-installer.go plugin command logging — now logs both outcome and duration at the subprocess boundary"
  ]
}

[bborbe]

Must Fix is now empty and CI is green — thank you for reconsidering the cancellation and time.Now() findings.

On the remaining Should-Fix items I have to decline, because this round reverses round 1's explicit ruling on the same unchanged lines.

The V0 → V2 request would undo this PR

Round 1 adjudicated this rule and dismissed it, in its own words:

go-glog/use-v-for-debug-not-info — The glog.Infof calls are V0 boundary logs (before/after external calls), matching the documented exemption: "startup, shutdown, health changes, recovered panics" and "boundary calls" are V0-appropriate. Additionally, the rule's own applies_when marks it as for new projects — this is an existing glog project. Not a finding for this review.

Not one of those lines changed between rounds. Round 2 now asks for the opposite.

The substance also matters more than the inconsistency. This PR exists because the claude subprocess boundary was invisible at default verbosity — a run that failed or hung left no evidence it had started. Moving the new logs to V2 restores exactly that condition, since V2 is off in production. The change would be a no-op with extra lines.

The sibling boundary settles it: pi/pi-step.go:54-69 logs invoke, failure and success with glog.Infof at V0, unchanged and unflagged. The stated goal of this PR is to make the two boundaries symmetric. Applying V2 here alone re-creates the asymmetry in the opposite direction.

claude-plugin-installer.go:124 — cancellation in the line scan

Unchanged from my previous reply: this iterates a string already in memory, does no I/O, and breaks on first match. The subprocess it depends on has already returned, so there is no window in which cancellation could usefully interrupt it.

Measured on this repository during the review that produced this PR: 0 of 49 hits confirmed for this rule — 28 in functions with no ctx parameter at all, 7 anchored to a function signature or comment rather than a loop. Fleet-wide: 0 of 96.

Nice to Have

counterfeiter-mocks-required on PluginCommander / PluginInstaller — both directives exist; ast-grep's follows only inspects the immediate previous sibling node, so a directive sitting above a doc comment is invisible to it. Known rule bug, pre-existing and outside this diff either way.

no-time-now-direct — as covered in the previous reply, that time.Now() is the duration measurement the boundary-logging rule asked for.

---

No code changes this round. make precommit green, Must Fix empty, CI passing.