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 requestTimeContextKey = contextKey{"requestTime"}
  21
  22 var Logger logrus.FieldLogger = logrus.StandardLogger()
  23
  24 // LogRequests wraps an http.Handler, logging each request and
  25 // response via logrus.
  26 func LogRequests(h http.Handler) http.Handler {
  27         return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
  28                 w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
  29                 req = req.WithContext(context.WithValue(req.Context(), &requestTimeContextKey, time.Now()))
  30                 lgr := Logger.WithFields(logrus.Fields{
  31                         "RequestID":       req.Header.Get("X-Request-Id"),
  32                         "remoteAddr":      req.RemoteAddr,
  33                         "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
  34                         "reqMethod":       req.Method,
  35                         "reqHost":         req.Host,
  36                         "reqPath":         req.URL.Path[1:],
  37                         "reqQuery":        req.URL.RawQuery,
  38                         "reqBytes":        req.ContentLength,
  39                 })
  40                 logRequest(w, req, lgr)
  41                 defer logResponse(w, req, lgr)
  42                 h.ServeHTTP(w, req)
  43         })
  44 }
  45
  46 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
  47         lgr.Info("request")
  48 }
  49
  50 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
  51         if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
  52                 tDone := time.Now()
  53                 lgr = lgr.WithFields(logrus.Fields{
  54                         "timeTotal":     stats.Duration(tDone.Sub(tStart)),
  55                         "timeToStatus":  stats.Duration(w.writeTime.Sub(tStart)),
  56                         "timeWriteBody": stats.Duration(tDone.Sub(w.writeTime)),
  57                 })
  58         }
  59         respCode := w.WroteStatus()
  60         if respCode == 0 {
  61                 respCode = http.StatusOK
  62         }
  63         lgr.WithFields(logrus.Fields{
  64                 "respStatusCode": respCode,
  65                 "respStatus":     http.StatusText(respCode),
  66                 "respBytes":      w.WroteBodyBytes(),
  67         }).Info("response")
  68 }
  69
  70 type responseTimer struct {
  71         ResponseWriter
  72         wrote     bool
  73         writeTime time.Time
  74 }
  75
  76 func (rt *responseTimer) CloseNotify() <-chan bool {
  77         if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
  78                 return cn.CloseNotify()
  79         }
  80         return nil
  81 }
  82
  83 func (rt *responseTimer) WriteHeader(code int) {
  84         if !rt.wrote {
  85                 rt.wrote = true
  86                 rt.writeTime = time.Now()
  87         }
  88         rt.ResponseWriter.WriteHeader(code)
  89 }
  90
  91 func (rt *responseTimer) Write(p []byte) (int, error) {
  92         if !rt.wrote {
  93                 rt.wrote = true
  94                 rt.writeTime = time.Now()
  95         }
  96         return rt.ResponseWriter.Write(p)
  97 }