Log errors over printing (#71)

* log errors over printing Signed-off-by: Alex Goodman <[email protected]> * check for resources loaded before printing Signed-off-by: Alex Goodman <[email protected]> --------- Signed-off-by: Alex Goodman <[email protected]>
anchore · Nov 8, 2024 · 799401f · 799401f
1 parent ceccbdd
commit 799401f
Show file tree

Hide file tree

Showing 2 changed files with 133 additions and 22 deletions.
diff --git a/application.go b/application.go
@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"io"
 	"os"
 	"os/signal"
 	"strings"
@@ -35,9 +36,10 @@ type Application interface {
 }
 
 type application struct {
-	root        *cobra.Command
-	setupConfig SetupConfig `yaml:"-" mapstructure:"-"`
-	state       State       `yaml:"-" mapstructure:"-"`
+	root            *cobra.Command
+	setupConfig     SetupConfig `yaml:"-" mapstructure:"-"`
+	state           State       `yaml:"-" mapstructure:"-"`
+	resourcesLoaded bool
 }
 
 var _ interface {
@@ -69,7 +71,7 @@ func (a *application) Setup(cfgs ...any) func(_ *cobra.Command, _ []string) erro
 	return func(cmd *cobra.Command, _ []string) error {
 		// allow for the all configuration to be loaded first, then allow for the application
 		// PostLoad() to run, allowing the setup of resources (logger, bus, ui, etc.) and run user initializers
-		// as early as possible before the final configuration is logged. This allows for a couple things:
+		// as early as possible before the final configuration is logged. This allows for a couple of things:
 		// 1. user initializers to account for taking action before logging the final configuration (such as log redactions).
 		// 2. other user-facing PostLoad() functions to be able to use the logger, bus, etc. as early as possible. (though it's up to the caller on how these objects are made accessible)
 		allConfigs, err := a.loadConfigs(cmd, cfgs...)
@@ -112,6 +114,7 @@ func (a *application) runInitializers() error {
 			return err
 		}
 	}
+	a.resourcesLoaded = true
 	return nil
 }
 
@@ -271,12 +274,28 @@ func (a *application) Run() {
 	}()
 
 	if err := a.root.Execute(); err != nil {
-		msg := color.Red.Render(strings.TrimSpace(err.Error()))
-		fmt.Fprintln(os.Stderr, msg)
+		a.handleExitError(err, os.Stderr)
+
 		exitCode = 1
 	}
 }
 
