add support for iso8601 timestamps (#1529)

* add support for iso8601 timestamps

* Update pkg/log/zap/flags.go

Co-Authored-By: Lili Cosic <[email protected]>

* timeformat flag accepts zapcore formats

* add --zap-timeformat usage doc

* Update pkg/log/zap/flags.go

Co-Authored-By: Joe Lanford <[email protected]>

* expand log encoder support functional options and passing multiple encoder options simultaneously

* fix encoder references in tests

* fix encoder references in tests

* Update doc/user/logging.md

Co-Authored-By: Joe Lanford <[email protected]>

* set the encoder in both the json and console cases

* use zap's time encoding UnmarshalText functionality to avoid manually defining supported time formats

* rename timeformat to timeencoding/er so that it is consistent with zap's nomenclature

* rename timeformat to timeencoding/er so that it is consistent with zap's nomenclature

* add basic tests for zap time encoding

* pkg/log/zap/*: test improvements for sampling and encoders

* pkg/log/zap/flags*: timeEncoder Unmarshal comments/improvements

* doc/user/logging.md: fix zap-time-encoding flag name

* CHANGELOG.md,doc/user/logging.md: doc updates

Author: ironmike-au

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
 

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
 

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,26 +42,29 @@ 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.
 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
+	}
+}

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

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