diff --git a/dev-docs/ARCHITECTURE.md b/dev-docs/ARCHITECTURE.md index f613bfdc..cc2797e1 100644 --- a/dev-docs/ARCHITECTURE.md +++ b/dev-docs/ARCHITECTURE.md @@ -451,6 +451,23 @@ When a build-tool-primary detector (Maven, Gradle, Go, …) cannot produce a gra - **Degradation vs hand-off.** Only a real primary failure (not-ready, applicability-check error, install failure, resolve error, empty graph, scope-filter error) is annotated and warned about. `Applicable() == false` with no error is designed chain hand-off (e.g. the npm lockfile detector deferring to the native detector when no lockfile exists) and stays quiet. In chained fallbacks the outermost real failure wins, since users care about the planned primary. - **Default visibility.** At default verbosity the CLI logger is a no-op, so the authoritative channel is the `PipelineWarning` converted from the annotation after the parallel resolve phase — it renders as a ⚠ child in the scan/explain/diff progress UI, as a yellow notice in the text report, a warning blockquote in markdown, and a `resolution.fallback` object in scan JSON. A single Warn log (`pipeline: detector fell back`) fires per unique (subproject, primary, fallback) tuple for `-v` users. - **Stage observability.** Pipeline stages (detection, consolidation, enrichment, reachability, policy evaluation) emit Info start/completion logs with counts and durations; consolidation stays logger-free and the pipeline logs around it. Detector-internal completion lines remain owned by the detectors themselves, and recoverable detector subprocess failures log at Warn, not Error, because the pipeline degrades and continues. +- **Secret-safe subprocess logs.** Subprocess owners log the executable, + sanitized argument list, and working directory at Debug. The shared logging + sanitizer removes credential-shaped flag values and URL user information + while preserving ordinary arguments for reproduction. Executable values are + resolved binary paths or names and are assumed not to contain arguments or + credentials. URL query values are not parsed as credentials, so callers must + not treat URL sanitization as a general query-string redactor. The engine + logs orchestration state but never logs raw `install_args`. At DEBUG + verbosity (`-vv`), subprocess stderr is streamed to Bomly's stderr so users + can diagnose package-manager, analyzer, matcher, Git, Java, and managed + plugin failures. It is hidden at lower verbosity and is not stored in + structured results. Because Bomly cannot reliably sanitize arbitrary tool + output, DEBUG logs may contain credentials or other sensitive values printed + by those tools and must be handled as sensitive data. The serialized + `DetectionRequest.AllowStdErrLogging` field lets protocol-v1 detectors see + that the user enabled this output; process-local `Stderr` and `Verbose` + fields carry the destination and compatibility signal for built-ins. ### Decision: detector logs are request-scoped by subproject diff --git a/docs/TROUBLESHOOTING.md b/docs/TROUBLESHOOTING.md index 62ced5a7..03ac95b7 100644 --- a/docs/TROUBLESHOOTING.md +++ b/docs/TROUBLESHOOTING.md @@ -147,7 +147,12 @@ The animation is also skipped automatically when `CI` or `BOMLY_QUIET` is set, a ## Need more detail -Re-run with `-v` (INFO) or `-vv` (DEBUG). DEBUG logs include exact subprocess command lines, cache keys, and per-package decisions, which is usually enough to file a useful bug report. +Re-run with `-v` (INFO) or `-vv` (DEBUG). DEBUG logs include subprocess +executables, credential-sanitized arguments, working directories, cache keys, +and per-package decisions. They also include raw stderr from invoked package +managers, analyzers, matchers, Git, Java, and managed plugins. Bomly cannot +reliably remove secrets from arbitrary tool output, so treat DEBUG logs as +sensitive data. INFO logs do not include raw subprocess stderr. ```bash bomly scan --enrich -vv 2> bomly.log diff --git a/internal/analyzers/govulncheck/analyzer.go b/internal/analyzers/govulncheck/analyzer.go index 24f75c75..ff644c78 100644 --- a/internal/analyzers/govulncheck/analyzer.go +++ b/internal/analyzers/govulncheck/analyzer.go @@ -93,7 +93,7 @@ func (a Analyzer) Analyze(ctx context.Context, req model.AnalyzeRequest) (model. } runner := a.Runner if runner == nil { - runner = NewRunner(logger) + runner = newRunnerWithStderr(logger, req.Stderr) } overallStart := time.Now() diff --git a/internal/analyzers/govulncheck/runner_library.go b/internal/analyzers/govulncheck/runner_library.go index 2f37a6f3..e6bde603 100644 --- a/internal/analyzers/govulncheck/runner_library.go +++ b/internal/analyzers/govulncheck/runner_library.go @@ -5,7 +5,9 @@ import ( "context" "errors" "fmt" + "io" + "github.com/bomly-dev/bomly-cli/internal/logging" "go.uber.org/zap" govulnscan "golang.org/x/vuln/scan" ) @@ -18,12 +20,17 @@ func NewRunner(logger *zap.Logger) Runner { return libraryRunner{logger: ensureLogger(logger)} } +func newRunnerWithStderr(logger *zap.Logger, stderr io.Writer) Runner { + return libraryRunner{logger: ensureLogger(logger), stderr: stderr} +} + // libraryRunner is the in-process implementation of Runner. The Runner // interface is preserved (rather than calling api.Build directly from // the analyzer) so unit tests can inject a fakeRunner for deterministic // behavior without a real Go toolchain. type libraryRunner struct { logger *zap.Logger + stderr io.Writer } func (libraryRunner) Name() string { return "library" } @@ -36,10 +43,10 @@ func (r libraryRunner) Run(ctx context.Context, moduleDir string) (RunnerResult, zap.Strings("args", args)) var stdout bytes.Buffer - var stderr bytes.Buffer + stderr := logging.NewCommandStderr(r.stderr, r.stderr != nil) cmd := govulnscan.Command(ctx, args...) cmd.Stdout = &stdout - cmd.Stderr = &stderr + cmd.Stderr = stderr if err := cmd.Start(); err != nil { return RunnerResult{}, fmt.Errorf("govulncheck start: %w", err) @@ -48,7 +55,7 @@ func (r libraryRunner) Run(ctx context.Context, moduleDir string) (RunnerResult, r.logger.Debug("govulncheck: in-process runner produced output", zap.String("module_root", moduleDir), zap.Int("stdout_bytes", stdout.Len()), - zap.Int("stderr_bytes", stderr.Len())) + zap.Int64("stderr_bytes", stderr.ByteCount())) if waitErr != nil { // govulncheck.Cmd surfaces "exit status 3" (vulnerabilities @@ -65,13 +72,7 @@ func (r libraryRunner) Run(ctx context.Context, moduleDir string) (RunnerResult, } return result, nil } - // Surface stderr in the error message so build failures are - // debuggable from a single log line. - stderrPreview := truncateStderr(stderr.String(), 512) - if stderrPreview != "" { - return RunnerResult{}, fmt.Errorf("govulncheck failed: %w: %s", waitErr, stderrPreview) - } - return RunnerResult{}, fmt.Errorf("govulncheck failed: %w", waitErr) + return RunnerResult{}, fmt.Errorf("govulncheck failed: %w (stderr bytes: %d)", waitErr, stderr.ByteCount()) } return parseGovulncheckJSON(stdout.Bytes()) @@ -97,11 +98,3 @@ func isVulnsFound(err error) bool { } return false } - -// truncateStderr returns at most n bytes of s with an ellipsis when truncated. -func truncateStderr(s string, n int) string { - if len(s) <= n { - return s - } - return s[:n] + "..." -} diff --git a/internal/analyzers/govulncheck/testdata_test.go b/internal/analyzers/govulncheck/testdata_test.go index 0ac52a9e..c0c1f785 100644 --- a/internal/analyzers/govulncheck/testdata_test.go +++ b/internal/analyzers/govulncheck/testdata_test.go @@ -87,9 +87,6 @@ func TestGovulncheckDescriptorAndRunnerHelpers(t *testing.T) { if isVulnsFound(errors.New("exit status 1")) || isVulnsFound(nil) { t.Fatal("non-vulnerability errors must not match") } - if got := truncateStderr("abcdef", 3); got != "abc..." { - t.Fatalf("truncateStderr = %q", got) - } if got := NewRunner(nil).Name(); got != "library" { t.Fatalf("runner name = %q, want library", got) } diff --git a/internal/cli/benchmark_cmd.go b/internal/cli/benchmark_cmd.go index 769de72b..9713a911 100644 --- a/internal/cli/benchmark_cmd.go +++ b/internal/cli/benchmark_cmd.go @@ -62,7 +62,7 @@ func newBenchmarkCmd() *cobra.Command { InstallFirst: installFirst, Notifications: notifications, Logger: logger, - NativeScan: benchmarkNativeScanner(logger, streams.notificationWriter(), current.Verbosity > 0), + NativeScan: benchmarkNativeScanner(logger, streams.notificationWriter(), current.Verbosity >= 2), }) if renderErr := writeBenchmarkSummary(cmd, format, summary); renderErr != nil { return renderErr diff --git a/internal/cli/benchmark_run.go b/internal/cli/benchmark_run.go index 92aa70d1..17dbede5 100644 --- a/internal/cli/benchmark_run.go +++ b/internal/cli/benchmark_run.go @@ -17,13 +17,14 @@ import ( "go.uber.org/zap" ) -func benchmarkNativeScanner(logger *zap.Logger, stderr io.Writer, verbose bool) benchmark.NativeScanFunc { +// benchmarkNativeScanner builds pipeline requests directly instead of going +// through Options.PipelineRequest, so it must apply the same subprocess-stderr +// gate: raw tool output is forwarded only at debug verbosity (-vv). +func benchmarkNativeScanner(logger *zap.Logger, stderr io.Writer, debug bool) benchmark.NativeScanFunc { if logger == nil { logger = zap.NewNop() } - if stderr == nil { - stderr = io.Discard - } + stderr = benchmarkSubprocessStderr(stderr, debug) return func(ctx context.Context, req benchmark.NativeScanRequest) (benchmark.NativeScanResult, error) { checkoutDir, err := filepath.Abs(req.CheckoutDir) if err != nil { @@ -68,7 +69,7 @@ func benchmarkNativeScanner(logger *zap.Logger, stderr io.Writer, verbose bool) DetectorFilter: detectorFilter, InstallFirst: req.InstallFirst, Stderr: stderr, - Verbose: verbose, + Verbose: debug, }) if err != nil { return benchmark.NativeScanResult{}, fmt.Errorf("run benchmark native scan: %w", err) @@ -97,3 +98,13 @@ func benchmarkDetectorNames(results []sdk.DetectionResult) []string { sort.Strings(names) return names } + +// benchmarkSubprocessStderr mirrors the Options.PipelineRequest gate for +// pipeline requests that are built directly: raw subprocess stderr is +// forwarded only when debug verbosity (-vv) enabled it. +func benchmarkSubprocessStderr(stderr io.Writer, debug bool) io.Writer { + if !debug { + return nil + } + return stderr +} diff --git a/internal/cli/benchmark_run_test.go b/internal/cli/benchmark_run_test.go index 3594c520..d5300601 100644 --- a/internal/cli/benchmark_run_test.go +++ b/internal/cli/benchmark_run_test.go @@ -14,6 +14,15 @@ import ( "go.uber.org/zap" ) +func TestBenchmarkSubprocessStderrForwardsOnlyAtDebug(t *testing.T) { + if got := benchmarkSubprocessStderr(io.Discard, false); got != nil { + t.Fatalf("info-level stderr = %#v, want nil", got) + } + if got := benchmarkSubprocessStderr(io.Discard, true); got != io.Discard { + t.Fatalf("debug-level stderr = %#v, want the provided writer", got) + } +} + func TestBenchmarkNativeScannerUsesBomlyNativeDetector(t *testing.T) { projectDir := t.TempDir() lockfile := []byte(`{ diff --git a/internal/cli/diff_resolve.go b/internal/cli/diff_resolve.go index 885660f5..f38ca19f 100644 --- a/internal/cli/diff_resolve.go +++ b/internal/cli/diff_resolve.go @@ -25,13 +25,13 @@ func resolveGitDiffGraphs(ctx context.Context, options *opts.Options, prog *prog if repoCleanup != nil { defer func() { _ = repoCleanup() }() } - if err := git.VerifyRef(repoRoot, baseRef); err != nil { + if err := git.VerifyRef(logger, repoRoot, baseRef); err != nil { return diffResolvedTarget{}, diffResolvedTarget{}, "", nil, nil, exit.InvalidInputError("verify --base %q: %v", baseRef, err) } - if err := git.VerifyRef(repoRoot, headRef); err != nil { + if err := git.VerifyRef(logger, repoRoot, headRef); err != nil { return diffResolvedTarget{}, diffResolvedTarget{}, "", nil, nil, exit.InvalidInputError("verify --head %q: %v", headRef, err) } - changedLines, err := git.ChangedLineRanges(repoRoot, baseRef, headRef) + changedLines, err := git.ChangedLineRanges(logger, repoRoot, baseRef, headRef) if err != nil && logger != nil { logger.Warn("diff: changed line ranges unavailable", zap.Error(err)) } @@ -76,7 +76,7 @@ func resolveDiffRepo(options *opts.Options, prog *progress.Progress, logger *zap if err != nil { return "", nil, "", err } - repoRoot, err := git.FindRepoRoot(selectedPath) + repoRoot, err := git.FindRepoRoot(logger, selectedPath) if err != nil { return "", nil, "", exit.InvalidInputError("resolve local git repository: %v", err) } diff --git a/internal/cli/opts/options.go b/internal/cli/opts/options.go index 0737dc69..a0b9b62f 100644 --- a/internal/cli/opts/options.go +++ b/internal/cli/opts/options.go @@ -118,6 +118,9 @@ func (o *Options) AnalyzerFilter() sdk.AnalyzerFilter { func (o *Options) PipelineRequest(scope sdk.Scope, stderr io.Writer) engine.PipelineRequest { failOn, _ := sdk.ParseFailOnList(o.ResolvedConfig.FailOn) typosquatThreshold, _ := strconv.ParseFloat(strings.TrimSpace(o.ResolvedConfig.TyposquatThreshold), 64) + if !o.Verbose() { + stderr = nil + } return engine.PipelineRequest{ ProjectPath: o.executionTarget.Location, ExecutionTarget: o.executionTarget, @@ -150,7 +153,7 @@ func (o *Options) PipelineRequest(scope sdk.Scope, stderr io.Writer) engine.Pipe } } -// Verbose reports whether verbose command output is enabled. +// Verbose reports whether debug-level subprocess output is enabled. func (o *Options) Verbose() bool { return o.verbose } @@ -363,7 +366,7 @@ func (o *Options) PrepareForExecutionTarget(ctx context.Context, logger *zap.Log httpProvider: httpProvider, ResolvedConfig: resolved, Format: format, - verbose: resolved.Verbosity > 0, + verbose: resolved.Verbosity >= 2, cleanup: cleanup, findingPolicyResolvers: baselineResult.Resolvers, baselineEvaluation: baselineEvaluationFromLoadResult(baselineResult), diff --git a/internal/cli/opts/options_test.go b/internal/cli/opts/options_test.go index fa4590ae..13c924e0 100644 --- a/internal/cli/opts/options_test.go +++ b/internal/cli/opts/options_test.go @@ -1,6 +1,7 @@ package opts import ( + "bytes" "context" "os" "path/filepath" @@ -28,6 +29,22 @@ func TestCommandContextRoundTripsThroughContext(t *testing.T) { } } +func TestPipelineRequestExposesSubprocessStderrOnlyAtDebug(t *testing.T) { + var stderr bytes.Buffer + + infoOptions := Options{verbose: false} + info := infoOptions.PipelineRequest(sdk.ScopeUnknown, &stderr) + if info.Stderr != nil || info.Verbose { + t.Fatalf("info request enabled subprocess stderr: %#v", info) + } + + debugOptions := Options{verbose: true} + debug := debugOptions.PipelineRequest(sdk.ScopeUnknown, &stderr) + if debug.Stderr != &stderr || !debug.Verbose { + t.Fatalf("debug request did not enable subprocess stderr: %#v", debug) + } +} + func TestCommandContextResolveExecutionTarget_Image(t *testing.T) { options := Options{ResolvedConfig: config.Resolved{Image: "alpine:3.20"}} diff --git a/internal/cli/root_cmd.go b/internal/cli/root_cmd.go index 3296a747..61cf78d4 100644 --- a/internal/cli/root_cmd.go +++ b/internal/cli/root_cmd.go @@ -7,6 +7,7 @@ import ( "github.com/bomly-dev/bomly-cli/internal/cli/exit" "github.com/bomly-dev/bomly-cli/internal/cli/opts" + "github.com/bomly-dev/bomly-cli/internal/logging" "github.com/spf13/cobra" "github.com/spf13/pflag" "go.uber.org/zap" @@ -201,7 +202,7 @@ func logResolvedOptions(cmd *cobra.Command) { logger.Debug("Resolved options", zap.String("path", resolved.Path), zap.String("image", resolved.Image), - zap.String("url", resolved.URL), + zap.String("url", logging.SanitizeURL(resolved.URL)), zap.String("ref", resolved.Ref), zap.Bool("sbom", resolved.SBOM), zap.Bool("enrich", resolved.Enrich), @@ -215,7 +216,7 @@ func logResolvedOptions(cmd *cobra.Command) { zap.String("ecosystems", resolved.Ecosystems), zap.String("detectors", resolved.Detectors), zap.Bool("install_first", resolved.InstallFirst), - zap.Strings("install_args", resolved.InstallArgs), + zap.Strings("install_args", logging.SanitizeArgs(resolved.InstallArgs)), zap.String("config", resolved.Config), zap.Bool("verbose", resolved.Verbosity > 0), zap.Int("verbosity", resolved.Verbosity), diff --git a/internal/cli/root_cmd_test.go b/internal/cli/root_cmd_test.go index a1a6840c..200fff8f 100644 --- a/internal/cli/root_cmd_test.go +++ b/internal/cli/root_cmd_test.go @@ -4,6 +4,7 @@ import ( "bytes" "encoding/json" "fmt" + "io" "os" "os/exec" "path/filepath" @@ -2652,12 +2653,28 @@ func TestRoot_ScanCommand_MavenMissingJavaReturnsResolutionFailure(t *testing.T) if got := exit.Code(err); got != 3 { t.Fatalf("expected resolution failure exit code 3, got %d (err=%v)", got, err) } - if !strings.Contains(err.Error(), "Unable to locate a Java Runtime") { - t.Fatalf("expected Java runtime message in error, got %v", err) + if !strings.Contains(err.Error(), "diagnostic bytes:") || + strings.Contains(err.Error(), "Unable to locate a Java Runtime") { + t.Fatalf("expected secret-safe Java runtime message in error, got %v", err) } if stdout.Len() != 0 { t.Fatalf("expected no stdout on resolution failure, got %q", stdout.String()) } + + debugRoot, err := newRootCmd("0.9.0-test") + if err != nil { + t.Fatalf("newRootCmd() debug error = %v", err) + } + var debugStderr bytes.Buffer + debugRoot.SetOut(io.Discard) + debugRoot.SetErr(&debugStderr) + debugRoot.SetArgs([]string{"scan", "--path", projectDir, "--ecosystems", "maven", "--detectors", "maven-detector", "--format", "json", "-vv"}) + if err := debugRoot.Execute(); err == nil { + t.Fatal("expected debug scan to fail when Java is unavailable") + } + if !strings.Contains(debugStderr.String(), "Unable to locate a Java Runtime") { + t.Fatalf("expected Java diagnostics in debug output, got %q", debugStderr.String()) + } } func TestRoot_WhyCommand_GoModules_JSONOutput(t *testing.T) { diff --git a/internal/detectors/cargo/detector.go b/internal/detectors/cargo/detector.go index 7ecd7321..036911fe 100644 --- a/internal/detectors/cargo/detector.go +++ b/internal/detectors/cargo/detector.go @@ -129,8 +129,8 @@ func (d Detector) ResolveGraph(_ context.Context, req sdk.DetectionRequest) (sdk raw, err := cmd.Output() if err != nil { fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("cargo detector failure details", fields...) return sdk.DetectionResult{}, fmt.Errorf("run cargo metadata: %w", err) @@ -650,6 +650,10 @@ func trimTomlString(value string) string { // Install prepares Cargo dependencies before graph resolution. func (d Detector) Install(_ context.Context, req sdk.DetectionRequest) error { + logger := d.Logger + if logger == nil { + logger = zap.NewNop() + } cargoPath, err := cargoExecLookPath("cargo") if err != nil { return fmt.Errorf("resolve cargo executable: %w", err) @@ -658,6 +662,7 @@ func (d Detector) Install(_ context.Context, req sdk.DetectionRequest) error { cmd := cargoExecCommand(cargoPath, args...) cmd.Dir = d.workingDir(req.ProjectPath) cmd.Stderr = logging.NewCommandStderr(req.Stderr, req.Verbose) + logger.Debug("running cargo detector install-first", logging.CommandFields(cargoPath, args, cmd.Dir)...) if err := cmd.Run(); err != nil { return fmt.Errorf("run cargo fetch: %w", err) } diff --git a/internal/detectors/composer/detector.go b/internal/detectors/composer/detector.go index 64cf3b39..3d8db7c2 100644 --- a/internal/detectors/composer/detector.go +++ b/internal/detectors/composer/detector.go @@ -126,11 +126,11 @@ func (d Detector) Install(_ context.Context, req sdk.DetectionRequest) error { started := time.Now() logger.Info("Composer detector running install-first step") - logger.Debug("running composer detector install-first", zap.String("working_dir", cmd.Dir), zap.String("executable", composerPath), zap.Strings("args", args)) + logger.Debug("running composer detector install-first", logging.CommandFields(composerPath, args, cmd.Dir)...) if err := cmd.Run(); err != nil { fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("composer detector install-first failure details", fields...) return fmt.Errorf("run composer install: %w", err) diff --git a/internal/detectors/gomod/detector.go b/internal/detectors/gomod/detector.go index 5a88989e..11985ef3 100644 --- a/internal/detectors/gomod/detector.go +++ b/internal/detectors/gomod/detector.go @@ -161,8 +161,8 @@ func (d Detector) resolveGraph(stderr io.Writer, projectPath string, verbose boo if err != nil { logger.Warn(fmt.Sprintf("Go module detector failed: %v", err)) fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("go module detector failure details", fields...) return nil, fmt.Errorf("run go list -deps -json all: %w", err) @@ -470,7 +470,7 @@ func (d Detector) Install(_ context.Context, req sdk.DetectionRequest) error { cmd.Stderr = commandStderr started := time.Now() logger.Info("Go detector running install-first step") - logger.Debug("running go detector install-first", zap.String("working_dir", workingDir), zap.String("executable", goPath), zap.Strings("args", args)) + logger.Debug("running go detector install-first", logging.CommandFields(goPath, args, workingDir)...) if err := cmd.Run(); err != nil { return fmt.Errorf("run go mod download: %w", err) } diff --git a/internal/detectors/gradle/detector.go b/internal/detectors/gradle/detector.go index bccf85b0..10d0e31c 100644 --- a/internal/detectors/gradle/detector.go +++ b/internal/detectors/gradle/detector.go @@ -50,7 +50,7 @@ func (d Detector) Ready(ctx context.Context, req sdk.DetectionRequest) error { } else if _, _, err := d.commandSpec(workingDir, nil); err != nil { return detectors.CommandNotReadyError(executableName, err) } - return detectors.JavaReady(ctx) + return detectors.JavaReady(ctx, req.DetectorLogger(d.Logger)) } // Applicable returns true when the project looks like a Gradle build. @@ -251,8 +251,8 @@ func (d Detector) runDependencies(ctx context.Context, stderr io.Writer, working } logger.Warn(fmt.Sprintf("Gradle dependencies detector failed: %v", err)) fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("gradle dependencies detector failure details", fields...) return gradleParseResult{}, fmt.Errorf("run gradle dependencies: %w", err) @@ -754,7 +754,7 @@ func (d Detector) Install(ctx context.Context, req sdk.DetectionRequest) error { cmd.Stderr = commandStderr started := time.Now() logger.Info("Gradle detector running install-first step") - logger.Debug("running gradle detector install-first", zap.String("working_dir", workingDir), zap.String("executable", executable), zap.Strings("args", args)) + logger.Debug("running gradle detector install-first", logging.CommandFields(executable, args, workingDir)...) if err := cmd.Run(); err != nil { if errors.Is(cmdCtx.Err(), context.DeadlineExceeded) { err = fmt.Errorf("timed out after %s: %w", detectors.BuildToolTimeout, err) diff --git a/internal/detectors/gradle/detector_test.go b/internal/detectors/gradle/detector_test.go index a19a2928..d3f7f035 100644 --- a/internal/detectors/gradle/detector_test.go +++ b/internal/detectors/gradle/detector_test.go @@ -96,8 +96,9 @@ func TestDetectorReadyRequiresJava(t *testing.T) { if err == nil { t.Fatal("expected detector to be not ready without a usable Java runtime") } - if !strings.Contains(err.Error(), "Unable to locate a Java Runtime") { - t.Fatalf("expected Java runtime reason, got %q", err) + if !strings.Contains(err.Error(), "diagnostic bytes:") || + strings.Contains(err.Error(), "Unable to locate a Java Runtime") { + t.Fatalf("expected secret-safe Java runtime reason, got %q", err) } } diff --git a/internal/detectors/java_ready.go b/internal/detectors/java_ready.go index 7759fcdb..a5772227 100644 --- a/internal/detectors/java_ready.go +++ b/internal/detectors/java_ready.go @@ -9,7 +9,9 @@ import ( "strings" "time" + "github.com/bomly-dev/bomly-cli/internal/logging" "github.com/bomly-dev/bomly-cli/internal/system" + "go.uber.org/zap" ) // javaReadyTimeout bounds the `java -version` probe. It is only reached when @@ -23,7 +25,10 @@ const javaReadyTimeout = 30 * time.Second // returns nil when a runtime is usable and a non-nil error describing the // reason otherwise. The probe is bound to ctx and additionally guarded by an // internal timeout so a hung `java` cannot stall a scan. -func JavaReady(ctx context.Context) error { +func JavaReady(ctx context.Context, logger *zap.Logger) error { + if logger == nil { + logger = zap.NewNop() + } if _, err := system.LookPath("java"); err != nil { return errors.New("java executable not found on PATH") } @@ -31,19 +36,22 @@ func JavaReady(ctx context.Context) error { probeCtx, cancel := context.WithTimeout(ctx, javaReadyTimeout) defer cancel() - cmd := system.CommandContext(probeCtx, "java", "-version") - var output bytes.Buffer - cmd.Stdout = &output - cmd.Stderr = &output - if err := cmd.Run(); err != nil { + executable := "java" + args := []string{"-version"} + cmd := system.CommandContext(probeCtx, executable, args...) + var diagnostics bytes.Buffer + cmd.Stdout = &diagnostics + cmd.Stderr = &diagnostics + logger.Debug("running Java readiness probe", logging.CommandFields(executable, args, cmd.Dir)...) + err := cmd.Run() + if message := strings.TrimSpace(diagnostics.String()); message != "" { + logger.Debug("Java readiness probe diagnostics", zap.String("stderr", message)) + } + if err != nil { if errors.Is(probeCtx.Err(), context.DeadlineExceeded) { return fmt.Errorf("java readiness check timed out after %s", javaReadyTimeout) } - message := strings.TrimSpace(output.String()) - if message == "" { - message = err.Error() - } - return fmt.Errorf("java runtime is unavailable: %s", message) + return fmt.Errorf("java runtime is unavailable: %w (diagnostic bytes: %d)", err, diagnostics.Len()) } return nil } diff --git a/internal/detectors/maven/detector.go b/internal/detectors/maven/detector.go index 014392ef..0085245f 100644 --- a/internal/detectors/maven/detector.go +++ b/internal/detectors/maven/detector.go @@ -57,7 +57,7 @@ func (d Detector) Ready(ctx context.Context, req sdk.DetectionRequest) error { if _, _, err := d.resolveRunner(detectors.RequestWorkingDir(req)); err != nil { return detectors.CommandNotReadyError("mvn", err) } - return detectors.JavaReady(ctx) + return detectors.JavaReady(ctx, req.DetectorLogger(d.Logger)) } // Applicable reports whether the project looks like a Maven project. @@ -254,8 +254,8 @@ func (d Detector) resolveGraph(ctx context.Context, stderr io.Writer, projectPat } logger.Warn(fmt.Sprintf("Maven dependencies detector failed: %v", err)) fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("maven dependencies detector failure details", fields...) return nil, fmt.Errorf("run maven dependency tree: %w", err) @@ -596,7 +596,7 @@ func (d Detector) Install(ctx context.Context, req sdk.DetectionRequest) error { cmd.Stderr = commandStderr started := time.Now() logger.Info("Maven detector running install-first step") - logger.Debug("running maven detector install-first", zap.String("working_dir", cmd.Dir), zap.String("executable", executable), zap.Strings("args", args)) + logger.Debug("running maven detector install-first", logging.CommandFields(executable, args, cmd.Dir)...) if err := cmd.Run(); err != nil { if errors.Is(cmdCtx.Err(), context.DeadlineExceeded) { err = fmt.Errorf("timed out after %s: %w", detectors.BuildToolTimeout, err) diff --git a/internal/detectors/maven/detector_test.go b/internal/detectors/maven/detector_test.go index b3a25b1a..c8e9e53f 100644 --- a/internal/detectors/maven/detector_test.go +++ b/internal/detectors/maven/detector_test.go @@ -212,8 +212,9 @@ func TestMavenDetectorReadyRequiresJava(t *testing.T) { if err == nil { t.Fatal("expected detector to be not ready without a usable Java runtime") } - if !strings.Contains(err.Error(), "Unable to locate a Java Runtime") { - t.Fatalf("expected Java runtime reason, got %q", err) + if !strings.Contains(err.Error(), "diagnostic bytes:") || + strings.Contains(err.Error(), "Unable to locate a Java Runtime") { + t.Fatalf("expected secret-safe Java runtime reason, got %q", err) } } diff --git a/internal/detectors/node/common.go b/internal/detectors/node/common.go index 97e6aaf2..a3ca2069 100644 --- a/internal/detectors/node/common.go +++ b/internal/detectors/node/common.go @@ -77,8 +77,8 @@ func (d BaseDetector) ResolveGraph(stderr io.Writer, projectPath string, verbose if err := cmd.Run(); err != nil { logger.Warn(fmt.Sprintf("%s failed: %v", detectorName, err)) fields := []zap.Field{zap.Error(err), zap.String("detector", detectorName)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("external dependency detector failure details", fields...) return nil, fmt.Errorf("run %s: %w", detectorName, err) @@ -109,11 +109,12 @@ func (d BaseDetector) Install(ctx context.Context, req sdk.DetectionRequest, exe cmd.Stderr = commandStderr started := time.Now() logger.Info(fmt.Sprintf("%s running install-first step", detectorName)) - logger.Debug("running detector install-first", zap.String("detector", detectorName), zap.String("working_dir", cmd.Dir), zap.String("executable", executable), zap.Strings("args", args)) + logger.Debug("running detector install-first", + append([]zap.Field{zap.String("detector", detectorName)}, logging.CommandFields(executable, args, cmd.Dir)...)...) if err := cmd.Run(); err != nil { fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("detector install-first failure details", fields...) return fmt.Errorf("run %s install step: %w", detectorName, err) diff --git a/internal/detectors/node/logging_test.go b/internal/detectors/node/logging_test.go new file mode 100644 index 00000000..35baeffb --- /dev/null +++ b/internal/detectors/node/logging_test.go @@ -0,0 +1,69 @@ +package node + +import ( + "bytes" + "context" + "fmt" + "os" + "strings" + "testing" + + "github.com/bomly-dev/bomly-cli/sdk" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" +) + +func TestInstallLogsReproducibleCommandAndDebugStderr(t *testing.T) { + executable, err := os.Executable() + if err != nil { + t.Fatal(err) + } + core, observed := observer.New(zap.DebugLevel) + logger := zap.New(core) + t.Setenv("BOMLY_NODE_INSTALL_HELPER", "1") + workingDir := t.TempDir() + args := []string{ + "--token", "token-secret", + "--registry=https://user:url-secret@example.test/packages", + "--color=always", + } + var visibleStderr bytes.Buffer + + err = (BaseDetector{Logger: logger, WorkingDir: workingDir}).Install( + context.Background(), + sdk.DetectionRequest{InstallArgs: args, Stderr: &visibleStderr, Verbose: true}, + executable, + []string{"-test.run=TestNodeInstallLoggingHelper", "--"}, + "test detector", + ) + if err != nil { + t.Fatalf("Install() error = %v", err) + } + if !strings.Contains(visibleStderr.String(), "stderr-secret") { + t.Fatalf("subprocess stderr was not mirrored in debug mode: %q", visibleStderr.String()) + } + + entries := observed.FilterMessage("running detector install-first").All() + if len(entries) != 1 { + t.Fatalf("command logs = %#v", observed.All()) + } + fields := entries[0].ContextMap() + rendered := fmt.Sprint(fields) + for _, secret := range []string{"token-secret", "url-secret", "stderr-secret", "user"} { + if strings.Contains(rendered, secret) { + t.Fatalf("command log retained %q: %s", secret, rendered) + } + } + if fields["executable"] != executable || fields["working_dir"] != workingDir || + !strings.Contains(rendered, "--color=always") || + !strings.Contains(rendered, "[REDACTED]") { + t.Fatalf("command log lost reproducible fields: %#v", fields) + } +} + +func TestNodeInstallLoggingHelper(t *testing.T) { + if os.Getenv("BOMLY_NODE_INSTALL_HELPER") != "1" { + return + } + _, _ = fmt.Fprintln(os.Stderr, "stderr-secret") +} diff --git a/internal/detectors/pub/pub_native.go b/internal/detectors/pub/pub_native.go index 35037f8c..26dfb4f2 100644 --- a/internal/detectors/pub/pub_native.go +++ b/internal/detectors/pub/pub_native.go @@ -57,15 +57,17 @@ func (d NativeDetector) ResolveGraph(_ context.Context, req sdk.DetectionRequest d.Logger = req.DetectorLogger(d.Logger) logger := d.logger() workingDir := d.workingDir(req.ProjectPath) + executable := "dart" + args := []string{"pub", "deps", "--json"} - cmd := system.Command("dart", "pub", "deps", "--json") + cmd := system.Command(executable, args...) cmd.Dir = workingDir var out bytes.Buffer cmd.Stdout = &out cmd.Stderr = logging.NewCommandStderr(req.Stderr, req.Verbose) started := time.Now() - logger.Debug("running pub native detector", zap.String("working_dir", workingDir)) + logger.Debug("running pub native detector", logging.CommandFields(executable, args, workingDir)...) if err := cmd.Run(); err != nil { logger.Debug("dart pub deps failed", zap.Error(err)) return sdk.DetectionResult{}, fmt.Errorf("dart pub deps: %w", err) diff --git a/internal/detectors/python/common.go b/internal/detectors/python/common.go index 3508f139..3e2dab30 100644 --- a/internal/detectors/python/common.go +++ b/internal/detectors/python/common.go @@ -99,13 +99,13 @@ func (d baseDetector) resolveGraph(req sdk.DetectionRequest, detectorName string cmd.Stderr = commandStderr started := time.Now() - sanitizedCommand := sanitizeCommand(command) - logger.Debug("running external dependency detector", zap.String("detector", detectorName), zap.String("working_dir", cmd.Dir), zap.String("executable", sanitizedCommand[0]), zap.Strings("args", sanitizedCommand[1:])) + logger.Debug("running external dependency detector", + append([]zap.Field{zap.String("detector", detectorName)}, logging.CommandFields(command[0], command[1:], cmd.Dir)...)...) if err := cmd.Run(); err != nil { logger.Warn(fmt.Sprintf("%s failed: %v", detectorName, err)) fields := []zap.Field{zap.Error(err), zap.String("detector", detectorName)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("external dependency detector failure details", fields...) return nil, fmt.Errorf("run %s: %w", detectorName, err) @@ -143,12 +143,12 @@ func (d baseDetector) install(ctx context.Context, req sdk.DetectionRequest, det cmd.Stderr = commandStderr started := time.Now() logger.Info(fmt.Sprintf("%s running install-first step", detectorName)) - sanitizedCommand := sanitizeCommand(command) - logger.Debug("running python detector install-first", zap.String("detector", detectorName), zap.String("working_dir", cmd.Dir), zap.String("executable", sanitizedCommand[0]), zap.Strings("args", sanitizedCommand[1:])) + logger.Debug("running python detector install-first", + append([]zap.Field{zap.String("detector", detectorName)}, logging.CommandFields(command[0], command[1:], cmd.Dir)...)...) if err := cmd.Run(); err != nil { fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("python detector install-first failure details", fields...) return fmt.Errorf("run %s install step: %w", detectorName, err) diff --git a/internal/detectors/python/pip_resolution_test.go b/internal/detectors/python/pip_resolution_test.go index 6711636d..1e7d39f9 100644 --- a/internal/detectors/python/pip_resolution_test.go +++ b/internal/detectors/python/pip_resolution_test.go @@ -8,6 +8,7 @@ import ( "strings" "testing" + "github.com/bomly-dev/bomly-cli/internal/logging" "github.com/bomly-dev/bomly-cli/internal/testutil" "github.com/bomly-dev/bomly-cli/sdk" ) @@ -121,7 +122,7 @@ func TestPipDetectorDoesNotReturnAmbientPipAuditEnvironment(t *testing.T) { } func TestSanitizeCommandRedactsCredentials(t *testing.T) { - got := sanitizeCommand([]string{"python", "-m", "pip", "install", "--password", "secret", "--index-url=https://user:token@example.com/simple"}) + got := logging.SanitizeArgs([]string{"python", "-m", "pip", "install", "--password", "secret", "--index-url=https://user:token@example.com/simple"}) joined := strings.Join(got, " ") if strings.Contains(joined, "secret") || strings.Contains(joined, "token") { t.Fatalf("credentials were not redacted: %v", got) diff --git a/internal/detectors/python/pipenv.go b/internal/detectors/python/pipenv.go index cbd7eb9a..4d387837 100644 --- a/internal/detectors/python/pipenv.go +++ b/internal/detectors/python/pipenv.go @@ -4,11 +4,13 @@ import ( "context" "encoding/json" "fmt" + "io" "os" "path/filepath" "strings" "github.com/bomly-dev/bomly-cli/internal/detectors" + "github.com/bomly-dev/bomly-cli/internal/logging" "github.com/bomly-dev/bomly-cli/internal/system" "github.com/bomly-dev/bomly-cli/sdk" "go.uber.org/zap" @@ -70,7 +72,7 @@ func (d PipenvDetector) ResolveGraph(ctx context.Context, req sdk.DetectionReque // Pipfile.lock is flat (no parent-child edges), so the build tool wins here. // Only attempt pip inspect when a venv is already populated; otherwise `pipenv run` // silently creates an empty venv and pip inspect returns only bootstrap packages. - if pipenvVenvExists(workingDir) { + if pipenvVenvExists(workingDir, logger, req.Stderr, req.Verbose) { command, err := pipInspectCommand("pipenv", "run") if err == nil { if depsGraph, err := base.resolveGraph(req, "Pipenv detector", command); err == nil { @@ -88,7 +90,7 @@ func (d PipenvDetector) ResolveGraph(ctx context.Context, req sdk.DetectionReque if lockPath := filepath.Join(workingDir, "Pipfile.lock"); fileExists(lockPath) { installCommand := pipenvSyncCommand(req) - if err := base.install(ctx, req, "Pipenv detector", installCommand); err == nil && pipenvVenvExists(workingDir) { + if err := base.install(ctx, req, "Pipenv detector", installCommand); err == nil && pipenvVenvExists(workingDir, logger, req.Stderr, req.Verbose) { if command, err := pipInspectCommand("pipenv", "run"); err == nil { if depsGraph, err := base.resolveGraph(req, "Pipenv detector", command); err == nil { annotateGraphScopes(depsGraph, workingDir) @@ -140,9 +142,13 @@ func (d PipenvDetector) Install(ctx context.Context, req sdk.DetectionRequest) e // pipenvVenvExists checks whether a pipenv virtual environment has been created // for the given working directory. It avoids triggering lazy venv creation. -func pipenvVenvExists(workingDir string) bool { - cmd := system.Command("pipenv", "--venv") +func pipenvVenvExists(workingDir string, logger *zap.Logger, stderr io.Writer, debug bool) bool { + executable := "pipenv" + args := []string{"--venv"} + cmd := system.Command(executable, args...) cmd.Dir = workingDir + cmd.Stderr = logging.NewCommandStderr(stderr, debug) + logger.Debug("checking Pipenv virtualenv", logging.CommandFields(executable, args, workingDir)...) out, err := cmd.Output() if err != nil { return false diff --git a/internal/detectors/python/resolution.go b/internal/detectors/python/resolution.go index 4982cc26..e0c5f8a7 100644 --- a/internal/detectors/python/resolution.go +++ b/internal/detectors/python/resolution.go @@ -2,23 +2,13 @@ package python import ( "fmt" - "net/url" - "strings" "github.com/bomly-dev/bomly-cli/internal/detectors" + "github.com/bomly-dev/bomly-cli/internal/logging" "github.com/bomly-dev/bomly-cli/sdk" "go.uber.org/zap" ) -var sensitiveCommandFlags = map[string]struct{}{ - "--password": {}, - "--token": {}, - "--access-token": {}, - "--client-secret": {}, - "--secret": {}, - "--key": {}, -} - func manifestWithResolution(req sdk.DetectionRequest, patterns []string, resolution *sdk.ResolutionMetadata) sdk.ManifestMetadata { manifest := detectors.InferManifestMetadata(req, patterns) manifest.Resolution = resolution @@ -31,51 +21,12 @@ func resolutionMetadata(method sdk.ResolutionMethod, installExecuted bool, insta InstallExecuted: installExecuted, } if installExecuted && len(installCommand) > 0 { - out.InstallCommand = sanitizeCommand(installCommand) + out.InstallCommand = logging.SanitizeArgs(installCommand) out.InstallWorkingDir = workingDir } return out } -func sanitizeCommand(command []string) []string { - out := make([]string, len(command)) - redactNext := false - for i, value := range command { - if redactNext { - out[i] = "[REDACTED]" - redactNext = false - continue - } - if flag, valuePart, ok := strings.Cut(value, "="); ok { - if _, sensitive := sensitiveCommandFlags[flag]; sensitive { - out[i] = flag + "=[REDACTED]" - continue - } - out[i] = flag + "=" + redactURL(valuePart) - continue - } - if _, sensitive := sensitiveCommandFlags[value]; sensitive { - out[i] = value - redactNext = true - continue - } - out[i] = redactURL(value) - } - return out -} - -func redactURL(value string) string { - if !strings.Contains(value, "://") { - return value - } - parsed, err := url.Parse(value) - if err != nil || parsed.User == nil { - return value - } - parsed.User = url.User("[REDACTED]") - return parsed.String() -} - func logResolution(logger *zap.Logger, detectorName string, workingDir string, resolution *sdk.ResolutionMetadata) { if logger == nil { logger = zap.NewNop() diff --git a/internal/detectors/python/venv.go b/internal/detectors/python/venv.go index d0cea19a..9364147f 100644 --- a/internal/detectors/python/venv.go +++ b/internal/detectors/python/venv.go @@ -80,12 +80,13 @@ func createPythonVenv(ctx context.Context, base baseDetector, req sdk.DetectionR cmd.Stderr = commandStderr started := time.Now() logger.Info(fmt.Sprintf("%s creating isolated virtualenv", detectorName)) - sanitizedCommand := sanitizeCommand(command) - logger.Debug("creating python virtualenv", zap.String("detector", detectorName), zap.String("working_dir", cmd.Dir), zap.String("venv", venvDir), zap.String("executable", sanitizedCommand[0]), zap.Strings("args", sanitizedCommand[1:])) + fields := []zap.Field{zap.String("detector", detectorName), zap.String("venv", venvDir)} + fields = append(fields, logging.CommandFields(command[0], command[1:], cmd.Dir)...) + logger.Debug("creating python virtualenv", fields...) if err := cmd.Run(); err != nil { fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("python virtualenv creation failed", fields...) return "", fmt.Errorf("create venv: %w", err) diff --git a/internal/detectors/ruby/detector.go b/internal/detectors/ruby/detector.go index 864b9b50..04c54d38 100644 --- a/internal/detectors/ruby/detector.go +++ b/internal/detectors/ruby/detector.go @@ -132,11 +132,11 @@ func (d Detector) Install(_ context.Context, req sdk.DetectionRequest) error { started := time.Now() logger.Info("Bundler detector running install-first step") - logger.Debug("running bundler detector install-first", zap.String("working_dir", cmd.Dir), zap.String("executable", bundlePath), zap.Strings("args", args)) + logger.Debug("running bundler detector install-first", logging.CommandFields(bundlePath, args, cmd.Dir)...) if err := cmd.Run(); err != nil { fields := []zap.Field{zap.Error(err)} - if commandStderr.String() != "" { - fields = append(fields, zap.String("stderr", commandStderr.String())) + if commandStderr.ByteCount() > 0 { + fields = append(fields, zap.Int64("stderr_bytes", commandStderr.ByteCount())) } logger.Debug("bundler detector install-first failure details", fields...) return fmt.Errorf("run bundle install: %w", err) diff --git a/internal/detectors/sbt/detector_test.go b/internal/detectors/sbt/detector_test.go index 797c2cdf..fb4a5bb7 100644 --- a/internal/detectors/sbt/detector_test.go +++ b/internal/detectors/sbt/detector_test.go @@ -100,8 +100,9 @@ func TestNativeDetectorReadyRequiresJava(t *testing.T) { if err == nil { t.Fatal("expected detector to be not ready without a usable Java runtime") } - if !strings.Contains(err.Error(), "Unable to locate a Java Runtime") { - t.Fatalf("expected Java runtime reason, got %q", err) + if !strings.Contains(err.Error(), "diagnostic bytes:") || + strings.Contains(err.Error(), "Unable to locate a Java Runtime") { + t.Fatalf("expected secret-safe Java runtime reason, got %q", err) } } diff --git a/internal/detectors/sbt/sbt_native.go b/internal/detectors/sbt/sbt_native.go index 1c74c9e7..7d332f1f 100644 --- a/internal/detectors/sbt/sbt_native.go +++ b/internal/detectors/sbt/sbt_native.go @@ -34,11 +34,11 @@ func (d NativeDetector) PackageManagerSupport() []sdk.PackageManagerSupport { } // Ready reports whether the sbt binary and a usable Java runtime are available. -func (d NativeDetector) Ready(ctx context.Context, _ sdk.DetectionRequest) error { +func (d NativeDetector) Ready(ctx context.Context, req sdk.DetectionRequest) error { if _, err := system.LookPath("sbt"); err != nil { return detectors.CommandNotReadyError("sbt", err) } - return detectors.JavaReady(ctx) + return detectors.JavaReady(ctx, req.DetectorLogger(d.Logger)) } // Applicable reports whether sbt build files are present. @@ -80,14 +80,16 @@ func (d NativeDetector) ResolveGraph(ctx context.Context, req sdk.DetectionReque cmdCtx, cancel := detectors.BuildToolContext(ctx) defer cancel() - cmd := system.CommandContext(cmdCtx, "sbt", "--no-colors", "--batch", "dependencyTree") + executable := "sbt" + args := []string{"--no-colors", "--batch", "dependencyTree"} + cmd := system.CommandContext(cmdCtx, executable, args...) cmd.Dir = workingDir var out bytes.Buffer cmd.Stdout = &out cmd.Stderr = logging.NewCommandStderr(req.Stderr, req.Verbose) started := time.Now() - logger.Debug("running sbt native detector", zap.String("working_dir", workingDir)) + logger.Debug("running sbt native detector", logging.CommandFields(executable, args, workingDir)...) if err := cmd.Run(); err != nil { if errors.Is(cmdCtx.Err(), context.DeadlineExceeded) { err = fmt.Errorf("timed out after %s: %w", detectors.BuildToolTimeout, err) diff --git a/internal/detectors/swiftpm/swiftpm_native.go b/internal/detectors/swiftpm/swiftpm_native.go index 40a6849b..d97468e8 100644 --- a/internal/detectors/swiftpm/swiftpm_native.go +++ b/internal/detectors/swiftpm/swiftpm_native.go @@ -57,15 +57,17 @@ func (d NativeDetector) ResolveGraph(_ context.Context, req sdk.DetectionRequest d.Logger = req.DetectorLogger(d.Logger) logger := d.logger() workingDir := d.workingDir(req.ProjectPath) + executable := "swift" + args := []string{"package", "show-dependencies", "--format", "json"} - cmd := system.Command("swift", "package", "show-dependencies", "--format", "json") + cmd := system.Command(executable, args...) cmd.Dir = workingDir var out bytes.Buffer cmd.Stdout = &out cmd.Stderr = logging.NewCommandStderr(req.Stderr, req.Verbose) started := time.Now() - logger.Debug("running SwiftPM native detector", zap.String("working_dir", workingDir)) + logger.Debug("running SwiftPM native detector", logging.CommandFields(executable, args, workingDir)...) if err := cmd.Run(); err != nil { logger.Debug("swift package show-dependencies failed", zap.Error(err)) return sdk.DetectionResult{}, fmt.Errorf("swift package show-dependencies: %w", err) diff --git a/internal/detectors/syft/resolve_external.go b/internal/detectors/syft/resolve_external.go index b9396ec9..4a5233f6 100644 --- a/internal/detectors/syft/resolve_external.go +++ b/internal/detectors/syft/resolve_external.go @@ -36,19 +36,21 @@ func (d Detector) ResolveGraph(ctx context.Context, req sdk.DetectionRequest) (s } started := time.Now() - logger.Debug("running external syft detector", zap.String("target", target)) + args := syftCommandArgs(target, req) + logger.Debug("running external syft detector", logging.CommandFields("syft", args, workingDir)...) if req.EnrichmentEnabled { logger.Debug("enabling syft CLI detector enrichment", zap.Strings("enrich", syftDetectorEnrichmentValues)) } - var stdout, stderr bytes.Buffer - cmd := system.Command("syft", syftCommandArgs(target, req)...) + var stdout bytes.Buffer + commandStderr := logging.NewCommandStderr(req.Stderr, req.Verbose) + cmd := system.Command("syft", args...) cmd.Dir = workingDir cmd.Stdout = &stdout - cmd.Stderr = &stderr + cmd.Stderr = commandStderr if err := cmd.Run(); err != nil { - logger.Warn(fmt.Sprintf("syft CLI failed: %v (stderr: %s)", err, stderr.String())) + logger.Warn("syft CLI failed", zap.Error(err), zap.Int64("stderr_bytes", commandStderr.ByteCount())) return sdk.DetectionResult{}, fmt.Errorf("run syft: %w", err) } diff --git a/internal/engine/pipeline_resolve.go b/internal/engine/pipeline_resolve.go index 5514f8c2..a63c9961 100644 --- a/internal/engine/pipeline_resolve.go +++ b/internal/engine/pipeline_resolve.go @@ -131,19 +131,20 @@ func resolveWorkerCount(subprojectCount int) int { func (p *Pipeline) resolveSubproject(ctx context.Context, req PipelineRequest, sub sdk.Subproject) ([]sdk.DetectionResult, error) { baseReq := sdk.DetectionRequest{ - ProjectPath: sub.ExecutionTarget.Location, - ExecutionTarget: sub.ExecutionTarget, - Subproject: sub, - Ecosystem: sub.Ecosystem, - PackageManager: sub.PrimaryPackageManager(), - EnrichmentEnabled: req.EnrichEnabled || req.MatchEnabled, - DetectorFilter: req.DetectorFilter, - ScopeFilter: req.ScopeFilter, - InstallFirst: req.InstallFirst, - InstallArgs: req.InstallArgs, - CoreVersion: req.CoreVersion, - Stderr: req.Stderr, - Verbose: req.Verbose, + ProjectPath: sub.ExecutionTarget.Location, + ExecutionTarget: sub.ExecutionTarget, + Subproject: sub, + Ecosystem: sub.Ecosystem, + PackageManager: sub.PrimaryPackageManager(), + EnrichmentEnabled: req.EnrichEnabled || req.MatchEnabled, + DetectorFilter: req.DetectorFilter, + ScopeFilter: req.ScopeFilter, + InstallFirst: req.InstallFirst, + InstallArgs: req.InstallArgs, + CoreVersion: req.CoreVersion, + AllowStdErrLogging: req.Verbose, + Stderr: req.Stderr, + Verbose: req.Verbose, } detectorNames := sub.PlannedDetectors @@ -321,7 +322,6 @@ func (p *Pipeline) resolveDetector(ctx context.Context, req sdk.DetectionRequest p.Logger.Debug("pipeline: running detector install-first", zap.String("detector", descriptor.Name), zap.String("subproject", req.Subproject.RelativePath), - zap.Strings("install_args", req.InstallArgs), ) if err := installer.Install(ctx, req); err != nil { return p.resolveFallback(ctx, req, detector, fmt.Errorf("detector %s: install-first failed: %w", descriptor.Name, err), progress) diff --git a/internal/git/git.go b/internal/git/git.go index 37563575..b5844288 100644 --- a/internal/git/git.go +++ b/internal/git/git.go @@ -9,6 +9,7 @@ import ( "strconv" "strings" + "github.com/bomly-dev/bomly-cli/internal/logging" "github.com/bomly-dev/bomly-cli/internal/system" "go.uber.org/zap" ) @@ -40,7 +41,7 @@ func CloneTemp(logger *zap.Logger, repoURL, ref string) (string, error) { } // FindRepoRoot resolves the git repository root for path. -func FindRepoRoot(path string) (string, error) { +func FindRepoRoot(logger *zap.Logger, path string) (string, error) { if err := ensureGitAvailable(); err != nil { return "", err } @@ -51,7 +52,7 @@ func FindRepoRoot(path string) (string, error) { if err != nil { return "", fmt.Errorf("resolve path %q: %w", path, err) } - stdout, err := runGit(absPath, "rev-parse", "--show-toplevel") + stdout, err := runGit(logger, absPath, "rev-parse", "--show-toplevel") if err != nil { return "", fmt.Errorf("find git repository root for %q: %w", absPath, err) } @@ -59,11 +60,11 @@ func FindRepoRoot(path string) (string, error) { } // VerifyRef verifies that ref resolves to a commit in repoPath. -func VerifyRef(repoPath, ref string) error { +func VerifyRef(logger *zap.Logger, repoPath, ref string) error { if ref == "" { return fmt.Errorf("ref is empty") } - if _, err := resolveCommit(repoPath, ref); err != nil { + if _, err := resolveCommit(logger, repoPath, ref); err != nil { return fmt.Errorf("verify git ref %q: %w", ref, err) } return nil @@ -72,11 +73,11 @@ func VerifyRef(repoPath, ref string) error { // ChangedLineRanges returns added/changed head-side line ranges from a git // diff. Deleted-only hunks are omitted because there is no head line for SARIF // to annotate. -func ChangedLineRanges(repoPath, baseRef, headRef string) (map[string][]LineRange, error) { +func ChangedLineRanges(logger *zap.Logger, repoPath, baseRef, headRef string) (map[string][]LineRange, error) { if err := ensureGitAvailable(); err != nil { return nil, err } - out, err := runGit(repoPath, "diff", "--unified=0", "--no-ext-diff", "--no-color", baseRef, headRef) + out, err := runGit(logger, repoPath, "diff", "--unified=0", "--no-ext-diff", "--no-color", baseRef, headRef) if err != nil { return nil, fmt.Errorf("git diff %q..%q: %w", baseRef, headRef, err) } @@ -88,7 +89,7 @@ func CheckoutRef(logger *zap.Logger, repoPath, ref string) error { if ref == "" { return fmt.Errorf("ref is empty") } - commit, err := resolveCommit(repoPath, ref) + commit, err := resolveCommit(logger, repoPath, ref) if err != nil { return err } @@ -101,13 +102,13 @@ func MaterializeLocalRef(logger *zap.Logger, sourceRepoPath, ref string) (string if err := ensureGitAvailable(); err != nil { return "", err } - root, err := FindRepoRoot(sourceRepoPath) + root, err := FindRepoRoot(logger, sourceRepoPath) if err != nil { return "", err } resolvedRef := "" if ref != "" { - resolvedRef, err = resolveCommit(root, ref) + resolvedRef, err = resolveCommit(logger, root, ref) if err != nil { return "", err } @@ -137,17 +138,18 @@ func ensureGitAvailable() error { } func cloneInto(logger *zap.Logger, source, dest, ref string, local bool) error { + safeSource := logging.SanitizeURL(source) args := []string{"clone", "--quiet"} if local { args = append(args, "--local") } args = append(args, source, dest) - if _, err := runGit("", args...); err != nil { + if _, err := runGit(logger, "", args...); err != nil { if logger != nil { logger.Error(fmt.Sprintf("Git clone failed: %v", err)) - logger.Debug("git clone failure details", zap.String("source", source), zap.String("destination", dest), zap.Error(err)) + logger.Debug("git clone failure details", zap.String("source", safeSource), zap.String("destination", dest), zap.Error(err)) } - return fmt.Errorf("clone git repository %q: %w", source, err) + return fmt.Errorf("clone git repository %q: %w", safeSource, err) } if ref != "" { if err := CheckoutRef(logger, dest, ref); err != nil { @@ -157,9 +159,9 @@ func cloneInto(logger *zap.Logger, source, dest, ref string, local bool) error { return nil } -func resolveCommit(repoPath, ref string) (string, error) { +func resolveCommit(logger *zap.Logger, repoPath, ref string) (string, error) { for _, candidate := range refResolutionCandidates(ref) { - stdout, err := runGit(repoPath, "rev-parse", "--verify", candidate+"^{commit}") + stdout, err := runGit(logger, repoPath, "rev-parse", "--verify", candidate+"^{commit}") if err == nil { return strings.TrimSpace(stdout), nil } @@ -176,7 +178,7 @@ func refResolutionCandidates(ref string) []string { } func checkoutCommit(logger *zap.Logger, repoPath, commit, originalRef string) error { - if _, err := runGit(repoPath, "checkout", "--quiet", "--detach", commit); err != nil { + if _, err := runGit(logger, repoPath, "checkout", "--quiet", "--detach", commit); err != nil { if logger != nil { logger.Error(fmt.Sprintf("Git checkout failed: %v", err)) logger.Debug("git checkout failure details", zap.String("repository", repoPath), zap.String("ref", originalRef), zap.String("commit", commit), zap.Error(err)) @@ -186,21 +188,25 @@ func checkoutCommit(logger *zap.Logger, repoPath, commit, originalRef string) er return nil } -func runGit(workingDir string, args ...string) (string, error) { +func runGit(logger *zap.Logger, workingDir string, args ...string) (string, error) { + if logger == nil { + logger = zap.NewNop() + } + logger.Debug("running Git command", logging.CommandFields("git", args, workingDir)...) cmd := system.Command("git", args...) if workingDir != "" { cmd.Dir = workingDir } var stdout bytes.Buffer - var stderr bytes.Buffer + var diagnostics bytes.Buffer cmd.Stdout = &stdout - cmd.Stderr = &stderr - if err := cmd.Run(); err != nil { - message := strings.TrimSpace(stderr.String()) - if message == "" { - return "", err - } - return "", fmt.Errorf("%w: %s", err, message) + cmd.Stderr = &diagnostics + err := cmd.Run() + if message := strings.TrimSpace(diagnostics.String()); message != "" { + logger.Debug("Git command diagnostics", zap.String("stderr", message)) + } + if err != nil { + return "", fmt.Errorf("%w (stderr bytes: %d)", err, diagnostics.Len()) } return stdout.String(), nil } diff --git a/internal/git/git_test.go b/internal/git/git_test.go index ec6a293f..ad7ea9c9 100644 --- a/internal/git/git_test.go +++ b/internal/git/git_test.go @@ -1,14 +1,34 @@ package git import ( + "errors" "os" "os/exec" "path/filepath" "runtime" "strings" "testing" + + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" ) +func TestCloneIntoRedactsUserinfoAndPreservesExitError(t *testing.T) { + requireGit(t) + const source = "unsupported://user:clone-secret@example.test/repository" + err := cloneInto(nil, source, filepath.Join(t.TempDir(), "clone"), "", false) + if err == nil { + t.Fatal("cloneInto() error = nil, want unsupported transport error") + } + var exitErr *exec.ExitError + if !errors.As(err, &exitErr) { + t.Fatalf("cloneInto() did not preserve exec.ExitError: %v", err) + } + if strings.Contains(err.Error(), "user") || strings.Contains(err.Error(), "clone-secret") { + t.Fatalf("cloneInto() exposed URL user information: %v", err) + } +} + func TestCloneTempMaterializesRequestedCommitWithoutChangingSource(t *testing.T) { sourceRepo, mainSHA, featureSHA := createGitRepoWithFeatureBranch(t) @@ -65,7 +85,7 @@ func TestMaterializeLocalRefKeepsRepositorySymlinksAsSymlinks(t *testing.T) { func TestResolveCommitWithSHA(t *testing.T) { repoDir, headSHA, _ := createGitRepoWithFeatureBranch(t) - resolved, err := resolveCommit(repoDir, headSHA) + resolved, err := resolveCommit(nil, repoDir, headSHA) if err != nil { t.Fatalf("resolveCommit() error = %v", err) } @@ -79,11 +99,11 @@ func TestResolveCommitWithRemoteTrackingBranch(t *testing.T) { cloneDir := filepath.Join(t.TempDir(), "clone") runGitCommand(t, "", "clone", "--quiet", sourceRepo, cloneDir) - if err := VerifyRef(cloneDir, "feature"); err != nil { + if err := VerifyRef(nil, cloneDir, "feature"); err != nil { t.Fatalf("VerifyRef() error = %v", err) } - resolved, err := resolveCommit(cloneDir, "feature") + resolved, err := resolveCommit(nil, cloneDir, "feature") if err != nil { t.Fatalf("resolveCommit() error = %v", err) } @@ -95,7 +115,7 @@ func TestResolveCommitWithRemoteTrackingBranch(t *testing.T) { func TestResolveCommitWithMissingRef(t *testing.T) { repoDir, _, _ := createGitRepoWithFeatureBranch(t) - _, err := resolveCommit(repoDir, "missing-branch") + _, err := resolveCommit(nil, repoDir, "missing-branch") if err == nil { t.Fatal("resolveCommit() error = nil, want error") } @@ -104,6 +124,23 @@ func TestResolveCommitWithMissingRef(t *testing.T) { } } +func TestRunGitLogsStderrAtDebug(t *testing.T) { + requireGit(t) + core, observed := observer.New(zap.DebugLevel) + + if _, err := runGit(zap.New(core), t.TempDir(), "rev-parse", "--verify", "missing-ref^{commit}"); err == nil { + t.Fatal("runGit() error = nil, want error") + } + + entries := observed.FilterMessage("Git command diagnostics").All() + if len(entries) != 1 { + t.Fatalf("Git diagnostic logs = %#v", observed.All()) + } + if stderr, _ := entries[0].ContextMap()["stderr"].(string); !strings.Contains(stderr, "fatal:") { + t.Fatalf("Git stderr log = %#v", entries[0].ContextMap()) + } +} + func createGitRepoWithFeatureBranch(t *testing.T) (string, string, string) { t.Helper() requireGit(t) diff --git a/internal/logging/command.go b/internal/logging/command.go new file mode 100644 index 00000000..1a431d7e --- /dev/null +++ b/internal/logging/command.go @@ -0,0 +1,111 @@ +package logging + +import ( + "net/url" + "os" + "strings" + "unicode" + + "go.uber.org/zap" +) + +const redactedArgument = "[REDACTED]" + +// SanitizeArgs returns a copy of args with credential values and URL user +// information removed. Non-secret arguments remain unchanged so DEBUG logs can +// still reproduce the command. +func SanitizeArgs(args []string) []string { + sanitized := make([]string, len(args)) + redactNext := false + for index, argument := range args { + if redactNext { + sanitized[index] = redactedArgument + redactNext = false + continue + } + if flag, value, found := strings.Cut(argument, "="); found { + if sensitiveFlag(flag) { + sanitized[index] = flag + "=" + redactedArgument + continue + } + sanitized[index] = flag + "=" + redactURLUserinfo(value) + continue + } + if strings.Contains(argument, "://") { + sanitized[index] = redactURLUserinfo(argument) + continue + } + if strings.HasPrefix(argument, "-") && sensitiveFlag(argument) { + sanitized[index] = argument + redactNext = true + continue + } + sanitized[index] = redactURLUserinfo(argument) + } + return sanitized +} + +// CommandFields returns the standard secret-safe DEBUG fields for a subprocess. +// Args are sanitized. The executable must be a resolved binary path or name, +// not a command string containing arguments or credentials. +func CommandFields(executable string, args []string, workingDir string) []zap.Field { + if strings.TrimSpace(workingDir) == "" { + if current, err := os.Getwd(); err == nil { + workingDir = current + } + } + return []zap.Field{ + zap.String("executable", executable), + zap.Strings("args", SanitizeArgs(args)), + zap.String("working_dir", workingDir), + } +} + +// SanitizeURL removes user information from a URL before it is logged. It +// fails closed when URL parsing fails. Query values are not inspected, so +// callers must not use this helper as a general query-string redactor. +func SanitizeURL(value string) string { + if !strings.Contains(value, "://") { + return value + } + parsed, err := url.Parse(value) + if err != nil { + return redactedArgument + } + parsed.User = nil + return parsed.String() +} + +func sensitiveFlag(value string) bool { + if value == "" { + return false + } + parts := strings.FieldsFunc(strings.ToLower(value), func(r rune) bool { + return !unicode.IsLetter(r) && !unicode.IsDigit(r) + }) + for _, part := range parts { + switch part { + case "password", "passwd", "token", "authtoken", "secret", + "credential", "credentials", "apikey", "username", "login", + "auth", "authorization", "bearer", "pat", "passphrase", "pass", + "pwd", "header": + return true + } + } + return len(parts) == 1 && parts[0] == "key" +} + +func redactURLUserinfo(value string) string { + if !strings.Contains(value, "://") { + return value + } + parsed, err := url.Parse(value) + if err != nil { + return redactedArgument + } + if parsed.User == nil { + return value + } + parsed.User = url.User(redactedArgument) + return parsed.String() +} diff --git a/internal/logging/command_test.go b/internal/logging/command_test.go new file mode 100644 index 00000000..1c1056af --- /dev/null +++ b/internal/logging/command_test.go @@ -0,0 +1,106 @@ +package logging + +import ( + "reflect" + "strings" + "testing" +) + +func TestSanitizeArgsRedactsCredentialValuesAndURLUserinfo(t *testing.T) { + input := []string{ + "install", + "--token", "plain-token", + "--password=plain-password", + "-Drepo.password=maven-password", + "--registry=https://user:registry-password@example.test/packages", + "git+https://git-user:git-token@example.test/repo.git", + "--auth", "auth-secret", + "--authorization=authorization-secret", + "--bearer", "bearer-secret", + "--pat=pat-secret", + "--passphrase", "passphrase-secret", + "--pass=pass-secret", + "--pwd", "pwd-secret", + "--header", "Authorization: Bearer header-secret", + "//registry.npmjs.org/:_authToken=npm-secret", + "--color=always", + "package-name", + } + original := append([]string(nil), input...) + + got := SanitizeArgs(input) + + if !reflect.DeepEqual(input, original) { + t.Fatalf("SanitizeArgs() mutated input:\nwant %#v\ngot %#v", original, input) + } + for _, secret := range []string{ + "plain-token", "plain-password", "maven-password", + "registry-password", "git-token", "git-user", "auth-secret", + "authorization-secret", "bearer-secret", "pat-secret", + "passphrase-secret", "pass-secret", "pwd-secret", "header-secret", + "npm-secret", + } { + if strings.Contains(strings.Join(got, " "), secret) { + t.Fatalf("SanitizeArgs() retained %q in %#v", secret, got) + } + } + wantUnchanged := []string{"install", "--token", "--color=always", "package-name"} + for _, value := range wantUnchanged { + if !containsArgument(got, value) { + t.Fatalf("SanitizeArgs() removed reproducible argument %q from %#v", value, got) + } + } + if got[2] != redactedArgument || + got[3] != "--password="+redactedArgument || + got[4] != "-Drepo.password="+redactedArgument || + got[20] != "//registry.npmjs.org/:_authToken="+redactedArgument { + t.Fatalf("SanitizeArgs() credential forms = %#v", got) + } +} + +func TestSanitizeArgsDoesNotTreatOrdinaryAuthoredFlagsAsCredentials(t *testing.T) { + input := []string{ + "--author", "example", + "--user-agent=bomly", + "--sort-key", "name", + "--ssh-key=/tmp/id_ed25519.pub", + "https://example.test/public", + } + if got := SanitizeArgs(input); !reflect.DeepEqual(got, input) { + t.Fatalf("SanitizeArgs() changed ordinary args:\nwant %#v\ngot %#v", input, got) + } +} + +func TestSanitizeArgsDoesNotTreatPositionalArgumentsAsCredentialFlags(t *testing.T) { + input := []string{ + "install", "pass", "some-pkg", + "auth", "another-pkg", + "token", "final-pkg", + } + if got := SanitizeArgs(input); !reflect.DeepEqual(got, input) { + t.Fatalf("SanitizeArgs() changed positional args:\nwant %#v\ngot %#v", input, got) + } +} + +func TestSanitizeURLFailsClosedAndDoesNotInspectQueryValues(t *testing.T) { + if got := SanitizeURL("https://user:%zz@example.test/path"); got != redactedArgument { + t.Fatalf("SanitizeURL(malformed) = %q, want %q", got, redactedArgument) + } + + got := SanitizeURL("https://user:password@example.test/path?access_token=query-value") + if strings.Contains(got, "user") || strings.Contains(got, "password") { + t.Fatalf("SanitizeURL() retained user information: %q", got) + } + if !strings.Contains(got, "access_token=query-value") { + t.Fatalf("SanitizeURL() unexpectedly changed query values: %q", got) + } +} + +func containsArgument(values []string, want string) bool { + for _, value := range values { + if value == want { + return true + } + } + return false +} diff --git a/internal/logging/logger.go b/internal/logging/logger.go index 507e568d..f887b4d0 100644 --- a/internal/logging/logger.go +++ b/internal/logging/logger.go @@ -1,7 +1,6 @@ package logging import ( - "bytes" "encoding/json" "io" "strings" @@ -242,40 +241,37 @@ func cloneFieldValue(value any) any { } } -// CommandStderr captures subprocess stderr and only mirrors it when verbose mode is enabled. +// CommandStderr counts subprocess stderr and optionally mirrors it to the +// caller's debug output. It does not retain the contents. type CommandStderr struct { - buffer bytes.Buffer visible io.Writer - verbose bool + debug bool + bytes int64 } -// NewCommandStderr creates a subprocess stderr writer for the selected verbosity. -func NewCommandStderr(visible io.Writer, verbose bool) *CommandStderr { - return &CommandStderr{visible: visible, verbose: verbose} +// NewCommandStderr creates a subprocess stderr counter. When debug is true, +// writes are also forwarded to visible as they arrive. +func NewCommandStderr(visible io.Writer, debug bool) *CommandStderr { + return &CommandStderr{visible: visible, debug: debug} } -// Write records stderr output and mirrors it when verbose mode is enabled. +// Write records the byte count and mirrors the bytes when debug output is +// enabled. func (w *CommandStderr) Write(p []byte) (int, error) { if w == nil { return len(p), nil } - - if _, err := w.buffer.Write(p); err != nil { - return 0, err - } - if !w.verbose || w.visible == nil { - return len(p), nil - } - if _, err := w.visible.Write(p); err != nil { - return 0, err + w.bytes += int64(len(p)) + if w.debug && w.visible != nil { + return w.visible.Write(p) } return len(p), nil } -// String returns the captured stderr contents with surrounding whitespace trimmed. -func (w *CommandStderr) String() string { +// ByteCount returns the number of bytes written to subprocess stderr. +func (w *CommandStderr) ByteCount() int64 { if w == nil { - return "" + return 0 } - return strings.TrimSpace(w.buffer.String()) + return w.bytes } diff --git a/internal/logging/logger_test.go b/internal/logging/logger_test.go index 79ba592a..e782ee9a 100644 --- a/internal/logging/logger_test.go +++ b/internal/logging/logger_test.go @@ -31,11 +31,11 @@ func TestNewConsoleAndCommandStderr(t *testing.T) { if _, err := writer.Write([]byte("warn: noisy stderr\n")); err != nil { t.Fatalf("Write() error = %v", err) } - if got := writer.String(); got != "warn: noisy stderr" { - t.Fatalf("String() = %q", got) + if got := writer.ByteCount(); got != int64(len("warn: noisy stderr\n")) { + t.Fatalf("ByteCount() = %d", got) } if !strings.Contains(visible.String(), "warn: noisy stderr") { - t.Fatalf("expected visible writer mirroring, got %q", visible.String()) + t.Fatalf("expected debug writer mirroring, got %q", visible.String()) } } diff --git a/internal/matchers/grype/external.go b/internal/matchers/grype/external.go index 8f14a0ed..2ae1b676 100644 --- a/internal/matchers/grype/external.go +++ b/internal/matchers/grype/external.go @@ -16,6 +16,7 @@ import ( "github.com/bomly-dev/bomly-cli/internal/sbom" "github.com/bomly-dev/bomly-cli/internal/system" "github.com/bomly-dev/bomly-cli/sdk" + "go.uber.org/zap" ) // Ready reports whether the external grype binary is available. @@ -48,15 +49,17 @@ func (a Matcher) Match(_ context.Context, req sdk.MatchRequest) (sdk.MatchResult return sdk.MatchResult{Registry: req.Registry, MatcherStats: grypeMatcherStats(0, 0, 0)}, fmt.Errorf("grype: serialize sbom: %w", err) } - var stdout, stderr bytes.Buffer - cmd := system.Command("grype", "-o", "json") + args := []string{"-o", "json"} + var stdout bytes.Buffer + commandStderr := logging.NewCommandStderr(req.Stderr, req.Stderr != nil) + cmd := system.Command("grype", args...) cmd.Stdin = bytes.NewReader(spdxBytes) cmd.Stdout = &stdout - cmd.Stderr = &stderr + cmd.Stderr = commandStderr - logger.Debug("running external grype matcher") + logger.Debug("running external grype matcher", logging.CommandFields("grype", args, cmd.Dir)...) if err := cmd.Run(); err != nil { - logger.Warn(fmt.Sprintf("grype CLI failed: %v (stderr: %s)", err, stderr.String())) + logger.Warn("grype CLI failed", zap.Error(err), zap.Int64("stderr_bytes", commandStderr.ByteCount())) return sdk.MatchResult{Registry: req.Registry, MatcherStats: grypeMatcherStats(0, 0, 0)}, fmt.Errorf("grype match failed: %w", err) } diff --git a/internal/plugin/runtime/hashicorp/runtime.go b/internal/plugin/runtime/hashicorp/runtime.go index 8d2085c7..d05394fb 100644 --- a/internal/plugin/runtime/hashicorp/runtime.go +++ b/internal/plugin/runtime/hashicorp/runtime.go @@ -3,8 +3,10 @@ package hashicorp import ( "context" "fmt" + "os" "os/exec" + "github.com/bomly-dev/bomly-cli/internal/logging" "github.com/bomly-dev/bomly-cli/sdk" "github.com/hashicorp/go-hclog" hplugin "github.com/hashicorp/go-plugin" @@ -20,14 +22,23 @@ type Client struct { func Start(ctx context.Context, executable string, env []string, verbosity int) (*Client, error) { cmd := exec.CommandContext(ctx, executable) cmd.Env = append(cmd.Env, env...) + workingDir, _ := os.Getwd() + eventLogger := pluginLogger(verbosity) + eventLogger.Debug("starting plugin subprocess", + "executable", executable, + "args", logging.SanitizeArgs(cmd.Args[1:]), + "working_dir", workingDir, + ) client := hplugin.NewClient(&hplugin.ClientConfig{ HandshakeConfig: sdk.HandshakeConfig(), AllowedProtocols: []hplugin.Protocol{hplugin.ProtocolGRPC}, Cmd: cmd, - Logger: pluginLogger(verbosity), - Plugins: sdk.ClientPluginMap(), - Managed: true, - GRPCDialOptions: nil, + // Managed plugin stderr is visible only with debug logging. The plugin + // owns this output, so users must treat debug logs as sensitive. + Logger: pluginLogger(verbosity), + Plugins: sdk.ClientPluginMap(), + Managed: true, + GRPCDialOptions: nil, }) rpcClient, err := client.Client() @@ -49,16 +60,12 @@ func Start(ctx context.Context, executable string, env []string, verbosity int) } func pluginLogger(verbosity int) hclog.Logger { - if verbosity <= 0 { + if verbosity < 2 { return hclog.NewNullLogger() } - level := hclog.Info - if verbosity >= 2 { - level = hclog.Debug - } return hclog.New(&hclog.LoggerOptions{ Name: "plugin", - Level: level, + Level: hclog.Debug, }) } diff --git a/internal/registry/builder.go b/internal/registry/builder.go index d84c7bff..494d2a98 100644 --- a/internal/registry/builder.go +++ b/internal/registry/builder.go @@ -3,7 +3,6 @@ package registry import ( "context" "fmt" - "net/url" "sort" "strconv" "strings" @@ -34,6 +33,7 @@ import ( "github.com/bomly-dev/bomly-cli/internal/detectors/sbt" "github.com/bomly-dev/bomly-cli/internal/detectors/swiftpm" "github.com/bomly-dev/bomly-cli/internal/detectors/syft" + "github.com/bomly-dev/bomly-cli/internal/logging" "github.com/bomly-dev/bomly-cli/internal/matchers/depsdev" "github.com/bomly-dev/bomly-cli/internal/matchers/grype" osvmatcher "github.com/bomly-dev/bomly-cli/internal/matchers/osv" @@ -390,21 +390,12 @@ func (r *Registry) registerScorecardMatcher() { r.RegisterMatcherWithOptions(matcher, ComponentOptions{DefaultEnabled: false}) } r.logger.Debug("scorecard matcher configured", - zap.String("api_base", endpointForLog(scoreCfg.APIBase)), + zap.String("api_base", logging.SanitizeURL(scoreCfg.APIBase)), zap.String("cache_dir", scoreCfg.CacheDir), zap.Duration("cache_ttl", scoreCfg.CacheTTL), ) } -func endpointForLog(value string) string { - parsed, err := url.Parse(value) - if err != nil { - return "[invalid URL]" - } - parsed.User = nil - return parsed.String() -} - func (r *Registry) httpClientProvider() *sdk.HTTPClientProvider { if r.httpProvider != nil { return r.httpProvider diff --git a/sdk/detector.go b/sdk/detector.go index 9942209d..a3cb57ec 100644 --- a/sdk/detector.go +++ b/sdk/detector.go @@ -32,16 +32,21 @@ type DetectionRequest struct { PackageManager PackageManager `json:"packageManager,omitempty"` // EnrichmentEnabled allows orchestration to request detector-time metadata // enrichment when a downstream command has opted into package enrichment. - EnrichmentEnabled bool `json:"enrichmentEnabled,omitempty"` - DetectorFilter DetectorFilter `json:"detectorFilter"` - ScopeFilter Scope `json:"scopeFilter,omitempty"` - Query DependencyQuery `json:"query"` - InstallFirst bool `json:"installFirst,omitempty"` - InstallArgs []string `json:"installArgs,omitempty"` - CoreVersion string `json:"coreVersion,omitempty"` - AllowStdErrLogging bool `json:"allowStdErrLogging,omitempty"` - Stderr io.Writer `json:"-"` - Verbose bool `json:"-"` + EnrichmentEnabled bool `json:"enrichmentEnabled,omitempty"` + DetectorFilter DetectorFilter `json:"detectorFilter"` + ScopeFilter Scope `json:"scopeFilter,omitempty"` + Query DependencyQuery `json:"query"` + InstallFirst bool `json:"installFirst,omitempty"` + InstallArgs []string `json:"installArgs,omitempty"` + CoreVersion string `json:"coreVersion,omitempty"` + // AllowStdErrLogging tells a detector that the user enabled debug output + // and accepts the detector's raw subprocess diagnostics in that output. + AllowStdErrLogging bool `json:"allowStdErrLogging,omitempty"` + // Stderr and Verbose are process-local fields used by built-in detectors. + // Stderr is nil unless debug output is enabled. Verbose mirrors + // AllowStdErrLogging for compatibility with existing detector code. + Stderr io.Writer `json:"-"` + Verbose bool `json:"-"` // Logger is a request-scoped logger injected by the pipeline, already // bound to the subproject and detector this request targets. It lets a // detector instance that is shared across concurrently-resolved