set logging dest to be stdout, and simplify cmd logging (#4588)

This PR creates a simplified logging mode for command line outputs and
makes it the default mode, and only apply configurable log mode with
`serve` command.

Also sets the logging destination as `stdout` instead of `stderr`

cmd/cli/config/list.go

@@ -41,7 +41,7 @@ Each key shown can be used with:
 			if err != nil {
 				return err
 			}
-			log.Info().Msgf("Config loaded from: %s, and with data-dir %s", cfg.Paths(), cfg.Get(types.DataDirKey))
+			log.Debug().Msgf("Config loaded from: %s, and with data-dir %s", cfg.Paths(), cfg.Get(types.DataDirKey))
 			return list(cmd, cfg, o)
 		},
 	}

cmd/cli/devstack/devstack.go

@@ -6,6 +6,7 @@ import (
 	"path/filepath"
 	"strconv"
 
+	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
 	"github.com/spf13/viper"
 	"k8s.io/kubectl/pkg/util/i18n"
@@ -103,9 +104,7 @@ func NewCmd() *cobra.Command {
 		RunE: func(cmd *cobra.Command, _ []string) error {
 			// TODO: a hack to force debug logging for devstack
 			//  until I figure out why flags and env vars are not working
-			if err := logger.ConfigureLogging(string(logger.LogModeDefault), "debug"); err != nil {
-				return fmt.Errorf("failed to configure logging: %w", err)
-			}
+			logger.ConfigureLogging(logger.LogModeDefault, zerolog.DebugLevel)
 			return runDevstack(cmd, ODs)
 		},
 	}

cmd/cli/root.go

@@ -76,15 +76,11 @@ func NewRootCmd() *cobra.Command {
 		// While we allow users to configure logging via the config file, they are applied
 		// and will override this configuration at a later stage when the config is loaded.
 		// This is needed to ensure any logs before the config is loaded are captured.
-		logMode := viper.GetString(types.LoggingModeKey)
-		if logMode == "" {
-			logMode = string(logger.LogModeDefault)
-		}
 		logLevel := viper.GetString(types.LoggingLevelKey)
 		if logLevel == "" {
 			logLevel = "Info"
 		}
-		if err := logger.ConfigureLogging(logMode, logLevel); err != nil {
+		if err := logger.ParseAndConfigureLogging(string(logger.LogModeCmd), logLevel); err != nil {
 			return fmt.Errorf("failed to configure logging: %w", err)
 		}
 

cmd/cli/serve/serve.go

@@ -95,6 +95,10 @@ func NewCmd() *cobra.Command {
 				return fmt.Errorf("failed to setup config: %w", err)
 			}
 
+			if err = logger.ParseAndConfigureLogging(cfg.Logging.Mode, cfg.Logging.Level); err != nil {
+				return fmt.Errorf("failed to configure logging: %w", err)
+			}
+
 			log.Info().Msgf("Config loaded from: %s, and with data-dir %s",
 				rawCfg.Paths(), rawCfg.Get(types.DataDirKey))
 
@@ -103,7 +107,6 @@ func NewCmd() *cobra.Command {
 			if err != nil {
 				return fmt.Errorf("failed to reconcile repo: %w", err)
 			}
-
 			return serve(cmd, cfg, fsr)
 		},
 	}

cmd/util/repo.go

@@ -12,6 +12,7 @@ import (
 	"github.com/bacalhau-project/bacalhau/cmd/util/hook"
 	"github.com/bacalhau-project/bacalhau/pkg/config"
 	"github.com/bacalhau-project/bacalhau/pkg/config/types"
+	"github.com/bacalhau-project/bacalhau/pkg/logger"
 	"github.com/bacalhau-project/bacalhau/pkg/repo"
 	"github.com/bacalhau-project/bacalhau/pkg/setup"
 )
@@ -75,6 +76,12 @@ func SetupConfigType(cmd *cobra.Command) (*config.Config, error) {
 	if err != nil {
 		return nil, err
 	}
+
+	// We always apply the configured logging level. Logging mode on the other hand is only applied with serve cmd
+	if err = logger.ParseAndConfigureLoggingLevel(cfg.Get(types.LoggingLevelKey).(string)); err != nil {
+		return nil, fmt.Errorf("failed to configure logging: %w", err)
+	}
+
 	return cfg, nil
 }
 

pkg/logger/logger.go

@@ -13,6 +13,7 @@ import (
 	"runtime/debug"
 	"strconv"
 	"strings"
+	"sync"
 	"time"
 
 	"github.com/rs/zerolog/pkgerrors"
@@ -29,22 +30,31 @@ type LogMode string
 
 // Available logging modes
 const (
-	LogModeDefault  LogMode = "default"
-	LogModeStation  LogMode = "station"
-	LogModeJSON     LogMode = "json"
-	LogModeCombined LogMode = "combined"
-	LogModeEvent    LogMode = "event"
+	LogModeDefault LogMode = "default"
+	LogModeJSON    LogMode = "json"
+	LogModeCmd     LogMode = "cmd"
+)
+
+var (
+	logMu sync.Mutex
 )
 
 func ParseLogMode(s string) (LogMode, error) {
-	lm := []LogMode{LogModeDefault, LogModeStation, LogModeJSON, LogModeCombined, LogModeEvent}
+	lm := []LogMode{LogModeDefault, LogModeJSON, LogModeCmd}
 	for _, logMode := range lm {
 		if strings.ToLower(s) == strings.ToLower(string(logMode)) {
 			return logMode, nil
 		}
 	}
-	return "Error", fmt.Errorf("%q is an invalid log-mode (valid modes: %q)",
-		s, lm)
+	return "", fmt.Errorf("%q is an invalid log-mode (valid modes: %q)", s, lm)
+}
+
+func ParseLogLevel(s string) (zerolog.Level, error) {
+	l, err := zerolog.ParseLevel(s)
+	if err != nil {
+		return l, fmt.Errorf("%q is an invalid log-level", s)
+	}
+	return l, nil
 }
 
 var nodeIDFieldName = "NodeID"
@@ -57,12 +67,14 @@ func init() { //nolint:gochecknoinits
 		strings.HasSuffix(os.Args[0], ".test") ||
 		flag.Lookup("test.v") != nil ||
 		flag.Lookup("test.run") != nil {
-		configureLogging(zerolog.DebugLevel, defaultLogging())
+		ConfigureLoggingLevel(zerolog.DebugLevel)
+		configureLogging(defaultLogging())
 		return
 	}
 
 	// the default log level when not running a test is ERROR
-	configureLogging(zerolog.ErrorLevel, bufferLogs())
+	ConfigureLoggingLevel(zerolog.ErrorLevel)
+	configureLogging(bufferLogs())
 }
 
 func ErrOrDebug(err error) zerolog.Level {
@@ -82,46 +94,66 @@ type tTesting interface {
 func ConfigureTestLogging(t tTesting) {
 	oldLogger := log.Logger
 	oldContextLogger := zerolog.DefaultContextLogger
-	configureLogging(zerolog.DebugLevel, zerolog.NewConsoleWriter(zerolog.ConsoleTestWriter(t), defaultLogFormat))
+	ConfigureLoggingLevel(zerolog.DebugLevel)
+	configureLogging(zerolog.NewConsoleWriter(zerolog.ConsoleTestWriter(t), defaultLogFormat))
 	t.Cleanup(func() {
 		log.Logger = oldLogger
 		zerolog.DefaultContextLogger = oldContextLogger
 	})
 }
 
-func ConfigureLogging(modeStr, levelStr string) error {
-	logModeConfig := defaultLogging()
-
+func ParseAndConfigureLogging(modeStr, levelStr string) error {
 	mode, err := ParseLogMode(modeStr)
 	if err != nil {
-		return fmt.Errorf("invalid log mode: %w", err)
+		return err
 	}
-	level, err := zerolog.ParseLevel(levelStr)
+	level, err := ParseLogLevel(levelStr)
 	if err != nil {
-		return fmt.Errorf("invalid log level: %w", err)
+		return err
 	}
 
+	ConfigureLogging(mode, level)
+	return nil
+}
+
+func ConfigureLogging(mode LogMode, level zerolog.Level) {
+	var logWriter io.Writer
 	switch mode {
 	case LogModeDefault:
-		logModeConfig = defaultLogging()
-	case LogModeStation:
-		logModeConfig = defaultStationLogging()
+		logWriter = defaultLogging()
 	case LogModeJSON:
-		logModeConfig = jsonLogging()
-	case LogModeEvent:
-		logModeConfig = eventLogging()
-	case LogModeCombined:
-		logModeConfig = combinedLogging()
+		logWriter = jsonLogging()
+	case LogModeCmd:
+		logWriter = clientLogging()
+	default:
+		logWriter = defaultLogging()
 	}
-	configureLogging(level, logModeConfig)
 
-	LogBufferedLogs(logModeConfig)
+	ConfigureLoggingLevel(level)
+	configureLogging(logWriter)
+	LogBufferedLogs(logWriter)
+}
+
+func ParseAndConfigureLoggingLevel(level string) error {
+	l, err := ParseLogLevel(level)
+	if err != nil {
+		return err
+	}
+	ConfigureLoggingLevel(l)
 	return nil
 }
 
-func configureLogging(level zerolog.Level, logWriter io.Writer) {
-	zerolog.TimeFieldFormat = time.RFC3339Nano
+func ConfigureLoggingLevel(level zerolog.Level) {
+	logMu.Lock()
+	defer logMu.Unlock()
 	zerolog.SetGlobalLevel(level)
+}
+
+func configureLogging(logWriter io.Writer) {
+	logMu.Lock()
+	defer logMu.Unlock()
+
+	zerolog.TimeFieldFormat = time.RFC3339Nano
 
 	info, ok := debug.ReadBuildInfo()
 	if ok && info.Main.Path != "" {
@@ -148,21 +180,13 @@ func jsonLogging() io.Writer {
 	return os.Stdout
 }
 
-func eventLogging() io.Writer {
-	return io.Discard
-}
-
-func combinedLogging() io.Writer {
-	return zerolog.MultiLevelWriter(defaultLogging(), os.Stdout)
-}
-
 func defaultLogging() io.Writer {
 	return zerolog.NewConsoleWriter(defaultLogFormat)
 }
 
 func defaultLogFormat(w *zerolog.ConsoleWriter) {
 	isTerminal := isatty.IsTerminal(os.Stdout.Fd())
-	w.Out = os.Stderr
+	w.Out = os.Stdout
 	w.NoColor = !isTerminal
 	w.TimeFormat = "15:04:05.999 |"
 	w.PartsOrder = []string{
@@ -187,25 +211,10 @@ func defaultLogFormat(w *zerolog.ConsoleWriter) {
 	}
 }
 
-func defaultStationLogging() io.Writer {
+func clientLogging() io.Writer {
 	return zerolog.NewConsoleWriter(func(w *zerolog.ConsoleWriter) {
-		isTerminal := isatty.IsTerminal(os.Stdout.Fd())
-		w.Out = os.Stdout
-		w.NoColor = !isTerminal
-		w.PartsOrder = []string{
-			zerolog.LevelFieldName,
-			zerolog.MessageFieldName,
-		}
-
-		w.FormatLevel = func(i interface{}) string {
-			return strings.ToUpper(i.(string)) + ":"
-		}
-		w.FormatErrFieldName = func(i interface{}) string {
-			return "- "
-		}
-		w.FormatErrFieldValue = func(i interface{}) string {
-			return strings.Trim(i.(string), "\"")
-		}
+		defaultLogFormat(w)
+		w.PartsOrder = []string{zerolog.MessageFieldName}
 	})
 }
 

pkg/logger/logger_test.go

@@ -23,7 +23,8 @@ func TestConfigureLogging(t *testing.T) {
 	})
 
 	var logging strings.Builder
-	configureLogging(zerolog.InfoLevel, zerolog.NewConsoleWriter(func(w *zerolog.ConsoleWriter) {
+	ConfigureLoggingLevel(zerolog.InfoLevel)
+	configureLogging(zerolog.NewConsoleWriter(func(w *zerolog.ConsoleWriter) {
 		defaultLogFormat(w)
 		w.Out = &logging
 		w.NoColor = true
@@ -40,3 +41,66 @@ func TestConfigureLogging(t *testing.T) {
 	assert.Contains(t, actual, "pkg/logger/testpackage/subpackage/subsubpackage/testutil.go", "Log statement doesn't contain the full package path")
 	assert.Contains(t, actual, `stack:[{"func":"TestLog","line":`, "Log statement didn't automatically include the error's stacktrace")
 }
+
+func TestParseAndConfigureLogging(t *testing.T) {
+	err := ParseAndConfigureLogging("default", "debug")
+	assert.NoError(t, err)
+	assert.Equal(t, zerolog.DebugLevel, zerolog.GlobalLevel())
+
+	err = ParseAndConfigureLogging("json", "info")
+	assert.NoError(t, err)
+	assert.Equal(t, zerolog.InfoLevel, zerolog.GlobalLevel())
+
+	err = ParseAndConfigureLogging("invalid", "error")
+	assert.Error(t, err)
+
+	err = ParseAndConfigureLogging("default", "invalid")
+	assert.Error(t, err)
+}
+
+func TestParseLogMode(t *testing.T) {
+	tests := []struct {
+		input    string
+		expected LogMode
+		hasError bool
+	}{
+		{"default", LogModeDefault, false},
+		{"json", LogModeJSON, false},
+		{"cmd", LogModeCmd, false},
+		{"invalid", "", true},
+	}
+
+	for _, test := range tests {
+		result, err := ParseLogMode(test.input)
+		if test.hasError {
+			assert.Error(t, err)
+		} else {
+			assert.NoError(t, err)
+			assert.Equal(t, test.expected, result)
+		}
+	}
+}
+
+func TestParseLogLevel(t *testing.T) {
+	tests := []struct {
+		input    string
+		expected zerolog.Level
+		hasError bool
+	}{
+		{"debug", zerolog.DebugLevel, false},
+		{"info", zerolog.InfoLevel, false},
+		{"warn", zerolog.WarnLevel, false},
+		{"error", zerolog.ErrorLevel, false},
+		{"invalid", zerolog.NoLevel, true},
+	}
+
+	for _, test := range tests {
+		result, err := ParseLogLevel(test.input)
+		if test.hasError {
+			assert.Error(t, err)
+		} else {
+			assert.NoError(t, err)
+			assert.Equal(t, test.expected, result)
+		}
+	}
+}

pkg/setup/setup.go

@@ -9,7 +9,6 @@ import (
 
 	"github.com/bacalhau-project/bacalhau/pkg/config"
 	"github.com/bacalhau-project/bacalhau/pkg/config/types"
-	"github.com/bacalhau-project/bacalhau/pkg/logger"
 	"github.com/bacalhau-project/bacalhau/pkg/repo/migrations"
 
 	"github.com/bacalhau-project/bacalhau/pkg/repo"
@@ -25,9 +24,6 @@ func SetupMigrationManager() (*repo.MigrationManager, error) {
 
 // SetupBacalhauRepo ensures that a bacalhau repo and config exist and are initialized.
 func SetupBacalhauRepo(cfg types.Bacalhau) (*repo.FsRepo, error) {
-	if err := logger.ConfigureLogging(cfg.Logging.Mode, cfg.Logging.Level); err != nil {
-		return nil, fmt.Errorf("failed to configure logging: %w", err)
-	}
 	migrationManger, err := SetupMigrationManager()
 	if err != nil {
 		return nil, fmt.Errorf("failed to create migration manager: %w", err)