logger: change time field format to include milliseconds (#30)

blacklane · Feb 1, 2021 · a919f21 · a919f21
1 parent 0a519f7
commit a919f21
Show file tree

Hide file tree

Showing 6 changed files with 14 additions and 11 deletions.
diff --git a/logger/internal/constants.go b/logger/internal/constants.go
@@ -26,6 +26,8 @@ const (
 	FieldStatus          = "status"
 	FieldRequestDuration = "request_duration"
 
+	TimeFieldFormat = "2006-01-02T15:04:05.000Z07:00"
+
 	// Event constants
 
 	// EventRequestFinished should be used as 'event' when logging a finished request/job

diff --git a/logger/logger.go b/logger/logger.go
@@ -23,6 +23,7 @@ type ConsoleWriter = zerolog.ConsoleWriter
 //   New(os.Stdout, "myAwesomeApp", WithStr("foo", "bar"))
 func New(w io.Writer, appName string, configs ...func(cfg *config)) Logger {
 	zerolog.TimestampFieldName = internal.FieldTimestamp
+	zerolog.TimeFieldFormat = internal.TimeFieldFormat
 
 	c := zerolog.New(w).
 		With().

diff --git a/logger/logger_example_test.go b/logger/logger_example_test.go
@@ -18,5 +18,5 @@ func ExampleNew() {
 	l.Info().Msg("Hello, Gophers!")
 
 	// Output:
-	// {"level":"info","application":"example","key1":"value1","key2":"value2","timestamp":"0001-01-01T00:00:00Z","message":"Hello, Gophers!"}
+	// {"level":"info","application":"example","key1":"value1","key2":"value2","timestamp":"0001-01-01T00:00:00.000Z","message":"Hello, Gophers!"}
 }
diff --git a/logger/middleware/events_test.go b/logger/middleware/events_test.go
@@ -33,7 +33,7 @@ func ExampleEventsAddLogger() {
 	_ = hh.Handle(context.Background(), events.Event{})
 
 	// Output:
-	// {"level":"info","application":"ExampleEventsAddLogger","timestamp":"2009-11-10T23:00:00Z","message":"Hello, Gophers from events"}
+	// {"level":"info","application":"ExampleEventsAddLogger","timestamp":"2009-11-10T23:00:00.000Z","message":"Hello, Gophers from events"}
 }
 
 func ExampleEventsHandlerStatusLogger_success() {
@@ -62,7 +62,7 @@ func ExampleEventsHandlerStatusLogger_success() {
 	_ = h.Handle(ctx, events.Event{Payload: []byte(`{"event":"event_name_here"}`)})
 
 	// Output:
-	// {"level":"info","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"event_name_here succeeded"}
+	// {"level":"info","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01.000Z","message":"event_name_here succeeded"}
 }
 
 func ExampleEventsHandlerStatusLogger_onlyLogCertainEvents() {
@@ -92,7 +92,7 @@ func ExampleEventsHandlerStatusLogger_onlyLogCertainEvents() {
 	_ = h.Handle(ctx, events.Event{Payload: []byte(`{"event":"do_not_log_event"}`)})
 
 	// Output:
-	// {"level":"info","application":"ExampleEventsLogger","event":"log_event","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"log_event succeeded"}
+	// {"level":"info","application":"ExampleEventsLogger","event":"log_event","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01.000Z","message":"log_event succeeded"}
 }
 
 func ExampleEventsHandlerStatusLogger_failure() {
@@ -121,7 +121,7 @@ func ExampleEventsHandlerStatusLogger_failure() {
 	_ = h.Handle(ctx, events.Event{Payload: []byte(`{"event":"event_name_here"}`)})
 
 	// Output:
-	// {"level":"error","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Failure","tracking_id":"tracking_id-ExampleEventsLogger_Failure","error":"bad","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"event_name_here failed"}
+	// {"level":"error","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Failure","tracking_id":"tracking_id-ExampleEventsLogger_Failure","error":"bad","duration_ms":1000,"timestamp":"2009-11-10T23:00:01.000Z","message":"event_name_here failed"}
 }
 
 func ExampleEventsHandlerStatusLoggerWithNameFn() {
@@ -162,5 +162,5 @@ func ExampleEventsHandlerStatusLoggerWithNameFn() {
 	_ = h.Handle(ctx, events.Event{Payload: []byte(`{"name":"event_name_here"}`)})
 
 	// Output:
-	// {"level":"info","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"event_name_here succeeded"}
+	// {"level":"info","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01.000Z","message":"event_name_here succeeded"}
 }
diff --git a/logger/middleware/http_example_test.go b/logger/middleware/http_example_test.go
@@ -36,7 +36,7 @@ func ExampleHTTPAddLogger() {
 	h.ServeHTTP(w, r)
 
 	// Output:
-	// {"level":"info","application":"","timestamp":"2009-11-10T23:00:00Z","message":"Hello, Gophers"}
+	// {"level":"info","application":"","timestamp":"2009-11-10T23:00:00.000Z","message":"Hello, Gophers"}
 }
 
 func ExampleHTTPRequestLogger_simple() {
@@ -61,7 +61,7 @@ func ExampleHTTPRequestLogger_simple() {
 	h.ServeHTTP(w, r.WithContext(ctx))
 
 	// Output:
-	// {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"localhost","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"","route":"","tracking_id":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":0,"timestamp":"2009-11-10T23:00:00Z","message":"GET /foo"}
+	// {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"localhost","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"","route":"","tracking_id":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":0,"timestamp":"2009-11-10T23:00:00.000Z","message":"GET /foo"}
 }
 
 func ExampleHTTPRequestLogger_complete() {
@@ -90,7 +90,7 @@ func ExampleHTTPRequestLogger_complete() {
 	h.ServeHTTP(w, rr)
 
 	// Output:
-	// {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"42.42.42.42","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"42","route":"","tracking_id":"42","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":1000,"timestamp":"2009-11-10T23:00:02Z","message":"GET /foo"}
+	// {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"42.42.42.42","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"42","route":"","tracking_id":"42","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":1000,"timestamp":"2009-11-10T23:00:02.000Z","message":"GET /foo"}
 }
 
 func ExampleHTTPRequestLogger_skipRoutes() {
@@ -121,5 +121,5 @@ func ExampleHTTPRequestLogger_skipRoutes() {
 	h.ServeHTTP(w, rLive.WithContext(ctx))
 
 	// Output:
-	// {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"localhost","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"","route":"","tracking_id":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":0,"timestamp":"2009-11-10T23:00:00Z","message":"GET /foo"}
+	// {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"localhost","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"","route":"","tracking_id":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":0,"timestamp":"2009-11-10T23:00:00.000Z","message":"GET /foo"}
 }
diff --git a/logger/middleware/http_test.go b/logger/middleware/http_test.go
@@ -27,7 +27,7 @@ func (m chain) apply(handler http.Handler) http.Handler {
 }
 
 func TestHTTPRequestLogger(t *testing.T) {
-	want := `{"level":"info","application":"TestHTTPRequestLogger","entry_point":false,"host":"example.com","ip":"localhost","params":"","path":"/do_not_skip","request_depth":0,"request_id":"a_known_id","route":"","tracking_id":"a_known_id","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":0,"request_duration":0,"timestamp":"2009-11-10T23:00:00Z","message":"GET /do_not_skip"}` + "\n"
+	want := `{"level":"info","application":"TestHTTPRequestLogger","entry_point":false,"host":"example.com","ip":"localhost","params":"","path":"/do_not_skip","request_depth":0,"request_id":"a_known_id","route":"","tracking_id":"a_known_id","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":0,"request_duration":0,"timestamp":"2009-11-10T23:00:00.000Z","message":"GET /do_not_skip"}` + "\n"
 
 	// Set current time function so we can control the request duration
 	logger.SetNowFunc(func() time.Time {