sdk/go/httpserver/logger.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: Apache-2.0
   4
   5 package httpserver
   6
   7 import (
   8         "bufio"
   9         "context"
  10         "net"
  11         "net/http"
  12         "sync"
  13         "time"
  14
  15         "git.arvados.org/arvados.git/sdk/go/ctxlog"
  16         "git.arvados.org/arvados.git/sdk/go/stats"
  17         "github.com/sirupsen/logrus"
  18 )
  19
  20 type contextKey struct {
  21         name string
  22 }
  23
  24 var (
  25         requestTimeContextKey       = contextKey{"requestTime"}
  26         responseLogFieldsContextKey = contextKey{"responseLogFields"}
  27         mutexContextKey             = contextKey{"mutex"}
  28 )
  29
  30 type hijacker interface {
  31         http.ResponseWriter
  32         http.Hijacker
  33 }
  34
  35 // hijackNotifier wraps a ResponseWriter, calling the provided
  36 // Notify() func if/when the wrapped Hijacker is hijacked.
  37 type hijackNotifier struct {
  38         hijacker
  39         hijacked chan<- bool
  40 }
  41
  42 func (hn hijackNotifier) Hijack() (net.Conn, *bufio.ReadWriter, error) {
  43         close(hn.hijacked)
  44         return hn.hijacker.Hijack()
  45 }
  46
  47 // HandlerWithDeadline cancels the request context if the request
  48 // takes longer than the specified timeout without having its
  49 // connection hijacked.
  50 //
  51 // If timeout is 0, there is no deadline: HandlerWithDeadline is a
  52 // no-op.
  53 func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler {
  54         if timeout == 0 {
  55                 return next
  56         }
  57         return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
  58                 ctx, cancel := context.WithCancel(r.Context())
  59                 defer cancel()
  60                 nodeadline := make(chan bool)
  61                 go func() {
  62                         select {
  63                         case <-nodeadline:
  64                         case <-ctx.Done():
  65                         case <-time.After(timeout):
  66                                 cancel()
  67                         }
  68                 }()
  69                 if hj, ok := w.(hijacker); ok {
  70                         w = hijackNotifier{hj, nodeadline}
  71                 }
  72                 next.ServeHTTP(w, r.WithContext(ctx))
  73         })
  74 }
  75
  76 func SetResponseLogFields(ctx context.Context, fields logrus.Fields) {
  77         m, _ := ctx.Value(&mutexContextKey).(*sync.Mutex)
  78         c, _ := ctx.Value(&responseLogFieldsContextKey).(logrus.Fields)
  79         if m == nil || c == nil {
  80                 return
  81         }
  82         m.Lock()
  83         defer m.Unlock()
  84         for k, v := range fields {
  85                 c[k] = v
  86         }
  87 }
  88
  89 // LogRequests wraps an http.Handler, logging each request and
  90 // response.
  91 func LogRequests(h http.Handler) http.Handler {
  92         return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
  93                 w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
  94                 lgr := ctxlog.FromContext(req.Context()).WithFields(logrus.Fields{
  95                         "RequestID":       req.Header.Get("X-Request-Id"),
  96                         "remoteAddr":      req.RemoteAddr,
  97                         "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
  98                         "reqMethod":       req.Method,
  99                         "reqHost":         req.Host,
 100                         "reqPath":         req.URL.Path[1:],
 101                         "reqQuery":        req.URL.RawQuery,
 102                         "reqBytes":        req.ContentLength,
 103                 })
 104                 ctx := req.Context()
 105                 ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
 106                 ctx = context.WithValue(ctx, &responseLogFieldsContextKey, logrus.Fields{})
 107                 ctx = context.WithValue(ctx, &mutexContextKey, &sync.Mutex{})
 108                 ctx = ctxlog.Context(ctx, lgr)
 109                 req = req.WithContext(ctx)
 110
 111                 logRequest(w, req, lgr)
 112                 defer logResponse(w, req, lgr)
 113                 h.ServeHTTP(rewrapResponseWriter(w, wrapped), req)
 114         })
 115 }
 116
 117 // Rewrap w to restore additional interfaces provided by wrapped.
 118 func rewrapResponseWriter(w http.ResponseWriter, wrapped http.ResponseWriter) http.ResponseWriter {
 119         if hijacker, ok := wrapped.(http.Hijacker); ok {
 120                 return struct {
 121                         http.ResponseWriter
 122                         http.Hijacker
 123                 }{w, hijacker}
 124         }
 125         return w
 126 }
 127
 128 func Logger(req *http.Request) logrus.FieldLogger {
 129         return ctxlog.FromContext(req.Context())
 130 }
 131
 132 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
 133         lgr.Info("request")
 134 }
 135
 136 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
 137         if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
 138                 tDone := time.Now()
 139                 writeTime := w.writeTime
 140                 if !w.wrote {
 141                         // Empty response body. Header was sent when
 142                         // handler exited.
 143                         writeTime = tDone
 144                 }
 145                 lgr = lgr.WithFields(logrus.Fields{
 146                         "timeTotal":     stats.Duration(tDone.Sub(tStart)),
 147                         "timeToStatus":  stats.Duration(writeTime.Sub(tStart)),
 148                         "timeWriteBody": stats.Duration(tDone.Sub(writeTime)),
 149                 })
 150         }
 151         if responseLogFields, ok := req.Context().Value(&responseLogFieldsContextKey).(logrus.Fields); ok {
 152                 lgr = lgr.WithFields(responseLogFields)
 153         }
 154         respCode := w.WroteStatus()
 155         if respCode == 0 {
 156                 respCode = http.StatusOK
 157         }
 158         fields := logrus.Fields{
 159                 "respStatusCode": respCode,
 160                 "respStatus":     http.StatusText(respCode),
 161                 "respBytes":      w.WroteBodyBytes(),
 162         }
 163         if respCode >= 400 {
 164                 fields["respBody"] = string(w.Sniffed())
 165         }
 166         lgr.WithFields(fields).Info("response")
 167 }
 168
 169 type responseTimer struct {
 170         ResponseWriter
 171         wrote     bool
 172         writeTime time.Time
 173 }
 174
 175 func (rt *responseTimer) CloseNotify() <-chan bool {
 176         if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
 177                 return cn.CloseNotify()
 178         }
 179         return nil
 180 }
 181
 182 func (rt *responseTimer) WriteHeader(code int) {
 183         if !rt.wrote {
 184                 rt.wrote = true
 185                 rt.writeTime = time.Now()
 186         }
 187         rt.ResponseWriter.WriteHeader(code)
 188 }
 189
 190 func (rt *responseTimer) Write(p []byte) (int, error) {
 191         if !rt.wrote {
 192                 rt.wrote = true
 193                 rt.writeTime = time.Now()
 194         }
 195         return rt.ResponseWriter.Write(p)
 196 }