diff --git a/internal/agent/auth_hook.go b/internal/agent/auth_hook.go index f5d557c..ffe7894 100644 --- a/internal/agent/auth_hook.go +++ b/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, diff --git a/internal/agent/credential_source.go b/internal/agent/credential_source.go index 70bf06e..2aef12a 100644 --- a/internal/agent/credential_source.go +++ b/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 diff --git a/internal/agent/credential_source_test.go b/internal/agent/credential_source_test.go index 82ff30e..0cb36e7 100644 --- a/internal/agent/credential_source_test.go +++ b/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) diff --git a/internal/agent/service.go b/internal/agent/service.go index 5ca56c0..7cba47a 100644 --- a/internal/agent/service.go +++ b/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 } diff --git a/internal/agent/service_test.go b/internal/agent/service_test.go index e8b5568..1c1d871 100644 --- a/internal/agent/service_test.go +++ b/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) { diff --git a/internal/cli/cli.go b/internal/cli/cli.go index 1cfc226..c4820d1 100644 --- a/internal/cli/cli.go +++ b/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 diff --git a/internal/cli/cli_test.go b/internal/cli/cli_test.go index 043a178..1161bc4 100644 --- a/internal/cli/cli_test.go +++ b/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{{ diff --git a/internal/execution/run.go b/internal/execution/run.go index fc39faa..663d24b 100644 --- a/internal/execution/run.go +++ b/internal/execution/run.go @@ -5,15 +5,18 @@ import ( "errors" "fmt" "io" + "log/slog" "net/http" "os" "os/exec" "path/filepath" "strconv" "strings" + "time" "github.com/realmroot/toolbox/internal/agent" "github.com/realmroot/toolbox/internal/catalog" + "github.com/realmroot/toolbox/internal/observability" ) type Runner struct { @@ -22,6 +25,7 @@ type Runner struct { stdin io.Reader stdout io.Writer stderr io.Writer + logger *slog.Logger } type RunOptions struct { @@ -31,11 +35,16 @@ type RunOptions struct { RequestAuthority func(context.Context, []string) error } -func NewRunner(service *agent.Service, client *http.Client, stdin io.Reader, stdout, stderr io.Writer) *Runner { - return &Runner{service: service, client: client, stdin: stdin, stdout: stdout, stderr: stderr} +func NewRunner(service *agent.Service, client *http.Client, stdin io.Reader, stdout, stderr io.Writer, loggers ...*slog.Logger) *Runner { + logger := slog.New(slog.NewTextHandler(io.Discard, nil)) + if len(loggers) == 1 { + logger = loggers[0] + } + return &Runner{service: service, client: client, stdin: stdin, stdout: stdout, stderr: stderr, logger: logger} } func (r *Runner) Run(ctx context.Context, server catalog.ResourceServer, integrations []catalog.ToolIntegration, command []string, options RunOptions) error { + startedAt := time.Now() if len(command) == 0 { return errors.New("native command is required after --") } @@ -43,6 +52,8 @@ func (r *Runner) Run(ctx context.Context, server catalog.ResourceServer, integra if err != nil { return err } + observability.LogDuration(r.logger, observability.LevelTrace, "native_command.resolve", startedAt, "integration", integration.ID, "executable", filepath.Base(executable)) + phaseStartedAt := time.Now() var binding agent.CredentialBinding if options.ExactAuthorizationContext { binding, err = r.service.BindingForAuthorizationContextEffectiveScopes( @@ -56,6 +67,7 @@ func (r *Runner) Run(ctx context.Context, server catalog.ResourceServer, integra if err != nil { return fmt.Errorf("load selected %s Context authority: %w; inspect Contexts with `realmroot toolbox %s context` or request access with `realmroot agent request`", server.CommandName, err, server.CommandName) } + observability.LogDuration(r.logger, observability.LevelTrace, "authority.resolve", phaseStartedAt, "scope_count", len(binding.Scopes)) binding.Scopes = intersectScopes(binding.Scopes, options.EffectiveScopes) broker, err := NewBroker( server.ResourceURL, @@ -86,6 +98,7 @@ func (r *Runner) Run(ctx context.Context, server catalog.ResourceServer, integra return err } defer broker.Close() + phaseStartedAt = time.Now() environment := cleanEnvironment(os.Environ(), providerCredentialNames(integration.ID)) switch integration.Protocol { case "cloudflare-api-base": @@ -135,9 +148,16 @@ func (r *Runner) Run(ctx context.Context, server catalog.ResourceServer, integra default: return fmt.Errorf("Resource Server integration %q uses unsupported protocol %q", integration.ID, integration.Protocol) } + observability.LogDuration(r.logger, observability.LevelTrace, "broker.start", phaseStartedAt, "protocol", integration.Protocol) child := exec.CommandContext(ctx, executable, command[1:]...) child.Stdin, child.Stdout, child.Stderr, child.Env = r.stdin, r.stdout, r.stderr, environment + phaseStartedAt = time.Now() err = child.Run() + result := "ok" + if err != nil { + result = "error" + } + observability.LogDuration(r.logger, slog.LevelDebug, "child.execute", phaseStartedAt, "executable", filepath.Base(executable), "result", result) if err == nil { return nil } diff --git a/internal/observability/logging.go b/internal/observability/logging.go new file mode 100644 index 0000000..20c54d2 --- /dev/null +++ b/internal/observability/logging.go @@ -0,0 +1,113 @@ +package observability + +import ( + "context" + "crypto/rand" + "encoding/hex" + "errors" + "fmt" + "io" + "log/slog" + "net/http" + "strings" + "time" +) + +const LevelTrace = slog.Level(-8) + +type Config struct { + Logger *slog.Logger + TraceID string +} + +func New(output io.Writer, levelName string) (Config, error) { + level, err := ParseLevel(levelName) + if err != nil { + return Config{}, err + } + traceID, err := randomHex(16) + if err != nil { + return Config{}, fmt.Errorf("generate diagnostic trace ID: %w", err) + } + handler := slog.NewTextHandler(output, &slog.HandlerOptions{ + Level: level, + ReplaceAttr: func(_ []string, attribute slog.Attr) slog.Attr { + if attribute.Key == slog.LevelKey && attribute.Value.Any().(slog.Level) == LevelTrace { + attribute.Value = slog.StringValue("TRACE") + } + return attribute + }, + }) + return Config{Logger: slog.New(handler).With("trace_id", traceID), TraceID: traceID}, nil +} + +func ParseLevel(value string) (slog.Level, error) { + switch strings.ToLower(strings.TrimSpace(value)) { + case "trace": + return LevelTrace, nil + case "debug": + return slog.LevelDebug, nil + case "info": + return slog.LevelInfo, nil + case "warn", "warning", "": + return slog.LevelWarn, nil + case "error": + return slog.LevelError, nil + default: + return 0, errors.New("--log-level must be one of trace, debug, info, warn, or error") + } +} + +func LogDuration(logger *slog.Logger, level slog.Level, phase string, startedAt time.Time, attributes ...any) { + logger.Log(context.Background(), level, "phase.complete", append([]any{"phase", phase, "duration_ms", time.Since(startedAt).Milliseconds()}, attributes...)...) +} + +type Transport struct { + Base http.RoundTripper + Logger *slog.Logger + TraceID string +} + +func (t Transport) RoundTrip(request *http.Request) (*http.Response, error) { + base := t.Base + if base == nil { + base = http.DefaultTransport + } + spanID, err := randomHex(8) + if err != nil { + return nil, fmt.Errorf("generate HTTP diagnostic span ID: %w", err) + } + outbound := request.Clone(request.Context()) + outbound.Header = request.Header.Clone() + if outbound.Header.Get("traceparent") == "" { + outbound.Header.Set("traceparent", "00-"+t.TraceID+"-"+spanID+"-01") + } + outbound.Header.Set("x-correlation-id", t.TraceID) + startedAt := time.Now() + t.Logger.Log(request.Context(), LevelTrace, "http.request", "method", request.Method, "host", request.URL.Host, "path", request.URL.Path) + response, err := base.RoundTrip(outbound) + attributes := []any{ + "method", request.Method, + "host", request.URL.Host, + "path", request.URL.Path, + "duration_ms", time.Since(startedAt).Milliseconds(), + } + if err != nil { + t.Logger.Debug("http.complete", append(attributes, "result", "error", "error", err.Error())...) + return nil, err + } + t.Logger.Debug("http.complete", append(attributes, + "result", "ok", + "status", response.StatusCode, + "request_id", response.Header.Get("request-id"), + )...) + return response, nil +} + +func randomHex(bytes int) (string, error) { + value := make([]byte, bytes) + if _, err := rand.Read(value); err != nil { + return "", err + } + return hex.EncodeToString(value), nil +} diff --git a/internal/observability/logging_test.go b/internal/observability/logging_test.go new file mode 100644 index 0000000..3c2e0a5 --- /dev/null +++ b/internal/observability/logging_test.go @@ -0,0 +1,62 @@ +package observability + +import ( + "bytes" + "context" + "io" + "net/http" + "strings" + "testing" +) + +type roundTripFunc func(*http.Request) (*http.Response, error) + +func (f roundTripFunc) RoundTrip(request *http.Request) (*http.Response, error) { return f(request) } + +func TestTransportCorrelatesAndRedactsHTTPDiagnostics(t *testing.T) { + // [spec: cli/cli-diagnostics] + var output bytes.Buffer + config, err := New(&output, "debug") + if err != nil { + t.Fatal(err) + } + transport := Transport{ + Logger: config.Logger, TraceID: config.TraceID, + Base: roundTripFunc(func(request *http.Request) (*http.Response, error) { + if !strings.Contains(request.Header.Get("traceparent"), config.TraceID) { + t.Fatalf("traceparent = %q", request.Header.Get("traceparent")) + } + if request.Header.Get("x-correlation-id") != config.TraceID { + t.Fatalf("x-correlation-id = %q", request.Header.Get("x-correlation-id")) + } + return &http.Response{ + StatusCode: http.StatusOK, + Header: http.Header{"Request-Id": []string{"worker-request"}}, + Body: io.NopCloser(strings.NewReader("ok")), + Request: request, + }, nil + }), + } + request, _ := http.NewRequestWithContext(context.Background(), http.MethodGet, "https://example.com/items?token=secret", nil) + request.Header.Set("authorization", "Bearer secret") + if _, err := transport.RoundTrip(request); err != nil { + t.Fatal(err) + } + log := output.String() + for _, expected := range []string{"level=DEBUG", "msg=http.complete", "host=example.com", "path=/items", "request_id=worker-request"} { + if !strings.Contains(log, expected) { + t.Fatalf("log omitted %q: %s", expected, log) + } + } + for _, secret := range []string{"token=secret", "Bearer secret"} { + if strings.Contains(log, secret) { + t.Fatalf("log exposed %q: %s", secret, log) + } + } +} + +func TestNewRejectsUnknownLogLevel(t *testing.T) { + if _, err := New(io.Discard, "verbose"); err == nil || !strings.Contains(err.Error(), "--log-level") { + t.Fatalf("error = %v", err) + } +} diff --git a/specs/cli.feature b/specs/cli.feature index 62f2336..a573cb6 100644 --- a/specs/cli.feature +++ b/specs/cli.feature @@ -14,6 +14,14 @@ Feature: Realmroot Toolbox command line And release builds may also report their source commit and build time And JSON output uses stable version, commit, and build time fields + @journey:cli-diagnostics @entrypoint:root + Scenario: Inspect command execution diagnostics + When the Agent selects a log level with "--log-level" + Then diagnostics at that level and above are written to standard error + And native execution reports discovery, authorization, broker, HTTP, and child-process timing + And diagnostics correlate one command across Realmroot and Resource Server requests + But credentials, request bodies, and URL query parameters are never logged + @journey:invalid-command @entrypoint:agent Scenario: Reject an unsupported Agent command When the Agent runs an unsupported command such as "realmroot agent status"