[ARVADOS] created: 83dccf3a1700a6a7a91bac1587db69840ae99793

[git at public.curoverse.com]

        at  83dccf3a1700a6a7a91bac1587db69840ae99793 (commit)


commit 83dccf3a1700a6a7a91bac1587db69840ae99793
Author: Tom Clegg <tom at curoverse.com>
Date:   Thu Dec 3 12:29:09 2015 -0500

    7888: Log how much time was spent before/after sending response headers.

diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index 47bb6d7..a97f271 100644
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -17,15 +17,24 @@ type LoggingResponseWriter struct {
 	Length int
 	http.ResponseWriter
 	ResponseBody string
+	sentHdr      time.Time
 }
 
 // WriteHeader writes header to ResponseWriter
 func (loggingWriter *LoggingResponseWriter) WriteHeader(code int) {
+	if loggingWriter.sentHdr == zeroTime {
+		loggingWriter.sentHdr = time.Now()
+	}
 	loggingWriter.Status = code
 	loggingWriter.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()
+	}
 	loggingWriter.Length += len(data)
 	if loggingWriter.Status >= 400 {
 		loggingWriter.ResponseBody += string(data)
@@ -46,12 +55,16 @@ func MakeLoggingRESTRouter() *LoggingRESTRouter {
 
 func (loggingRouter *LoggingRESTRouter) ServeHTTP(resp http.ResponseWriter, req *http.Request) {
 	t0 := time.Now()
-	loggingWriter := LoggingResponseWriter{http.StatusOK, 0, resp, ""}
+	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)
 	}
-	log.Printf("[%s] %s %s %.6fs %d %d \"%s\"", req.RemoteAddr, req.Method, req.URL.Path[1:], time.Since(t0).Seconds(), loggingWriter.Status, loggingWriter.Length, statusText)
+	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)
 
 }

-----------------------------------------------------------------------


hooks/post-receive
--