From 3c26b09d712aba988131f9d19938115b1c4568af Mon Sep 17 00:00:00 2001 From: Keepers Date: Mon, 15 May 2023 16:03:37 -0600 Subject: [PATCH] separate log level and format config (#3398) Separates the log level and log format. This will allows sdk consumers using `SeedLogger` to utilize JSON format logs without sacrificing log level controls. --- #### Does this PR need a docs update or release note? - [x] :no_entry: No #### Type of change - [x] :robot: Supportability/Tests #### Test Plan - [x] :muscle: Manual --- src/cmd/factory/factory.go | 6 +- src/cmd/getM365/main.go | 6 +- src/cmd/purge/purge.go | 6 +- src/internal/kopia/wrapper_test.go | 7 +- src/internal/tester/cli.go | 19 +- src/pkg/logger/logger.go | 302 +++++++++++++++++------------ src/pkg/logger/logger_test.go | 48 ++++- 7 files changed, 254 insertions(+), 140 deletions(-) diff --git a/src/cmd/factory/factory.go b/src/cmd/factory/factory.go index 67b0347be..e7201fc50 100644 --- a/src/cmd/factory/factory.go +++ b/src/cmd/factory/factory.go @@ -41,7 +41,11 @@ var sharePointCmd = &cobra.Command{ // ------------------------------------------------------------------------------------------ func main() { - ctx, _ := logger.SeedLevel(context.Background(), logger.Development) + ls := logger.Settings{ + Level: logger.LLDebug, + Format: logger.LFText, + } + ctx, _ := logger.CtxOrSeed(context.Background(), ls) ctx = SetRootCmd(ctx, factoryCmd) defer func() { diff --git a/src/cmd/getM365/main.go b/src/cmd/getM365/main.go index 17aa71d78..c7acd3175 100644 --- a/src/cmd/getM365/main.go +++ b/src/cmd/getM365/main.go @@ -17,7 +17,11 @@ var rootCmd = &cobra.Command{ } func main() { - ctx, _ := logger.SeedLevel(context.Background(), logger.Development) + ls := logger.Settings{ + Level: logger.LLDebug, + Format: logger.LFText, + } + ctx, _ := logger.CtxOrSeed(context.Background(), ls) ctx = SetRootCmd(ctx, rootCmd) defer logger.Flush(ctx) diff --git a/src/cmd/purge/purge.go b/src/cmd/purge/purge.go index 0074ad61c..d9f1133c1 100644 --- a/src/cmd/purge/purge.go +++ b/src/cmd/purge/purge.go @@ -49,7 +49,11 @@ var ErrPurging = clues.New("not all items were successfully purged") // ------------------------------------------------------------------------------------------ func main() { - ctx, _ := logger.SeedLevel(context.Background(), logger.Development) + ls := logger.Settings{ + Level: logger.LLDebug, + Format: logger.LFText, + } + ctx, _ := logger.CtxOrSeed(context.Background(), ls) ctx = SetRootCmd(ctx, purgeCmd) defer logger.Flush(ctx) diff --git a/src/internal/kopia/wrapper_test.go b/src/internal/kopia/wrapper_test.go index 48041cd91..013ffdb2c 100644 --- a/src/internal/kopia/wrapper_test.go +++ b/src/internal/kopia/wrapper_test.go @@ -1006,8 +1006,13 @@ func (suite *KopiaSimpleRepoIntegrationSuite) SetupTest() { t := suite.T() expectedDirs := 6 expectedFiles := len(suite.filesByPath) + + ls := logger.Settings{ + Level: logger.LLDebug, + Format: logger.LFText, + } //nolint:forbidigo - suite.ctx, _ = logger.SeedLevel(context.Background(), logger.Development) + suite.ctx, _ = logger.CtxOrSeed(context.Background(), ls) c, err := openKopiaRepo(t, suite.ctx) require.NoError(t, err, clues.ToCore(err)) diff --git a/src/internal/tester/cli.go b/src/internal/tester/cli.go index 6783fe251..925233d2e 100644 --- a/src/internal/tester/cli.go +++ b/src/internal/tester/cli.go @@ -34,21 +34,32 @@ func StubRootCmd(args ...string) *cobra.Command { } func NewContext() (context.Context, func()) { - level := logger.Info + level := logger.LLInfo + format := logger.LFText for _, a := range os.Args { if a == "-test.v=true" { - level = logger.Development + level = logger.LLDebug } } + ls := logger.Settings{ + Level: level, + Format: format, + } + //nolint:forbidigo - ctx, _ := logger.SeedLevel(context.Background(), level) + ctx, _ := logger.CtxOrSeed(context.Background(), ls) return ctx, func() { logger.Flush(ctx) } } func WithContext(ctx context.Context) (context.Context, func()) { - ctx, _ = logger.SeedLevel(ctx, logger.Development) + ls := logger.Settings{ + Level: logger.LLDebug, + Format: logger.LFText, + } + ctx, _ = logger.CtxOrSeed(ctx, ls) + return ctx, func() { logger.Flush(ctx) } } diff --git a/src/pkg/logger/logger.go b/src/pkg/logger/logger.go index cc632b422..39636a99c 100644 --- a/src/pkg/logger/logger.go +++ b/src/pkg/logger/logger.go @@ -12,6 +12,9 @@ import ( "github.com/spf13/pflag" "go.uber.org/zap" "go.uber.org/zap/zapcore" + "golang.org/x/exp/slices" + + "github.com/alcionai/corso/src/internal/common" ) // Default location for writing logs, initialized in platform specific files @@ -22,20 +25,38 @@ var ( loggerton *zap.SugaredLogger ) -type logLevel int +type logLevel string const ( - Development logLevel = iota - Info - Warn - Production - Disabled + LLDebug logLevel = "debug" + LLInfo logLevel = "info" + LLWarn logLevel = "warn" + LLError logLevel = "error" + LLDisabled logLevel = "disabled" +) + +type logFormat string + +const ( + // use for cli/terminal + LFText logFormat = "text" + // use for cloud logging + LFJSON logFormat = "json" +) + +type piiAlg string + +const ( + PIIHash piiAlg = "hash" + PIIMask piiAlg = "mask" + PIIPlainText piiAlg = "plaintext" ) // flag names const ( DebugAPIFN = "debug-api-calls" LogFileFN = "log-file" + LogFormatFN = "log-format" LogLevelFN = "log-level" ReadableLogsFN = "readable-logs" MaskSensitiveDataFN = "mask-sensitive-data" @@ -44,32 +65,28 @@ const ( // flag values var ( DebugAPIFV bool - logFileFV = "" - LogLevelFV = "info" + logFileFV string + LogFormatFV string + LogLevelFV string ReadableLogsFV bool MaskSensitiveDataFV bool - LogFile string // logFileFV after processing + LogFile string // logFileFV after processing + piiHandling string // piiHandling after MaskSensitiveDataFV processing ) const ( Stderr = "stderr" Stdout = "stdout" - - PIIHash = "hash" - PIIMask = "mask" - PIIPlainText = "plaintext" - - LLDebug = "debug" - LLInfo = "info" - LLWarn = "warn" - LLError = "error" - LLDisabled = "disabled" ) // Returns the default location for writing logs func defaultLogLocation() string { - return filepath.Join(userLogsDir, "corso", "logs", time.Now().UTC().Format("2006-01-02T15-04-05Z")+".log") + return filepath.Join( + userLogsDir, + "corso", + "logs", + time.Now().UTC().Format("2006-01-02T15-04-05Z")+".log") } // adds the persistent flag --log-level and --log-file to the provided command. @@ -90,9 +107,15 @@ func addFlags(fs *pflag.FlagSet, defaultFile string) { fs.StringVar( &LogLevelFV, LogLevelFN, - LLInfo, + string(LLInfo), fmt.Sprintf("set the log level to %s|%s|%s|%s", LLDebug, LLInfo, LLWarn, LLError)) + fs.StringVar( + &LogFormatFV, + LogFormatFN, + string(LFText), + fmt.Sprintf("set the log format to %s|%s", LFText, LFJSON)) + // The default provided here is only for help info fs.StringVar(&logFileFV, LogFileFN, defaultFile, "location for writing logs, use '-' for stdout") fs.BoolVar(&DebugAPIFV, DebugAPIFN, false, "add non-2xx request/response errors to logging") @@ -110,13 +133,6 @@ func addFlags(fs *pflag.FlagSet, defaultFile string) { "anonymize personal data in log output") } -// Settings records the user's preferred logging settings. -type Settings struct { - File string // what file to log to (alt: stderr, stdout) - Level string // what level to log at - PIIHandling string // how to obscure pii -} - // Due to races between the lazy evaluation of flags in cobra and the // need to init logging behavior in a ctx, log-level and log-file gets // pre-processed manually here using pflags. The canonical @@ -130,50 +146,58 @@ func PreloadLoggingFlags(args []string) Settings { // prevents overriding the corso/cobra help processor fs.BoolP("help", "h", false, "") - ls := Settings{ - File: "", - Level: LogLevelFV, + set := Settings{ + File: defaultLogLocation(), + Format: LFText, + Level: LLInfo, PIIHandling: PIIPlainText, } // parse the os args list to find the log level flag if err := fs.Parse(args); err != nil { - return ls - } - - if MaskSensitiveDataFV { - ls.PIIHandling = PIIHash + return set } // retrieve the user's preferred log level - // automatically defaults to "info" + // defaults to "info" levelString, err := fs.GetString(LogLevelFN) if err != nil { - return ls + return set } - ls.Level = levelString + set.Level = logLevel(levelString) + + // retrieve the user's preferred log format + // defaults to "text" + formatString, err := fs.GetString(LogFormatFN) + if err != nil { + return set + } + + set.Format = logFormat(formatString) // retrieve the user's preferred log file location - // automatically defaults to default log location + // defaults to default log location lffv, err := fs.GetString(LogFileFN) if err != nil { - return ls + return set } - ls.File = GetLogFile(lffv) - LogFile = ls.File + set.File = GetLogFile(lffv) + LogFile = set.File // retrieve the user's preferred PII handling algorithm - // automatically defaults to default log location - pii, err := fs.GetString(MaskSensitiveDataFN) + // defaults to "plaintext" + maskPII, err := fs.GetBool(MaskSensitiveDataFN) if err != nil { - return ls + return set } - ls.PIIHandling = pii + if maskPII { + set.PIIHandling = PIIHash + } - return ls + return set } // GetLogFile parses the log file. Uses the provided value, if populated, @@ -207,72 +231,104 @@ func GetLogFile(logFileFlagVal string) string { return r } -func genLogger(level logLevel, logfile string) (*zapcore.Core, *zap.SugaredLogger) { +// Settings records the user's preferred logging settings. +type Settings struct { + File string // what file to log to (alt: stderr, stdout) + Format logFormat // whether to format as text (console) or json (cloud) + Level logLevel // what level to log at + PIIHandling piiAlg // how to obscure pii +} + +// EnsureDefaults sets any non-populated settings to their default value. +// exported for testing without circular dependencies. +func (s Settings) EnsureDefaults() Settings { + set := s + + levels := []logLevel{LLDisabled, LLDebug, LLInfo, LLWarn, LLError} + if len(set.Level) == 0 || !slices.Contains(levels, set.Level) { + set.Level = LLInfo + } + + formats := []logFormat{LFText, LFJSON} + if len(set.Format) == 0 || !slices.Contains(formats, set.Format) { + set.Format = LFText + } + + algs := []piiAlg{PIIPlainText, PIIMask, PIIHash} + if len(set.PIIHandling) == 0 || !slices.Contains(algs, set.PIIHandling) { + set.PIIHandling = piiAlg(common.First(piiHandling, string(PIIPlainText))) + } + + if len(set.File) == 0 { + set.File = GetLogFile("") + } + + return set +} + +// --------------------------------------------------------------------------- +// constructors +// --------------------------------------------------------------------------- + +func genLogger(set Settings) (*zapcore.Core, *zap.SugaredLogger) { // when testing, ensure debug logging matches the test.v setting for _, arg := range os.Args { if arg == `--test.v=true` { - level = Development + set.Level = LLDebug } } - // set up a logger core to use as a fallback - levelFilter := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - switch level { - case Info: - return lvl >= zapcore.InfoLevel - case Warn: - return lvl >= zapcore.WarnLevel - case Production: - return lvl >= zapcore.ErrorLevel - case Disabled: - return false - default: - return true - } - }) - out := zapcore.Lock(os.Stderr) - consoleEncoder := zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()) - core := zapcore.NewTee( - zapcore.NewCore(consoleEncoder, out, levelFilter), - ) - - // then try to set up a logger directly var ( lgr *zap.Logger err error opts = []zap.Option{zap.AddStacktrace(zapcore.PanicLevel)} + + // set up a logger core to use as a fallback + levelFilter = zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { + switch set.Level { + case LLInfo: + return lvl >= zapcore.InfoLevel + case LLWarn: + return lvl >= zapcore.WarnLevel + case LLError: + return lvl >= zapcore.ErrorLevel + case LLDisabled: + return false + default: + return true + } + }) + + out = zapcore.Lock(os.Stderr) + consoleEncoder = zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()) + core = zapcore.NewTee( + zapcore.NewCore(consoleEncoder, out, levelFilter), + ) + + cfg zap.Config ) - if level != Production { - cfg := zap.NewDevelopmentConfig() - - switch level { - case Info: - cfg.Level = zap.NewAtomicLevelAt(zapcore.InfoLevel) - case Warn: - cfg.Level = zap.NewAtomicLevelAt(zapcore.WarnLevel) - case Disabled: - cfg.Level = zap.NewAtomicLevelAt(zapcore.FatalLevel) - } + switch set.Format { + case LFJSON: + cfg = setLevel(zap.NewProductionConfig(), set.Level) + cfg.OutputPaths = []string{set.File} + default: + cfg = setLevel(zap.NewDevelopmentConfig(), set.Level) if ReadableLogsFV { opts = append(opts, zap.WithCaller(false)) cfg.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout("15:04:05.00") - if logfile == Stderr || logfile == Stdout { + if set.File == Stderr || set.File == Stdout { cfg.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder } } - cfg.OutputPaths = []string{logfile} - lgr, err = cfg.Build(opts...) - } else { - cfg := zap.NewProductionConfig() - cfg.OutputPaths = []string{logfile} - lgr, err = cfg.Build(opts...) + cfg.OutputPaths = []string{set.File} } // fall back to the core config if the default creation fails + lgr, err = cfg.Build(opts...) if err != nil { lgr = zap.New(core) } @@ -280,7 +336,22 @@ func genLogger(level logLevel, logfile string) (*zapcore.Core, *zap.SugaredLogge return &core, lgr.Sugar() } -func singleton(level logLevel, logfile string) *zap.SugaredLogger { +func setLevel(cfg zap.Config, level logLevel) zap.Config { + switch level { + case LLInfo: + cfg.Level = zap.NewAtomicLevelAt(zapcore.InfoLevel) + case LLWarn: + cfg.Level = zap.NewAtomicLevelAt(zapcore.WarnLevel) + case LLError: + cfg.Level = zap.NewAtomicLevelAt(zapcore.ErrorLevel) + case LLDisabled: + cfg.Level = zap.NewAtomicLevelAt(zapcore.FatalLevel) + } + + return cfg +} + +func singleton(set Settings) *zap.SugaredLogger { if loggerton != nil { return loggerton } @@ -292,7 +363,10 @@ func singleton(level logLevel, logfile string) *zap.SugaredLogger { return loggerton } - logCore, loggerton = genLogger(level, logfile) + set = set.EnsureDefaults() + setCluesSecretsHash(set.PIIHandling) + + logCore, loggerton = genLogger(set) return loggerton } @@ -310,18 +384,11 @@ const ctxKey loggingKey = "corsoLogger" // cobra. This early parsing is necessary since logging depends on // a seeded context prior to cobra evaluating flags. func Seed(ctx context.Context, set Settings) (context.Context, *zap.SugaredLogger) { - if len(set.Level) == 0 { - set.Level = LLInfo - } - - setCluesSecretsHash(set.PIIHandling) - - zsl := singleton(levelOf(set.Level), set.File) - + zsl := singleton(set) return Set(ctx, zsl), zsl } -func setCluesSecretsHash(alg string) { +func setCluesSecretsHash(alg piiAlg) { switch alg { case PIIHash: // TODO: a persistent hmac key for each tenant would be nice @@ -334,18 +401,12 @@ func setCluesSecretsHash(alg string) { } } -// SeedLevel generates a logger within the context with the given log-level. -func SeedLevel(ctx context.Context, level logLevel) (context.Context, *zap.SugaredLogger) { +// CtxOrSeed attempts to retrieve the logger from the ctx. If not found, it +// generates a logger with the given settings and adds it to the context. +func CtxOrSeed(ctx context.Context, set Settings) (context.Context, *zap.SugaredLogger) { l := ctx.Value(ctxKey) if l == nil { - logfile := os.Getenv("CORSO_LOG_FILE") - - if len(logfile) == 0 { - logfile = defaultLogLocation() - } - - zsl := singleton(level, logfile) - + zsl := singleton(set) return Set(ctx, zsl), zsl } @@ -365,7 +426,7 @@ func Set(ctx context.Context, logger *zap.SugaredLogger) context.Context { func Ctx(ctx context.Context) *zap.SugaredLogger { l := ctx.Value(ctxKey) if l == nil { - return singleton(levelOf(LogLevelFV), defaultLogLocation()) + l = singleton(Settings{}.EnsureDefaults()) } return l.(*zap.SugaredLogger).With(clues.In(ctx).Slice()...) @@ -381,22 +442,6 @@ func CtxErr(ctx context.Context, err error) *zap.SugaredLogger { With(clues.InErr(err).Slice()...) } -// transforms the llevel flag value to a logLevel enum -func levelOf(lvl string) logLevel { - switch lvl { - case LLDebug: - return Development - case LLWarn: - return Warn - case LLError: - return Production - case LLDisabled: - return Disabled - } - - return Info -} - // Flush writes out all buffered logs. func Flush(ctx context.Context) { _ = Ctx(ctx).Sync() @@ -408,7 +453,6 @@ func Flush(ctx context.Context) { type wrapper struct { zap.SugaredLogger - forceDebugLogLevel bool } diff --git a/src/pkg/logger/logger_test.go b/src/pkg/logger/logger_test.go index 644c23aa0..910b546b0 100644 --- a/src/pkg/logger/logger_test.go +++ b/src/pkg/logger/logger_test.go @@ -32,7 +32,8 @@ func (suite *LoggerUnitSuite) TestAddLoggingFlags() { Run: func(cmd *cobra.Command, args []string) { assert.True(t, logger.DebugAPIFV, logger.DebugAPIFN) assert.True(t, logger.ReadableLogsFV, logger.ReadableLogsFN) - assert.Equal(t, logger.LLError, logger.LogLevelFV, logger.LogLevelFN) + assert.Equal(t, string(logger.LLError), logger.LogLevelFV, logger.LogLevelFN) + assert.Equal(t, string(logger.LFText), logger.LogFormatFV, logger.LogFormatFN) assert.True(t, logger.MaskSensitiveDataFV, logger.MaskSensitiveDataFN) // empty assertion here, instead of matching "log-file", because the LogFile // var isn't updated by running the command (this is expected and correct), @@ -48,7 +49,8 @@ func (suite *LoggerUnitSuite) TestAddLoggingFlags() { "test", "--" + logger.DebugAPIFN, "--" + logger.LogFileFN, "log-file", - "--" + logger.LogLevelFN, logger.LLError, + "--" + logger.LogLevelFN, string(logger.LLError), + "--" + logger.LogFormatFN, string(logger.LFText), "--" + logger.ReadableLogsFN, "--" + logger.MaskSensitiveDataFN, }) @@ -66,7 +68,8 @@ func (suite *LoggerUnitSuite) TestPreloadLoggingFlags() { args := []string{ "--" + logger.DebugAPIFN, "--" + logger.LogFileFN, "log-file", - "--" + logger.LogLevelFN, logger.LLError, + "--" + logger.LogLevelFN, string(logger.LLError), + "--" + logger.LogFormatFN, string(logger.LFText), "--" + logger.ReadableLogsFN, "--" + logger.MaskSensitiveDataFN, } @@ -77,5 +80,44 @@ func (suite *LoggerUnitSuite) TestPreloadLoggingFlags() { assert.True(t, logger.ReadableLogsFV, logger.ReadableLogsFN) assert.Equal(t, "log-file", settings.File, "settings.File") assert.Equal(t, logger.LLError, settings.Level, "settings.Level") + assert.Equal(t, logger.LFText, settings.Format, "settings.Format") assert.Equal(t, logger.PIIHash, settings.PIIHandling, "settings.PIIHandling") } + +func (suite *LoggerUnitSuite) TestPreloadLoggingFlags_badArgsEnsureDefault() { + t := suite.T() + + logger.DebugAPIFV = false + logger.ReadableLogsFV = false + + args := []string{ + "--" + logger.DebugAPIFN, + "--" + logger.LogFileFN, "log-file", + "--" + logger.LogLevelFN, "not-a-level", + "--" + logger.LogFormatFN, "not-a-format", + "--" + logger.ReadableLogsFN, + "--" + logger.MaskSensitiveDataFN, + } + + settings := logger.PreloadLoggingFlags(args) + settings = settings.EnsureDefaults() + + assert.Equal(t, logger.LLInfo, settings.Level, "settings.Level") + assert.Equal(t, logger.LFText, settings.Format, "settings.Format") +} + +func (suite *LoggerUnitSuite) TestSettings_ensureDefaults() { + t := suite.T() + + s := logger.Settings{} + require.Empty(t, s.File, "file") + require.Empty(t, s.Level, "level") + require.Empty(t, s.Format, "format") + require.Empty(t, s.PIIHandling, "piialg") + + s = s.EnsureDefaults() + require.NotEmpty(t, s.File, "file") + require.NotEmpty(t, s.Level, "level") + require.NotEmpty(t, s.Format, "format") + require.NotEmpty(t, s.PIIHandling, "piialg") +}