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