diff --git a/log/access_logger.go b/log/access_logger.go index b131ed24f3072a89cd20c20223810cc628789ef6..a74af2fbfe8cf55ba0a0264e83cc205e9427cf69 100644 --- a/log/access_logger.go +++ b/log/access_logger.go @@ -57,6 +57,7 @@ type loggingResponseWriter struct { wroteHeader bool written int64 started time.Time + ttfb time.Duration config *accessLoggerConfig contentType string } @@ -82,6 +83,8 @@ func (l *loggingResponseWriter) WriteHeader(status int) { l.wroteHeader = true l.status = status l.contentType = l.Header().Get("Content-Type") + l.ttfb = time.Since(l.started) + l.rw.WriteHeader(status) } @@ -149,6 +152,10 @@ func (l *loggingResponseWriter) accessLogFields(r *http.Request) logrus.Fields { fields[requestDurationField] = int64(duration / time.Millisecond) } + if fieldsBitMask&RequestTTFB != 0 && l.ttfb > 0 { + fields[requestTTFBField] = l.ttfb.Milliseconds() + } + if fieldsBitMask&System != 0 { fields[systemField] = "http" } diff --git a/log/access_logger_fields.go b/log/access_logger_fields.go index 39765dade4c3c1444fb64cc3c94c6e82a662f415..f542353d26e2b38f4788d9c94335a7516d979052 100644 --- a/log/access_logger_fields.go +++ b/log/access_logger_fields.go @@ -45,6 +45,11 @@ const ( // HTTPResponseContentType field will record the response content-type in the access log. HTTPResponseContentType + + // RequestTTFB field will record the time to the first byte being written (HTTP Header effectively) + // in the access log. Time is recorded before an actual Write happens to ensure that this metric + // is not affected by a slow client receiving data. + RequestTTFB ) const defaultEnabledFields = ^AccessLogField(0) // By default, all fields are enabled @@ -63,6 +68,7 @@ const ( httpRequestReferrerField = "referrer" // ESC: http.request.referrer httpUserAgentField = "user_agent" // ESC: user_agent.original requestDurationField = "duration_ms" // ESC: no mapping + requestTTFBField = "ttfb_ms" // ESC: no mapping systemField = "system" // ESC: no mapping httpResponseContentTypeField = "content_type" // ESC: no mapping ) diff --git a/log/access_logger_test.go b/log/access_logger_test.go index 9268e50a7f8a7e80e9c22088145257f0d1ab7500..316240aaf0f69702472d14b590974f2023fff668 100644 --- a/log/access_logger_test.go +++ b/log/access_logger_test.go @@ -7,6 +7,7 @@ import ( "net/http" "net/http/httptest" "testing" + "time" "github.com/stretchr/testify/require" ) @@ -20,6 +21,7 @@ func TestAccessLogger(t *testing.T) { options []AccessLoggerOption requestHeaders map[string]string responseHeaders map[string]string + handler http.Handler }{ { name: "trivial", @@ -114,6 +116,52 @@ func TestAccessLogger(t *testing.T) { `\bcontent_type=text/plain`, }, }, + { + name: "time to the first byte", + body: "ok", + logMatchers: []string{ + `\bttfb_ms=\d+`, + }, + }, + { + name: "time to the first byte, with long delay", + body: "yo", + logMatchers: []string{ + // we expect the delay to be around `10ms` + `\bttfb_ms=1\d\b`, + }, + handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(10 * time.Millisecond) + fmt.Fprint(w, "yo") + }), + }, + { + name: "time to the first byte, with a slow data transfer", + body: "yo", + logMatchers: []string{ + // we expect the delay to be lower than `10ms` + `\bttfb_ms=\d\b`, + }, + handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + time.Sleep(10 * time.Millisecond) + fmt.Fprint(w, "yo") + }), + }, + { + name: "time to the first byte, with a long processing and slow data transfer", + body: "yo", + logMatchers: []string{ + // we expect the delay to be around `10ms` + `\bttfb_ms=1\d\b`, + }, + handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(10 * time.Millisecond) + w.WriteHeader(http.StatusInternalServerError) + time.Sleep(20 * time.Millisecond) + fmt.Fprint(w, "yo") + }), + }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { @@ -123,17 +171,20 @@ func TestAccessLogger(t *testing.T) { _, err := Initialize(WithLogger(logger), WithWriter(buf)) require.NoError(t, err) - var handler http.Handler - handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - for k, v := range tt.responseHeaders { - w.Header().Add(k, v) - } - // This if-statement provides test coverage for the case where the - // handler never calls Write or WriteHeader. - if len(tt.body) > 0 { - fmt.Fprint(w, tt.body) - } - }) + handler := tt.handler + + if handler == nil { + handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + for k, v := range tt.responseHeaders { + w.Header().Add(k, v) + } + // This if-statement provides test coverage for the case where the + // handler never calls Write or WriteHeader. + if len(tt.body) > 0 { + fmt.Fprint(w, tt.body) + } + }) + } opts := []AccessLoggerOption{WithAccessLogger(logger)} opts = append(opts, tt.options...)