Add debug events to command execution

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)
+	}
+}

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.

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
+	app         *App
-	ctx      context.Context
+	ctx         context.Context
-	streams  Streams
+	streams     Streams
-	reporter *Reporter
+	reporter    *Reporter
-	options  commandmeta.ParseOptions
+	debugEvents []string
-	snapshot *routingSnapshot
+	options     commandmeta.ParseOptions
-	session  *internalcobra.Session
+	snapshot    *routingSnapshot
-	route    routeResult
+	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 {