diff --git a/logger/internal/constants.go b/logger/internal/constants.go index 058d70d..ea82ed1 100644 --- 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 index 957d474..25a5c99 100644 --- 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 index 60f8de0..94584bc 100644 --- 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 index 2422fbe..a166319 100644 --- 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 index cc1d3f7..10ee4ce 100644 --- 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 index d3883ce..006fffa 100644 --- 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 {