X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/f69395a08509cc8c664c3256019d4d3cdb67db86..1d656f4f1ec1f890a7677e748bea43a08cfa0b6c:/services/keepstore/logging_router.go

diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index d9dfc35739..0f556b538a 100644
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -4,47 +4,74 @@ package main
 // LoggingResponseWriter
 
 import (
-	"github.com/gorilla/mux"
 	"log"
 	"net/http"
 	"strings"
+	"time"
 )
 
+// LoggingResponseWriter has anonymous fields ResponseWriter and ResponseBody
 type LoggingResponseWriter struct {
 	Status int
 	Length int
 	http.ResponseWriter
-	Response string
+	ResponseBody string
+	sentHdr      time.Time
 }
 
-func (loggingWriter *LoggingResponseWriter) WriteHeader(code int) {
-	loggingWriter.Status = code
-	loggingWriter.ResponseWriter.WriteHeader(code)
+// 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()
 }
 
-func (loggingWriter *LoggingResponseWriter) Write(data []byte) (int, error) {
-	loggingWriter.Length += len(data)
-	if loggingWriter.Status >= 400 {
-		loggingWriter.Response += string(data)
+// WriteHeader writes header to ResponseWriter
+func (resp *LoggingResponseWriter) WriteHeader(code int) {
+	if resp.sentHdr == zeroTime {
+		resp.sentHdr = time.Now()
 	}
-	return loggingWriter.ResponseWriter.Write(data)
+	resp.Status = code
+	resp.ResponseWriter.WriteHeader(code)
 }
 
-type LoggingRESTRouter struct {
-	router *mux.Router
+var zeroTime time.Time
+
+func (resp *LoggingResponseWriter) Write(data []byte) (int, error) {
+	if resp.Length == 0 && len(data) > 0 && resp.sentHdr == zeroTime {
+		resp.sentHdr = time.Now()
+	}
+	resp.Length += len(data)
+	if resp.Status >= 400 {
+		resp.ResponseBody += string(data)
+	}
+	return resp.ResponseWriter.Write(data)
 }
 
-func MakeLoggingRESTRouter() *LoggingRESTRouter {
-	router := MakeRESTRouter()
-	return (&LoggingRESTRouter{router})
+// LoggingRESTRouter is used to add logging capabilities to mux.Router
+type LoggingRESTRouter struct {
+	router http.Handler
 }
 
-func (loggingRouter *LoggingRESTRouter) ServeHTTP(resp http.ResponseWriter, req *http.Request) {
-	loggingWriter := LoggingResponseWriter{200, 0, resp, ""}
-	loggingRouter.router.ServeHTTP(&loggingWriter, req)
-	if loggingWriter.Status >= 400 {
-		log.Printf("[%s] %s %s %d %d \"%s\"", req.RemoteAddr, req.Method, req.URL.Path[1:], loggingWriter.Status, loggingWriter.Length, strings.TrimSpace(loggingWriter.Response))
-	} else {
-		log.Printf("[%s] %s %s %d %d \"OK\"", req.RemoteAddr, req.Method, req.URL.Path[1:], loggingWriter.Status, loggingWriter.Length)
+func (loggingRouter *LoggingRESTRouter) ServeHTTP(wrappedResp http.ResponseWriter, req *http.Request) {
+	t0 := time.Now()
+	resp := LoggingResponseWriter{http.StatusOK, 0, wrappedResp, "", zeroTime}
+	loggingRouter.router.ServeHTTP(&resp, req)
+	statusText := http.StatusText(resp.Status)
+	if resp.Status >= 400 {
+		statusText = strings.Replace(resp.ResponseBody, "\n", "", -1)
 	}
+	now := time.Now()
+	tTotal := now.Sub(t0)
+	tLatency := resp.sentHdr.Sub(t0)
+	tResponse := now.Sub(resp.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(), resp.Status, resp.Length, statusText)
+
 }