13697: Cancel request context after API.RequestTimeout.

[arvados.git] / sdk / go / httpserver / logger.go

diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index a66b0c9f162fc26161744a518d9ea484b179de82..1916880963494333ce9d4356f1d1c9d2eba55f3b 100644 (file)
--- 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,53 +9,138 @@ import (
        "net/http"
        "time"
 
-       "git.curoverse.com/arvados.git/sdk/go/stats"
-       log "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 {
        name string
 }
 
-var requestTimeContextKey = contextKey{"requestTime"}
+var (
+       requestTimeContextKey = contextKey{"requestTime"}
+)
+
+// 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))
+       })
+}
+
+// HandlerWithDeadline cancels the request context if the request
+// takes longer than the specified timeout.
+func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler {
+       return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+               ctx, cancel := context.WithDeadline(r.Context(), time.Now().Add(timeout))
+               defer cancel()
+               next.ServeHTTP(w, r.WithContext(ctx))
+       })
+}
 
 // LogRequests wraps an http.Handler, logging each request and
-// response via logrus.
+// response.
 func LogRequests(h http.Handler) http.Handler {
        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 := ctxlog.FromContext(req.Context()).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 = 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 logRequest(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+// 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) {
        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)),
+               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(writeTime.Sub(tStart)),
+                       "timeWriteBody": stats.Duration(tDone.Sub(writeTime)),
                })
        }
-       lgr.WithFields(log.Fields{
-               "respStatusCode": w.WroteStatus(),
-               "respStatus":     http.StatusText(w.WroteStatus()),
+       respCode := w.WroteStatus()
+       if respCode == 0 {
+               respCode = http.StatusOK
+       }
+       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 {
+       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)
 }