Use RFC3339 in UTC as the default time format for log messages (#84)

* Use RFC3339 in UTC as the default time format for log messages This ensures that times that are logged in messages can be deserialised by the encoding/json package irrespective of the timezone that the time is in when logged; currently if the time is not in UTC, the ISO8601 format that is used is not accepted. Also provide a non-UTC formatter that can be used where the timezone is important. * Add test for non-UTC timestamp Also fix time validation in logger tests. --------- Co-authored-by: Andrew Wilkins <[email protected]>
elastic · Dec 2, 2024 · 43fc05e · 43fc05e
1 parent 54335a2
commit 43fc05e
Show file tree

Hide file tree

Showing 5 changed files with 61 additions and 7 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -2,6 +2,7 @@
 Changelog for ecszap
 
 ## unreleased
+* Use RFC3339 in UTC as the default time format for log messages [pull#84](https://github.com/elastic/ecs-logging-go-zap/pull/84)
 
 ## 1.0.2
 * Updated zap to v1.24.0 [pull#50](https://github.com/elastic/ecs-logging-go-zap/pull/50)

diff --git a/encoder.go b/encoder.go
@@ -49,6 +49,39 @@ func ShortCallerEncoder(c zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder
 	encodeCaller(&caller{c, false}, enc)
 }
 
+// RFC3339TimeEncoder serializes a time.Time to an RFC3339-formatted string
+// with millisecond precision.
+//
+// If enc supports AppendTimeLayout(t time.Time,layout string), it's used
+// instead of appending a pre-formatted string value.
+func RFC3339TimeEncoder(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
+	type appendTimeEncoder interface {
+		AppendTimeLayout(time.Time, string)
+	}
+	// Use a custom RFC3339 layout with obligatory millisecond
+	// precision rather than the second-resolution or optional
+	// nano-second resolution that is provided in the time
+	// package.
+	const rfc3339millis = "2006-01-02T15:04:05.000Z07:00"
+	if enc, ok := enc.(appendTimeEncoder); ok {
+		enc.AppendTimeLayout(t, rfc3339millis)
+		return
+	}
+
+	enc.AppendString(t.Format(rfc3339millis))
+}
+
+// RFC3339UTCTimeEncoder serializes a time.Time to an RFC3339-formatted string
+// with millisecond precision in UTC.
+//
+// If enc supports AppendTimeLayout(t time.Time,layout string), it's used
+// instead of appending a pre-formatted string value.
+//
+// RFC3339UTCTimeEncoder is the default time encoder used by EncoderConfig.
+func RFC3339UTCTimeEncoder(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
+	RFC3339TimeEncoder(t.In(time.UTC), enc)
+}
+
 // UnmarshalText creates a CallerEncoder function,
 // `full` is unmarshalled to FullCallerEncoder,
 // defaults to ShortCallerEncoder,

diff --git a/encoder_config.go b/encoder_config.go
@@ -34,7 +34,7 @@ var (
 	messageKey    = "message"
 	stackTraceKey = "log.origin.stack_trace"
 	timeKey       = "@timestamp"
-	encodeTime    = zapcore.ISO8601TimeEncoder
+	encodeTime    = RFC3339UTCTimeEncoder
 )
 
 // EncoderConfig exports all non ECS related configurable settings.

diff --git a/encoder_config_test.go b/encoder_config_test.go
@@ -37,11 +37,13 @@ func TestJSONEncoder_EncoderConfig(t *testing.T) {
 	for _, tc := range []struct {
 		name     string
 		cfg      EncoderConfig
+		tz       *time.Location
 		input    string
 		expected string
 	}{
 		{name: "defaultConfig",
 			cfg: NewDefaultEncoderConfig(),
+			tz:  time.UTC,
 			expected: `{"log.level": "debug",
 						"@timestamp": "2020-09-13T10:48:03.000Z",
 						"message": "log message",
@@ -60,6 +62,7 @@ func TestJSONEncoder_EncoderConfig(t *testing.T) {
 				EnableCaller:     false,
 				EnableStackTrace: false,
 			},
+			tz: time.UTC,
 			expected: `{"log.level": "debug",
 						"@timestamp": "2020-09-13T10:48:03.000Z",
 						"message": "log message",
@@ -77,6 +80,7 @@ func TestJSONEncoder_EncoderConfig(t *testing.T) {
 				EncodeDuration: zapcore.MillisDurationEncoder,
 				EncodeCaller:   ShortCallerEncoder,
 			},
+			tz: time.UTC,
 			expected: `{"log.level": "DEBUG",
 						"@timestamp": "2020-09-13T10:48:03.000Z",
 						"message": "log message",
@@ -90,12 +94,21 @@ func TestJSONEncoder_EncoderConfig(t *testing.T) {
 						"foo": "bar",
 						"dur": 5}`},
 		{name: "defaultUnmarshal",
+			tz: time.UTC,
+			expected: `{"log.level": "debug",
+						"@timestamp": "2020-09-13T10:48:03.000Z",
+						"message": "log message",
+						"foo": "bar",
+						"dur": 5000000}`},
+		{name: "nonUTC",
+			tz: time.FixedZone("UTC-8", -8*60*60),
 			expected: `{"log.level": "debug",
 						"@timestamp": "2020-09-13T10:48:03.000Z",
 						"message": "log message",
 						"foo": "bar",
 						"dur": 5000000}`},
 		{name: "allEnabled",
+			tz: time.UTC,
 			input: `{"enableName": true, 
   					 "enableStackTrace": true,
 					 "enableCaller":true,
@@ -116,6 +129,7 @@ func TestJSONEncoder_EncoderConfig(t *testing.T) {
 						"dur": 5}`},
 		{name: "fullCaller",
 			input: `{"callerEncoder": "full","enableCaller":true}`,
+			tz:    time.UTC,
 			expected: `{"log.level": "debug",
 						"@timestamp": "2020-09-13T10:48:03.000Z",
 						"message": "log message",
@@ -131,7 +145,7 @@ func TestJSONEncoder_EncoderConfig(t *testing.T) {
 			// setup
 			entry := zapcore.Entry{
 				Level:      zapcore.DebugLevel,
-				Time:       time.Unix(1599994083, 0).UTC(),
+				Time:       time.Unix(1599994083, 0).In(tc.tz),
 				Message:    "log message",
 				Caller:     caller,
 				Stack:      "frames",

diff --git a/logger_test.go b/logger_test.go
@@ -79,7 +79,13 @@ func (tw *testOutput) validate(t *testing.T, keys ...string) {
 			case "datetime":
 				var s string
 				s, ok = val.(string)
-				if _, err := time.Parse("2006-01-02T15:04:05.000Z0700", s); err == nil {
+				if !ok {
+					break
+				}
+				var tv time.Time
+				// Depends on the agreement between Go quoting and JSON quoting
+				// for time values.
+				if err := json.Unmarshal([]byte(strconv.Quote(s)), &tv); err == nil {
 					ok = true
 				}
 			case "integer":
@@ -125,7 +131,7 @@ func TestECSZapLogger(t *testing.T) {
 
 			// strongly typed fields
 			logger.Info("testlog", zap.String("foo", "bar"))
-			out.validate(t, "foo", "log.origin")
+			out.validate(t, "@timestamp", "foo", "log.origin")
 
 			// caller function
 			outLogOrigin, ok := out.m["log.origin"].(map[string]interface{})
@@ -135,7 +141,7 @@ func TestECSZapLogger(t *testing.T) {
 			// log a wrapped error
 			out.reset()
 			logger.With(zap.Error(errors.New("test error"))).Error("boom")
-			out.validate(t, "error", "message")
+			out.validate(t, "@timestamp", "error", "message")
 			assert.Equal(t, "boom", out.m["message"])
 			outErr, ok := out.m["error"].(map[string]interface{})
 			require.True(t, ok, out.m["error"])
@@ -146,7 +152,7 @@ func TestECSZapLogger(t *testing.T) {
 			logger = logger.With(zap.String("foo", "bar"))
 			logger = logger.Named("mylogger")
 			logger.Debug("debug message")
-			out.validate(t, "log.logger", "foo")
+			out.validate(t, "@timestamp", "log.logger", "foo")
 
 			// Use loosely typed logger
 			out.reset()
@@ -155,7 +161,7 @@ func TestECSZapLogger(t *testing.T) {
 				"foo", "bar",
 				"count", 17,
 			)
-			out.validate(t, "log.origin", "foo", "count")
+			out.validate(t, "@timestamp", "log.origin", "foo", "count")
 			out.reset()
 		})
 	}