X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/9cc572d6a44262e21251372e28b549cfc09e681a..5aa7b2ef565348e637af8dfd9351f82c8cc5b5e6:/sdk/go/httpserver/logger.go

diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index 9577718c76..78a1f77adb 100644
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -1,6 +1,6 @@
 // Copyright (C) The Arvados Authors. All rights reserved.
 //
-// SPDX-License-Identifier: AGPL-3.0
+// SPDX-License-Identifier: Apache-2.0
 
 package httpserver
 
@@ -9,8 +9,9 @@ import (
 	"net/http"
 	"time"
 
-	"git.curoverse.com/arvados.git/sdk/go/stats"
-	"github.com/Sirupsen/logrus"
+	"git.arvados.org/arvados.git/sdk/go/ctxlog"
+	"git.arvados.org/arvados.git/sdk/go/stats"
+	"github.com/sirupsen/logrus"
 )
 
 type contextKey struct {
@@ -19,18 +20,23 @@ type contextKey struct {
 
 var (
 	requestTimeContextKey = contextKey{"requestTime"}
-	loggerContextKey      = contextKey{"logger"}
 )
 
+// HandlerWithContext returns an http.Handler that changes the request
+// context to ctx (replacing http.Server's default
+// context.Background()), then calls next.
+func HandlerWithContext(ctx context.Context, next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		next.ServeHTTP(w, r.WithContext(ctx))
+	})
+}
+
 // LogRequests wraps an http.Handler, logging each request and
-// response via logger.
-func LogRequests(logger logrus.FieldLogger, h http.Handler) http.Handler {
-	if logger == nil {
-		logger = logrus.StandardLogger()
-	}
+// response.
+func LogRequests(h http.Handler) http.Handler {
 	return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
 		w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
-		lgr := logger.WithFields(logrus.Fields{
+		lgr := ctxlog.FromContext(req.Context()).WithFields(logrus.Fields{
 			"RequestID":       req.Header.Get("X-Request-Id"),
 			"remoteAddr":      req.RemoteAddr,
 			"reqForwardedFor": req.Header.Get("X-Forwarded-For"),
@@ -42,21 +48,28 @@ func LogRequests(logger logrus.FieldLogger, h http.Handler) http.Handler {
 		})
 		ctx := req.Context()
 		ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
-		ctx = context.WithValue(ctx, &loggerContextKey, lgr)
+		ctx = ctxlog.Context(ctx, lgr)
 		req = req.WithContext(ctx)
 
 		logRequest(w, req, lgr)
 		defer logResponse(w, req, lgr)
-		h.ServeHTTP(w, req)
+		h.ServeHTTP(rewrapResponseWriter(w, wrapped), req)
 	})
 }
 
-func Logger(req *http.Request) logrus.FieldLogger {
-	if lgr, ok := req.Context().Value(&loggerContextKey).(logrus.FieldLogger); ok {
-		return lgr
-	} else {
-		return logrus.StandardLogger()
+// Rewrap w to restore additional interfaces provided by wrapped.
+func rewrapResponseWriter(w http.ResponseWriter, wrapped http.ResponseWriter) http.ResponseWriter {
+	if hijacker, ok := wrapped.(http.Hijacker); ok {
+		return struct {
+			http.ResponseWriter
+			http.Hijacker
+		}{w, hijacker}
 	}
+	return w
+}
+
+func Logger(req *http.Request) logrus.FieldLogger {
+	return ctxlog.FromContext(req.Context())
 }
 
 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
@@ -66,21 +79,31 @@ 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()
 	if respCode == 0 {
 		respCode = http.StatusOK
 	}
-	lgr.WithFields(logrus.Fields{
+	fields := logrus.Fields{
 		"respStatusCode": respCode,
 		"respStatus":     http.StatusText(respCode),
 		"respBytes":      w.WroteBodyBytes(),
-	}).Info("response")
+	}
+	if respCode >= 400 {
+		fields["respBody"] = string(w.Sniffed())
+	}
+	lgr.WithFields(fields).Info("response")
 }
 
 type responseTimer struct {