From 584a942436bae29c275f7952d9d78d29593b4f50 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Sun, 16 Apr 2017 01:20:14 -0400 Subject: [PATCH] log: Add TimestampFormat. - TimestampFormat is a function to produce time Valuers with arbitrary time formats. - The Valuer generates values of the unexported type timeFormat, a value that defers formating timestamps until serialization, which improves performance when a log event is not serialized. - DefaultTimestamp and DefaultTimestampUTC are now created using TimestampFormat. --- log/value.go | 56 +++++++++++++++++++++++++++++++++++++++-------- log/value_test.go | 43 ++++++++++++++++++++++++++++++++++-- 2 files changed, 88 insertions(+), 11 deletions(-) diff --git a/log/value.go b/log/value.go index 0ce9b01f4..b56f154f8 100644 --- a/log/value.go +++ b/log/value.go @@ -32,13 +32,52 @@ func containsValuer(keyvals []interface{}) bool { return false } -// Timestamp returns a Valuer that invokes the underlying function when bound, -// returning a time.Time. Users will probably want to use DefaultTimestamp or -// DefaultTimestampUTC. +// Timestamp returns a timestamp Valuer. It invokes the t function to get the +// time; unless you are doing something tricky, pass time.Now. +// +// Most users will want to use DefaultTimestamp or DefaultTimestampUTC, which +// are TimestampFormats that use the RFC3339Nano format. func Timestamp(t func() time.Time) Valuer { return func() interface{} { return t() } } +// TimestampFormat returns a timestamp Valuer with a custom time format. It +// invokes the t function to get the time to format; unless you are doing +// something tricky, pass time.Now. The layout string is passed to +// Time.Format. +// +// Most users will want to use DefaultTimestamp or DefaultTimestampUTC, which +// are TimestampFormats that use the RFC3339Nano format. +func TimestampFormat(t func() time.Time, layout string) Valuer { + return func() interface{} { + return timeFormat{ + time: t(), + layout: layout, + } + } +} + +// A timeFormat represents an instant in time and a layout used when +// marshaling to a text format. +type timeFormat struct { + time time.Time + layout string +} + +func (tf timeFormat) String() string { + return tf.time.Format(tf.layout) +} + +// MarshalText implements encoding.TextMarshaller. +func (tf timeFormat) MarshalText() (text []byte, err error) { + // The following code adapted from the standard library time.Time.Format + // method. Using the same undocumented magic constant to extend the size + // of the buffer as seen there. + b := make([]byte, 0, len(tf.layout)+10) + b = tf.time.AppendFormat(b, tf.layout) + return b, nil +} + // Caller returns a Valuer that returns a file and line from a specified depth // in the callstack. Users will probably want to use DefaultCaller. func Caller(depth int) Valuer { @@ -48,15 +87,14 @@ func Caller(depth int) Valuer { var ( // DefaultTimestamp is a Valuer that returns the current wallclock time, // respecting time zones, when bound. - DefaultTimestamp = Valuer(func() interface{} { - return time.Now().Format(time.RFC3339Nano) - }) + DefaultTimestamp = TimestampFormat(time.Now, time.RFC3339Nano) // DefaultTimestampUTC is a Valuer that returns the current time in UTC // when bound. - DefaultTimestampUTC = Valuer(func() interface{} { - return time.Now().UTC().Format(time.RFC3339Nano) - }) + DefaultTimestampUTC = TimestampFormat( + func() time.Time { return time.Now().UTC() }, + time.RFC3339Nano, + ) // DefaultCaller is a Valuer that returns the file and line where the Log // method was invoked. It can only be used with log.With. diff --git a/log/value_test.go b/log/value_test.go index f67eecece..3a0c835a3 100644 --- a/log/value_test.go +++ b/log/value_test.go @@ -1,7 +1,9 @@ package log_test import ( + "encoding" "fmt" + "reflect" "testing" "time" @@ -34,7 +36,7 @@ func TestValueBinding(t *testing.T) { if want, have := start.Add(time.Second), timestamp; want != have { t.Errorf("output[1]: want %v, have %v", want, have) } - if want, have := "value_test.go:29", fmt.Sprint(output[3]); want != have { + if want, have := "value_test.go:31", fmt.Sprint(output[3]); want != have { t.Errorf("output[3]: want %s, have %s", want, have) } @@ -47,7 +49,7 @@ func TestValueBinding(t *testing.T) { if want, have := start.Add(2*time.Second), timestamp; want != have { t.Errorf("output[1]: want %v, have %v", want, have) } - if want, have := "value_test.go:42", fmt.Sprint(output[3]); want != have { + if want, have := "value_test.go:44", fmt.Sprint(output[3]); want != have { t.Errorf("output[3]: want %s, have %s", want, have) } } @@ -90,6 +92,43 @@ func TestValueBinding_loggingZeroKeyvals(t *testing.T) { } } +func TestTimestampFormat(t *testing.T) { + t.Parallel() + + start := time.Date(2015, time.April, 25, 0, 0, 0, 0, time.UTC) + now := start + mocktime := func() time.Time { + now = now.Add(time.Second) + return now + } + + tv := log.TimestampFormat(mocktime, time.RFC822) + + if want, have := now.Add(time.Second).Format(time.RFC822), fmt.Sprint(tv()); want != have { + t.Errorf("wrong time format: want %v, have %v", want, have) + } + + if want, have := now.Add(2*time.Second).Format(time.RFC822), fmt.Sprint(tv()); want != have { + t.Errorf("wrong time format: want %v, have %v", want, have) + } + + mustMarshal := func(v interface{}) []byte { + b, err := v.(encoding.TextMarshaler).MarshalText() + if err != nil { + t.Fatal("error marshaling text:", err) + } + return b + } + + if want, have := now.Add(3*time.Second).AppendFormat(nil, time.RFC822), mustMarshal(tv()); !reflect.DeepEqual(want, have) { + t.Errorf("wrong time format: want %s, have %s", want, have) + } + + if want, have := now.Add(4*time.Second).AppendFormat(nil, time.RFC822), mustMarshal(tv()); !reflect.DeepEqual(want, have) { + t.Errorf("wrong time format: want %s, have %s", want, have) + } +} + func BenchmarkValueBindingTimestamp(b *testing.B) { logger := log.NewNopLogger() lc := log.With(logger, "ts", log.DefaultTimestamp)