diff --git a/CHANGELOG.md b/CHANGELOG.md index c0047b6890..af66c90ae6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,7 @@ ### Added - Document new compile-time dependency `mercurial` in user-facing documentation. ([#1683](https://github.com/operator-framework/operator-sdk/pull/1683)) +- Adds new flag `--zap-time-encoding` to the flagset provided by `pkg/log/zap`. This flag configures the timestamp format produced by the zap logger. See the [logging doc](https://github.com/operator-framework/operator-sdk/blob/master/doc/user/logging.md) for more information. ([#1529](https://github.com/operator-framework/operator-sdk/pull/1529)) ### Changed diff --git a/doc/user/logging.md b/doc/user/logging.md index fe40a07ba5..489b97d42c 100644 --- a/doc/user/logging.md +++ b/doc/user/logging.md @@ -14,6 +14,7 @@ By default, `zap.Logger()` will return a logger that is ready for production use * `--zap-encoder` string - Sets the zap log encoding (`json` or `console`) * `--zap-level` string or integer - Sets the zap log level (`debug`, `info`, `error`, or an integer value greater than 0). If 4 or greater the verbosity of client-go will be set to this level. * `--zap-sample` - Enables zap's sampling mode. Sampling will be disabled for integer log levels greater than 1. +* `--zap-time-encoding` string - Sets the zap time format (`epoch`, `millis`, `nano`, or `iso8601`) ### A simple example diff --git a/pkg/log/zap/flags.go b/pkg/log/zap/flags.go index d94911d94b..f8449479ac 100644 --- a/pkg/log/zap/flags.go +++ b/pkg/log/zap/flags.go @@ -29,10 +29,11 @@ import ( var ( zapFlagSet *pflag.FlagSet - development bool - encoderVal encoderValue - levelVal levelValue - sampleVal sampleValue + development bool + encoderVal encoderValue + levelVal levelValue + sampleVal sampleValue + timeEncodingVal timeEncodingValue ) func init() { @@ -41,6 +42,7 @@ func init() { zapFlagSet.Var(&encoderVal, "zap-encoder", "Zap log encoding ('json' or 'console')") zapFlagSet.Var(&levelVal, "zap-level", "Zap log level (one of 'debug', 'info', 'error' or any integer value > 0)") zapFlagSet.Var(&sampleVal, "zap-sample", "Enable zap log sampling. Sampling will be disabled for integer log levels > 1") + zapFlagSet.Var(&timeEncodingVal, "zap-time-encoding", "Sets the zap time format ('epoch', 'millis', 'nano', or 'iso8601')") } // FlagSet - The zap logging flagset. @@ -48,19 +50,21 @@ func FlagSet() *pflag.FlagSet { return zapFlagSet } +type encoderConfigFunc func(*zapcore.EncoderConfig) + type encoderValue struct { - set bool - encoder zapcore.Encoder - str string + set bool + newEncoder func(...encoderConfigFunc) zapcore.Encoder + str string } func (v *encoderValue) Set(e string) error { v.set = true switch e { case "json": - v.encoder = jsonEncoder() + v.newEncoder = newJSONEncoder case "console": - v.encoder = consoleEncoder() + v.newEncoder = newConsoleEncoder default: return fmt.Errorf("unknown encoder \"%s\"", e) } @@ -76,13 +80,19 @@ func (v encoderValue) Type() string { return "encoder" } -func jsonEncoder() zapcore.Encoder { +func newJSONEncoder(ecfs ...encoderConfigFunc) zapcore.Encoder { encoderConfig := zap.NewProductionEncoderConfig() + for _, f := range ecfs { + f(&encoderConfig) + } return zapcore.NewJSONEncoder(encoderConfig) } -func consoleEncoder() zapcore.Encoder { +func newConsoleEncoder(ecfs ...encoderConfigFunc) zapcore.Encoder { encoderConfig := zap.NewDevelopmentEncoderConfig() + for _, f := range ecfs { + f(&encoderConfig) + } return zapcore.NewConsoleEncoder(encoderConfig) } @@ -158,3 +168,48 @@ func (v sampleValue) IsBoolFlag() bool { func (v sampleValue) Type() string { return "sample" } + +type timeEncodingValue struct { + set bool + timeEncoder zapcore.TimeEncoder + str string +} + +func (v *timeEncodingValue) Set(s string) error { + v.set = true + + // As of zap v1.9.1, UnmarshalText does not return an error. Instead, it + // uses the epoch time encoding when unknown strings are unmarshalled. + // + // Set s to "epoch" if it doesn't match one of the known formats, so that + // it aligns with the default time encoder function. + // + // TODO: remove this entire switch statement if UnmarshalText is ever + // refactored to return an error. + switch s { + case "iso8601", "ISO8601", "millis", "nanos": + default: + s = "epoch" + } + + v.str = s + return v.timeEncoder.UnmarshalText([]byte(s)) +} + +func (v timeEncodingValue) String() string { + return v.str +} + +func (v timeEncodingValue) IsBoolFlag() bool { + return false +} + +func (v timeEncodingValue) Type() string { + return "timeEncoding" +} + +func withTimeEncoding(te zapcore.TimeEncoder) encoderConfigFunc { + return func(ec *zapcore.EncoderConfig) { + ec.EncodeTime = te + } +} diff --git a/pkg/log/zap/flags_test.go b/pkg/log/zap/flags_test.go index f03f2110f9..74a97e817e 100644 --- a/pkg/log/zap/flags_test.go +++ b/pkg/log/zap/flags_test.go @@ -167,14 +167,14 @@ func TestEncoder(t *testing.T) { input: "json", expStr: "json", expSet: true, - expEncoder: jsonEncoder(), + expEncoder: newJSONEncoder(), }, { name: "console encoder", input: "console", expStr: "console", expSet: true, - expEncoder: consoleEncoder(), + expEncoder: newConsoleEncoder(), }, { name: "unknown encoder", @@ -196,7 +196,63 @@ func TestEncoder(t *testing.T) { assert.Equal(t, tc.expSet, encoder.set) assert.Equal(t, "encoder", encoder.Type()) assert.Equal(t, tc.expStr, encoder.String()) - assert.ObjectsAreEqual(tc.expEncoder, encoder.encoder) + assert.ObjectsAreEqual(tc.expEncoder, encoder.newEncoder) + }) + } +} +func TestTimeEncoder(t *testing.T) { + testCases := []struct { + name string + input string + shouldErr bool + expStr string + expSet bool + }{ + { + name: "iso8601 time encoding", + input: "iso8601", + expStr: "iso8601", + expSet: true, + }, + { + name: "millis time encoding", + input: "millis", + expStr: "millis", + expSet: true, + }, + { + name: "nanos time encoding", + input: "nanos", + expStr: "nanos", + expSet: true, + }, + { + name: "epoch time encoding", + input: "epoch", + expStr: "epoch", + expSet: true, + }, + { + name: "invalid time encoding", + input: "invalid", + expStr: "epoch", + expSet: true, + shouldErr: false, + }, + } + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + te := timeEncodingValue{} + err := te.Set(tc.input) + if err != nil && !tc.shouldErr { + t.Fatalf("Unknown error - %v", err) + } + if tc.shouldErr { + assert.Error(t, err) + } + assert.Equal(t, tc.expSet, te.set) + assert.Equal(t, "timeEncoding", te.Type()) + assert.Equal(t, tc.expStr, te.String()) }) } } diff --git a/pkg/log/zap/logger.go b/pkg/log/zap/logger.go index 795cbff3f3..fa4db44b08 100644 --- a/pkg/log/zap/logger.go +++ b/pkg/log/zap/logger.go @@ -31,8 +31,12 @@ func Logger() logr.Logger { } func LoggerTo(destWriter io.Writer) logr.Logger { - syncer := zapcore.AddSync(destWriter) conf := getConfig() + return createLogger(conf, destWriter) +} + +func createLogger(conf config, destWriter io.Writer) logr.Logger { + syncer := zapcore.AddSync(destWriter) conf.encoder = &logf.KubeAwareEncoder{Encoder: conf.encoder, Verbose: conf.level.Level() < 0} if conf.sample { @@ -56,23 +60,32 @@ type config struct { func getConfig() config { var c config + var newEncoder func(...encoderConfigFunc) zapcore.Encoder + // Set the defaults depending on the log mode (development vs. production) if development { - c.encoder = consoleEncoder() + newEncoder = newConsoleEncoder c.level = zap.NewAtomicLevelAt(zap.DebugLevel) c.opts = append(c.opts, zap.Development(), zap.AddStacktrace(zap.ErrorLevel)) c.sample = false } else { - c.encoder = jsonEncoder() + newEncoder = newJSONEncoder c.level = zap.NewAtomicLevelAt(zap.InfoLevel) c.opts = append(c.opts, zap.AddStacktrace(zap.WarnLevel)) c.sample = true } // Override the defaults if the flags were set explicitly on the command line + var ecfs []encoderConfigFunc if encoderVal.set { - c.encoder = encoderVal.encoder + newEncoder = encoderVal.newEncoder + } + if timeEncodingVal.set { + ecfs = append(ecfs, withTimeEncoding(timeEncodingVal.timeEncoder)) } + + c.encoder = newEncoder(ecfs...) + if levelVal.set { c.level = zap.NewAtomicLevelAt(levelVal.level) } diff --git a/pkg/log/zap/logger_test.go b/pkg/log/zap/logger_test.go index e5cd0008c2..8ddd878578 100644 --- a/pkg/log/zap/logger_test.go +++ b/pkg/log/zap/logger_test.go @@ -15,16 +15,13 @@ package zap import ( - "io" - "os" + "bytes" "testing" "time" "go.uber.org/zap" "go.uber.org/zap/zapcore" - "github.com/go-logr/logr" - "github.com/go-logr/zapr" "github.com/stretchr/testify/assert" ) @@ -32,12 +29,13 @@ func TestGetConfig(t *testing.T) { var opts []zap.Option testCases := []struct { - name string - inDevel bool - inEncoder encoderValue - inLevel levelValue - inSample sampleValue - expected config + name string + inDevel bool + inEncoder encoderValue + inLevel levelValue + inSample sampleValue + inTimeEncoding timeEncodingValue + expected config }{ { name: "development on", @@ -51,8 +49,11 @@ func TestGetConfig(t *testing.T) { inSample: sampleValue{ set: false, }, + inTimeEncoding: timeEncodingValue{ + set: false, + }, expected: config{ - encoder: consoleEncoder(), + encoder: newConsoleEncoder(), level: zap.NewAtomicLevelAt(zap.DebugLevel), opts: append(opts, zap.Development(), zap.AddStacktrace(zap.ErrorLevel)), sample: false, @@ -70,8 +71,11 @@ func TestGetConfig(t *testing.T) { inSample: sampleValue{ set: false, }, + inTimeEncoding: timeEncodingValue{ + set: false, + }, expected: config{ - encoder: jsonEncoder(), + encoder: newJSONEncoder(), level: zap.NewAtomicLevelAt(zap.InfoLevel), opts: append(opts, zap.AddStacktrace(zap.WarnLevel)), sample: true, @@ -81,8 +85,8 @@ func TestGetConfig(t *testing.T) { name: "set encoder", inDevel: false, inEncoder: encoderValue{ - set: true, - encoder: consoleEncoder(), + set: true, + newEncoder: newConsoleEncoder, }, inLevel: levelValue{ set: false, @@ -90,8 +94,11 @@ func TestGetConfig(t *testing.T) { inSample: sampleValue{ set: false, }, + inTimeEncoding: timeEncodingValue{ + set: false, + }, expected: config{ - encoder: jsonEncoder(), + encoder: newConsoleEncoder(), level: zap.NewAtomicLevelAt(zap.InfoLevel), opts: append(opts, zap.AddStacktrace(zap.WarnLevel)), sample: true, @@ -110,8 +117,11 @@ func TestGetConfig(t *testing.T) { inSample: sampleValue{ set: false, }, + inTimeEncoding: timeEncodingValue{ + set: false, + }, expected: config{ - encoder: jsonEncoder(), + encoder: newJSONEncoder(), level: zap.NewAtomicLevelAt(zap.ErrorLevel), opts: append(opts, zap.AddStacktrace(zap.WarnLevel)), sample: true, @@ -130,13 +140,39 @@ func TestGetConfig(t *testing.T) { inSample: sampleValue{ set: false, }, + inTimeEncoding: timeEncodingValue{ + set: false, + }, expected: config{ - encoder: jsonEncoder(), + encoder: newJSONEncoder(), level: zap.NewAtomicLevelAt(zapcore.Level(-10)), opts: append(opts, zap.AddStacktrace(zap.WarnLevel)), sample: false, }, }, + { + name: "set sampling", + inDevel: false, + inEncoder: encoderValue{ + set: false, + }, + inLevel: levelValue{ + set: false, + }, + inSample: sampleValue{ + set: true, + sample: false, + }, + inTimeEncoding: timeEncodingValue{ + set: false, + }, + expected: config{ + encoder: newJSONEncoder(), + level: zap.NewAtomicLevelAt(zap.InfoLevel), + opts: append(opts, zap.AddStacktrace(zap.WarnLevel)), + sample: false, + }, + }, { name: "set level using custom level, sample override not possible", inDevel: false, @@ -151,13 +187,52 @@ func TestGetConfig(t *testing.T) { set: true, sample: true, }, + inTimeEncoding: timeEncodingValue{ + set: false, + }, expected: config{ - encoder: jsonEncoder(), + encoder: newJSONEncoder(), level: zap.NewAtomicLevelAt(zapcore.Level(-10)), opts: append(opts, zap.AddStacktrace(zap.WarnLevel)), sample: false, }, }, + { + name: "set time encoding", + inDevel: false, + inEncoder: encoderValue{ + set: false, + }, + inLevel: levelValue{ + set: false, + }, + inSample: sampleValue{ + set: false, + }, + inTimeEncoding: timeEncodingValue{ + set: true, + timeEncoder: zapcore.EpochMillisTimeEncoder, + }, + expected: config{ + encoder: newJSONEncoder(withTimeEncoding(zapcore.EpochMillisTimeEncoder)), + level: zap.NewAtomicLevelAt(zap.InfoLevel), + opts: append(opts, zap.AddStacktrace(zap.WarnLevel)), + sample: true, + }, + }, + } + + entry := zapcore.Entry{ + Level: levelVal.level, + Time: time.Now(), + LoggerName: "TestLogger", + Message: "Test message", + Caller: zapcore.EntryCaller{ + Defined: true, + File: "dummy_file.go", + Line: 10, + }, + Stack: "Sample stack", } for _, tc := range testCases { @@ -166,27 +241,35 @@ func TestGetConfig(t *testing.T) { encoderVal = tc.inEncoder levelVal = tc.inLevel sampleVal = tc.inSample + timeEncodingVal = tc.inTimeEncoding cfg := getConfig() assert.Equal(t, tc.expected.level, cfg.level) assert.Equal(t, len(tc.expected.opts), len(cfg.opts)) assert.Equal(t, tc.expected.sample, cfg.sample) - dalog := createLogger(cfg, os.Stderr) - dalog.V(10).Info("This should not panic") - }) - } -} + // Test that the encoder returned by getConfig encodes an entry + // the same way that the expected encoder does. In addition to + // testing that the correct entry encoding (json vs. console) is + // used, this also tests that the correct time encoding is used. + expectedEncoderOut, err := tc.expected.encoder.EncodeEntry(entry, []zapcore.Field{{Key: "fieldKey", Type: zapcore.StringType, String: "fieldValue"}}) + if err != nil { + t.Fatalf("Unexpected error encoding entry with expected encoder: %s", err) + } + actualEncoderOut, err := cfg.encoder.EncodeEntry(entry, []zapcore.Field{{Key: "fieldKey", Type: zapcore.StringType, String: "fieldValue"}}) + if err != nil { + t.Fatalf("Unexpected error encoding entry with actual encoder: %s", err) + } + assert.Equal(t, expectedEncoderOut.String(), actualEncoderOut.String()) -func createLogger(cfg config, dest io.Writer) logr.Logger { - syncer := zapcore.AddSync(dest) - if cfg.sample { - cfg.opts = append(cfg.opts, zap.WrapCore(func(core zapcore.Core) zapcore.Core { - return zapcore.NewSampler(core, time.Second, 100, 100) - })) + // This test helps ensure that we disable sampling for verbose log + // levels. Logging at V(10) should never panic, which would happen + // if sampling is enabled at this level. + assert.NotPanics(t, func() { + out := &bytes.Buffer{} + dalog := createLogger(cfg, out) + dalog.V(10).Info("This should not panic") + }) + }) } - cfg.opts = append(cfg.opts, zap.AddCallerSkip(1), zap.ErrorOutput(syncer)) - log := zap.New(zapcore.NewCore(cfg.encoder, syncer, cfg.level)) - log = log.WithOptions(cfg.opts...) - return zapr.NewLogger(log) }