diff --git a/README.md b/README.md index 7be20081..051fdea6 100644 --- a/README.md +++ b/README.md @@ -690,6 +690,15 @@ All commands accept the global flags: |------|-----------| | `--profile ` | Select a configured profile and bypass repo-aware routing. When omitted, PR-aware commands use `repository_profiles`; commands that cannot resolve a route require `--profile`. During `init`, an omitted profile starts with the suggested name `default`. | | `--backend ` | Compatibility/runtime backend selector. It cannot override an explicit credential store destination. | +| `--quiet` | Suppress structured progress logs on stderr. Command stdout and stderr error reporting stay unchanged. | + +Progress-bearing commands emit one-line structured events on stderr in the +form `cr progress event= command="..." op="..." target="..." ...`. +This output is intended for human progress visibility and simple substring +parsers. JSON and text results continue to write to stdout only. In this slice, +structured progress is enabled for `benchmark run`, `benchmark select`, +`benchmark compare`, `data prune`, `data purge`, `config clear`, and +`sessions delete`. ### `cr` @@ -899,6 +908,11 @@ reset, `config.yml` is removed. `config clear` never touches durable review data. Use `cr data purge` for the data pillar. +When progress logging is enabled, `config clear` brackets config load, profile +resolution, credential-store open, credential deletion, optional profile-config +removal, and optional cache cleanup on stderr. Partial-success failures still +render their JSON or text result on stdout before returning the final error. + ### `cr me` ```text @@ -1076,6 +1090,12 @@ reviewed by the dry-run child command. Optional `stages.synthesis` metadata is reserved for future benchmark support and does not change `benchmark run` execution yet. +`benchmark run` emits progress on stderr for suite load and selection, results +directory creation, each matrix run, child `cr review` subprocess execution, +suite artifact writes, and comparison artifact generation. Child review +subprocesses are invoked with `--quiet` so their internal progress does not +pollute captured benchmark stderr artifacts. + ### `cr benchmark select` ```text @@ -1106,6 +1126,10 @@ When one selector run fails after partial execution, `benchmark select` records that run as failed and continues the remaining matrix when it can still write trustworthy suite artifacts. +`benchmark select` emits progress on stderr for suite load and selection, +results directory creation, per-profile runtime open, each selector run, +selection pipeline execution, and artifact generation. + ### `cr benchmark compare` ```text @@ -1118,6 +1142,9 @@ does not invoke models, read live PR state, mutate Git provider state, or require provider credentials. `cr benchmark run` and `cr benchmark select` write the same comparison artifacts automatically. +`benchmark compare` emits progress on stderr while it loads the suite summary, +builds the comparison model, and writes JSON and Markdown artifacts. + ### `cr sessions list` ```text @@ -1146,6 +1173,9 @@ cr sessions delete [--json] Deletes one named LLM session row. It does not delete provider-side session state. Missing sessions return an error. +`sessions delete` emits progress on stderr for layout resolution, legacy +migration, ledger open, and session deletion. + ### `cr data show` ```text @@ -1180,6 +1210,10 @@ Prune deletes the ledger row first, then removes artifact directories best effort. Unsafe artifact paths and remove failures are reported as warnings after the ledger row is deleted. +When progress logging is enabled, `data prune` emits stderr brackets for layout +resolution, optional legacy migration, ledger open, run selection, delete +actions, orphan discovery and removal, and the dry-run legacy check. + ### `cr data purge` ```text @@ -1191,6 +1225,9 @@ Purges the whole local data root. `--yes` is required unless `--dry-run` is set. Purge does not open the ledger database, so it can remove a corrupt local data root. `--json` emits the data root, dry-run status, and removed status. +`data purge` emits progress on stderr for layout resolution and the purge +action itself. + Flags: | Flag | Semantics | diff --git a/docs/development.md b/docs/development.md index a273ffb2..4383f31a 100644 --- a/docs/development.md +++ b/docs/development.md @@ -26,6 +26,25 @@ Structured LLM calls in the review pipeline are durable per-task units. See `docs/llm-task-artifacts.md` for the artifact schema, status taxonomy, and resume invariants. +## Progress Logging + +Non-review CLI progress now flows through one reusable component in +`internal/progress`. The contract for this slice is: + +- progress writes to stderr only +- JSON and text result payloads stay on stdout +- `--quiet` suppresses progress only +- lines are single-line structured records: + `cr progress event= command="..." op="..." target="..." ...` + +Current command coverage is `benchmark run`, `benchmark select`, +`benchmark compare`, `data prune`, `data purge`, `config clear`, and +`sessions delete`. + +Command packages own the `command=` label and stderr sink. Lower-level reuse is +intentionally narrow: `internal/datalifecycle` accepts a tiny start/end +progress interface rather than importing Cobra or root options. + ## Quick Commands ```bash diff --git a/internal/cmd/benchmarkcmd/benchmarkcmd_test.go b/internal/cmd/benchmarkcmd/benchmarkcmd_test.go index 12b37a30..e80f1ce6 100644 --- a/internal/cmd/benchmarkcmd/benchmarkcmd_test.go +++ b/internal/cmd/benchmarkcmd/benchmarkcmd_test.go @@ -125,6 +125,99 @@ func TestDoctorJSONUsesDefaultExecutable(t *testing.T) { } } +func TestBenchmarkCompareProgressWritesToStderr(t *testing.T) { + resultsDir := t.TempDir() + summary := benchmarkSuiteSummary{ + SchemaVersion: benchmarkArtifactSchemaVersion, + Mode: benchmarkModeReview, + SuiteID: "suite1", + ResultsDir: resultsDir, + SelectedCandidates: []benchmarkCandidate{{ + ID: "first", + Profile: "home", + Stages: benchmarkCandidateStages{Selection: benchmarkSelectionStage{Model: "kimi"}}, + }}, + SelectedCases: []benchmarkCase{{ID: "case_one", PR: "https://github.com/open-cli-collective/codereview-cli/pull/1"}}, + Runs: []benchmarkRun{ + matrixFixtureRun(resultsDir, "0001-c01-k01-first-case_one", "first", "case_one", 0, failureNone, 1, map[string]int{"major": 1}, 10), + }, + Artifacts: suiteArtifacts{ + Manifest: filepath.Join(resultsDir, "manifest.json"), + SummaryJSONL: filepath.Join(resultsDir, "summary.jsonl"), + SuiteSummary: filepath.Join(resultsDir, "suite-summary.json"), + Report: filepath.Join(resultsDir, "report.md"), + ComparisonJSON: filepath.Join(resultsDir, "comparison.json"), + ComparisonMarkdown: filepath.Join(resultsDir, "comparison.md"), + }, + } + writeComparisonFixture(t, summary) + writeReviewJSON(t, summary.Runs[0].Artifacts.ReviewJSON, view.ReviewDryRun{Run: view.ReviewRun{RunID: "child-run-1"}}) + + cfgPath := filepath.Join(t.TempDir(), "config.yml") + if err := config.Save(cfgPath, testConfig()); err != nil { + t.Fatalf("config Save: %v", err) + } + var stdout bytes.Buffer + var stderr bytes.Buffer + cmd, opts := root.NewCommandWithOptions(&root.Options{ + ConfigPath: cfgPath, + Stdout: &stdout, + Stderr: &stderr, + Quiet: false, + }) + Register(cmd, opts) + + if err := root.Execute(cmd, []string{"benchmark", "compare", resultsDir, "--json"}); err != nil { + t.Fatalf("Execute: %v", err) + } + if !strings.Contains(stderr.String(), `command="benchmark.compare" op="load_summary"`) { + t.Fatalf("stderr = %q, want load_summary progress", stderr.String()) + } + if !strings.Contains(stderr.String(), `command="benchmark.compare" op="write_markdown"`) { + t.Fatalf("stderr = %q, want write_markdown progress", stderr.String()) + } + var got comparisonReport + if err := json.Unmarshal(stdout.Bytes(), &got); err != nil { + t.Fatalf("Unmarshal JSON: %v\nstdout=%s\nstderr=%s", err, stdout.String(), stderr.String()) + } +} + +func TestRunProgressWritesToStderr(t *testing.T) { + cmd, out, errOut := newTestCommandWithStderr(t, false) + suitePath := writeBenchmarkSuite(t, validBenchmarkSuite(t)) + crBin := writeExecutableCRBin(t) + resultsDir := filepath.Join(t.TempDir(), "results") + withBenchmarkRunSeams(t, fixedBenchmarkTime(), func(_ context.Context, _ string, _ []string) reviewCommandResult { + return reviewCommandResult{ + Stdout: reviewDryRunJSON(t, "child-run-1"), + Stderr: []byte("child stderr\n"), + ExitCode: 0, + Duration: time.Second, + } + }) + + if err := root.Execute(cmd, []string{ + "benchmark", "run", suitePath, + "--candidate", "first", + "--case", "case_one", + "--results-dir", resultsDir, + "--cr-bin", crBin, + "--json", + }); err != nil { + t.Fatalf("Execute: %v", err) + } + if !strings.Contains(errOut.String(), `command="benchmark.run" op="execute_run"`) { + t.Fatalf("stderr = %q, want execute_run progress", errOut.String()) + } + if !strings.Contains(errOut.String(), `command="benchmark.run" op="write_comparison"`) { + t.Fatalf("stderr = %q, want write_comparison progress", errOut.String()) + } + var got benchmarkSuiteSummary + if err := json.Unmarshal(out.Bytes(), &got); err != nil { + t.Fatalf("Unmarshal JSON: %v\nstdout=%s\nstderr=%s", err, out.String(), errOut.String()) + } +} + func TestDoctorJSONReportsOptionalSynthesisStage(t *testing.T) { cmd, out := newTestCommand(t) synthesisPrompt := filepath.Join(t.TempDir(), "synthesis-v1.md") @@ -424,6 +517,7 @@ func TestRunExecutesSelectedMatrixAndWritesArtifacts(t *testing.T) { } wantFirstArgs := []string{ "--profile", "home", + "--quiet", "review", "https://github.com/open-cli-collective/codereview-cli/pull/1", "--dry-run", "--json", "--selection-model", "claude-sonnet-4-6", @@ -440,6 +534,7 @@ func TestRunExecutesSelectedMatrixAndWritesArtifacts(t *testing.T) { } wantSecondArgs := []string{ "--profile", "home", + "--quiet", "review", "https://github.com/open-cli-collective/codereview-cli/pull/2", "--dry-run", "--json", "--review-base-sha", "1111111", @@ -461,6 +556,7 @@ func TestRunExecutesSelectedMatrixAndWritesArtifacts(t *testing.T) { } wantThirdArgs := []string{ "--profile", "home", + "--quiet", "review", "https://github.com/open-cli-collective/codereview-cli/pull/1", "--dry-run", "--json", "--selection-model", "kimi", @@ -475,6 +571,7 @@ func TestRunExecutesSelectedMatrixAndWritesArtifacts(t *testing.T) { } wantFourthArgs := []string{ "--profile", "home", + "--quiet", "review", "https://github.com/open-cli-collective/codereview-cli/pull/2", "--dry-run", "--json", "--review-base-sha", "1111111", @@ -935,19 +1032,26 @@ func TestRunReusesExplicitResultsDirAndOverwritesOwnedArtifacts(t *testing.T) { } func newTestCommand(t *testing.T) (*cobra.Command, *bytes.Buffer) { + cmd, out, _ := newTestCommandWithStderr(t, true) + return cmd, out +} + +func newTestCommandWithStderr(t *testing.T, quiet bool) (*cobra.Command, *bytes.Buffer, *bytes.Buffer) { t.Helper() cfgPath := filepath.Join(t.TempDir(), "config.yml") if err := config.Save(cfgPath, testConfig()); err != nil { t.Fatalf("config Save: %v", err) } var out bytes.Buffer + var errOut bytes.Buffer cmd, opts := root.NewCommandWithOptions(&root.Options{ ConfigPath: cfgPath, Stdout: &out, - Stderr: &bytes.Buffer{}, + Stderr: &errOut, + Quiet: quiet, }) Register(cmd, opts) - return cmd, &out + return cmd, &out, &errOut } func writeBenchmarkSuite(t *testing.T, body string) string { diff --git a/internal/cmd/benchmarkcmd/compare.go b/internal/cmd/benchmarkcmd/compare.go index f759c7dd..d9bf87c8 100644 --- a/internal/cmd/benchmarkcmd/compare.go +++ b/internal/cmd/benchmarkcmd/compare.go @@ -13,6 +13,7 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/benchmark" "github.com/open-cli-collective/codereview-cli/internal/cmd/exitcode" "github.com/open-cli-collective/codereview-cli/internal/cmd/root" + "github.com/open-cli-collective/codereview-cli/internal/progress" "github.com/open-cli-collective/codereview-cli/internal/view" ) @@ -183,7 +184,8 @@ func newCompareCommand(opts *root.Options) *cobra.Command { return nil }, RunE: func(_ *cobra.Command, args []string) error { - comparison, err := writeComparisonArtifactsForResultsDir(args[0]) + logger := newProgressLogger(opts) + comparison, err := writeComparisonArtifactsForResultsDirWithProgress(args[0], logger) if err != nil { return mapBenchmarkError(err) } @@ -200,17 +202,29 @@ func newCompareCommand(opts *root.Options) *cobra.Command { } func writeComparisonArtifactsForResultsDir(resultsDir string) (comparisonReport, error) { + return writeComparisonArtifactsForResultsDirWithProgress(resultsDir, progress.New(nil, true, nil)) +} + +func writeComparisonArtifactsForResultsDirWithProgress(resultsDir string, logger *progress.Logger) (comparisonReport, error) { + resolveSpan := logger.Start("benchmark.compare", "load_summary", "results") summary, resolvedDir, err := loadBenchmarkSummaryForCompare(resultsDir) if err != nil { - return comparisonReport{}, err + return comparisonReport{}, endProgressSpan(resolveSpan, err) } + resolveSpan.End(nil) + buildSpan := logger.Start("benchmark.compare", "build_comparison", summary.SuiteID) comparison := buildComparison(summary, resolvedDir) + buildSpan.End(nil) + jsonSpan := logger.Start("benchmark.compare", "write_json", summary.SuiteID) if err := writeJSONFile(comparison.Artifacts.ComparisonJSON, comparison); err != nil { - return comparisonReport{}, err + return comparisonReport{}, endProgressSpan(jsonSpan, err) } + jsonSpan.End(nil) + mdSpan := logger.Start("benchmark.compare", "write_markdown", summary.SuiteID) if err := writeArtifactFile(comparison.Artifacts.ComparisonMarkdown, []byte(renderComparisonMarkdown(comparison))); err != nil { - return comparisonReport{}, err + return comparisonReport{}, endProgressSpan(mdSpan, err) } + mdSpan.End(nil) return comparison, nil } diff --git a/internal/cmd/benchmarkcmd/progress.go b/internal/cmd/benchmarkcmd/progress.go new file mode 100644 index 00000000..ac26c97b --- /dev/null +++ b/internal/cmd/benchmarkcmd/progress.go @@ -0,0 +1,20 @@ +package benchmarkcmd + +import ( + "github.com/open-cli-collective/codereview-cli/internal/cmd/root" + "github.com/open-cli-collective/codereview-cli/internal/progress" +) + +func newProgressLogger(opts *root.Options) *progress.Logger { + if opts == nil { + return progress.New(nil, true, nil) + } + return progress.New(opts.Stderr, opts.Quiet, nil) +} + +func endProgressSpan(span *progress.Span, err error) error { + if span != nil { + span.End(err) + } + return err +} diff --git a/internal/cmd/benchmarkcmd/run.go b/internal/cmd/benchmarkcmd/run.go index 6a60faad..ab84d444 100644 --- a/internal/cmd/benchmarkcmd/run.go +++ b/internal/cmd/benchmarkcmd/run.go @@ -20,6 +20,7 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/benchmark" "github.com/open-cli-collective/codereview-cli/internal/cmd/exitcode" "github.com/open-cli-collective/codereview-cli/internal/cmd/root" + "github.com/open-cli-collective/codereview-cli/internal/progress" "github.com/open-cli-collective/codereview-cli/internal/view" ) @@ -241,30 +242,39 @@ func newRunCommand(opts *root.Options) *cobra.Command { } func runBenchmarkSuite(ctx context.Context, opts *root.Options, flags runFlags, suitePath string) (benchmarkSuiteSummary, error) { + logger := newProgressLogger(opts) + suiteSpan := logger.Start("benchmark.run", "load_suite", "suite") suite, _, err := loadConfigAndSuite(opts, suitePath) if err != nil { - return benchmarkSuiteSummary{}, err + return benchmarkSuiteSummary{}, endProgressSpan(suiteSpan, err) } + suiteSpan.End(nil) + selectSpan := logger.Start("benchmark.run", "select_matrix", suite.Suite.ID) selectedCandidates, selectedCases, err := benchmark.Select(suite, flags.candidates, flags.cases) if err != nil { - return benchmarkSuiteSummary{}, mapBenchmarkError(err) + return benchmarkSuiteSummary{}, endProgressSpan(selectSpan, mapBenchmarkError(err)) } + selectSpan.End(nil) + resolveSpan := logger.Start("benchmark.run", "resolve_cr_bin", suite.Suite.ID) crBin, err := resolveRunCRBin(flags.crBin) if err != nil { - return benchmarkSuiteSummary{}, mapBenchmarkError(err) + return benchmarkSuiteSummary{}, endProgressSpan(resolveSpan, mapBenchmarkError(err)) } + resolveSpan.End(nil) started := benchmarkNow().UTC() + resultsSpan := logger.Start("benchmark.run", "prepare_results", suite.Suite.ID) resultsDir, err := resolveRunResultsDir(suite.Suite.ID, flags.resultsDir, started) if err != nil { - return benchmarkSuiteSummary{}, err + return benchmarkSuiteSummary{}, endProgressSpan(resultsSpan, err) } suiteHash, err := suiteFileSHA256(suite.Path) if err != nil { - return benchmarkSuiteSummary{}, err + return benchmarkSuiteSummary{}, endProgressSpan(resultsSpan, err) } if err := os.MkdirAll(resultsDir, artifactDirPerm); err != nil { - return benchmarkSuiteSummary{}, fmt.Errorf("benchmark: create results dir: %w", err) + return benchmarkSuiteSummary{}, endProgressSpan(resultsSpan, fmt.Errorf("benchmark: create results dir: %w", err)) } + resultsSpan.End(nil) suiteDir := filepath.Dir(suite.Path) summary := benchmarkSuiteSummary{ @@ -294,7 +304,7 @@ func runBenchmarkSuite(ctx context.Context, opts *root.Options, flags runFlags, for caseIndex, benchCase := range selectedCases { matrixIndex++ runID := benchmarkRunID(matrixIndex, candidateIndex, caseIndex, candidate, benchCase) - runSummary, err := executeBenchmarkRun(ctx, suiteDir, resultsDir, crBin, runID, candidate, benchCase) + runSummary, err := executeBenchmarkRun(ctx, logger, suiteDir, resultsDir, crBin, runID, candidate, benchCase) if err != nil { return benchmarkSuiteSummary{}, err } @@ -315,19 +325,24 @@ func runBenchmarkSuite(ctx context.Context, opts *root.Options, flags runFlags, completed := benchmarkNow().UTC() summary.CompletedAt = completed.Format(time.RFC3339) summary.DurationMS = durationMS(completed.Sub(started)) + writeArtifactsSpan := logger.Start("benchmark.run", "write_suite_artifacts", suite.Suite.ID) if err := writeSuiteArtifacts(summary); err != nil { - return benchmarkSuiteSummary{}, err + return benchmarkSuiteSummary{}, endProgressSpan(writeArtifactsSpan, err) } + writeArtifactsSpan.End(nil) + compareSpan := logger.Start("benchmark.run", "write_comparison", suite.Suite.ID) if _, err := writeComparisonArtifactsForResultsDir(summary.ResultsDir); err != nil { - return benchmarkSuiteSummary{}, fmt.Errorf("benchmark: write comparison artifacts after suite artifacts were written to %s; rerun `cr benchmark compare %s`: %w", summary.ResultsDir, summary.ResultsDir, err) + return benchmarkSuiteSummary{}, endProgressSpan(compareSpan, fmt.Errorf("benchmark: write comparison artifacts after suite artifacts were written to %s; rerun `cr benchmark compare %s`: %w", summary.ResultsDir, summary.ResultsDir, err)) } + compareSpan.End(nil) return summary, nil } -func executeBenchmarkRun(ctx context.Context, suiteDir, resultsDir, crBin, runID string, candidate benchmark.Candidate, benchCase benchmark.Case) (benchmarkRun, error) { +func executeBenchmarkRun(ctx context.Context, logger *progress.Logger, suiteDir, resultsDir, crBin, runID string, candidate benchmark.Candidate, benchCase benchmark.Case) (benchmarkRun, error) { + runSpan := logger.Start("benchmark.run", "execute_run", runID) runDir := filepath.Join(resultsDir, runID) if err := os.MkdirAll(runDir, artifactDirPerm); err != nil { - return benchmarkRun{}, fmt.Errorf("benchmark: create run dir %s: %w", runID, err) + return benchmarkRun{}, endProgressSpan(runSpan, fmt.Errorf("benchmark: create run dir %s: %w", runID, err)) } artifacts := runArtifacts{ Dir: runDir, @@ -336,7 +351,9 @@ func executeBenchmarkRun(ctx context.Context, suiteDir, resultsDir, crBin, runID MetricsJSON: filepath.Join(runDir, "metrics.json"), } args := reviewArgs(suiteDir, candidate, benchCase) + childSpan := logger.Start("benchmark.run", "child_review", runID) child := runReviewCommand(ctx, crBin, args) + childSpan.End(child.Err) runSummary := benchmarkRun{ RunID: runID, @@ -378,14 +395,15 @@ func executeBenchmarkRun(ctx context.Context, suiteDir, resultsDir, crBin, runID } if err := writeArtifactFile(artifacts.ReviewJSON, child.Stdout); err != nil { - return benchmarkRun{}, err + return benchmarkRun{}, endProgressSpan(runSpan, err) } if err := writeArtifactFile(artifacts.Stderr, child.Stderr); err != nil { - return benchmarkRun{}, err + return benchmarkRun{}, endProgressSpan(runSpan, err) } if err := writeJSONFile(artifacts.MetricsJSON, runSummary); err != nil { - return benchmarkRun{}, err + return benchmarkRun{}, endProgressSpan(runSpan, err) } + runSpan.End(nil) return runSummary, nil } @@ -419,7 +437,7 @@ func runReviewCommandReal(ctx context.Context, crBin string, args []string) revi } func reviewArgs(suiteDir string, candidate benchmark.Candidate, benchCase benchmark.Case) []string { - args := []string{"--profile", candidate.Profile, "review", benchCase.PR, "--dry-run", "--json"} + args := []string{"--profile", candidate.Profile, "--quiet", "review", benchCase.PR, "--dry-run", "--json"} if benchCase.ReviewBaseSHA != "" { args = append(args, "--review-base-sha", benchCase.ReviewBaseSHA) } diff --git a/internal/cmd/benchmarkcmd/select.go b/internal/cmd/benchmarkcmd/select.go index f886ed11..7312b927 100644 --- a/internal/cmd/benchmarkcmd/select.go +++ b/internal/cmd/benchmarkcmd/select.go @@ -20,6 +20,7 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/config" "github.com/open-cli-collective/codereview-cli/internal/llm" "github.com/open-cli-collective/codereview-cli/internal/pipeline" + "github.com/open-cli-collective/codereview-cli/internal/progress" "github.com/open-cli-collective/codereview-cli/internal/prref" ) @@ -74,26 +75,33 @@ func newSelectCommand(opts *root.Options) *cobra.Command { } func runBenchmarkSelectionSuite(ctx context.Context, cmd *cobra.Command, opts *root.Options, flags selectFlags, suitePath string) (benchmarkSuiteSummary, error) { + logger := newProgressLogger(opts) + suiteSpan := logger.Start("benchmark.select", "load_suite", "suite") suite, cfg, err := loadConfigAndSuiteWithValidator(opts, suitePath, benchmark.ValidateForSelection) if err != nil { - return benchmarkSuiteSummary{}, err + return benchmarkSuiteSummary{}, endProgressSpan(suiteSpan, err) } + suiteSpan.End(nil) + selectSpan := logger.Start("benchmark.select", "select_matrix", suite.Suite.ID) selectedCandidates, selectedCases, err := benchmark.Select(suite, flags.candidates, flags.cases) if err != nil { - return benchmarkSuiteSummary{}, mapBenchmarkError(err) + return benchmarkSuiteSummary{}, endProgressSpan(selectSpan, mapBenchmarkError(err)) } + selectSpan.End(nil) started := benchmarkNow().UTC() + resultsSpan := logger.Start("benchmark.select", "prepare_results", suite.Suite.ID) resultsDir, err := resolveSelectResultsDir(suite.Suite.ID, flags.resultsDir, started) if err != nil { - return benchmarkSuiteSummary{}, err + return benchmarkSuiteSummary{}, endProgressSpan(resultsSpan, err) } suiteHash, err := suiteFileSHA256(suite.Path) if err != nil { - return benchmarkSuiteSummary{}, err + return benchmarkSuiteSummary{}, endProgressSpan(resultsSpan, err) } if err := os.MkdirAll(resultsDir, artifactDirPerm); err != nil { - return benchmarkSuiteSummary{}, fmt.Errorf("benchmark: create results dir: %w", err) + return benchmarkSuiteSummary{}, endProgressSpan(resultsSpan, fmt.Errorf("benchmark: create results dir: %w", err)) } + resultsSpan.End(nil) var cleanups []func() defer func() { @@ -106,6 +114,7 @@ func runBenchmarkSelectionSuite(ctx context.Context, cmd *cobra.Command, opts *r if state, ok := runtimes[profileName]; ok { return state } + runtimeSpan := logger.Start("benchmark.select", "open_runtime", profileName) resolvedName, profile, resolveErr := config.ResolveProfile(cfg, profileName) state := selectionRuntimeState{ profileName: resolvedName, @@ -121,6 +130,11 @@ func runBenchmarkSelectionSuite(ctx context.Context, cmd *cobra.Command, opts *r } } runtimes[profileName] = state + if state.err != nil { + runtimeSpan.End(state.err) + } else { + runtimeSpan.End(nil) + } return state } @@ -152,7 +166,7 @@ func runBenchmarkSelectionSuite(ctx context.Context, cmd *cobra.Command, opts *r for caseIndex, benchCase := range selectedCases { matrixIndex++ runID := benchmarkRunID(matrixIndex, candidateIndex, caseIndex, candidate, benchCase) - runSummary, runErr := executeBenchmarkSelectRun(ctx, suiteDir, resultsDir, runID, candidate, benchCase, state) + runSummary, runErr := executeBenchmarkSelectRun(ctx, logger, suiteDir, resultsDir, runID, candidate, benchCase, state) if runErr != nil { return benchmarkSuiteSummary{}, runErr } @@ -172,30 +186,35 @@ func runBenchmarkSelectionSuite(ctx context.Context, cmd *cobra.Command, opts *r completed := benchmarkNow().UTC() summary.CompletedAt = completed.Format(time.RFC3339) summary.DurationMS = durationMS(completed.Sub(started)) + writeArtifactsSpan := logger.Start("benchmark.select", "write_suite_artifacts", suite.Suite.ID) if err := writeSuiteArtifacts(summary); err != nil { - return benchmarkSuiteSummary{}, err + return benchmarkSuiteSummary{}, endProgressSpan(writeArtifactsSpan, err) } + writeArtifactsSpan.End(nil) + compareSpan := logger.Start("benchmark.select", "write_comparison", suite.Suite.ID) if _, err := writeComparisonArtifactsForResultsDir(summary.ResultsDir); err != nil { - return benchmarkSuiteSummary{}, fmt.Errorf("benchmark: write comparison artifacts after suite artifacts were written to %s; rerun `cr benchmark compare %s`: %w", summary.ResultsDir, summary.ResultsDir, err) + return benchmarkSuiteSummary{}, endProgressSpan(compareSpan, fmt.Errorf("benchmark: write comparison artifacts after suite artifacts were written to %s; rerun `cr benchmark compare %s`: %w", summary.ResultsDir, summary.ResultsDir, err)) } + compareSpan.End(nil) return summary, nil } -func executeBenchmarkSelectRun(ctx context.Context, suiteDir, resultsDir, runID string, candidate benchmark.Candidate, benchCase benchmark.Case, state selectionRuntimeState) (benchmarkRun, error) { +func executeBenchmarkSelectRun(ctx context.Context, logger *progress.Logger, suiteDir, resultsDir, runID string, candidate benchmark.Candidate, benchCase benchmark.Case, state selectionRuntimeState) (benchmarkRun, error) { + runSpan := logger.Start("benchmark.select", "execute_run", runID) runDir := filepath.Join(resultsDir, runID) if err := os.MkdirAll(runDir, artifactDirPerm); err != nil { - return benchmarkRun{}, fmt.Errorf("benchmark: create run dir %s: %w", runID, err) + return benchmarkRun{}, endProgressSpan(runSpan, fmt.Errorf("benchmark: create run dir %s: %w", runID, err)) } artifacts, err := selectionRunArtifacts(runDir) if err != nil { - return benchmarkRun{}, err + return benchmarkRun{}, endProgressSpan(runSpan, err) } recipe := benchmarkRunRecipe{ Candidate: summarizeCandidates(suiteDir, []benchmark.Candidate{candidate})[0], Case: summarizeCases([]benchmark.Case{benchCase})[0], } if err := writeJSONFile(artifacts.RecipeJSON, recipe); err != nil { - return benchmarkRun{}, err + return benchmarkRun{}, endProgressSpan(runSpan, err) } runSummary := benchmarkRun{ @@ -221,22 +240,32 @@ func executeBenchmarkSelectRun(ctx context.Context, suiteDir, resultsDir, runID ) if state.err != nil { recordSelectionRunFailure(&runSummary, &stderrBody, state.err) - return finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + finalized, err := finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + return finalized, endProgressSpan(runSpan, err) } + promptSpan := logger.Start("benchmark.select", "load_prompt", runID) selectionPromptInstructions, err := loadSelectionPromptInstructions(suiteDir, candidate.Stages.Selection.Prompt) if err != nil { recordSelectionRunFailure(&runSummary, &stderrBody, err) - return finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + promptSpan.End(err) + finalized, ferr := finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + return finalized, endProgressSpan(runSpan, ferr) } + promptSpan.End(nil) + parseSpan := logger.Start("benchmark.select", "parse_pr", runID) ref, err := prref.ParseGitHubPullURL(benchCase.PR) if err != nil { recordSelectionRunFailure(&runSummary, &stderrBody, err) - return finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + parseSpan.End(err) + finalized, ferr := finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + return finalized, endProgressSpan(runSpan, ferr) } + parseSpan.End(nil) - result, err := runSelectionOnly(ctx, pipeline.Options{ + selectionSpan := logger.Start("benchmark.select", "selection_pipeline", runID) + selectionResult, err := runSelectionOnly(ctx, pipeline.Options{ Provider: state.runtime.Provider, Adapter: state.runtime.Adapter, MaxAgents: candidate.MaxAgents, @@ -252,28 +281,36 @@ func executeBenchmarkSelectRun(ctx context.Context, suiteDir, resultsDir, runID SelectionEffortOverride: candidate.Stages.Selection.Effort, SelectionPromptInstructions: selectionPromptInstructions, }) - rawSelectionJSON = append([]byte(nil), result.SelectionSession.Response.StructuredOutput...) - if result.ReviewBaseSHA != "" { - runSummary.ReviewBaseSHA = result.ReviewBaseSHA + rawSelectionJSON = append([]byte(nil), selectionResult.SelectionSession.Response.StructuredOutput...) + if selectionResult.ReviewBaseSHA != "" { + runSummary.ReviewBaseSHA = selectionResult.ReviewBaseSHA } - if result.ReviewHeadSHA != "" { - runSummary.ReviewHeadSHA = result.ReviewHeadSHA + if selectionResult.ReviewHeadSHA != "" { + runSummary.ReviewHeadSHA = selectionResult.ReviewHeadSHA } - if result.CurrentBaseSHA != "" { - runSummary.CurrentBaseSHA = result.CurrentBaseSHA + if selectionResult.CurrentBaseSHA != "" { + runSummary.CurrentBaseSHA = selectionResult.CurrentBaseSHA } - if result.CurrentHeadSHA != "" { - runSummary.CurrentHeadSHA = result.CurrentHeadSHA + if selectionResult.CurrentHeadSHA != "" { + runSummary.CurrentHeadSHA = selectionResult.CurrentHeadSHA } if err != nil { recordSelectionRunFailure(&runSummary, &stderrBody, err) - return finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + selectionSpan.End(err) + finalized, ferr := finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + return finalized, endProgressSpan(runSpan, ferr) } + selectionSpan.End(nil) runSummary.FailureClassification = failureNone - runSummary.SelectedAgents = summarizeSelectedAgents(result.Selection.SelectedAgents) - runSummary.ThreadActionCount = len(result.Selection.ThreadActions) - return finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + runSummary.SelectedAgents = summarizeSelectedAgents(selectionResult.Selection.SelectedAgents) + runSummary.ThreadActionCount = len(selectionResult.Selection.ThreadActions) + finalized, err := finalizeSelectionRun(runSummary, start, rawSelectionJSON, stderrBody) + if err != nil { + return benchmarkRun{}, endProgressSpan(runSpan, err) + } + runSpan.End(nil) + return finalized, nil } func finalizeSelectionRun(runSummary benchmarkRun, started time.Time, rawSelectionJSON, stderrBody []byte) (benchmarkRun, error) { diff --git a/internal/cmd/benchmarkcmd/select_test.go b/internal/cmd/benchmarkcmd/select_test.go index e2ef5712..afe7328e 100644 --- a/internal/cmd/benchmarkcmd/select_test.go +++ b/internal/cmd/benchmarkcmd/select_test.go @@ -141,6 +141,53 @@ func TestSelectExecutesSelectedMatrixAndWritesArtifacts(t *testing.T) { assertFileContains(t, got.Runs[0].Artifacts.RecipeJSON, `"case"`) } +func TestSelectProgressWritesToStderr(t *testing.T) { + cmd, out, errOut := newTestCommandWithStderr(t, false) + suitePath := writeBenchmarkSuite(t, validBenchmarkSuite(t)) + resultsDir := filepath.Join(t.TempDir(), "results") + + withBenchmarkSelectSeams(t, + func(context.Context, string, bool, config.File, config.Profile) (reviewcmd.SelectionRuntime, error) { + return reviewcmd.SelectionRuntime{Cleanup: func() {}}, nil + }, + func(_ context.Context, _ pipeline.Options, req pipeline.SelectionRequest) (pipeline.SelectionResult, error) { + artifacts := pipeline.ArtifactPathsFromDir(req.ArtifactDir) + if err := os.MkdirAll(artifacts.AgentLogsDir, 0o700); err != nil { + t.Fatalf("MkdirAll agent logs: %v", err) + } + return pipeline.SelectionResult{ + Artifacts: artifacts, + Selection: llm.Selection{ + SelectedAgents: []llm.SelectedAgent{{AgentID: "harness:alpha"}}, + }, + SelectionSession: pipeline.SelectionSession{ + Response: llm.Response{StructuredOutput: []byte(`{"schema_version":1,"selected_agents":[{"agent_id":"harness:alpha"}],"thread_actions":[]}`)}, + }, + }, nil + }, + ) + + if err := root.Execute(cmd, []string{ + "benchmark", "select", suitePath, + "--candidate", "first", + "--case", "case_one", + "--results-dir", resultsDir, + "--json", + }); err != nil { + t.Fatalf("Execute: %v", err) + } + if !strings.Contains(errOut.String(), `command="benchmark.select" op="selection_pipeline"`) { + t.Fatalf("stderr = %q, want selection_pipeline progress", errOut.String()) + } + if !strings.Contains(errOut.String(), `command="benchmark.select" op="write_comparison"`) { + t.Fatalf("stderr = %q, want write_comparison progress", errOut.String()) + } + var got benchmarkSuiteSummary + if err := json.Unmarshal(out.Bytes(), &got); err != nil { + t.Fatalf("Unmarshal JSON: %v\nstdout=%s\nstderr=%s", err, out.String(), errOut.String()) + } +} + func TestSelectRecordsRuntimeFailuresWithoutInvokingSelection(t *testing.T) { cmd, out := newTestCommand(t) suitePath := writeBenchmarkSuite(t, validBenchmarkSuite(t)) diff --git a/internal/cmd/configcmd/configcmd.go b/internal/cmd/configcmd/configcmd.go index 38f76dbb..e74442c2 100644 --- a/internal/cmd/configcmd/configcmd.go +++ b/internal/cmd/configcmd/configcmd.go @@ -22,6 +22,7 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/configedit" "github.com/open-cli-collective/codereview-cli/internal/credentials" "github.com/open-cli-collective/codereview-cli/internal/prref" + "github.com/open-cli-collective/codereview-cli/internal/progress" "github.com/open-cli-collective/codereview-cli/internal/statepaths" "github.com/open-cli-collective/codereview-cli/internal/view" ) @@ -418,66 +419,84 @@ func Register(rootCmd *cobra.Command, opts *root.Options) { return nil }, RunE: func(cmd *cobra.Command, _ []string) error { + logger := newProgressLogger(opts) + mode := "live" + if clearDryRun { + mode = "dry-run" + } + modeSpan := logger.Start("config.clear", "mode", mode) + modeSpan.End(nil) + loadSpan := logger.Start("config.clear", "load_config", "active-profile") path, err := configPath(opts) if err != nil { - return exitcode.AuthConfig(err) + return exitcode.AuthConfig(endProgressSpan(loadSpan, err)) } cfg, err := config.Load(path) if err != nil { - return cmderr.Config(err) + return cmderr.Config(endProgressSpan(loadSpan, err)) } + loadSpan.End(nil) + profileSpan := logger.Start("config.clear", "resolve_profile", "active-profile") profileName, profile, err := config.ResolveProfile(cfg, opts.Profile) if err != nil { - return cmderr.Config(err) + return cmderr.Config(endProgressSpan(profileSpan, err)) } resolvedSecretsProfile, err := credentials.ResolveSecretsProfileForProfile(cfg, profile) if err != nil { - return cmderr.Config(err) + return cmderr.Config(endProgressSpan(profileSpan, err)) } refs, err := config.CredentialRefs(profile) if err != nil { - return cmderr.Config(err) + return cmderr.Config(endProgressSpan(profileSpan, err)) } profiles, err := distinctCredentialProfiles(refs) if err != nil { - return cmderr.Credential(err) + return cmderr.Credential(endProgressSpan(profileSpan, err)) } + profileSpan.End(nil) + storeSpan := logger.Start("config.clear", "open_credential_store", "active-profile") store, err := credentials.OpenResolvedStore(opts.Backend, cmderr.BackendFlagChanged(cmd), cfg, resolvedSecretsProfile) if err != nil { if errors.Is(err, config.ErrInvalid) || errors.Is(err, config.ErrProfileNotFound) || errors.Is(err, config.ErrSecretsProfileNotFound) { - return cmderr.Config(err) + return cmderr.Config(endProgressSpan(storeSpan, err)) } - return cmderr.Credential(err) + return cmderr.Credential(endProgressSpan(storeSpan, err)) } defer store.Close() backend, source, err := backendMetadata(store, opts.Backend, cmderr.BackendFlagChanged(cmd), cfg, resolvedSecretsProfile) if err != nil { - return cmderr.Credential(err) + return cmderr.Credential(endProgressSpan(storeSpan, err)) } + storeSpan.End(nil) result := view.ConfigClear{ Backend: string(backend), BackendSource: string(source), ActiveSecretsProfile: resolvedSecretsProfileViewPtr(resolvedSecretsProfile), DryRun: clearDryRun, } - for _, profile := range profiles { - keys, err := clearCredentialBundle(store, profile.Profile, clearDryRun) + clearSpan := logger.Start("config.clear", "clear_credentials", "active-profile") + for _, credentialProfile := range profiles { + keys, err := clearCredentialBundle(store, credentialProfile.Profile, clearDryRun) if err != nil { - return cmderr.Credential(err) + return cmderr.Credential(endProgressSpan(clearSpan, err)) } result.Cleared = append(result.Cleared, view.ClearedCredentialRef{ - Ref: profile.Full, + Ref: credentialProfile.Full, Keys: keys, }) } + clearSpan.End(nil) if clearAll { + configSpan := logger.Start("config.clear", "remove_profile_config", profileName) change, err := clearProfileFromConfig(path, cfg, profileName, clearDryRun) if err != nil { - return fmt.Errorf("config clear --all credentials already cleared for profile %q (%s), but config reset failed: %w", profileName, credentialRefList(profiles), err) + return endProgressSpan(configSpan, fmt.Errorf("config clear --all credentials already cleared for profile %q (%s), but config reset failed: %w", profileName, credentialRefList(profiles), err)) } + configSpan.End(nil) result.ConfigProfileRemoved = change.profileRemoved result.ConfigPathRemoved = change.configPathRemoved + cacheSpan := logger.Start("config.clear", "remove_cache", profileName) cache, err := clearCacheRoot(clearDryRun) result.Cache = &cache if err != nil { @@ -491,13 +510,14 @@ func Register(rootCmd *cobra.Command, opts *root.Options) { } if clearJSON { if renderErr := view.RenderConfigClearJSON(opts.Stdout, result); renderErr != nil { - return renderErr + return endProgressSpan(cacheSpan, renderErr) } } else if renderErr := view.RenderConfigClearText(opts.Stdout, result); renderErr != nil { - return renderErr + return endProgressSpan(cacheSpan, renderErr) } - return cacheErr + return endProgressSpan(cacheSpan, cacheErr) } + cacheSpan.End(nil) } if clearJSON { return view.RenderConfigClearJSON(opts.Stdout, result) @@ -513,6 +533,20 @@ func Register(rootCmd *cobra.Command, opts *root.Options) { rootCmd.AddCommand(configCmd) } +func newProgressLogger(opts *root.Options) *progress.Logger { + if opts == nil { + return progress.New(nil, true, nil) + } + return progress.New(opts.Stderr, opts.Quiet, nil) +} + +func endProgressSpan(span *progress.Span, err error) error { + if span != nil { + span.End(err) + } + return err +} + func newRetentionCommand(opts *root.Options) *cobra.Command { retentionCmd := &cobra.Command{ Use: "retention", diff --git a/internal/cmd/configcmd/configcmd_test.go b/internal/cmd/configcmd/configcmd_test.go index 9cabd2ae..66f1c95d 100644 --- a/internal/cmd/configcmd/configcmd_test.go +++ b/internal/cmd/configcmd/configcmd_test.go @@ -2509,6 +2509,33 @@ func TestConfigClearAllJSONIncludesCacheCleanupFailure(t *testing.T) { assertFileBackendMissing(t, "home", credentials.GitTokenKey) } +func TestConfigClearAllJSONKeepsStdoutCleanAndReportsProgressErrorOnStderr(t *testing.T) { + path := saveTestConfig(t, fileBackendConfig(t)) + _ = writeCacheSentinel(t) + seedFileBackend(t, "home", map[string]string{credentials.GitTokenKey: "home-token"}) + cmd, out, errOut := newTestCommandWithStderr(path, false) + oldRemove := removeCacheRoot + removeCacheRoot = func(string) error { + return fmt.Errorf("permission denied") + } + t.Cleanup(func() { removeCacheRoot = oldRemove }) + + err := root.Execute(cmd, []string{"--profile", "home", "config", "clear", "--all", "--json"}) + if err == nil { + t.Fatal("Execute error = nil, want cache cleanup failure") + } + var got view.ConfigClear + if err := json.Unmarshal(out.Bytes(), &got); err != nil { + t.Fatalf("Unmarshal JSON: %v\nstdout=%s\nstderr=%s", err, out.String(), errOut.String()) + } + if !strings.Contains(errOut.String(), `command="config.clear" op="remove_cache" target="home"`) { + t.Fatalf("stderr = %q, want remove_cache progress", errOut.String()) + } + if !strings.Contains(errOut.String(), `event=error`) { + t.Fatalf("stderr = %q, want error event", errOut.String()) + } +} + func TestConfigClearAllTextIncludesPartialResultOnCacheFailure(t *testing.T) { path := saveTestConfig(t, fileBackendConfig(t)) cacheFile := writeCacheSentinel(t) @@ -2599,22 +2626,38 @@ func newTestCommand(path string) (*cobra.Command, *bytes.Buffer) { return newTestCommandWithOptions(&root.Options{ ConfigPath: path, Stdin: strings.NewReader(""), + Quiet: true, }) } func newTestCommandWithOptions(opts *root.Options) (*cobra.Command, *bytes.Buffer) { var out bytes.Buffer + var errOut bytes.Buffer if opts == nil { opts = &root.Options{} } opts.Stdin = strings.NewReader("") opts.Stdout = &out - opts.Stderr = &out + opts.Stderr = &errOut cmd, opts := root.NewCommandWithOptions(opts) Register(cmd, opts) return cmd, &out } +func newTestCommandWithStderr(path string, quiet bool) (*cobra.Command, *bytes.Buffer, *bytes.Buffer) { + var out bytes.Buffer + var errOut bytes.Buffer + cmd, opts := root.NewCommandWithOptions(&root.Options{ + ConfigPath: path, + Stdin: strings.NewReader(""), + Stdout: &out, + Stderr: &errOut, + Quiet: quiet, + }) + Register(cmd, opts) + return cmd, &out, &errOut +} + const testFileCredentialStoreID = "test-file" func fileBackendConfig(t *testing.T) config.File { diff --git a/internal/cmd/datacmd/datacmd.go b/internal/cmd/datacmd/datacmd.go index 53b9382f..d118577a 100644 --- a/internal/cmd/datacmd/datacmd.go +++ b/internal/cmd/datacmd/datacmd.go @@ -13,6 +13,7 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/cmd/exitcode" "github.com/open-cli-collective/codereview-cli/internal/cmd/root" "github.com/open-cli-collective/codereview-cli/internal/datalifecycle" + "github.com/open-cli-collective/codereview-cli/internal/progress" "github.com/open-cli-collective/codereview-cli/internal/ledger" "github.com/open-cli-collective/codereview-cli/internal/statepaths" "github.com/open-cli-collective/codereview-cli/internal/view" @@ -48,7 +49,7 @@ func newShowCommand(opts *root.Options) *cobra.Command { return nil }, RunE: func(cmd *cobra.Command, _ []string) error { - layout, store, cleanup, err := openStore(cmd.Context(), false) + layout, store, cleanup, err := openStore(cmd.Context(), progress.New(nil, true, nil), "data.show", false) if err != nil { return err } @@ -81,6 +82,7 @@ func newPruneCommand(opts *root.Options) *cobra.Command { return nil }, RunE: func(cmd *cobra.Command, _ []string) error { + logger := newProgressLogger(opts) olderThanChanged := cmd.Flags().Changed("older-than") keepLastChanged := cmd.Flags().Changed("keep-last") if flags.olderThan > 0 && keepLastChanged { @@ -97,12 +99,16 @@ func newPruneCommand(opts *root.Options) *cobra.Command { keepLast = &flags.keepLast } - layout, store, cleanup, err := openStore(cmd.Context(), !flags.dryRun) + layout, store, cleanup, err := openStore(cmd.Context(), logger, "data.prune", !flags.dryRun) if err != nil { return err } defer cleanup() - result, err := datalifecycle.Prune(cmd.Context(), datalifecycle.Options{Layout: layout, Store: store}, datalifecycle.PruneOptions{ + result, err := datalifecycle.Prune(cmd.Context(), datalifecycle.Options{ + Layout: layout, + Store: store, + Progress: lifecycleProgressReporter{logger: logger, command: "data.prune"}, + }, datalifecycle.PruneOptions{ OlderThan: flags.olderThan, KeepLast: keepLast, DryRun: flags.dryRun, @@ -111,14 +117,16 @@ func newPruneCommand(opts *root.Options) *cobra.Command { return err } if flags.dryRun { + legacySpan := logger.Start("data.prune", "check_legacy", "data-root") legacyExists, err := statepaths.LegacyDataRootExists(layout) if err != nil { - return err + return endProgressSpan(legacySpan, err) } if legacyExists { legacyRoot := statepaths.LegacyDataRoot(layout) result.Warnings = append(result.Warnings, fmt.Sprintf("legacy data exists at %s or %s.migrating; dry-run does not migrate it, so this preview excludes legacy runs until a write command migrates them", legacyRoot, legacyRoot)) } + legacySpan.End(nil) } rendered := view.NewDataPrune(result) if flags.jsonOutput { @@ -146,17 +154,22 @@ func newPurgeCommand(opts *root.Options) *cobra.Command { return nil }, RunE: func(_ *cobra.Command, _ []string) error { + logger := newProgressLogger(opts) if flags.yes && flags.dryRun { return exitcode.Usage(fmt.Errorf("--yes and --dry-run are mutually exclusive")) } + layoutSpan := logger.Start("data.purge", "resolve_layout", "data-root") layout, err := statepaths.DefaultLayout() if err != nil { - return err + return endProgressSpan(layoutSpan, err) } + layoutSpan.End(nil) + purgeSpan := logger.Start("data.purge", "purge_root", "data-root") result, err := datalifecycle.Purge(layout, flags.dryRun, flags.yes, nil) if err != nil { - return exitcode.Usage(err) + return exitcode.Usage(endProgressSpan(purgeSpan, err)) } + purgeSpan.End(nil) rendered := view.NewDataPurge(result) if flags.jsonOutput { return view.RenderDataPurgeJSON(opts.Stdout, rendered) @@ -174,28 +187,58 @@ func addJSONFlag(cmd *cobra.Command, flags *commandFlags) { cmd.Flags().BoolVar(&flags.jsonOutput, "json", false, "Emit JSON") } -func openStore(ctx context.Context, migrateLegacyData bool) (statepaths.Layout, datalifecycle.Store, func(), error) { +func openStore(ctx context.Context, logger *progress.Logger, command string, migrateLegacyData bool) (statepaths.Layout, datalifecycle.Store, func(), error) { + layoutSpan := logger.Start(command, "resolve_layout", "data-root") layout, err := statepaths.DefaultLayout() if err != nil { - return statepaths.Layout{}, nil, nil, err + return statepaths.Layout{}, nil, nil, endProgressSpan(layoutSpan, err) } + layoutSpan.End(nil) if migrateLegacyData { + migrateSpan := logger.Start(command, "migrate_legacy", "data-root") if err := statepaths.MigrateLegacyDataRoot(layout); err != nil { - return statepaths.Layout{}, nil, nil, err + return statepaths.Layout{}, nil, nil, endProgressSpan(migrateSpan, err) } + migrateSpan.End(nil) } + ledgerSpan := logger.Start(command, "open_ledger", "data-root") if _, err := os.Stat(layout.LedgerDB()); errors.Is(err, os.ErrNotExist) { + ledgerSpan.End(nil) return layout, emptyLifecycleStore{}, func() {}, nil } else if err != nil { - return statepaths.Layout{}, nil, nil, err + return statepaths.Layout{}, nil, nil, endProgressSpan(ledgerSpan, err) } store, err := ledger.Open(ctx, layout.LedgerDB()) if err != nil { - return statepaths.Layout{}, nil, nil, err + return statepaths.Layout{}, nil, nil, endProgressSpan(ledgerSpan, err) } + ledgerSpan.End(nil) return layout, store, func() { _ = store.Close() }, nil } +type lifecycleProgressReporter struct { + logger *progress.Logger + command string +} + +func (r lifecycleProgressReporter) Start(op, target string) datalifecycle.ProgressSpan { + return r.logger.Start(r.command, op, target) +} + +func newProgressLogger(opts *root.Options) *progress.Logger { + if opts == nil { + return progress.New(nil, true, nil) + } + return progress.New(opts.Stderr, opts.Quiet, nil) +} + +func endProgressSpan(span *progress.Span, err error) error { + if span != nil { + span.End(err) + } + return err +} + type emptyLifecycleStore struct{} func (emptyLifecycleStore) ListRuns(context.Context) ([]ledger.Run, error) { diff --git a/internal/cmd/datacmd/datacmd_test.go b/internal/cmd/datacmd/datacmd_test.go index 4f91cf70..d171300b 100644 --- a/internal/cmd/datacmd/datacmd_test.go +++ b/internal/cmd/datacmd/datacmd_test.go @@ -381,8 +381,32 @@ func TestDataPurgeRequiresConfirmation(t *testing.T) { } } +func TestDataPruneProgressWritesToStderr(t *testing.T) { + statedirtest.Hermetic(t) + seedRun(t, "old-live", ledger.PostModeLive, testNow().Add(-91*24*time.Hour)) + var stdout, stderr bytes.Buffer + + if err := runDataCommandWithQuiet(&stdout, &stderr, false, "data", "prune", "--dry-run", "--json"); err != nil { + t.Fatalf("runDataCommand: %v; stderr = %q", err, stderr.String()) + } + if !strings.Contains(stderr.String(), `command="data.prune" op="resolve_layout"`) { + t.Fatalf("stderr = %q, want resolve_layout progress", stderr.String()) + } + if !strings.Contains(stderr.String(), `command="data.prune" op="find_orphans"`) { + t.Fatalf("stderr = %q, want find_orphans progress", stderr.String()) + } + var decoded view.DataPrune + if err := json.Unmarshal(stdout.Bytes(), &decoded); err != nil { + t.Fatalf("Unmarshal: %v; stdout = %q", err, stdout.String()) + } +} + func runDataCommand(stdout, stderr *bytes.Buffer, args ...string) error { - cmd, opts := root.NewCommandWithOptions(&root.Options{Stdout: stdout, Stderr: stderr}) + return runDataCommandWithQuiet(stdout, stderr, true, args...) +} + +func runDataCommandWithQuiet(stdout, stderr *bytes.Buffer, quiet bool, args ...string) error { + cmd, opts := root.NewCommandWithOptions(&root.Options{Stdout: stdout, Stderr: stderr, Quiet: quiet}) Register(cmd, opts) return root.Execute(cmd, args) } diff --git a/internal/cmd/root/root.go b/internal/cmd/root/root.go index bf68456d..7b4ea2b0 100644 --- a/internal/cmd/root/root.go +++ b/internal/cmd/root/root.go @@ -21,6 +21,7 @@ type Options struct { Profile string Backend string ConfigPath string + Quiet bool Stdin io.Reader Stdout io.Writer Stderr io.Writer @@ -74,6 +75,7 @@ func NewCommandWithOptions(opts *Options) (*cobra.Command, *Options) { cmd.Flags().BoolVar(&showVersion, "version", false, "Print the build version") cmd.PersistentFlags().StringVar(&opts.Profile, profileFlagName, "", "Profile name") cmd.PersistentFlags().StringVar(&opts.Backend, credstore.BackendFlagName, "", credstore.BackendFlagUsage()) + cmd.PersistentFlags().BoolVar(&opts.Quiet, "quiet", opts.Quiet, "Suppress progress logs") cmd.AddCommand(newVersionCommand(opts)) return cmd, opts diff --git a/internal/cmd/root/root_test.go b/internal/cmd/root/root_test.go index bc0bcb56..2b262267 100644 --- a/internal/cmd/root/root_test.go +++ b/internal/cmd/root/root_test.go @@ -61,6 +61,22 @@ func TestPersistentProfileFlagPopulatesOptions(t *testing.T) { } } +func TestPersistentQuietFlagPopulatesOptions(t *testing.T) { + var out bytes.Buffer + cmd, opts := NewCommandWithOptions(&Options{ + Stdin: strings.NewReader(""), + Stdout: &out, + Stderr: &out, + }) + + if err := Execute(cmd, []string{"--quiet", "version"}); err != nil { + t.Fatalf("Execute: %v", err) + } + if !opts.Quiet { + t.Fatal("Quiet = false, want true") + } +} + func TestCompletionCommandIsNotExposed(t *testing.T) { cmd, _ := NewCommand() err := Execute(cmd, []string{"completion"}) diff --git a/internal/cmd/sessionscmd/sessionscmd.go b/internal/cmd/sessionscmd/sessionscmd.go index 6317d2fe..c0b630c3 100644 --- a/internal/cmd/sessionscmd/sessionscmd.go +++ b/internal/cmd/sessionscmd/sessionscmd.go @@ -13,6 +13,7 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/cmd/exitcode" "github.com/open-cli-collective/codereview-cli/internal/cmd/root" "github.com/open-cli-collective/codereview-cli/internal/ledger" + "github.com/open-cli-collective/codereview-cli/internal/progress" "github.com/open-cli-collective/codereview-cli/internal/statepaths" "github.com/open-cli-collective/codereview-cli/internal/view" ) @@ -43,7 +44,7 @@ func newListCommand(opts *root.Options) *cobra.Command { return nil }, RunE: func(cmd *cobra.Command, _ []string) error { - store, cleanup, err := openStore(cmd.Context(), false) + store, cleanup, err := openStore(cmd.Context(), nil, "sessions.list", false) if err != nil { return err } @@ -83,7 +84,7 @@ func newShowCommand(opts *root.Options) *cobra.Command { }, RunE: func(cmd *cobra.Command, args []string) error { name := strings.TrimSpace(args[0]) - store, cleanup, err := openStore(cmd.Context(), false) + store, cleanup, err := openStore(cmd.Context(), nil, "sessions.show", false) if err != nil { return err } @@ -122,7 +123,8 @@ func newDeleteCommand(opts *root.Options) *cobra.Command { }, RunE: func(cmd *cobra.Command, args []string) error { name := strings.TrimSpace(args[0]) - store, cleanup, err := openStore(cmd.Context(), true) + logger := newProgressLogger(opts) + store, cleanup, err := openStore(cmd.Context(), logger, "sessions.delete", true) if err != nil { return err } @@ -130,11 +132,15 @@ func newDeleteCommand(opts *root.Options) *cobra.Command { if store == nil { return exitcode.With(exitcode.Failure, fmt.Errorf("session %q not found", name)) } + deleteSpan := logger.Start("sessions.delete", "delete_session", "session") if err := store.DeleteNamedSession(cmd.Context(), name); errors.Is(err, ledger.ErrNotFound) { + deleteSpan.End(err) return exitcode.With(exitcode.Failure, fmt.Errorf("session %q not found", name)) } else if err != nil { + deleteSpan.End(err) return err } + deleteSpan.End(nil) result := view.NewSessionsDelete(name) if flags.jsonOutput { return view.RenderSessionsDeleteJSON(opts.Stdout, result) @@ -150,24 +156,48 @@ func addCommonFlags(cmd *cobra.Command, flags *commandFlags) { cmd.Flags().BoolVar(&flags.jsonOutput, "json", false, "Emit JSON") } -func openStore(ctx context.Context, migrateLegacyData bool) (*ledger.Store, func(), error) { +func openStore(ctx context.Context, logger *progress.Logger, command string, migrateLegacyData bool) (*ledger.Store, func(), error) { + if logger == nil { + logger = progress.New(nil, true, nil) + } + layoutSpan := logger.Start(command, "resolve_layout", "session") layout, err := statepaths.DefaultLayout() if err != nil { - return nil, nil, err + return nil, nil, endProgressSpan(layoutSpan, err) } + layoutSpan.End(nil) if migrateLegacyData { + migrateSpan := logger.Start(command, "migrate_legacy", "session") if err := statepaths.MigrateLegacyDataRoot(layout); err != nil { - return nil, nil, err + return nil, nil, endProgressSpan(migrateSpan, err) } + migrateSpan.End(nil) } + ledgerSpan := logger.Start(command, "open_ledger", "session") if _, err := os.Stat(layout.LedgerDB()); errors.Is(err, os.ErrNotExist) { + ledgerSpan.End(nil) return nil, func() {}, nil } else if err != nil { - return nil, nil, err + return nil, nil, endProgressSpan(ledgerSpan, err) } store, err := ledger.Open(ctx, layout.LedgerDB()) if err != nil { - return nil, nil, err + return nil, nil, endProgressSpan(ledgerSpan, err) } + ledgerSpan.End(nil) return store, func() { _ = store.Close() }, nil } + +func newProgressLogger(opts *root.Options) *progress.Logger { + if opts == nil { + return progress.New(nil, true, nil) + } + return progress.New(opts.Stderr, opts.Quiet, nil) +} + +func endProgressSpan(span *progress.Span, err error) error { + if span != nil { + span.End(err) + } + return err +} diff --git a/internal/cmd/sessionscmd/sessionscmd_test.go b/internal/cmd/sessionscmd/sessionscmd_test.go index 9959f24d..1e4ddfdb 100644 --- a/internal/cmd/sessionscmd/sessionscmd_test.go +++ b/internal/cmd/sessionscmd/sessionscmd_test.go @@ -248,15 +248,40 @@ func TestSessionsDeleteMissingDoesNotCreateLedger(t *testing.T) { assertSessionStateAbsent(t, layout) } +func TestSessionsDeleteProgressWritesToStderr(t *testing.T) { + statedirtest.Hermetic(t) + insertNamedSession(t, namedSession("daily", "provider-session-2")) + cmd, stdout, stderr := newTestCommandWithOptions(&root.Options{Quiet: false}) + + if err := root.Execute(cmd, []string{"sessions", "delete", "daily", "--json"}); err != nil { + t.Fatalf("Execute: %v", err) + } + if !strings.Contains(stderr.String(), `command="sessions.delete" op="delete_session" target="session"`) { + t.Fatalf("stderr = %q, want delete progress", stderr.String()) + } + var decoded view.SessionsDelete + if err := json.Unmarshal(stdout.Bytes(), &decoded); err != nil { + t.Fatalf("Unmarshal: %v\n%s", err, stdout.String()) + } +} + func newTestCommand() (*cobra.Command, *bytes.Buffer) { + cmd, out, _ := newTestCommandWithOptions(&root.Options{Quiet: true}) + return cmd, out +} + +func newTestCommandWithOptions(opts *root.Options) (*cobra.Command, *bytes.Buffer, *bytes.Buffer) { var out bytes.Buffer - cmd, opts := root.NewCommandWithOptions(&root.Options{ - Stdin: strings.NewReader(""), - Stdout: &out, - Stderr: &out, - }) - Register(cmd, opts) - return cmd, &out + var errOut bytes.Buffer + if opts == nil { + opts = &root.Options{} + } + opts.Stdin = strings.NewReader("") + opts.Stdout = &out + opts.Stderr = &errOut + cmd, rootOpts := root.NewCommandWithOptions(opts) + Register(cmd, rootOpts) + return cmd, &out, &errOut } func insertNamedSession(t *testing.T, session ledger.NamedSession) { diff --git a/internal/datalifecycle/datalifecycle.go b/internal/datalifecycle/datalifecycle.go index fb10e6b7..c61f05fa 100644 --- a/internal/datalifecycle/datalifecycle.go +++ b/internal/datalifecycle/datalifecycle.go @@ -32,12 +32,24 @@ type Store interface { // RemoveAllFunc removes a path recursively. type RemoveAllFunc func(string) error +// ProgressReporter records lifecycle sub-steps without depending on a specific +// CLI surface. +type ProgressReporter interface { + Start(op, target string) ProgressSpan +} + +// ProgressSpan completes one lifecycle progress event. +type ProgressSpan interface { + End(error) +} + // Options contains lifecycle operation dependencies. type Options struct { Layout statepaths.Layout Store Store Now func() time.Time RemoveAll RemoveAllFunc + Progress ProgressReporter } // PruneOptions selects runs to prune. @@ -161,23 +173,33 @@ func Prune(ctx context.Context, opts Options, prune PruneOptions) (PruneResult, if err := validatePruneOptions(prune); err != nil { return PruneResult{}, err } + listSpan := startProgress(opts.Progress, "list_runs", "data-root") runs, err := opts.Store.ListRuns(ctx) if err != nil { + listSpan.End(err) return PruneResult{}, err } + listSpan.End(nil) + selectSpan := startProgress(opts.Progress, "select_runs", "data-root") selected := selectRuns(runs, prune, opts.now()) + selectSpan.End(nil) result := PruneResult{DryRun: prune.DryRun, SelectedRuns: runItems(selected)} if prune.DryRun { + orphanSpan := startProgress(opts.Progress, "find_orphans", "data-root") orphanItems, err := findOrphans(opts.Layout, runs) if err != nil { + orphanSpan.End(err) return result, err } + orphanSpan.End(nil) result.OrphansRemoved = orphanItems return result, nil } + deleteSpan := startProgress(opts.Progress, "delete_runs", "data-root") for _, run := range selected { if err := opts.Store.DeleteRun(ctx, run.RunID); err != nil { + deleteSpan.End(err) return result, err } item := runItem(run) @@ -190,13 +212,19 @@ func Prune(ctx context.Context, opts Options, prune PruneOptions) (PruneResult, result.Warnings = append(result.Warnings, fmt.Sprintf("failed to remove artifacts for run %s at %s: %v", run.RunID, run.ArtifactPath, err)) } } + deleteSpan.End(nil) + remainingSpan := startProgress(opts.Progress, "reload_runs", "data-root") remaining, err := opts.Store.ListRuns(ctx) if err != nil { + remainingSpan.End(err) return result, err } + remainingSpan.End(nil) + orphanSpan := startProgress(opts.Progress, "remove_orphans", "data-root") orphans, err := findOrphans(opts.Layout, remaining) if err != nil { + orphanSpan.End(err) return result, err } for _, orphan := range orphans { @@ -206,6 +234,7 @@ func Prune(ctx context.Context, opts Options, prune PruneOptions) (PruneResult, } result.OrphansRemoved = append(result.OrphansRemoved, orphan) } + orphanSpan.End(nil) _ = removeEmptyParents(runsRoot(opts.Layout)) return result, nil } @@ -326,6 +355,21 @@ func (p RetentionPolicy) retentionFor(mode ledger.PostMode) (time.Duration, bool return p.LiveMaxAge, false } +type noopProgressSpan struct{} + +func (noopProgressSpan) End(error) {} + +func startProgress(reporter ProgressReporter, op, target string) ProgressSpan { + if reporter == nil { + return noopProgressSpan{} + } + span := reporter.Start(op, target) + if span == nil { + return noopProgressSpan{} + } + return span +} + func findOrphans(layout statepaths.Layout, runs []ledger.Run) ([]OrphanItem, error) { return orphanItems(layout, runs) } diff --git a/internal/progress/progress.go b/internal/progress/progress.go new file mode 100644 index 00000000..761e417e --- /dev/null +++ b/internal/progress/progress.go @@ -0,0 +1,187 @@ +// Package progress writes structured progress breadcrumbs to stderr for long-running CLI work. +package progress + +import ( + "io" + "strconv" + "strings" + "sync" + "time" +) + +// Clock returns the current time. +type Clock func() time.Time + +// Logger writes structured progress lines. +type Logger struct { + w io.Writer + disabled bool + now Clock + mu sync.Mutex +} + +// Span represents one started progress operation. +type Span struct { + logger *Logger + command string + op string + target string + started time.Time + done bool +} + +// New returns a logger that writes progress to w unless disabled is true. +func New(w io.Writer, disabled bool, now Clock) *Logger { + if now == nil { + now = time.Now + } + return &Logger{w: w, disabled: disabled, now: now} +} + +// Start writes a start line and returns a span that can be ended exactly once. +func (l *Logger) Start(command, op, target string) *Span { + span := &Span{ + logger: l, + command: command, + op: op, + target: target, + started: l.now(), + } + l.writeLine(progressLine{ + event: "start", + command: command, + op: op, + target: target, + }) + return span +} + +// End writes a finish or error line. It is a no-op for disabled loggers or a +// span that has already ended. +func (s *Span) End(err error) { + if s == nil || s.logger == nil || s.done || s.logger.disabled { + return + } + s.done = true + dur := durationMS(s.logger.now().Sub(s.started)) + line := progressLine{ + command: s.command, + op: s.op, + target: s.target, + durationMS: dur, + } + if err != nil { + line.event = "error" + line.status = "error" + line.errSummary = sanitizeErrorSummary(err.Error()) + } else { + line.event = "finish" + line.status = "ok" + } + s.logger.writeLine(line) +} + +type progressLine struct { + event string + command string + op string + target string + durationMS int64 + status string + errSummary string +} + +func (l *Logger) writeLine(line progressLine) { + if l == nil || l.disabled || l.w == nil { + return + } + var b strings.Builder + b.WriteString("cr progress") + if line.event != "" { + b.WriteString(" event=") + b.WriteString(line.event) + } + if line.command != "" { + b.WriteString(" command=") + b.WriteString(quoteValue(line.command)) + } + if line.op != "" { + b.WriteString(" op=") + b.WriteString(quoteValue(line.op)) + } + if line.target != "" { + b.WriteString(" target=") + b.WriteString(quoteValue(line.target)) + } + if line.durationMS > 0 || line.event == "finish" || line.event == "error" { + b.WriteString(" duration_ms=") + b.WriteString(strconv.FormatInt(line.durationMS, 10)) + } + if line.status != "" { + b.WriteString(" status=") + b.WriteString(line.status) + } + if line.errSummary != "" { + b.WriteString(" error=") + b.WriteString(quoteValue(line.errSummary)) + } + b.WriteByte('\n') + + l.mu.Lock() + defer l.mu.Unlock() + _, _ = io.WriteString(l.w, b.String()) +} + +func quoteValue(value string) string { + var b strings.Builder + b.Grow(len(value) + 2) + b.WriteByte('"') + for _, r := range value { + switch r { + case '\\', '"', '=': + b.WriteByte('\\') + b.WriteRune(r) + case '\n': + b.WriteString(`\n`) + case '\r': + b.WriteString(`\r`) + case '\t': + b.WriteString(`\t`) + default: + b.WriteRune(r) + } + } + b.WriteByte('"') + return b.String() +} + +func sanitizeErrorSummary(err string) string { + err = strings.ReplaceAll(err, "\r", " ") + err = strings.ReplaceAll(err, "\n", " ") + err = strings.TrimSpace(err) + if err == "" { + return "error" + } + err = redactPathLikeSegments(err) + if len(err) > 160 { + err = err[:157] + "..." + } + return err +} + +func redactPathLikeSegments(s string) string { + parts := strings.Fields(s) + for i, part := range parts { + if strings.Contains(part, "/") || strings.Contains(part, `\`) { + parts[i] = "[path]" + } + } + return strings.Join(parts, " ") +} + +func durationMS(d time.Duration) int64 { + if d <= 0 { + return 0 + } + return d.Milliseconds() +} diff --git a/internal/progress/progress_test.go b/internal/progress/progress_test.go new file mode 100644 index 00000000..2a76e03e --- /dev/null +++ b/internal/progress/progress_test.go @@ -0,0 +1,101 @@ +package progress + +import ( + "bytes" + "errors" + "strings" + "testing" + "time" +) + +func TestLoggerStartAndEndFormatsLines(t *testing.T) { + var out bytes.Buffer + clock := &fixedClock{ + times: []time.Time{ + time.Unix(10, 0), + time.Unix(10, 25*int64(time.Millisecond)), + }, + } + logger := New(&out, false, clock.Now) + + span := logger.Start("benchmark.run", "run_suite", "suite=one") + span.End(nil) + + got := out.String() + if !strings.Contains(got, `cr progress event=start command="benchmark.run" op="run_suite" target="suite\=one"`) { + t.Fatalf("start line = %q", got) + } + if !strings.Contains(got, `cr progress event=finish command="benchmark.run" op="run_suite" target="suite\=one" duration_ms=25 status=ok`) { + t.Fatalf("finish line = %q", got) + } +} + +func TestLoggerEndErrorSanitizesSummary(t *testing.T) { + var out bytes.Buffer + clock := &fixedClock{ + times: []time.Time{ + time.Unix(20, 0), + time.Unix(20, 50*int64(time.Millisecond)), + }, + } + logger := New(&out, false, clock.Now) + + span := logger.Start("config.clear", "cache_cleanup", "session") + span.End(errors.New("failed to remove /tmp/private/file\ntry again")) + + got := out.String() + if !strings.Contains(got, `event=error`) || !strings.Contains(got, `status=error`) { + t.Fatalf("error line = %q", got) + } + if strings.Contains(got, "/tmp/private/file") { + t.Fatalf("error line leaked path: %q", got) + } + if !strings.Contains(got, `error="failed to remove [path] try again"`) { + t.Fatalf("error summary = %q", got) + } +} + +func TestDisabledLoggerWritesNothing(t *testing.T) { + var out bytes.Buffer + logger := New(&out, true, time.Now) + + span := logger.Start("sessions.delete", "delete", "session") + span.End(nil) + + if out.Len() != 0 { + t.Fatalf("output = %q, want empty", out.String()) + } +} + +func TestEndOnlyWritesOnce(t *testing.T) { + var out bytes.Buffer + clock := &fixedClock{ + times: []time.Time{ + time.Unix(30, 0), + time.Unix(30, 10*int64(time.Millisecond)), + time.Unix(30, 20*int64(time.Millisecond)), + }, + } + logger := New(&out, false, clock.Now) + + span := logger.Start("data.prune", "prune", "data-root") + span.End(nil) + span.End(nil) + + if got := strings.Count(out.String(), "event=finish"); got != 1 { + t.Fatalf("finish count = %d, want 1; output = %q", got, out.String()) + } +} + +type fixedClock struct { + times []time.Time +} + +func (c *fixedClock) Now() time.Time { + if len(c.times) == 0 { + return time.Unix(0, 0) + } + t := c.times[0] + c.times = c.times[1:] + return t +}