+func (a application) handleExitError(err error, stderr io.Writer) {
+	msg := color.Red.Render(strings.TrimSpace(err.Error()))
+
+	hasLogger := a.state.Logger != nil
+	shouldLog := hasLogger && a.resourcesLoaded
+	shouldPrint := !hasLogger || !a.resourcesLoaded
+
+	if shouldLog {
+		a.state.Logger.Error(msg)
+	}
+
+	if shouldPrint {
+		fmt.Fprintln(stderr, msg)
+	}
+}
+
 func (a *application) SetupRootCommand(cmd *cobra.Command, cfgs ...any) *cobra.Command {
 	a.root = cmd
 	return a.setupRootCommand(cmd, cfgs...)

diff --git a/application_test.go b/application_test.go
@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"os"
 	"os/exec"
+	"path/filepath"
 	"regexp"
 	"testing"
 
@@ -73,18 +74,6 @@ func (m mockUI) Teardown(_ bool) error {
 	return nil
 }
 
-var _ logger.Logger = (*mockLogger)(nil)
-
-type mockLogger struct {
-	logger.Logger
-}
-
-func newMockLogger() *mockLogger {
-	return &mockLogger{
-		Logger: discard.New(),
-	}
-}
-
 func Test_Application_Setup_WiresFangs(t *testing.T) {
 	name := "puppy"
 	version := "2.0"
@@ -155,10 +144,14 @@ func Test_Application_Setup_PassLoggerConstructor(t *testing.T) {
 	name := "puppy"
 	version := "2.0"
 
+	type mockLogger struct {
+		logger.Logger
+	}
+
 	cfg := NewSetupConfig(Identification{Name: name, Version: version}).
 		WithUI(&mockUI{}).
 		WithLoggerConstructor(func(_ Config, _ redact.Store) (logger.Logger, error) {
-			return newMockLogger(), nil
+			return &mockLogger{Logger: discard.New()}, nil
 		})
 
 	app := New(*cfg)
@@ -229,6 +222,7 @@ func Test_Application_Setup_RunsInitializers(t *testing.T) {
 	t.Setenv("PUPPY_THING_STUFF", "ruff-ruff!")
 
 	app := New(*cfg)
+	assert.False(t, app.(*application).resourcesLoaded)
 
 	cmd := app.SetupCommand(
 		&cobra.Command{
@@ -240,6 +234,8 @@ func Test_Application_Setup_RunsInitializers(t *testing.T) {
 		})
 
 	require.NoError(t, cmd.Execute())
+
+	assert.True(t, app.(*application).resourcesLoaded)
 }
 
 func Test_Application_Setup_RunsPostRuns(t *testing.T) {
@@ -361,8 +357,14 @@ func Test_RunPanicWithoutRootCommand(t *testing.T) {
 }
 
 func Test_RunExitError(t *testing.T) {
+	d := t.TempDir()
+	logFile := filepath.Join(d, "log.txt")
+
 	if os.Getenv("CLIO_RUN_EXIT_ERROR") == "YES" {
-		app := New(*NewSetupConfig(Identification{}).WithNoBus())
+		app := New(*NewSetupConfig(Identification{}).WithNoBus().WithLoggingConfig(LoggingConfig{
+			Level:        logger.InfoLevel,
+			FileLocation: os.Getenv("CLIO_LOG_FILE"),
+		}))
 		app.SetupRootCommand(&cobra.Command{
 			RunE: func(cmd *cobra.Command, args []string) error {
 				return fmt.Errorf("an error occurred")
@@ -373,18 +375,23 @@ func Test_RunExitError(t *testing.T) {
 	}
 
 	cmd := exec.Command(os.Args[0], "-test.run=Test_RunExitError")
-	cmd.Env = append(os.Environ(), "CLIO_RUN_EXIT_ERROR=YES")
+	cmd.Env = append(os.Environ(), fmt.Sprintf("CLIO_LOG_FILE=%s", logFile), "CLIO_RUN_EXIT_ERROR=YES")
 
 	var stdout, stderr bytes.Buffer
 	cmd.Stdout = &stdout
 	cmd.Stderr = &stderr
 
 	err := cmd.Run()
+
+	logContents, readErr := os.ReadFile(logFile)
+	require.NoError(t, readErr)
+
 	var e *exec.ExitError
 	if errors.As(err, &e) && !e.Success() {
-		// ensure that errors are reported to stderr, not stdout
+		// ensure that errors are reported to stderr/log, not stdout
 		assert.Contains(t, stderr.String(), "an error occurred")
 		assert.NotContains(t, stdout.String(), "an error occurred")
+		assert.Contains(t, string(logContents), "an error occurred")
 		return
 	}
 	t.Fatalf("process ran with err %v, want exit status 1", err)
@@ -416,3 +423,88 @@ func Test_Run_InvokesBusExit(t *testing.T) {
 
 	assert.Equal(t, e.Type, ExitEventType)
 }
+
+type mockErrorLogger struct {
+	logger.Logger
+	msg string
+}
+
+func (m *mockErrorLogger) Error(msg ...any) {
+	m.msg += fmt.Sprintf("%+v", msg)
+}
+
+func TestHandleExitError(t *testing.T) {
+	tests := []struct {
+		name        string
+		app         application
+		err         error
+		expectLog   bool
+		expectPrint bool
+	}{
+		{
+			name: "with logger and resources loaded",
+			app: application{
+				state: State{
+					Logger: &mockErrorLogger{},
+				},
+				resourcesLoaded: true,
+			},
+			err:         errors.New("test error"),
+			expectLog:   true,
+			expectPrint: false,
+		},
+		{
+			name: "with logger but resources not loaded",
+			app: application{
+				state: State{
+					Logger: &mockErrorLogger{},
+				},
+				resourcesLoaded: false,
+			},
+			err:         errors.New("test error"),
+			expectLog:   false,
+			expectPrint: true,
+		},
+		{
+			name: "without logger and resources loaded",
+			app: application{
+				state:           State{},
+				resourcesLoaded: true,
+			},
+			err:         errors.New("test error"),
+			expectLog:   false,
+			expectPrint: true,
+		},
+		{
+			name: "without logger and resources not loaded",
+			app: application{
+				state:           State{},
+				resourcesLoaded: false,
+			},
+			err:         errors.New("test error"),
+			expectLog:   false,
+			expectPrint: true,
+		},
+	}
+
+	originalStderr := os.Stderr
+	defer func() { os.Stderr = originalStderr }()
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var stderr bytes.Buffer
+
+			tt.app.handleExitError(tt.err, &stderr)
+
+			if tt.expectLog {
+				assert.Contains(t, tt.app.state.Logger.(*mockErrorLogger).msg, "test error")
+			}
+
+			if tt.expectPrint {
+				assert.Contains(t, stderr.String(), "test error")
+			} else {
+				assert.Empty(t, stderr.String())
+			}
+		})
+	}
+}