fix: prevent writing non-report output to stdout (#2324)

Signed-off-by: Keith Zantow <kzantow@gmail.com>

cmd/syft/cli/cli.go

@@ -1,6 +1,7 @@
 package cli
 
 import (
+	"io"
 	"os"
 
 	cranecmd "github.com/google/go-containerregistry/cmd/crane/cmd"
@@ -22,18 +23,18 @@ import (
 // It also constructs the syft attest command and the syft version command.
 // `RunE` is the earliest that the complete application configuration can be loaded.
 func Application(id clio.Identification) clio.Application {
-	app, _ := create(id)
-	return app
+	app, rootCmd := create(id, os.Stdout)
+	return ui.StdoutLoggingApplication(app, rootCmd)
 }
 
 // Command returns the root command for the syft CLI application. This is useful for embedding the entire syft CLI
 // into an existing application.
 func Command(id clio.Identification) *cobra.Command {
-	_, cmd := create(id)
+	_, cmd := create(id, os.Stdout)
 	return cmd
 }
 
-func create(id clio.Identification) (clio.Application, *cobra.Command) {
+func create(id clio.Identification, out io.Writer) (clio.Application, *cobra.Command) {
 	clioCfg := clio.NewSetupConfig(id).
 		WithGlobalConfigFlag().   // add persistent -c <path> for reading an application config from
 		WithGlobalLoggingFlags(). // add persistent -v and -q flags tied to the logging config
@@ -41,13 +42,13 @@ func create(id clio.Identification) (clio.Application, *cobra.Command) {
 		WithUIConstructor(
 			// select a UI based on the logging configuration and state of stdin (if stdin is a tty)
 			func(cfg clio.Config) ([]clio.UI, error) {
-				noUI := ui.None(cfg.Log.Quiet)
+				noUI := ui.None(out, cfg.Log.Quiet)
 				if !cfg.Log.AllowUI(os.Stdin) || cfg.Log.Quiet {
 					return []clio.UI{noUI}, nil
 				}
 
 				return []clio.UI{
-					ui.New(cfg.Log.Quiet,
+					ui.New(out, cfg.Log.Quiet,
 						handler.New(handler.DefaultHandlerConfig()),
 					),
 					noUI,

cmd/syft/internal/ui/__snapshots__/event_writer_test.snap

@@ -0,0 +1,41 @@
+
+[Test_writeEvents/no_events/stdout - 1]
+
+---
+
+[Test_writeEvents/no_events/stderr - 1]
+
+---
+
+[Test_writeEvents/all_events/stdout - 1]
+
+
+<my --
+-
+-
+report 1!!>
+<report 2>
+
+---
+
+[Test_writeEvents/all_events/stderr - 1]
+                    
+                    
+<my notification 1!!
+...still notifying> 
+                    
+                    
+<notification 2>
+<notification 3>
+A newer version of syft is available for download: v0.33.0 (installed version is [not provided])
+
+---
+
+[Test_writeEvents/quiet_only_shows_report/stdout - 1]
+<report 1>
+
+---
+
+[Test_writeEvents/quiet_only_shows_report/stderr - 1]
+
+---

cmd/syft/internal/ui/__snapshots__/post_ui_event_writer_test.snap

@@ -1,41 +0,0 @@
-
-[Test_postUIEventWriter_write/no_events/stdout - 1]
-
----
-
-[Test_postUIEventWriter_write/no_events/stderr - 1]
-
----
-
-[Test_postUIEventWriter_write/all_events/stdout - 1]
-
-
-<my --
--
--
-report 1!!>
-<report 2>
-
----
-
-[Test_postUIEventWriter_write/all_events/stderr - 1]
-                    
-                    
-<my notification 1!!
-...still notifying> 
-                    
-                    
-<notification 2>
-<notification 3>
-A newer version of syft is available for download: v0.33.0 (installed version is [not provided])
-
----
-
-[Test_postUIEventWriter_write/quiet_only_shows_report/stdout - 1]
-<report 1>
-
----
-
-[Test_postUIEventWriter_write/quiet_only_shows_report/stderr - 1]
-
----

cmd/syft/internal/ui/capture.go

@@ -0,0 +1,61 @@
+package ui
+
+import (
+	"io"
+	"os"
+	"time"
+
+	"github.com/anchore/syft/internal/log"
+)
+
+// capture replaces the provided *os.File and redirects output to the provided writer. The return value is a function,
+// which is used to stop the current capturing of output and restore the original file.
+// Example:
+//
+//	restore := capture(&os.Stderr, writer)
+//	// here, stderr will be captured and redirected to the provided writer
+//	restore() // block until the output has all been sent to the writer and restore the original stderr
+func capture(target **os.File, writer io.Writer, bufSize int) (close func()) {
+	original := *target
+
+	r, w, _ := os.Pipe()
+
+	*target = w
+
+	done := make(chan struct{}, 1)
+
+	go func() {
+		defer func() {
+			done <- struct{}{}
+		}()
+
+		buf := make([]byte, bufSize)
+		for {
+			if original == nil {
+				break
+			}
+
+			n, err := r.Read(buf)
+			if n > 0 {
+				_, _ = writer.Write(buf[0:n])
+			}
+
+			if err != nil {
+				break
+			}
+		}
+	}()
+
+	return func() {
+		if original != nil {
+			_ = w.Close()
+			select {
+			case <-done:
+			case <-time.After(1 * time.Second):
+				log.Debugf("stdout buffer timed out after 1 second")
+			}
+			*target = original
+			original = nil
+		}
+	}
+}

cmd/syft/internal/ui/capture_test.go

@@ -0,0 +1,85 @@
+package ui
+
+import (
+	"bytes"
+	"io"
+	"os"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+)
+
+func Test_capture(t *testing.T) {
+	r, w, _ := os.Pipe()
+	t.Logf("pipe1: %+v", w)
+
+	buf := &bytes.Buffer{}
+	buf2 := &bytes.Buffer{}
+
+	go func() {
+		// write to the main file (e.g. os.Stdout)
+		_, _ = w.WriteString("write1")
+
+		// capture the output to the provided buffer
+		restoreInitial := capture(&w, buf, 1024)
+		t.Logf("pipe2: %+v", w)
+		_, _ = w.WriteString("write2")
+
+		// capture output nested
+		restoreFirstCapture := capture(&w, buf2, 1024)
+		t.Logf("pipe3: %+v", w)
+		_, _ = w.WriteString("write3")
+
+		// discard file used to write the "write3"
+		restoreFirstCapture()
+
+		// restore should block until all output has been captured, so it's safe to read buf2 here
+		require.Equal(t, "write3", buf2.String())
+
+		// restore should be safe to call multiple times
+		restoreFirstCapture()
+		require.Equal(t, "write3", buf2.String())
+
+		// write again to the initial buffer
+		t.Logf("pipe2+: %+v", w)
+		_, _ = w.WriteString("write2+")
+
+		// restore the initial file (e.g. os.Stdout) and write more to it
+		restoreInitial()
+		t.Logf("pipe1+: %+v", w)
+		_, _ = w.WriteString("write1+")
+
+		// close the pipe to continue with the io.ReadAll, below
+		_ = w.Close()
+	}()
+
+	got, err := io.ReadAll(r)
+	require.NoError(t, err)
+	require.Equal(t, "write1write1+", string(got))
+
+	require.Equal(t, "write2write2+", buf.String())
+}
+
+func Test_captureBufSizes(t *testing.T) {
+	_, w, _ := os.Pipe()
+
+	buf := &bytes.Buffer{}
+	restore := capture(&w, buf, 200)
+
+	line := "line1\nline2\nline3"
+
+	_, err := w.WriteString(line)
+	require.NoError(t, err)
+
+	restore()
+	require.Equal(t, line, buf.String())
+
+	buf.Reset()
+	restore = capture(&w, buf, 2)
+
+	_, err = w.WriteString(line)
+	require.NoError(t, err)
+
+	restore()
+	require.Equal(t, line, buf.String())
+}

cmd/syft/internal/ui/event_writer.go

@@ -14,47 +14,35 @@ import (
 	"github.com/anchore/syft/syft/event/parsers"
 )
 
-type postUIEventWriter struct {
-	handles []postUIHandle
-}
-
-type postUIHandle struct {
-	respectQuiet bool
-	event        partybus.EventType
-	writer       io.Writer
-	dispatch     eventWriter
-}
-
-type eventWriter func(io.Writer, ...partybus.Event) error
-
-func newPostUIEventWriter(stdout, stderr io.Writer) *postUIEventWriter {
-	return &postUIEventWriter{
-		handles: []postUIHandle{
-			{
-				event:        event.CLIReport,
-				respectQuiet: false,
-				writer:       stdout,
-				dispatch:     writeReports,
-			},
-			{
-				event:        event.CLINotification,
-				respectQuiet: true,
-				writer:       stderr,
-				dispatch:     writeNotifications,
-			},
-			{
-				event:        event.CLIAppUpdateAvailable,
-				respectQuiet: true,
-				writer:       stderr,
-				dispatch:     writeAppUpdate,
-			},
+func writeEvents(out, err io.Writer, quiet bool, events ...partybus.Event) error {
+	handles := []struct {
+		event        partybus.EventType
+		respectQuiet bool
+		writer       io.Writer
+		dispatch     func(writer io.Writer, events ...partybus.Event) error
+	}{
+		{
+			event:        event.CLIReport,
+			respectQuiet: false,
+			writer:       out,
+			dispatch:     writeReports,
+		},
+		{
+			event:        event.CLINotification,
+			respectQuiet: true,
+			writer:       err,
+			dispatch:     writeNotifications,
+		},
+		{
+			event:        event.CLIAppUpdateAvailable,
+			respectQuiet: true,
+			writer:       err,
+			dispatch:     writeAppUpdate,
 		},
 	}
-}
 
-func (w postUIEventWriter) write(quiet bool, events ...partybus.Event) error {
 	var errs error
-	for _, h := range w.handles {
+	for _, h := range handles {
 		if quiet && h.respectQuiet {
 			continue
 		}

cmd/syft/internal/ui/event_writer_test.go

@@ -12,8 +12,7 @@ import (
 	"github.com/anchore/syft/syft/event/parsers"
 )
 
-func Test_postUIEventWriter_write(t *testing.T) {
-
+func Test_writeEvents(t *testing.T) {
 	tests := []struct {
 		name    string
 		quiet   bool
@@ -86,9 +85,9 @@ func Test_postUIEventWriter_write(t *testing.T) {
 
 			stdout := &bytes.Buffer{}
 			stderr := &bytes.Buffer{}
-			w := newPostUIEventWriter(stdout, stderr)
 
-			tt.wantErr(t, w.write(tt.quiet, tt.events...))
+			err := writeEvents(stdout, stderr, tt.quiet, tt.events...)
+			tt.wantErr(t, err)
 
 			t.Run("stdout", func(t *testing.T) {
 				snaps.MatchSnapshot(t, stdout.String())

cmd/syft/internal/ui/log_writer.go

@@ -0,0 +1,37 @@
+package ui
+
+import (
+	"bufio"
+	"bytes"
+	"io"
+	"strings"
+
+	"github.com/anchore/syft/internal/log"
+)
+
+func newLogWriter() io.Writer {
+	l := logWriter{}
+	l.r = bufio.NewReader(&l.buf)
+	return &l
+}
+
+type logWriter struct {
+	buf bytes.Buffer
+	r   *bufio.Reader
+}
+
+func (l *logWriter) Write(data []byte) (n int, err error) {
+	l.buf.Write(data)
+	s, err := l.r.ReadString('\n')
+	s = strings.TrimRight(s, "\n")
+	for s != "" {
+		log.Trace(s)
+		n += len(s)
+		if err != nil {
+			break
+		}
+		s, err = l.r.ReadString('\n')
+		s = strings.TrimRight(s, "\n")
+	}
+	return n, err
+}

cmd/syft/internal/ui/log_writer_test.go

@@ -0,0 +1,69 @@
+package ui
+
+import (
+	"io"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+
+	"github.com/anchore/go-logger"
+	"github.com/anchore/syft/internal/log"
+)
+
+func Test_logWriter(t *testing.T) {
+	w := newLogWriter()
+
+	orig := log.Get()
+	t.Cleanup(func() {
+		log.Set(orig)
+	})
+
+	bl := &bufferLogger{}
+	log.Set(bl)
+
+	_, _ = w.Write([]byte("a\nvalue"))
+
+	expected := []any{"a", "value"}
+	require.Equal(t, expected, bl.values)
+
+	bl.values = nil
+	_, _ = w.Write([]byte("some"))
+	_, _ = w.Write([]byte("thing"))
+
+	expected = []any{"some", "thing"}
+	require.Equal(t, expected, bl.values)
+}
+
+type bufferLogger struct{ values []any }
+
+func (l *bufferLogger) Tracef(_ string, _ ...interface{}) {}
+
+func (l *bufferLogger) Debugf(_ string, _ ...interface{}) {}
+
+func (l *bufferLogger) Infof(_ string, _ ...interface{}) {}
+
+func (l *bufferLogger) Warnf(_ string, _ ...interface{}) {}
+
+func (l *bufferLogger) Errorf(_ string, _ ...interface{}) {}
+
+func (l *bufferLogger) Trace(vals ...interface{}) {
+	l.values = append(l.values, vals...)
+}
+
+func (l *bufferLogger) Debug(_ ...interface{}) {}
+
+func (l *bufferLogger) Info(_ ...interface{}) {}
+
+func (l *bufferLogger) Warn(vals ...interface{}) {
+	l.values = append(l.values, vals...)
+}
+
+func (l *bufferLogger) Error(_ ...interface{}) {}
+
+func (l *bufferLogger) WithFields(_ ...interface{}) logger.MessageLogger { return l }
+
+func (l *bufferLogger) Nested(_ ...interface{}) logger.Logger { return l }
+
+func (l *bufferLogger) SetOutput(_ io.Writer) {}
+
+func (l *bufferLogger) GetOutput() io.Writer { return nil }

cmd/syft/internal/ui/no_ui.go

@@ -1,6 +1,7 @@
 package ui
 
 import (
+	"io"
 	"os"
 
 	"github.com/wagoodman/go-partybus"
@@ -12,13 +13,17 @@ import (
 var _ clio.UI = (*NoUI)(nil)
 
 type NoUI struct {
+	out            io.Writer
+	err            io.Writer
 	finalizeEvents []partybus.Event
 	subscription   partybus.Unsubscribable
 	quiet          bool
 }
 
-func None(quiet bool) *NoUI {
+func None(out io.Writer, quiet bool) *NoUI {
 	return &NoUI{
+		out:   out,
+		err:   os.Stderr,
 		quiet: quiet,
 	}
 }
@@ -38,5 +43,5 @@ func (n *NoUI) Handle(e partybus.Event) error {
 }
 
 func (n NoUI) Teardown(_ bool) error {
-	return newPostUIEventWriter(os.Stdout, os.Stderr).write(n.quiet, n.finalizeEvents...)
+	return writeEvents(n.out, n.err, n.quiet, n.finalizeEvents...)
 }

cmd/syft/internal/ui/stdout_logging_application.go

@@ -0,0 +1,63 @@
+package ui
+
+import (
+	"os"
+
+	"github.com/spf13/cobra"
+	"github.com/spf13/pflag"
+
+	"github.com/anchore/clio"
+)
+
+const defaultStdoutLogBufferSize = 1024
+
+// StdoutLoggingApplication wraps the provided app in a clio.Application, which captures non-report data
+// written to os.Stdout and instead logs it to the internal logger. It also modifies the rootCmd help function
+// to restore os.Stdout in order for Cobra to properly print help to stdout
+func StdoutLoggingApplication(app clio.Application, rootCmd *cobra.Command) clio.Application {
+	return &stdoutLoggingApplication{
+		delegate: app,
+		rootCmd:  rootCmd,
+	}
+}
+
+// stdoutLoggingApplication is a clio.Application, which captures data written to os.Stdout prior to the report
+// being output and instead sends non-report output to the internal logger
+type stdoutLoggingApplication struct {
+	delegate clio.Application
+	rootCmd  *cobra.Command
+}
+
+func (s *stdoutLoggingApplication) ID() clio.Identification {
+	return s.delegate.ID()
+}
+
+func (s *stdoutLoggingApplication) AddFlags(flags *pflag.FlagSet, cfgs ...any) {
+	s.delegate.AddFlags(flags, cfgs...)
+}
+
+func (s *stdoutLoggingApplication) SetupCommand(cmd *cobra.Command, cfgs ...any) *cobra.Command {
+	return s.delegate.SetupCommand(cmd, cfgs...)
+}
+
+func (s *stdoutLoggingApplication) SetupRootCommand(cmd *cobra.Command, cfgs ...any) *cobra.Command {
+	return s.delegate.SetupRootCommand(cmd, cfgs...)
+}
+
+func (s *stdoutLoggingApplication) Run() {
+	// capture everything written to stdout that is not report output
+	restoreStdout := capture(&os.Stdout, newLogWriter(), defaultStdoutLogBufferSize)
+	defer restoreStdout()
+
+	// need to restore stdout for cobra to properly output help text to the user on stdout
+	baseHelpFunc := s.rootCmd.HelpFunc()
+	defer s.rootCmd.SetHelpFunc(baseHelpFunc)
+	s.rootCmd.SetHelpFunc(func(command *cobra.Command, strings []string) {
+		restoreStdout()
+		baseHelpFunc(command, strings)
+	})
+
+	s.delegate.Run()
+}
+
+var _ clio.Application = (*stdoutLoggingApplication)(nil)

cmd/syft/internal/ui/ui.go

@@ -2,6 +2,7 @@ package ui
 
 import (
 	"fmt"
+	"io"
 	"os"
 	"sync"
 	"time"
@@ -25,6 +26,8 @@ var _ interface {
 } = (*UI)(nil)
 
 type UI struct {
+	out            io.Writer
+	err            io.Writer
 	program        *tea.Program
 	running        *sync.WaitGroup
 	quiet          bool
@@ -35,8 +38,10 @@ type UI struct {
 	frame   tea.Model
 }
 
-func New(quiet bool, handlers ...bubbly.EventHandler) *UI {
+func New(out io.Writer, quiet bool, handlers ...bubbly.EventHandler) *UI {
 	return &UI{
+		out:     out,
+		err:     os.Stderr,
 		handler: bubbly.NewHandlerCollection(handlers...),
 		frame:   frame.New(),
 		running: &sync.WaitGroup{},
@@ -99,8 +104,7 @@ func (m *UI) Teardown(force bool) error {
 
 	// TODO: allow for writing out the full log output to the screen (only a partial log is shown currently)
 	// this needs coordination to know what the last frame event is to change the state accordingly (which isn't possible now)
-
-	return newPostUIEventWriter(os.Stdout, os.Stderr).write(m.quiet, m.finalizeEvents...)
+	return writeEvents(m.out, m.err, m.quiet, m.finalizeEvents...)
 }
 
 // bubbletea.Model functions

go.mod

@@ -76,6 +76,8 @@ require (
 	modernc.org/sqlite v1.27.0
 )
 
+require github.com/spf13/pflag v1.0.5
+
 require (
 	dario.cat/mergo v1.0.0 // indirect
 	github.com/AdaLogics/go-fuzz-headers v0.0.0-20230811130428-ced1acdcaa24 // indirect
@@ -183,7 +185,6 @@ require (
 	github.com/skeema/knownhosts v1.2.0 // indirect
 	github.com/spf13/cast v1.5.1 // indirect
 	github.com/spf13/jwalterweatherman v1.1.0 // indirect
-	github.com/spf13/pflag v1.0.5 // indirect
 	github.com/spf13/viper v1.16.0 // indirect
 	github.com/subosito/gotenv v1.4.2 // indirect
 	github.com/sylabs/sif/v2 v2.11.5 // indirect