perf(exec): add correlated diagnostics and reuse grants

internal/agent/auth_hook.go

@@ -429,8 +429,9 @@ func ensureProtocolCredential(
 	}
 	if credential.AccessToken == "" || credential.ExpiresAt == nil ||
 		!time.Now().Add(5*time.Second).Before(*credential.ExpiresAt) ||
-		!sameStringSet(credential.Scopes, requiredScopes) {
-		updated, err := requestProtocolToken(ctx, client, state, *credential, configuration, requiredScopes)
+		!scopesContain(credential.Scopes, requiredScopes) {
+		requestedScopes := retainedBootstrapScopes(credential.Scopes, requiredScopes, configuration.AgentBootstrapScopes)
+		updated, err := requestProtocolToken(ctx, client, state, *credential, configuration, requestedScopes)
 		if err != nil {
 			return state, dpopCredential{}, err
 		}
@@ -443,6 +444,20 @@ func ensureProtocolCredential(
 	return state, *credential, nil
 }
 
+func retainedBootstrapScopes(current, required, supported []string) []string {
+	allowed := make(map[string]bool, len(supported))
+	for _, scope := range supported {
+		allowed[scope] = true
+	}
+	result := append([]string(nil), required...)
+	for _, scope := range current {
+		if allowed[scope] && !contains(result, scope) {
+			result = append(result, scope)
+		}
+	}
+	return result
+}
+
 func requestProtocolToken(
 	ctx context.Context,
 	client httpDoer,

internal/agent/credential_source.go

@@ -290,8 +290,9 @@ func ensureInternalProtocolCredential(
 	if credential.AccessToken == "" || credential.ExpiresAt == nil ||
 		!time.Now().Add(5*time.Second).Before(*credential.ExpiresAt) ||
 		!scopesContain(credential.Scopes, requiredScopes) {
+		requestedScopes := retainedBootstrapScopes(credential.Scopes, requiredScopes, configuration.AgentBootstrapScopes)
 		updated, err := requestProtocolToken(
-			ctx, client, reference.state, *credential, configuration, requiredScopes,
+			ctx, client, reference.state, *credential, configuration, requestedScopes,
 		)
 		if err != nil {
 			return dpopCredential{}, err

internal/agent/credential_source_test.go

@@ -90,6 +90,71 @@ func TestCredentialSourceIssuesAgentBootstrapCredentialWithRestishProof(t *testi
 	}
 }
 
+func TestInternalProtocolCredentialRetainsPreviouslyIssuedBootstrapScopes(t *testing.T) {
+	// [spec: cli/cli-diagnostics]
+	offer := testCredential(t, "", time.Time{})
+	states := newCredentialState(t, offer)
+	expiresAt := time.Now().Add(time.Minute)
+	privateKey, err := newDPoPPrivateKey()
+	if err != nil {
+		t.Fatal(err)
+	}
+	states.state.ProtocolCredential = &dpopCredential{
+		ResourceIndicator:  "https://auth.example.com/api",
+		CredentialEndpoint: "https://auth.example.com/api/auth/oauth2/token",
+		ProofTarget:        "https://auth.example.com/api/auth/oauth2/token",
+		PrivateKey:         privateKey, AccessToken: "resource-token", ExpiresAt: &expiresAt,
+		Scopes: []string{"resource-servers:read"},
+	}
+	tokenRequests := 0
+	client := roundTripFunc(func(request *http.Request) (*http.Response, error) {
+		tokenRequests++
+		encoded, err := io.ReadAll(request.Body)
+		if err != nil {
+			t.Fatal(err)
+		}
+		body, err := url.ParseQuery(string(encoded))
+		if err != nil {
+			t.Fatal(err)
+		}
+		if !sameStringSet(strings.Fields(body.Get("scope")), []string{"authorization-details:read", "resource-servers:read"}) {
+			t.Fatalf("scope = %q", body.Get("scope"))
+		}
+		return jsonResponse(http.StatusOK, map[string]any{
+			"access_token": "combined-token", "token_type": "DPoP", "expires_in": 300,
+		}), nil
+	})
+	configuration := agentConfiguration{
+		AgentTokenEndpoint: "https://auth.example.com/api/auth/oauth2/token",
+		AgentBootstrapScopes: []string{
+			"resource-servers:read", "authorization-details:read", "access-requests:read", "access-requests:write",
+		},
+	}
+
+	reference := credentialSourceStateReference{
+		path: "memory", state: states.state, reference: testCredentialSourceReference,
+		source: states.state.CredentialSources[testCredentialSourceReference],
+	}
+	credential, err := ensureInternalProtocolCredential(
+		context.Background(), client, states, reference, configuration, []string{"authorization-details:read"},
+	)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if !sameStringSet(credential.Scopes, []string{"authorization-details:read", "resource-servers:read"}) {
+		t.Fatalf("credential scopes = %v", credential.Scopes)
+	}
+	reference.state = states.state
+	if _, err := ensureInternalProtocolCredential(
+		context.Background(), client, states, reference, configuration, []string{"resource-servers:read"},
+	); err != nil {
+		t.Fatal(err)
+	}
+	if tokenRequests != 1 {
+		t.Fatalf("token requests = %d, want 1", tokenRequests)
+	}
+}
+
 func TestCredentialSourceDescribesStoredOfferWithoutCredentialMaterial(t *testing.T) {
 	offer := testCredential(t, "", time.Time{})
 	states := newCredentialState(t, offer)

internal/agent/service.go

@@ -391,6 +391,11 @@ func (s *Service) ExecutionBinding(resourceIndicator string, details []map[strin
 		if source.reference != active.Reference {
 			continue
 		}
+		if len(active.Scopes) > 0 {
+			if offer, ok := leastPrivilegeOffer(source.source.Offers, [][]string{active.Scopes}); ok {
+				return CredentialBinding{Reference: source.reference, Scopes: normalizedBindingScopes(offer.Scopes)}, nil
+			}
+		}
 		binding, ok := leastPrivilegeSourceBinding(source)
 		if !ok {
 			return CredentialBinding{}, os.ErrNotExist
@@ -488,10 +493,19 @@ func (s *Service) BindingForAuthorizationContextEffectiveScopes(resourceIndicato
 	for _, scope := range allowed {
 		allowedSet[scope] = true
 	}
+	active, activeErr := s.activeBinding(resourceIndicator)
+	if activeErr != nil && !errors.Is(activeErr, os.ErrNotExist) {
+		return CredentialBinding{}, activeErr
+	}
 	for _, source := range sources {
 		if !sameAuthorizationDetails(source.source.AuthorizationDetails, details) {
 			continue
 		}
+		if source.reference == active.Reference && len(active.Scopes) > 0 && allScopesAllowed(active.Scopes, allowedSet) {
+			if offer, ok := leastPrivilegeOffer(source.source.Offers, [][]string{active.Scopes}); ok {
+				return CredentialBinding{Reference: source.reference, Scopes: normalizedBindingScopes(offer.Scopes)}, nil
+			}
+		}
 		var selected []string
 		for _, offer := range source.source.Offers {
 			candidate := normalizedBindingScopes(offer.Scopes)
@@ -550,7 +564,11 @@ func (s *Service) BindingForReferenceScopeAlternatives(resourceIndicator, refere
 		if !ok {
 			return CredentialBinding{}, os.ErrNotExist
 		}
-		return CredentialBinding{Reference: reference, Scopes: normalizedBindingScopes(offer.Scopes)}, nil
+		binding := CredentialBinding{Reference: reference, Scopes: normalizedBindingScopes(offer.Scopes)}
+		if err := s.storeActiveBinding(resourceIndicator, binding); err != nil {
+			return CredentialBinding{}, err
+		}
+		return binding, nil
 	}
 	return CredentialBinding{}, os.ErrNotExist
 }

internal/agent/service_test.go

@@ -213,6 +213,17 @@ func TestExecutionBindingStartsWithOneApprovedAuthoritySet(t *testing.T) {
 	if len(readBinding.Scopes) != 1 || readBinding.Scopes[0] != "metadata:read" {
 		t.Fatalf("challenged execution binding = %#v", readBinding)
 	}
+	learnedBinding, err := service.BindingForAuthorizationContextEffectiveScopes(
+		resource,
+		details,
+		[]string{"contents:write", "metadata:read"},
+	)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(learnedBinding.Scopes) != 1 || learnedBinding.Scopes[0] != "metadata:read" {
+		t.Fatalf("learned execution binding = %#v", learnedBinding)
+	}
 }
 
 func TestEffectiveContextBindingSkipsOffersWithRevokedScopes(t *testing.T) {

internal/cli/cli.go

@@ -19,6 +19,7 @@ import (
 	"github.com/realmroot/toolbox/internal/buildinfo"
 	"github.com/realmroot/toolbox/internal/catalog"
 	"github.com/realmroot/toolbox/internal/execution"
+	"github.com/realmroot/toolbox/internal/observability"
 	restish "github.com/saltbo/restish/v2"
 	"github.com/spf13/cobra"
 )
@@ -33,6 +34,7 @@ type App struct {
 	scope     string
 	all       bool
 	context   string
+	logLevel  string
 }
 
 func New(stdout, stderr io.Writer) *cobra.Command {
@@ -45,8 +47,13 @@ func New(stdout, stderr io.Writer) *cobra.Command {
 	}
 	root.SetOut(stdout)
 	root.SetErr(stderr)
+	root.PersistentPreRunE = func(_ *cobra.Command, _ []string) error {
+		_, err := observability.ParseLevel(app.logLevel)
+		return err
+	}
 	root.PersistentFlags().StringVar(&app.origin, "realmroot-origin", environment("REALMROOT_ORIGIN", agent.DefaultOrigin), "Realmroot deployment origin")
 	root.PersistentFlags().BoolVar(&app.json, "json", false, "print Toolbox and Agent results as JSON")
+	root.PersistentFlags().StringVar(&app.logLevel, "log-level", environment("REALMROOT_LOG_LEVEL", "warn"), "diagnostic log level: trace, debug, info, warn, or error")
 	root.AddCommand(app.agentCommand(), app.toolboxCommand(), app.execCommand(), app.versionCommand())
 	return root
 }
@@ -89,15 +96,26 @@ func (a *App) execCommand() *cobra.Command {
 		DisableFlagParsing: true,
 		Args:               cobra.ArbitraryArgs,
 		RunE: func(command *cobra.Command, args []string) error {
+			startedAt := time.Now()
 			args, options, err := a.parseExecFlags(args)
 			if err != nil {
 				return err
 			}
+			observabilityConfig, err := observability.New(a.stderr, a.logLevel)
+			if err != nil {
+				return err
+			}
+			logger := observabilityConfig.Logger.With("operation", "exec")
+			result := "ok"
+			defer func() {
+				logger.Info("command.complete", "result", result, "duration_ms", time.Since(startedAt).Milliseconds())
+			}()
 			if len(args) == 1 && (args[0] == "--help" || args[0] == "-h") {
 				return command.Help()
 			}
-			service, catalogClient, httpClient, err := a.services()
+			service, catalogClient, httpClient, err := a.services(observabilityConfig)
 			if err != nil {
+				result = "error"
 				return err
 			}
 			if len(args) == 0 {
@@ -107,17 +125,23 @@ func (a *App) execCommand() *cobra.Command {
 				return a.listNativeTools(command.Context(), catalogClient)
 			}
 			resourceServer := args[0]
+			phaseStartedAt := time.Now()
 			server, err := catalogClient.Find(command.Context(), resourceServer)
 			if err != nil {
+				result = "error"
 				return err
 			}
+			observability.LogDuration(logger, observability.LevelTrace, "resource_server.resolve", phaseStartedAt, "resource_server", server.CommandName)
+			phaseStartedAt = time.Now()
 			integrations, err := catalogClient.ToolIntegrations(command.Context(), server)
 			if err != nil {
 				if len(args) == 1 && errors.Is(err, catalog.ErrNoToolIntegrations) {
 					return a.printNativeToolSummary(nativeToolSummary{ResourceServer: server.CommandName})
 				}
+				result = "error"
 				return err
 			}
+			observability.LogDuration(logger, observability.LevelTrace, "native_integrations.discover", phaseStartedAt, "resource_server", server.CommandName)
 			if len(args) == 1 || (len(args) == 2 && (args[1] == "--help" || args[1] == "-h")) {
 				if options.active() {
 					return errors.New("--context requires a native command")
@@ -134,10 +158,13 @@ func (a *App) execCommand() *cobra.Command {
 			if len(args) == 0 {
 				return errors.New("native command is required after --")
 			}
+			phaseStartedAt = time.Now()
 			details, err := catalogClient.AuthorizationDetails(command.Context(), server)
 			if err != nil {
+				result = "error"
 				return err
 			}
+			observability.LogDuration(logger, observability.LevelTrace, "authorization_context.discover", phaseStartedAt, "resource_server", server.CommandName)
 			selected, err := a.resolveContext(service, server, details, options.context)
 			if err != nil {
 				return err
@@ -146,8 +173,8 @@ func (a *App) execCommand() *cobra.Command {
 			if err != nil {
 				return err
 			}
-			runner := execution.NewRunner(service, httpClient, command.InOrStdin(), a.stdout, a.stderr)
-			return runner.Run(command.Context(), server, integrations, args, execution.RunOptions{
+			runner := execution.NewRunner(service, httpClient, command.InOrStdin(), a.stdout, a.stderr, logger)
+			err = runner.Run(command.Context(), server, integrations, args, execution.RunOptions{
 				AuthorizationDetails:      selected,
 				ExactAuthorizationContext: true,
 				EffectiveScopes:           executionScopes(details, selected, server.Scopes),
@@ -156,6 +183,10 @@ func (a *App) execCommand() *cobra.Command {
 					return err
 				},
 			})
+			if err != nil {
+				result = "error"
+			}
+			return err
 		},
 	}
 	command.Flags().String("context", "", "Resource Server Context name for this command")
@@ -186,6 +217,14 @@ func (a *App) parseExecFlags(args []string) ([]string, execOptions, error) {
 			a.origin = args[index]
 		case strings.HasPrefix(argument, "--realmroot-origin="):
 			a.origin = strings.TrimPrefix(argument, "--realmroot-origin=")
+		case argument == "--log-level":
+			if index+1 >= len(args) {
+				return nil, execOptions{}, errors.New("--log-level requires a value")
+			}
+			index++
+			a.logLevel = args[index]
+		case strings.HasPrefix(argument, "--log-level="):
+			a.logLevel = strings.TrimPrefix(argument, "--log-level=")
 		case argument == "--context":
 			if index+1 >= len(args) {
 				return nil, execOptions{}, errors.New("--context requires a value")
@@ -1002,8 +1041,19 @@ func (a *App) newRestishRuntimeWithCommandSurface(service *agent.Service, config
 	return runtime, nil
 }
 
-func (a *App) services() (*agent.Service, *catalog.Client, *http.Client, error) {
-	httpClient := &http.Client{Timeout: 30 * time.Second}
+func (a *App) services(configs ...observability.Config) (*agent.Service, *catalog.Client, *http.Client, error) {
+	var transport http.RoundTripper = http.DefaultTransport
+	if len(configs) == 0 {
+		config, err := observability.New(a.stderr, a.logLevel)
+		if err != nil {
+			return nil, nil, nil, err
+		}
+		configs = []observability.Config{config}
+	}
+	if len(configs) == 1 {
+		transport = observability.Transport{Base: transport, Logger: configs[0].Logger, TraceID: configs[0].TraceID}
+	}
+	httpClient := &http.Client{Timeout: 30 * time.Second, Transport: transport}
 	service, err := agent.NewService(a.origin, httpClient)
 	if err != nil {
 		return nil, nil, nil, err

internal/cli/cli_test.go

@@ -51,6 +51,19 @@ func TestRootHelpExposesOnlyProductCommands(t *testing.T) {
 	}
 }
 
+func TestRootHelpDocumentsDiagnosticLogLevel(t *testing.T) {
+	// [spec: cli/cli-diagnostics]
+	var stdout, stderr bytes.Buffer
+	command := New(&stdout, &stderr)
+	command.SetArgs([]string{"--help"})
+	if err := command.Execute(); err != nil {
+		t.Fatal(err)
+	}
+	if !strings.Contains(stdout.String(), "--log-level") || !strings.Contains(stdout.String(), "trace, debug, info, warn, or error") {
+		t.Fatalf("help omitted diagnostic log levels:\n%s", stdout.String())
+	}
+}
+
 func TestVersionCommandReportsBuildInformation(t *testing.T) {
 	// [spec: cli/cli-version]
 	original := buildinfo.Current()
@@ -217,6 +230,14 @@ func TestParseExecFlagsPreservesNativeArgumentsAfterSeparator(t *testing.T) {
 	}
 }
 
+func TestParseExecFlagsConsumesLogLevelBeforeNativeSeparator(t *testing.T) {
+	app := &App{}
+	args, _, err := app.parseExecFlags([]string{"--log-level", "trace", "github", "--", "gh", "api", "--log-level", "debug"})
+	if err != nil || app.logLevel != "trace" || strings.Join(args, " ") != "github -- gh api --log-level debug" {
+		t.Fatalf("args=%v logLevel=%q err=%v", args, app.logLevel, err)
+	}
+}
+
 func TestResourceServerContextUsesDisplayContractWithoutRawDetails(t *testing.T) {
 	// [spec: cli/resource-server-context]
 	details := []catalog.AuthorizationDetail{{