X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/3afec6824121eea6aed8c2d25567a5e8974d3100..e4a35f3914481226a2a4ff57618bc486839aa2ea:/services/keepstore/logging_router.go

diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index 30b10b3bca..63c28a24b3 100644
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -1,14 +1,20 @@
+// Copyright (C) The Arvados Authors. All rights reserved.
+//
+// SPDX-License-Identifier: AGPL-3.0
+
 package main
 
 // LoggingRESTRouter
 // 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 +71,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")
 }