X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/83dccf3a1700a6a7a91bac1587db69840ae99793..4f1a135e93df78bb833dff32562efe713c6f690e:/services/keepstore/logging_router.go

diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index a97f271327..63c28a24b3 100644
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -1,14 +1,21 @@
+// Copyright (C) The Arvados Authors. All rights reserved.
+//
+// SPDX-License-Identifier: AGPL-3.0
+
 package main
 
 // LoggingRESTRouter
 // LoggingResponseWriter
 
 import (
-	"github.com/gorilla/mux"
-	"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
@@ -20,51 +27,85 @@ type LoggingResponseWriter struct {
 	sentHdr      time.Time
 }
 
+// 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
+		// never sends anything (the interface doesn't
+		// guarantee that anything will ever be sent on the
+		// channel even if the client disconnects).
+		return nil
+	}
+	return wrapped.CloseNotify()
+}
+
 // 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 *mux.Router
+	router      http.Handler
+	idGenerator httpserver.IDGenerator
 }
 
-// MakeLoggingRESTRouter initializes LoggingRESTRouter
-func MakeLoggingRESTRouter() *LoggingRESTRouter {
-	router := MakeRESTRouter()
-	return (&LoggingRESTRouter{router})
-}
+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")
 
-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)
+	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 %.6fs %.6fs %.6fs %d %d \"%s\"", req.RemoteAddr, req.Method, req.URL.Path[1:], 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")
 }