diff --git a/src/cli/cli.go b/src/cli/cli.go index 0b578c5b5..4a851b3c2 100644 --- a/src/cli/cli.go +++ b/src/cli/cli.go @@ -163,6 +163,7 @@ func BuildCommandTree(cmd *cobra.Command) { // Handle builds and executes the cli processor. func Handle() { + //nolint:forbidigo ctx := config.Seed(context.Background()) ctx = print.SetRootCmd(ctx, corsoCmd) @@ -170,8 +171,7 @@ func Handle() { BuildCommandTree(corsoCmd) - loglevel, logfile := logger.PreloadLoggingFlags() - ctx, log := logger.Seed(ctx, loglevel, logfile) + ctx, log := logger.Seed(ctx, logger.PreloadLoggingFlags(os.Args[1:])) defer func() { _ = log.Sync() // flush all logs in the buffer diff --git a/src/cmd/sanity_test/sanity_tests.go b/src/cmd/sanity_test/sanity_tests.go index b5c57a4e8..a9a155f93 100644 --- a/src/cmd/sanity_test/sanity_tests.go +++ b/src/cmd/sanity_test/sanity_tests.go @@ -41,7 +41,13 @@ const ( // --------------------------------------------------------------------------- func main() { - ctx, log := logger.Seed(context.Background(), "info", logger.GetLogFile("")) + ls := logger.Settings{ + File: logger.GetLogFile(""), + Level: logger.LLInfo, + PIIHandling: logger.PIIPlainText, + } + + ctx, log := logger.Seed(context.Background(), ls) defer func() { _ = log.Sync() // flush all logs in the buffer }() diff --git a/src/internal/connector/graph/middleware.go b/src/internal/connector/graph/middleware.go index 01b5a3275..4b3e7e96e 100644 --- a/src/internal/connector/graph/middleware.go +++ b/src/internal/connector/graph/middleware.go @@ -122,7 +122,7 @@ func (handler *LoggingMiddleware) Intercept( // Return immediately if the response is good (2xx). // If api logging is toggled, log a body-less dump of the request/resp. if (resp.StatusCode / 100) == 2 { - if logger.DebugAPI || os.Getenv(log2xxGraphRequestsEnvKey) != "" { + if logger.DebugAPIFV || os.Getenv(log2xxGraphRequestsEnvKey) != "" { log.Debugw("2xx graph api resp", "response", getRespDump(ctx, resp, os.Getenv(log2xxGraphResponseEnvKey) != "")) } @@ -133,7 +133,7 @@ func (handler *LoggingMiddleware) Intercept( // When debugging is toggled, every non-2xx is recorded with a response dump. // Otherwise, throttling cases and other non-2xx responses are logged // with a slimmer reference for telemetry/supportability purposes. - if logger.DebugAPI || os.Getenv(logGraphRequestsEnvKey) != "" { + if logger.DebugAPIFV || os.Getenv(logGraphRequestsEnvKey) != "" { log.Errorw("non-2xx graph api response", "response", getRespDump(ctx, resp, true)) return resp, err } diff --git a/src/pkg/logger/example_logger_test.go b/src/pkg/logger/example_logger_test.go index 962dadc90..b71cddf11 100644 --- a/src/pkg/logger/example_logger_test.go +++ b/src/pkg/logger/example_logger_test.go @@ -14,11 +14,7 @@ import ( // mock helpers // --------------------------------------------------------------------------- -const ( - loglevel = "info" - logfile = logger.Stderr - itemID = "item_id" -) +const itemID = "item_id" var ( err error @@ -35,7 +31,14 @@ func Example_seed() { // the context. Seeding only needs to be done once. For example // Corso's CLI layer seeds the logger in the cli initialization. ctx := context.Background() - ctx, log := logger.Seed(ctx, loglevel, logfile) + + ls := logger.Settings{ + File: logger.Stderr, + Level: logger.LLInfo, + PIIHandling: logger.PIIPlainText, + } + + ctx, log := logger.Seed(ctx, ls) // SDK consumers who configure their own zap logger can Set their logger // into the context directly, instead of Seeding a new one. diff --git a/src/pkg/logger/logger.go b/src/pkg/logger/logger.go index 9b631889d..ad02751c4 100644 --- a/src/pkg/logger/logger.go +++ b/src/pkg/logger/logger.go @@ -2,6 +2,7 @@ package logger import ( "context" + "fmt" "os" "path/filepath" "time" @@ -19,17 +20,6 @@ var userLogsDir string var ( logCore *zapcore.Core loggerton *zap.SugaredLogger - - // logging level flag - llFlag = "info" - - // logging file flags - lfFlag = "" - - DebugAPI bool - readableOutput bool - - LogFile string ) type logLevel int @@ -42,16 +32,39 @@ const ( Disabled ) +// flag names const ( - debugAPIFN = "debug-api-calls" - logLevelFN = "log-level" - logFileFN = "log-file" - readableLogsFN = "readable-logs" + DebugAPIFN = "debug-api-calls" + LogFileFN = "log-file" + LogLevelFN = "log-level" + ReadableLogsFN = "readable-logs" + SensitiveInfoFN = "sensitive-info" +) + +// flag values +var ( + DebugAPIFV bool + logFileFV = "" + LogLevelFV = "info" + ReadableLogsFV bool + SensitiveInfoFV = PIIPlainText + + LogFile string // logFileFV after 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 @@ -65,18 +78,46 @@ func defaultLogLocation() string { // need to parse the log level before we execute the command. func AddLoggingFlags(cmd *cobra.Command) { fs := cmd.PersistentFlags() - fs.StringVar(&llFlag, logLevelFN, "info", "set the log level to debug|info|warn|error") + + addFlags(fs, "corso-.log") + + //nolint:errcheck + fs.MarkHidden(ReadableLogsFN) + // TODO(keepers): unhide when we have sufficient/complete coverage of PII handling + //nolint:errcheck + fs.MarkHidden(SensitiveInfoFN) +} + +// internal deduplication for adding flags +func addFlags(fs *pflag.FlagSet, defaultFile string) { + fs.StringVar( + &LogLevelFV, + LogLevelFN, + LLInfo, + fmt.Sprintf("set the log level to %s|%s|%s|%s", LLDebug, LLInfo, LLWarn, LLError)) // The default provided here is only for help info - fs.StringVar(&lfFlag, logFileFN, "corso-.log", "location for writing logs, use '-' for stdout") + 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") - fs.Bool(debugAPIFN, false, "add non-2xx request/response errors to logging") - - fs.Bool( - readableLogsFN, false, + fs.BoolVar( + &ReadableLogsFV, + ReadableLogsFN, + false, "minimizes log output for console readability: removes the file and date, colors the level") - //nolint:errcheck - fs.MarkHidden(readableLogsFN) + + fs.StringVar( + &SensitiveInfoFV, + SensitiveInfoFN, + PIIPlainText, + fmt.Sprintf("set the format for sensitive info in logs to %s|%s|%s", PIIHash, PIIMask, PIIPlainText)) +} + +// 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 @@ -84,39 +125,55 @@ func AddLoggingFlags(cmd *cobra.Command) { // pre-processed manually here using pflags. The canonical // AddLogLevelFlag() and AddLogFileFlag() ensures the flags are // displayed as part of the help/usage output. -func PreloadLoggingFlags() (string, string) { +func PreloadLoggingFlags(args []string) Settings { dlf := defaultLogLocation() fs := pflag.NewFlagSet("seed-logger", pflag.ContinueOnError) fs.ParseErrorsWhitelist.UnknownFlags = true - fs.String(logLevelFN, "info", "set the log level to debug|info|warn|error") - fs.String(logFileFN, dlf, "location for writing logs") - fs.BoolVar(&DebugAPI, debugAPIFN, false, "add non-2xx request/response errors to logging") - fs.BoolVar(&readableOutput, readableLogsFN, false, "minimizes log output: removes the file and date, colors the level") + addFlags(fs, dlf) + // prevents overriding the corso/cobra help processor fs.BoolP("help", "h", false, "") + ls := Settings{ + File: dlf, + Level: LogLevelFV, + PIIHandling: SensitiveInfoFV, + } + // parse the os args list to find the log level flag - if err := fs.Parse(os.Args[1:]); err != nil { - return "info", dlf + if err := fs.Parse(args); err != nil { + return ls } // retrieve the user's preferred log level // automatically defaults to "info" - levelString, err := fs.GetString(logLevelFN) + levelString, err := fs.GetString(LogLevelFN) if err != nil { - return "info", dlf + return ls } + ls.Level = levelString + // retrieve the user's preferred log file location // automatically defaults to default log location - lffv, err := fs.GetString(logFileFN) + lffv, err := fs.GetString(LogFileFN) if err != nil { - return "info", dlf + return ls } - logfile := GetLogFile(lffv) + ls.File = GetLogFile(lffv) + LogFile = ls.File - return levelString, logfile + // retrieve the user's preferred PII handling algorithm + // automatically defaults to default log location + pii, err := fs.GetString(SensitiveInfoFN) + if err != nil { + return ls + } + + ls.PIIHandling = pii + + return ls } // GetLogFile parses the log file. Uses the provided value, if populated, @@ -193,7 +250,7 @@ func genLogger(level logLevel, logfile string) (*zapcore.Core, *zap.SugaredLogge cfg.Level = zap.NewAtomicLevelAt(zapcore.FatalLevel) } - if readableOutput { + if ReadableLogsFV { opts = append(opts, zap.WithCaller(false)) cfg.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout("15:04:05.00") @@ -247,16 +304,31 @@ const ctxKey loggingKey = "corsoLogger" // It also parses the command line for flag values prior to executing // cobra. This early parsing is necessary since logging depends on // a seeded context prior to cobra evaluating flags. -func Seed(ctx context.Context, lvl, logfile string) (context.Context, *zap.SugaredLogger) { - if len(lvl) == 0 { - lvl = "info" +func Seed(ctx context.Context, set Settings) (context.Context, *zap.SugaredLogger) { + if len(set.Level) == 0 { + set.Level = LLInfo } - zsl := singleton(levelOf(lvl), logfile) + setCluesSecretsHash(set.PIIHandling) + + zsl := singleton(levelOf(set.Level), set.File) return Set(ctx, zsl), zsl } +func setCluesSecretsHash(alg string) { + switch alg { + case PIIHash: + // TODO: a persistent hmac key for each tenant would be nice + // as a way to correlate logs across runs. + clues.SetHasher(clues.DefaultHash()) + case PIIMask: + clues.SetHasher(clues.HashCfg{HashAlg: clues.Flatmask}) + case PIIPlainText: + clues.SetHasher(clues.NoHash()) + } +} + // SeedLevel generates a logger within the context with the given log-level. func SeedLevel(ctx context.Context, level logLevel) (context.Context, *zap.SugaredLogger) { l := ctx.Value(ctxKey) @@ -288,7 +360,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(llFlag), defaultLogLocation()) + return singleton(levelOf(LogLevelFV), defaultLogLocation()) } return l.(*zap.SugaredLogger).With(clues.In(ctx).Slice()...) @@ -307,13 +379,13 @@ func CtxErr(ctx context.Context, err error) *zap.SugaredLogger { // transforms the llevel flag value to a logLevel enum func levelOf(lvl string) logLevel { switch lvl { - case "debug": + case LLDebug: return Development - case "warn": + case LLWarn: return Warn - case "error": + case LLError: return Production - case "disabled": + case LLDisabled: return Disabled } diff --git a/src/pkg/logger/logger_test.go b/src/pkg/logger/logger_test.go new file mode 100644 index 000000000..7cb7926fa --- /dev/null +++ b/src/pkg/logger/logger_test.go @@ -0,0 +1,81 @@ +package logger_test + +import ( + "testing" + + "github.com/alcionai/clues" + "github.com/spf13/cobra" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "github.com/stretchr/testify/suite" + + "github.com/alcionai/corso/src/internal/tester" + "github.com/alcionai/corso/src/pkg/logger" +) + +type LoggerUnitSuite struct { + tester.Suite +} + +func TestLoggerUnitSuite(t *testing.T) { + suite.Run(t, &LoggerUnitSuite{Suite: tester.NewUnitSuite(t)}) +} + +func (suite *LoggerUnitSuite) TestAddLoggingFlags() { + t := suite.T() + + logger.DebugAPIFV = false + logger.ReadableLogsFV = false + + cmd := &cobra.Command{ + Use: "test", + 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, logger.PIIMask, logger.SensitiveInfoFV, logger.SensitiveInfoFN) + // empty assertion here, instead of matching "log-file", because the LogFile + // var isn't updated by running the command (this is expected and correct), + // while the logFileFV remains unexported. + assert.Empty(t, logger.LogFile, logger.LogFileFN) + }, + } + + logger.AddLoggingFlags(cmd) + + // Test arg parsing for few args + cmd.SetArgs([]string{ + "test", + "--" + logger.DebugAPIFN, + "--" + logger.LogFileFN, "log-file", + "--" + logger.LogLevelFN, logger.LLError, + "--" + logger.ReadableLogsFN, + "--" + logger.SensitiveInfoFN, logger.PIIMask, + }) + + err := cmd.Execute() + require.NoError(t, err, clues.ToCore(err)) +} + +func (suite *LoggerUnitSuite) TestPreloadLoggingFlags() { + t := suite.T() + + logger.DebugAPIFV = false + logger.ReadableLogsFV = false + + args := []string{ + "--" + logger.DebugAPIFN, + "--" + logger.LogFileFN, "log-file", + "--" + logger.LogLevelFN, logger.LLError, + "--" + logger.ReadableLogsFN, + "--" + logger.SensitiveInfoFN, logger.PIIMask, + } + + settings := logger.PreloadLoggingFlags(args) + + assert.True(t, logger.DebugAPIFV, logger.DebugAPIFN) + 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.PIIMask, settings.PIIHandling, "settings.PIIHandling") +}