Merge branch '8784-dir-listings'

[arvados.git] / services / keepstore / logging_router.go

diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index 8f547a4d4c83af76e9e32d13ed51e4feb9492542..63c28a24b35822517ac18ee4434eb65c6492d98c 100644 (file)
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -1,13 +1,21 @@
+// Copyright (C) The Arvados Authors. All rights reserved.
+//
+// SPDX-License-Identifier: AGPL-3.0
+
 package main
 
 // LoggingRESTRouter
 // LoggingResponseWriter
 
 import (
-       "log"
+       "context"
        "net/http"
        "strings"
        "time"
+
+       "git.curoverse.com/arvados.git/sdk/go/httpserver"
+       "git.curoverse.com/arvados.git/sdk/go/stats"
+       log "github.com/Sirupsen/logrus"
 )
 
 // LoggingResponseWriter has anonymous fields ResponseWriter and ResponseBody
@@ -19,8 +27,9 @@ type LoggingResponseWriter struct {
        sentHdr      time.Time
 }
 
-func (w *LoggingResponseWriter) CloseNotify() <-chan bool {
-       wrapped, ok := w.ResponseWriter.(http.CloseNotifier)
+// CloseNotify implements http.CloseNotifier.
+func (resp *LoggingResponseWriter) CloseNotify() <-chan bool {
+       wrapped, ok := resp.ResponseWriter.(http.CloseNotifier)
        if !ok {
                // If upstream doesn't implement CloseNotifier, we can
                // satisfy the interface by returning a channel that
@@ -33,44 +42,70 @@ func (w *LoggingResponseWriter) CloseNotify() <-chan bool {
 }
 
 // WriteHeader writes header to ResponseWriter
-func (loggingWriter *LoggingResponseWriter) WriteHeader(code int) {
-       if loggingWriter.sentHdr == zeroTime {
-               loggingWriter.sentHdr = time.Now()
+func (resp *LoggingResponseWriter) WriteHeader(code int) {
+       if resp.sentHdr == zeroTime {
+               resp.sentHdr = time.Now()
        }
-       loggingWriter.Status = code
-       loggingWriter.ResponseWriter.WriteHeader(code)
+       resp.Status = code
+       resp.ResponseWriter.WriteHeader(code)
 }
 
 var zeroTime time.Time
 
-func (loggingWriter *LoggingResponseWriter) Write(data []byte) (int, error) {
-       if loggingWriter.Length == 0 && len(data) > 0 && loggingWriter.sentHdr == zeroTime {
-               loggingWriter.sentHdr = time.Now()
+func (resp *LoggingResponseWriter) Write(data []byte) (int, error) {
+       if resp.Length == 0 && len(data) > 0 && resp.sentHdr == zeroTime {
+               resp.sentHdr = time.Now()
        }
-       loggingWriter.Length += len(data)
-       if loggingWriter.Status >= 400 {
-               loggingWriter.ResponseBody += string(data)
+       resp.Length += len(data)
+       if resp.Status >= 400 {
+               resp.ResponseBody += string(data)
        }
-       return loggingWriter.ResponseWriter.Write(data)
+       return resp.ResponseWriter.Write(data)
 }
 
 // LoggingRESTRouter is used to add logging capabilities to mux.Router
 type LoggingRESTRouter struct {
-       router http.Handler
+       router      http.Handler
+       idGenerator httpserver.IDGenerator
 }
 
-func (loggingRouter *LoggingRESTRouter) ServeHTTP(resp http.ResponseWriter, req *http.Request) {
-       t0 := time.Now()
-       loggingWriter := LoggingResponseWriter{http.StatusOK, 0, resp, "", zeroTime}
-       loggingRouter.router.ServeHTTP(&loggingWriter, req)
-       statusText := http.StatusText(loggingWriter.Status)
-       if loggingWriter.Status >= 400 {
-               statusText = strings.Replace(loggingWriter.ResponseBody, "\n", "", -1)
+func (loggingRouter *LoggingRESTRouter) ServeHTTP(wrappedResp http.ResponseWriter, req *http.Request) {
+       tStart := time.Now()
+
+       // Attach a requestID-aware logger to the request context.
+       lgr := log.WithField("RequestID", loggingRouter.idGenerator.Next())
+       ctx := context.WithValue(req.Context(), "logger", lgr)
+       req = req.WithContext(ctx)
+
+       lgr = lgr.WithFields(log.Fields{
+               "remoteAddr":      req.RemoteAddr,
+               "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
+               "reqMethod":       req.Method,
+               "reqPath":         req.URL.Path[1:],
+               "reqBytes":        req.ContentLength,
+       })
+       lgr.Debug("request")
+
+       resp := LoggingResponseWriter{http.StatusOK, 0, wrappedResp, "", zeroTime}
+       loggingRouter.router.ServeHTTP(&resp, req)
+       tDone := time.Now()
+
+       statusText := http.StatusText(resp.Status)
+       if resp.Status >= 400 {
+               statusText = strings.Replace(resp.ResponseBody, "\n", "", -1)
+       }
+       if resp.sentHdr == zeroTime {
+               // Nobody changed status or wrote any data, i.e., we
+               // returned a 200 response with no body.
+               resp.sentHdr = tDone
        }
-       now := time.Now()
-       tTotal := now.Sub(t0)
-       tLatency := loggingWriter.sentHdr.Sub(t0)
-       tResponse := now.Sub(loggingWriter.sentHdr)
-       log.Printf("[%s] %s %s %d %.6fs %.6fs %.6fs %d %d \"%s\"", req.RemoteAddr, req.Method, req.URL.Path[1:], req.ContentLength, tTotal.Seconds(), tLatency.Seconds(), tResponse.Seconds(), loggingWriter.Status, loggingWriter.Length, statusText)
 
+       lgr.WithFields(log.Fields{
+               "timeTotal":      stats.Duration(tDone.Sub(tStart)),
+               "timeToStatus":   stats.Duration(resp.sentHdr.Sub(tStart)),
+               "timeWriteBody":  stats.Duration(tDone.Sub(resp.sentHdr)),
+               "respStatusCode": resp.Status,
+               "respStatus":     statusText,
+               "respBytes":      resp.Length,
+       }).Info("response")
 }