sdk/go/httpserver/logger.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: AGPL-3.0
   4
   5 package httpserver
   6
   7 import (
   8         "context"
   9         "net/http"
  10         "time"
  11
  12         "git.curoverse.com/arvados.git/sdk/go/stats"
  13         "github.com/sirupsen/logrus"
  14 )
  15
  16 type contextKey struct {
  17         name string
  18 }
  19
  20 var (
  21         requestTimeContextKey = contextKey{"requestTime"}
  22         loggerContextKey      = contextKey{"logger"}
  23 )
  24
  25 // LogRequests wraps an http.Handler, logging each request and
  26 // response via logger.
  27 func LogRequests(logger logrus.FieldLogger, h http.Handler) http.Handler {
  28         if logger == nil {
  29                 logger = logrus.StandardLogger()
  30         }
  31         return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
  32                 w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
  33                 lgr := logger.WithFields(logrus.Fields{
  34                         "RequestID":       req.Header.Get("X-Request-Id"),
  35                         "remoteAddr":      req.RemoteAddr,
  36                         "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
  37                         "reqMethod":       req.Method,
  38                         "reqHost":         req.Host,
  39                         "reqPath":         req.URL.Path[1:],
  40                         "reqQuery":        req.URL.RawQuery,
  41                         "reqBytes":        req.ContentLength,
  42                 })
  43                 ctx := req.Context()
  44                 ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
  45                 ctx = context.WithValue(ctx, &loggerContextKey, lgr)
  46                 req = req.WithContext(ctx)
  47
  48                 logRequest(w, req, lgr)
  49                 defer logResponse(w, req, lgr)
  50                 h.ServeHTTP(w, req)
  51         })
  52 }
  53
  54 func Logger(req *http.Request) logrus.FieldLogger {
  55         if lgr, ok := req.Context().Value(&loggerContextKey).(logrus.FieldLogger); ok {
  56                 return lgr
  57         } else {
  58                 return logrus.StandardLogger()
  59         }
  60 }
  61
  62 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
  63         lgr.Info("request")
  64 }
  65
  66 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
  67         if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
  68                 tDone := time.Now()
  69                 lgr = lgr.WithFields(logrus.Fields{
  70                         "timeTotal":     stats.Duration(tDone.Sub(tStart)),
  71                         "timeToStatus":  stats.Duration(w.writeTime.Sub(tStart)),
  72                         "timeWriteBody": stats.Duration(tDone.Sub(w.writeTime)),
  73                 })
  74         }
  75         respCode := w.WroteStatus()
  76         if respCode == 0 {
  77                 respCode = http.StatusOK
  78         }
  79         lgr.WithFields(logrus.Fields{
  80                 "respStatusCode": respCode,
  81                 "respStatus":     http.StatusText(respCode),
  82                 "respBytes":      w.WroteBodyBytes(),
  83         }).Info("response")
  84 }
  85
  86 type responseTimer struct {
  87         ResponseWriter
  88         wrote     bool
  89         writeTime time.Time
  90 }
  91
  92 func (rt *responseTimer) CloseNotify() <-chan bool {
  93         if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
  94                 return cn.CloseNotify()
  95         }
  96         return nil
  97 }
  98
  99 func (rt *responseTimer) WriteHeader(code int) {
 100         if !rt.wrote {
 101                 rt.wrote = true
 102                 rt.writeTime = time.Now()
 103         }
 104         rt.ResponseWriter.WriteHeader(code)
 105 }
 106
 107 func (rt *responseTimer) Write(p []byte) (int, error) {
 108         if !rt.wrote {
 109                 rt.wrote = true
 110                 rt.writeTime = time.Now()
 111         }
 112         return rt.ResponseWriter.Write(p)
 113 }