larryh/corso
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

separate log level and format config (#3398)

Browse Source 
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

#### Type of change

- [x] 🤖 Supportability/Tests

#### Test Plan

- [x] 💪 Manual
This commit is contained in:
Keepers 2023-05-15 16:03:37 -06:00 committed by GitHub
parent 97ed97c1c3
commit 3c26b09d71
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
7 changed files with 254 additions and 140 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
src/cmd/factory/factory.go
View File

@ -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() {

6
src/cmd/getM365/main.go
View File

@ -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)

6
src/cmd/purge/purge.go
View File

@ -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)

7
src/internal/kopia/wrapper_test.go
View File

@ -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))

19
src/internal/tester/cli.go
View File

@ -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) }
}

302
src/pkg/logger/logger.go
View File

@ -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
}

48
src/pkg/logger/logger_test.go
View File

@ -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")
}