[ARVADOS] updated: 1.1.0-189-g4412d92

[Git user]

Summary of changes:
 sdk/go/httpserver/logger.go | 35 ++++++++++++++++++++++++++++-------
 1 file changed, 28 insertions(+), 7 deletions(-)

       via  4412d92e672d4df12ffc04c2b747b750e313cae9 (commit)
      from  03a016b1edff72e698474cd31a887530ea89b530 (commit)

Those revisions listed above that are new to this repository have
not appeared on any other notification email; so we list those
revisions in full, below.


commit 4412d92e672d4df12ffc04c2b747b750e313cae9
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date:   Mon Nov 27 10:51:45 2017 -0500

    12167: Restore timeToStatus + timeWriteBody in keepstore/proxy logs.
    
    Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>

diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index a66b0c9..decb2ff 100644
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -23,7 +23,7 @@ var requestTimeContextKey = contextKey{"requestTime"}
 // response via logrus.
 func LogRequests(h http.Handler) http.Handler {
 	return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
-		w := WrapResponseWriter(wrapped)
+		w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
 		req = req.WithContext(context.WithValue(req.Context(), &requestTimeContextKey, time.Now()))
 		lgr := log.WithFields(log.Fields{
 			"RequestID":       req.Header.Get("X-Request-Id"),
@@ -39,18 +39,17 @@ func LogRequests(h http.Handler) http.Handler {
 	})
 }
 
-func logRequest(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+func logRequest(w *responseTimer, req *http.Request, lgr *log.Entry) {
 	lgr.Info("request")
 }
 
-func logResponse(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+func logResponse(w *responseTimer, req *http.Request, lgr *log.Entry) {
 	if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
 		tDone := time.Now()
 		lgr = lgr.WithFields(log.Fields{
-			"timeTotal": stats.Duration(tDone.Sub(tStart)),
-			// TODO: track WriteHeader timing
-			// "timeToStatus":  stats.Duration(w.sentHdr.Sub(tStart)),
-			// "timeWriteBody": stats.Duration(tDone.Sub(w.sentHdr)),
+			"timeTotal":     stats.Duration(tDone.Sub(tStart)),
+			"timeToStatus":  stats.Duration(w.writeTime.Sub(tStart)),
+			"timeWriteBody": stats.Duration(tDone.Sub(w.writeTime)),
 		})
 	}
 	lgr.WithFields(log.Fields{
@@ -59,3 +58,25 @@ func logResponse(w ResponseWriter, req *http.Request, lgr *log.Entry) {
 		"respBytes":      w.WroteBodyBytes(),
 	}).Info("response")
 }
+
+type responseTimer struct {
+	ResponseWriter
+	wrote     bool
+	writeTime time.Time
+}
+
+func (rt *responseTimer) WriteHeader(code int) {
+	if !rt.wrote {
+		rt.wrote = true
+		rt.writeTime = time.Now()
+	}
+	rt.ResponseWriter.WriteHeader(code)
+}
+
+func (rt *responseTimer) Write(p []byte) (int, error) {
+	if !rt.wrote {
+		rt.wrote = true
+		rt.writeTime = time.Now()
+	}
+	return rt.ResponseWriter.Write(p)
+}

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


hooks/post-receive
--