From f3e9326544c6088088668b57b79fccc39945123d Mon Sep 17 00:00:00 2001 From: Eric Rakestraw Date: Mon, 26 Oct 2026 03:03:57 +0000 Subject: [PATCH] Add debug events to command execution --- debug_events_test.go | 118 ++++++++++++++++++++++++++++++ docs/roadmap/implementation.md | 11 ++- execute.go | 127 +++++++++++++++++++++++++++++---- 3 files changed, 241 insertions(+), 15 deletions(-) create mode 100644 debug_events_test.go diff --git a/debug_events_test.go b/debug_events_test.go new file mode 100644 index 0000000..c736de3 --- /dev/null +++ b/debug_events_test.go @@ -0,0 +1,118 @@ +package commandkit + +import ( + "bytes" + "context" + "errors" + "strings" + "testing" +) + +func TestDebugEventsFollowModeAndFinalizationOrder(t *testing.T) { + cause := errors.New("private operation cause") + command := NewCommand(CommandSpec[struct{}]{ + Name: "run", + Run: func(inv Invocation, _ struct{}) Outcome { + if err := inv.Reporter().AtEnd().Info("deferred summary"); err != nil { + t.Errorf("queue summary: %v", err) + } + return Failure("operation failed").WithCause(cause) + }, + }) + app, err := New(Identity{Name: "Example"}, command, Alias("shortcut", "run"), FlagAlias("--trace", "--debug")) + if err != nil { + t.Fatal(err) + } + var diagnostics bytes.Buffer + outcome := app.Execute(context.Background(), []string{"shortcut", "--verbose", "--trace"}, Streams{Err: &diagnostics}) + if outcome.Kind != OutcomeOperational || !errors.Is(outcome.Cause, cause) { + t.Fatalf("outcome = %#v", outcome) + } + got := diagnostics.String() + for _, fragment := range []string{ + "resolved command alias \"shortcut\" to \"run\"", + "selected debug reporting mode using --trace (alias for --debug)", + "INFO: deferred summary", + "handler completed for \"run\" with operational outcome and status 1", + "ERROR: operation failed", + } { + if !strings.Contains(got, fragment) { + t.Errorf("diagnostics %q omit %q", got, fragment) + } + } + if strings.Contains(got, cause.Error()) { + t.Fatalf("diagnostics exposed the operation cause: %q", got) + } + ordered := []string{ + "resolved command alias", + "selected debug reporting mode", + "INFO: deferred summary", + "handler completed", + "ERROR: operation failed", + } + previous := -1 + for _, fragment := range ordered { + index := strings.Index(got, fragment) + if index <= previous { + t.Fatalf("diagnostic event %q out of order in %q", fragment, got) + } + previous = index + } +} + +func TestDebugEventsRespectFinalQuietSelection(t *testing.T) { + command := NewCommand(CommandSpec[struct{}]{ + Name: "run", + Run: func(Invocation, struct{}) Outcome { return Success() }, + }) + app, err := New(Identity{Name: "Example"}, command) + if err != nil { + t.Fatal(err) + } + var diagnostics bytes.Buffer + outcome := app.Execute(context.Background(), []string{"run", "--debug", "--quiet"}, Streams{Err: &diagnostics}) + if outcome.Kind != OutcomeSuccess || diagnostics.Len() != 0 { + t.Fatalf("outcome = %#v, diagnostics = %q", outcome, diagnostics.String()) + } +} + +func TestDebugCompletionRequiresAHandler(t *testing.T) { + command := NewCommand(CommandSpec[struct{}]{ + Name: "run", + Run: func(Invocation, struct{}) Outcome { return Success() }, + }) + app, err := New(Identity{Name: "Example"}, command) + if err != nil { + t.Fatal(err) + } + var diagnostics bytes.Buffer + app.Execute(context.Background(), []string{"unknown", "--debug"}, Streams{Err: &diagnostics}) + if strings.Contains(diagnostics.String(), "handler completed") { + t.Fatalf("no-handler diagnostics include completion: %q", diagnostics.String()) + } +} + +func TestDebugDeliveryFailureAffectsInvocationOutcome(t *testing.T) { + ran := false + command := NewCommand(CommandSpec[struct{}]{ + Name: "run", + Run: func(Invocation, struct{}) Outcome { + ran = true + return Success() + }, + }) + app, err := New(Identity{Name: "Example"}, command) + if err != nil { + t.Fatal(err) + } + writeErr := errors.New("debug destination failed") + outcome := app.Execute(context.Background(), []string{"run", "--debug"}, Streams{ + Err: executeReportingFailureWriter{err: writeErr}, + }) + if !ran { + t.Fatal("debug delivery failure prevented handler execution") + } + if outcome.Kind != OutcomeOperational || outcome.Status != 1 || !errors.Is(outcome.Presentation.Diagnostics.WriteError, writeErr) { + t.Fatalf("outcome = %#v", outcome) + } +} diff --git a/docs/roadmap/implementation.md b/docs/roadmap/implementation.md index 415fdb8..a0bfd41 100644 --- a/docs/roadmap/implementation.md +++ b/docs/roadmap/implementation.md @@ -1,6 +1,6 @@ # Invocation reporting implementation plan -Status: Stages 1–8 complete. Stage 9 is next. +Status: Stages 1–9 complete. Stage 10 is next. ## Objective and authority @@ -349,7 +349,7 @@ scheduled for the later suite reconciliation. ## Stage 9: Add core debug events -Status: pending. +Status: complete. 1. Instrument routing, command-alias resolution, verbosity selection, and handler completion. Explain the relevant entered/canonical paths and decisions. @@ -371,6 +371,13 @@ Validation: `--verbose --debug` reveals earlier selection events; explanation, absence of completion when no handler runs, and debug delivery failure. Assert selected meaning and order rather than incidental prose. +Routing, reporting-mode selection, and handler-completion events now use shared +Debug reporting. Early events are submitted after mode selection, and completion +is submitted after deferred messages. Focused tests cover alias identity, +selection order, quiet suppression, completion ordering, no-handler behavior, +cause privacy, and debug delivery failure. Internal suites pass; execution of +root tests remains deferred until the legacy external callers are reconciled. + ## Stage 10: Separate ConfigKit provider messages and explanations Status: pending. diff --git a/execute.go b/execute.go index b35baf9..6f588ab 100644 --- a/execute.go +++ b/execute.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" "io" + "strconv" "strings" internalcobra "gitea.maximumdirect.net/eric/CommandKit/internal/cobra" @@ -21,18 +22,22 @@ func (a *App) Execute(ctx context.Context, args []string, streams Streams) Outco current := newExecution(a, ctx, streams) if a == nil { err := errors.New("cannot execute commands on a nil app") - return current.finalize(Failure(err.Error()).WithCause(err), nil) + return current.finalize(Failure(err.Error()).WithCause(err), nil, false) } if ctx == nil { err := errors.New("invocation context must not be nil") - return current.finalize(Failure(err.Error()).WithCause(err), nil) + return current.finalize(Failure(err.Error()).WithCause(err), nil, false) } routedSnapshot := current.snapshot current.route = resolveEnteredRoute(args, routedSnapshot) + current.recordRouteEvents() parsed := current.parse(current.route.args) current.reporter.applySelection(parsed.Reporting) + current.recordSelectionEvents(parsed) + current.submitDebugEvents() var outcome Outcome path := parsed.Path + handlerRan := false if parsed.Failure != nil { outcome = Usage(parsed.Failure.Message) } else if current.route.kind == routeDiscovery { @@ -59,22 +64,24 @@ func (a *App) Execute(ctx context.Context, args []string, streams Streams) Outco if err != nil { outcome = classifyInputError(err) } else { + handlerRan = true outcome = run(current) } } } - return current.finalize(outcome, path) + return current.finalize(outcome, path, handlerRan) } type execution struct { - app *App - ctx context.Context - streams Streams - reporter *Reporter - options commandmeta.ParseOptions - snapshot *routingSnapshot - session *internalcobra.Session - route routeResult + app *App + ctx context.Context + streams Streams + reporter *Reporter + debugEvents []string + options commandmeta.ParseOptions + snapshot *routingSnapshot + session *internalcobra.Session + route routeResult } type commandExecution struct { @@ -220,7 +227,90 @@ func (current *execution) routeUsageLine() string { return line + "\nAlias for: " + canonical } -func (current *execution) finalize(outcome Outcome, path []string) Outcome { +func (current *execution) recordRouteEvents() { + entered := current.route.enteredPath.String() + canonical := current.route.canonicalPath.String() + switch current.route.kind { + case routeCanonical: + if entered == canonical { + if canonical == "" { + current.debugEvents = append(current.debugEvents, "selected the application root command") + } else { + current.debugEvents = append(current.debugEvents, fmt.Sprintf("selected command path %q", canonical)) + } + } else { + current.debugEvents = append(current.debugEvents, fmt.Sprintf("resolved command alias %q to %q", entered, canonical)) + } + case routeDiscovery: + current.debugEvents = append(current.debugEvents, fmt.Sprintf("selected discovery route for prefix %q", entered)) + default: + if entered != "" { + current.debugEvents = append(current.debugEvents, fmt.Sprintf("no canonical route matched command path %q", entered)) + } + } +} + +func (current *execution) recordSelectionEvents(result commandmeta.Result) { + mode := "ordinary" + flagName := "" + switch result.Reporting.Mode { + case commandmeta.ReportingModeQuiet: + mode, flagName = "quiet", "quiet" + case commandmeta.ReportingModeVerbose: + mode, flagName = "verbose", "verbose" + case commandmeta.ReportingModeDebug: + mode, flagName = "debug", "debug" + } + event := "selected ordinary reporting mode" + if flagName != "" { + event = fmt.Sprintf("selected %s reporting mode", mode) + for index := len(result.FlagOccurrences) - 1; index >= 0; index-- { + occurrence := result.FlagOccurrences[index] + if occurrence.Name != flagName { + continue + } + enabled, err := strconv.ParseBool(occurrence.RawValue) + if err != nil || !enabled { + continue + } + canonical := "--" + flagName + if occurrence.Spelling != canonical { + event += fmt.Sprintf(" using %s (alias for %s)", occurrence.Spelling, canonical) + } else { + event += fmt.Sprintf(" using %s", canonical) + } + break + } + } + current.debugEvents = append(current.debugEvents, event) + if result.Reporting.ProgressSet { + state := "disabled" + if result.Reporting.Progress { + state = "enabled" + } + event := "explicitly " + state + " progress output" + for index := len(result.FlagOccurrences) - 1; index >= 0; index-- { + occurrence := result.FlagOccurrences[index] + if occurrence.Name == "progress" { + if occurrence.Spelling != "--progress" { + event += fmt.Sprintf(" using %s (alias for --progress)", occurrence.Spelling) + } + break + } + } + current.debugEvents = append(current.debugEvents, event) + } +} + +func (current *execution) submitDebugEvents() { + events := current.debugEvents + current.debugEvents = nil + for _, event := range events { + _ = current.reporter.Debug(event) + } +} + +func (current *execution) finalize(outcome Outcome, path []string, handlerRan bool) Outcome { if outcome.Kind == OutcomeUsage { details := append([]Detail(nil), outcome.Explanation.Details...) details = append(details, func(w io.Writer) error { @@ -233,7 +323,18 @@ func (current *execution) finalize(outcome Outcome, path []string) Outcome { }) outcome.Explanation.Details = details } - return current.reporter.finalize(outcome, nil) + var completion func(*Reporter) + if handlerRan { + completion = func(reporter *Reporter) { + kind := outcome.Kind + if kind == "" && outcome.Status == 0 && outcome.Domain == "" { + kind = OutcomeSuccess + } + path := current.route.canonicalPath.String() + _ = reporter.Debug(fmt.Sprintf("handler completed for %q with %s outcome and status %d", path, kind, outcome.Status)) + } + } + return current.reporter.finalize(outcome, completion) } func (current *execution) usageText(path []string) string {