X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/03a016b1edff72e698474cd31a887530ea89b530..ab92b051d6f09f1b3e670ecd39e8c96ed34570db:/sdk/go/httpserver/logger.go

diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index a66b0c9f16..9577718c76 100644
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -10,52 +10,104 @@ import (
 	"time"
 
 	"git.curoverse.com/arvados.git/sdk/go/stats"
-	log "github.com/Sirupsen/logrus"
+	"github.com/Sirupsen/logrus"
 )
 
 type contextKey struct {
 	name string
 }
 
-var requestTimeContextKey = contextKey{"requestTime"}
+var (
+	requestTimeContextKey = contextKey{"requestTime"}
+	loggerContextKey      = contextKey{"logger"}
+)
 
 // LogRequests wraps an http.Handler, logging each request and
-// response via logrus.
-func LogRequests(h http.Handler) http.Handler {
+// response via logger.
+func LogRequests(logger logrus.FieldLogger, h http.Handler) http.Handler {
+	if logger == nil {
+		logger = logrus.StandardLogger()
+	}
 	return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
-		w := WrapResponseWriter(wrapped)
-		req = req.WithContext(context.WithValue(req.Context(), &requestTimeContextKey, time.Now()))
-		lgr := log.WithFields(log.Fields{
+		w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
+		lgr := logger.WithFields(logrus.Fields{
 			"RequestID":       req.Header.Get("X-Request-Id"),
 			"remoteAddr":      req.RemoteAddr,
 			"reqForwardedFor": req.Header.Get("X-Forwarded-For"),
 			"reqMethod":       req.Method,
+			"reqHost":         req.Host,
 			"reqPath":         req.URL.Path[1:],
+			"reqQuery":        req.URL.RawQuery,
 			"reqBytes":        req.ContentLength,
 		})
+		ctx := req.Context()
+		ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
+		ctx = context.WithValue(ctx, &loggerContextKey, lgr)
+		req = req.WithContext(ctx)
+
 		logRequest(w, req, lgr)
 		defer logResponse(w, req, lgr)
 		h.ServeHTTP(w, req)
 	})
 }
 
-func logRequest(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+func Logger(req *http.Request) logrus.FieldLogger {
+	if lgr, ok := req.Context().Value(&loggerContextKey).(logrus.FieldLogger); ok {
+		return lgr
+	} else {
+		return logrus.StandardLogger()
+	}
+}
+
+func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
 	lgr.Info("request")
 }
 
-func logResponse(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+func logResponse(w *responseTimer, req *http.Request, lgr *logrus.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)),
+		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)),
 		})
 	}
-	lgr.WithFields(log.Fields{
-		"respStatusCode": w.WroteStatus(),
-		"respStatus":     http.StatusText(w.WroteStatus()),
+	respCode := w.WroteStatus()
+	if respCode == 0 {
+		respCode = http.StatusOK
+	}
+	lgr.WithFields(logrus.Fields{
+		"respStatusCode": respCode,
+		"respStatus":     http.StatusText(respCode),
 		"respBytes":      w.WroteBodyBytes(),
 	}).Info("response")
 }
+
+type responseTimer struct {
+	ResponseWriter
+	wrote     bool
+	writeTime time.Time
+}
+
+func (rt *responseTimer) CloseNotify() <-chan bool {
+	if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
+		return cn.CloseNotify()
+	}
+	return nil
+}
+
+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)
+}