1 // Copyright (C) The Arvados Authors. All rights reserved.
3 // SPDX-License-Identifier: Apache-2.0
14 "git.arvados.org/arvados.git/sdk/go/ctxlog"
15 "git.arvados.org/arvados.git/sdk/go/stats"
16 "github.com/sirupsen/logrus"
19 type contextKey struct {
24 requestTimeContextKey = contextKey{"requestTime"}
27 type hijacker interface {
32 // hijackNotifier wraps a ResponseWriter, calling the provided
33 // Notify() func if/when the wrapped Hijacker is hijacked.
34 type hijackNotifier struct {
39 func (hn hijackNotifier) Hijack() (net.Conn, *bufio.ReadWriter, error) {
41 return hn.hijacker.Hijack()
44 // HandlerWithDeadline cancels the request context if the request
45 // takes longer than the specified timeout without having its
46 // connection hijacked.
47 func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler {
48 return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
49 ctx, cancel := context.WithCancel(r.Context())
51 nodeadline := make(chan bool)
56 case <-time.After(timeout):
60 if hj, ok := w.(hijacker); ok {
61 w = hijackNotifier{hj, nodeadline}
63 next.ServeHTTP(w, r.WithContext(ctx))
67 // LogRequests wraps an http.Handler, logging each request and
69 func LogRequests(h http.Handler) http.Handler {
70 return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
71 w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
72 lgr := ctxlog.FromContext(req.Context()).WithFields(logrus.Fields{
73 "RequestID": req.Header.Get("X-Request-Id"),
74 "remoteAddr": req.RemoteAddr,
75 "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
76 "reqMethod": req.Method,
78 "reqPath": req.URL.Path[1:],
79 "reqQuery": req.URL.RawQuery,
80 "reqBytes": req.ContentLength,
83 ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
84 ctx = ctxlog.Context(ctx, lgr)
85 req = req.WithContext(ctx)
87 logRequest(w, req, lgr)
88 defer logResponse(w, req, lgr)
89 h.ServeHTTP(rewrapResponseWriter(w, wrapped), req)
93 // Rewrap w to restore additional interfaces provided by wrapped.
94 func rewrapResponseWriter(w http.ResponseWriter, wrapped http.ResponseWriter) http.ResponseWriter {
95 if hijacker, ok := wrapped.(http.Hijacker); ok {
104 func Logger(req *http.Request) logrus.FieldLogger {
105 return ctxlog.FromContext(req.Context())
108 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
112 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
113 if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
115 writeTime := w.writeTime
117 // Empty response body. Header was sent when
121 lgr = lgr.WithFields(logrus.Fields{
122 "timeTotal": stats.Duration(tDone.Sub(tStart)),
123 "timeToStatus": stats.Duration(writeTime.Sub(tStart)),
124 "timeWriteBody": stats.Duration(tDone.Sub(writeTime)),
127 respCode := w.WroteStatus()
129 respCode = http.StatusOK
131 fields := logrus.Fields{
132 "respStatusCode": respCode,
133 "respStatus": http.StatusText(respCode),
134 "respBytes": w.WroteBodyBytes(),
137 fields["respBody"] = string(w.Sniffed())
139 lgr.WithFields(fields).Info("response")
142 type responseTimer struct {
148 func (rt *responseTimer) CloseNotify() <-chan bool {
149 if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
150 return cn.CloseNotify()
155 func (rt *responseTimer) WriteHeader(code int) {
158 rt.writeTime = time.Now()
160 rt.ResponseWriter.WriteHeader(code)
163 func (rt *responseTimer) Write(p []byte) (int, error) {
166 rt.writeTime = time.Now()
168 return rt.ResponseWriter.Write(p)