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         "context"
   9         "net/http"
  10         "time"
  11
  12         "git.arvados.org/arvados.git/sdk/go/ctxlog"
  13         "git.arvados.org/arvados.git/sdk/go/stats"
  14         "github.com/sirupsen/logrus"
  15 )
  16
  17 type contextKey struct {
  18         name string
  19 }
  20
  21 var (
  22         requestTimeContextKey = contextKey{"requestTime"}
  23 )
  24
  25 // HandlerWithContext returns an http.Handler that changes the request
  26 // context to ctx (replacing http.Server's default
  27 // context.Background()), then calls next.
  28 func HandlerWithContext(ctx context.Context, next http.Handler) http.Handler {
  29         return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
  30                 next.ServeHTTP(w, r.WithContext(ctx))
  31         })
  32 }
  33
  34 // HandlerWithDeadline cancels the request context if the request
  35 // takes longer than the specified timeout.
  36 func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler {
  37         return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
  38                 ctx, cancel := context.WithDeadline(r.Context(), time.Now().Add(timeout))
  39                 defer cancel()
  40                 next.ServeHTTP(w, r.WithContext(ctx))
  41         })
  42 }
  43
  44 // LogRequests wraps an http.Handler, logging each request and
  45 // response.
  46 func LogRequests(h http.Handler) http.Handler {
  47         return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
  48                 w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
  49                 lgr := ctxlog.FromContext(req.Context()).WithFields(logrus.Fields{
  50                         "RequestID":       req.Header.Get("X-Request-Id"),
  51                         "remoteAddr":      req.RemoteAddr,
  52                         "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
  53                         "reqMethod":       req.Method,
  54                         "reqHost":         req.Host,
  55                         "reqPath":         req.URL.Path[1:],
  56                         "reqQuery":        req.URL.RawQuery,
  57                         "reqBytes":        req.ContentLength,
  58                 })
  59                 ctx := req.Context()
  60                 ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
  61                 ctx = ctxlog.Context(ctx, lgr)
  62                 req = req.WithContext(ctx)
  63
  64                 logRequest(w, req, lgr)
  65                 defer logResponse(w, req, lgr)
  66                 h.ServeHTTP(rewrapResponseWriter(w, wrapped), req)
  67         })
  68 }
  69
  70 // Rewrap w to restore additional interfaces provided by wrapped.
  71 func rewrapResponseWriter(w http.ResponseWriter, wrapped http.ResponseWriter) http.ResponseWriter {
  72         if hijacker, ok := wrapped.(http.Hijacker); ok {
  73                 return struct {
  74                         http.ResponseWriter
  75                         http.Hijacker
  76                 }{w, hijacker}
  77         }
  78         return w
  79 }
  80
  81 func Logger(req *http.Request) logrus.FieldLogger {
  82         return ctxlog.FromContext(req.Context())
  83 }
  84
  85 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
  86         lgr.Info("request")
  87 }
  88
  89 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
  90         if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
  91                 tDone := time.Now()
  92                 writeTime := w.writeTime
  93                 if !w.wrote {
  94                         // Empty response body. Header was sent when
  95                         // handler exited.
  96                         writeTime = tDone
  97                 }
  98                 lgr = lgr.WithFields(logrus.Fields{
  99                         "timeTotal":     stats.Duration(tDone.Sub(tStart)),
 100                         "timeToStatus":  stats.Duration(writeTime.Sub(tStart)),
 101                         "timeWriteBody": stats.Duration(tDone.Sub(writeTime)),
 102                 })
 103         }
 104         respCode := w.WroteStatus()
 105         if respCode == 0 {
 106                 respCode = http.StatusOK
 107         }
 108         fields := logrus.Fields{
 109                 "respStatusCode": respCode,
 110                 "respStatus":     http.StatusText(respCode),
 111                 "respBytes":      w.WroteBodyBytes(),
 112         }
 113         if respCode >= 400 {
 114                 fields["respBody"] = string(w.Sniffed())
 115         }
 116         lgr.WithFields(fields).Info("response")
 117 }
 118
 119 type responseTimer struct {
 120         ResponseWriter
 121         wrote     bool
 122         writeTime time.Time
 123 }
 124
 125 func (rt *responseTimer) CloseNotify() <-chan bool {
 126         if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
 127                 return cn.CloseNotify()
 128         }
 129         return nil
 130 }
 131
 132 func (rt *responseTimer) WriteHeader(code int) {
 133         if !rt.wrote {
 134                 rt.wrote = true
 135                 rt.writeTime = time.Now()
 136         }
 137         rt.ResponseWriter.WriteHeader(code)
 138 }
 139
 140 func (rt *responseTimer) Write(p []byte) (int, error) {
 141         if !rt.wrote {
 142                 rt.wrote = true
 143                 rt.writeTime = time.Now()
 144         }
 145         return rt.ResponseWriter.Write(p)
 146 }