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 )
  26
  27 type hijacker interface {
  28         http.ResponseWriter
  29         http.Hijacker
  30 }
  31
  32 // hijackNotifier wraps a ResponseWriter, calling the provided
  33 // Notify() func if/when the wrapped Hijacker is hijacked.
  34 type hijackNotifier struct {
  35         hijacker
  36         hijacked chan<- bool
  37 }
  38
  39 func (hn hijackNotifier) Hijack() (net.Conn, *bufio.ReadWriter, error) {
  40         close(hn.hijacked)
  41         return hn.hijacker.Hijack()
  42 }
  43
  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())
  50                 defer cancel()
  51                 nodeadline := make(chan bool)
  52                 go func() {
  53                         select {
  54                         case <-nodeadline:
  55                         case <-ctx.Done():
  56                         case <-time.After(timeout):
  57                                 cancel()
  58                         }
  59                 }()
  60                 if hj, ok := w.(hijacker); ok {
  61                         w = hijackNotifier{hj, nodeadline}
  62                 }
  63                 next.ServeHTTP(w, r.WithContext(ctx))
  64         })
  65 }
  66
  67 // LogRequests wraps an http.Handler, logging each request and
  68 // response.
  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,
  77                         "reqHost":         req.Host,
  78                         "reqPath":         req.URL.Path[1:],
  79                         "reqQuery":        req.URL.RawQuery,
  80                         "reqBytes":        req.ContentLength,
  81                 })
  82                 ctx := req.Context()
  83                 ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
  84                 ctx = ctxlog.Context(ctx, lgr)
  85                 req = req.WithContext(ctx)
  86
  87                 logRequest(w, req, lgr)
  88                 defer logResponse(w, req, lgr)
  89                 h.ServeHTTP(rewrapResponseWriter(w, wrapped), req)
  90         })
  91 }
  92
  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 {
  96                 return struct {
  97                         http.ResponseWriter
  98                         http.Hijacker
  99                 }{w, hijacker}
 100         }
 101         return w
 102 }
 103
 104 func Logger(req *http.Request) logrus.FieldLogger {
 105         return ctxlog.FromContext(req.Context())
 106 }
 107
 108 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
 109         lgr.Info("request")
 110 }
 111
 112 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
 113         if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
 114                 tDone := time.Now()
 115                 writeTime := w.writeTime
 116                 if !w.wrote {
 117                         // Empty response body. Header was sent when
 118                         // handler exited.
 119                         writeTime = tDone
 120                 }
 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)),
 125                 })
 126         }
 127         respCode := w.WroteStatus()
 128         if respCode == 0 {
 129                 respCode = http.StatusOK
 130         }
 131         fields := logrus.Fields{
 132                 "respStatusCode": respCode,
 133                 "respStatus":     http.StatusText(respCode),
 134                 "respBytes":      w.WroteBodyBytes(),
 135         }
 136         if respCode >= 400 {
 137                 fields["respBody"] = string(w.Sniffed())
 138         }
 139         lgr.WithFields(fields).Info("response")
 140 }
 141
 142 type responseTimer struct {
 143         ResponseWriter
 144         wrote     bool
 145         writeTime time.Time
 146 }
 147
 148 func (rt *responseTimer) CloseNotify() <-chan bool {
 149         if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
 150                 return cn.CloseNotify()
 151         }
 152         return nil
 153 }
 154
 155 func (rt *responseTimer) WriteHeader(code int) {
 156         if !rt.wrote {
 157                 rt.wrote = true
 158                 rt.writeTime = time.Now()
 159         }
 160         rt.ResponseWriter.WriteHeader(code)
 161 }
 162
 163 func (rt *responseTimer) Write(p []byte) (int, error) {
 164         if !rt.wrote {
 165                 rt.wrote = true
 166                 rt.writeTime = time.Now()
 167         }
 168         return rt.ResponseWriter.Write(p)
 169 }