16100: Fix bogus timing stats for empty responses.

Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom@tomclegg.ca>

diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index 30f5e2612b91dfdeff2a82f9082c4934aca0c6e3..8886f9517dfd5983032235e713a000f5615880b7 100644 (file)
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -68,10 +68,16 @@ func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
        if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
                tDone := time.Now()
+               writeTime := w.writeTime
+               if !w.wrote {
+                       // Empty response body. Header was sent when
+                       // handler exited.
+                       writeTime = tDone
+               }
                lgr = lgr.WithFields(logrus.Fields{
                        "timeTotal":     stats.Duration(tDone.Sub(tStart)),
-                       "timeToStatus":  stats.Duration(w.writeTime.Sub(tStart)),
-                       "timeWriteBody": stats.Duration(tDone.Sub(w.writeTime)),
+                       "timeToStatus":  stats.Duration(writeTime.Sub(tStart)),
+                       "timeWriteBody": stats.Duration(tDone.Sub(writeTime)),
                })
        }
        respCode := w.WroteStatus()