Merge branch '10467-client-disconnect' closes #10467

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

diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index 30b10b3bca52265b9742c4f9d585de686c4c8670..e34f8581fd5448d606a6305e52c0673f944a8898 100644 (file)
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -4,11 +4,13 @@ package main
 // LoggingResponseWriter
 
 import (
+       "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"
 )
 
@@ -65,30 +67,41 @@ type LoggingRESTRouter struct {
 
 func (loggingRouter *LoggingRESTRouter) ServeHTTP(wrappedResp http.ResponseWriter, req *http.Request) {
        tStart := time.Now()
-       lgr := log.WithFields(log.Fields{
-               "RequestID":       loggingRouter.idGenerator.Next(),
-               "RemoteAddr":      req.RemoteAddr,
-               "X-Forwarded-For": req.Header.Get("X-Forwarded-For"),
-               "ReqMethod":       req.Method,
-               "ReqPath":         req.URL.Path[1:],
-               "ReqBytes":        req.ContentLength,
+
+       // 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.Info("request")
+       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
+       }
 
-       tDone := time.Now()
        lgr.WithFields(log.Fields{
-               "TimeTotal":      tDone.Sub(tStart).Seconds(),
-               "TimeToStatus":   resp.sentHdr.Sub(tStart).Seconds(),
-               "TimeWriteBody":  tDone.Sub(resp.sentHdr).Seconds(),
-               "RespStatusCode": resp.Status,
-               "RespStatus":     statusText,
-               "RespBytes":      resp.Length,
+               "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")
 }