From f9d5c971d381a26e8f9393ee7f04de4016cba13c Mon Sep 17 00:00:00 2001 From: Walid Baruni Date: Mon, 7 Oct 2024 16:01:16 +0200 Subject: [PATCH] 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 | 2 +- cmd/cli/devstack/devstack.go | 5 +- cmd/cli/root.go | 6 +- cmd/cli/serve/serve.go | 5 +- cmd/util/repo.go | 7 ++ pkg/logger/logger.go | 121 +++++++++++++++++++---------------- pkg/logger/logger_test.go | 66 ++++++++++++++++++- pkg/setup/setup.go | 4 -- 8 files changed, 145 insertions(+), 71 deletions(-) diff --git a/cmd/cli/config/list.go b/cmd/cli/config/list.go index c3d970b132..905f443811 100644 --- a/cmd/cli/config/list.go +++ b/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) }, } diff --git a/cmd/cli/devstack/devstack.go b/cmd/cli/devstack/devstack.go index 8eb9102566..80fb3ed4d2 100644 --- a/cmd/cli/devstack/devstack.go +++ b/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) }, } diff --git a/cmd/cli/root.go b/cmd/cli/root.go index 9677911d71..8df28fa5ee 100644 --- a/cmd/cli/root.go +++ b/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) } diff --git a/cmd/cli/serve/serve.go b/cmd/cli/serve/serve.go index 2ca436e133..8886b58ae4 100644 --- a/cmd/cli/serve/serve.go +++ b/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) }, } diff --git a/cmd/util/repo.go b/cmd/util/repo.go index 042041a056..a295d53661 100644 --- a/cmd/util/repo.go +++ b/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 } diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index c053cd9b94..dc34a033c0 100644 --- a/pkg/logger/logger.go +++ b/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} }) } diff --git a/pkg/logger/logger_test.go b/pkg/logger/logger_test.go index ac25c6536d..7786c4b979 100644 --- a/pkg/logger/logger_test.go +++ b/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) + } + } +} diff --git a/pkg/setup/setup.go b/pkg/setup/setup.go index 345268831e..d270600bec 100644 --- a/pkg/setup/setup.go +++ b/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)