// Copyright (C) The Arvados Authors. All rights reserved.
//
-// SPDX-License-Identifier: AGPL-3.0
+// SPDX-License-Identifier: Apache-2.0
package httpserver
import (
+ "bufio"
"context"
+ "net"
"net/http"
+ "sync"
"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 {
name string
}
-var requestTimeContextKey = contextKey{"requestTime"}
+var (
+ requestTimeContextKey = contextKey{"requestTime"}
+ responseLogFieldsContextKey = contextKey{"responseLogFields"}
+ mutexContextKey = contextKey{"mutex"}
+)
+
+type hijacker interface {
+ http.ResponseWriter
+ http.Hijacker
+}
+
+// hijackNotifier wraps a ResponseWriter, calling the provided
+// Notify() func if/when the wrapped Hijacker is hijacked.
+type hijackNotifier struct {
+ hijacker
+ hijacked chan<- bool
+}
+
+func (hn hijackNotifier) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+ close(hn.hijacked)
+ return hn.hijacker.Hijack()
+}
+
+// HandlerWithDeadline cancels the request context if the request
+// takes longer than the specified timeout without having its
+// connection hijacked.
+//
+// If timeout is 0, there is no deadline: HandlerWithDeadline is a
+// no-op.
+func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler {
+ if timeout == 0 {
+ return next
+ }
+ return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+ ctx, cancel := context.WithCancel(r.Context())
+ defer cancel()
+ nodeadline := make(chan bool)
+ go func() {
+ select {
+ case <-nodeadline:
+ case <-ctx.Done():
+ case <-time.After(timeout):
+ cancel()
+ }
+ }()
+ if hj, ok := w.(hijacker); ok {
+ w = hijackNotifier{hj, nodeadline}
+ }
+ next.ServeHTTP(w, r.WithContext(ctx))
+ })
+}
-var Logger logrus.FieldLogger = logrus.StandardLogger()
+func SetResponseLogFields(ctx context.Context, fields logrus.Fields) {
+ m, _ := ctx.Value(&mutexContextKey).(*sync.Mutex)
+ c, _ := ctx.Value(&responseLogFieldsContextKey).(logrus.Fields)
+ if m == nil || c == nil {
+ return
+ }
+ m.Lock()
+ defer m.Unlock()
+ for k, v := range fields {
+ c[k] = v
+ }
+}
// 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 := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
- req = req.WithContext(context.WithValue(req.Context(), &requestTimeContextKey, time.Now()))
- 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"),
"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, &responseLogFieldsContextKey, logrus.Fields{})
+ ctx = context.WithValue(ctx, &mutexContextKey, &sync.Mutex{})
+ 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)
})
}
+// 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 *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)),
})
}
+ if responseLogFields, ok := req.Context().Value(&responseLogFieldsContextKey).(logrus.Fields); ok {
+ lgr = lgr.WithFields(responseLogFields)
+ }
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 {
projects / arvados.git / blobdiff