services/keepstore/logging_router.go

   1 package main
   2
   3 // LoggingRESTRouter
   4 // LoggingResponseWriter
   5
   6 import (
   7         "context"
   8         "net/http"
   9         "strings"
  10         "time"
  11
  12         "git.curoverse.com/arvados.git/sdk/go/httpserver"
  13         "git.curoverse.com/arvados.git/sdk/go/stats"
  14         log "github.com/Sirupsen/logrus"
  15 )
  16
  17 // LoggingResponseWriter has anonymous fields ResponseWriter and ResponseBody
  18 type LoggingResponseWriter struct {
  19         Status int
  20         Length int
  21         http.ResponseWriter
  22         ResponseBody string
  23         sentHdr      time.Time
  24 }
  25
  26 // CloseNotify implements http.CloseNotifier.
  27 func (resp *LoggingResponseWriter) CloseNotify() <-chan bool {
  28         wrapped, ok := resp.ResponseWriter.(http.CloseNotifier)
  29         if !ok {
  30                 // If upstream doesn't implement CloseNotifier, we can
  31                 // satisfy the interface by returning a channel that
  32                 // never sends anything (the interface doesn't
  33                 // guarantee that anything will ever be sent on the
  34                 // channel even if the client disconnects).
  35                 return nil
  36         }
  37         return wrapped.CloseNotify()
  38 }
  39
  40 // WriteHeader writes header to ResponseWriter
  41 func (resp *LoggingResponseWriter) WriteHeader(code int) {
  42         if resp.sentHdr == zeroTime {
  43                 resp.sentHdr = time.Now()
  44         }
  45         resp.Status = code
  46         resp.ResponseWriter.WriteHeader(code)
  47 }
  48
  49 var zeroTime time.Time
  50
  51 func (resp *LoggingResponseWriter) Write(data []byte) (int, error) {
  52         if resp.Length == 0 && len(data) > 0 && resp.sentHdr == zeroTime {
  53                 resp.sentHdr = time.Now()
  54         }
  55         resp.Length += len(data)
  56         if resp.Status >= 400 {
  57                 resp.ResponseBody += string(data)
  58         }
  59         return resp.ResponseWriter.Write(data)
  60 }
  61
  62 // LoggingRESTRouter is used to add logging capabilities to mux.Router
  63 type LoggingRESTRouter struct {
  64         router      http.Handler
  65         idGenerator httpserver.IDGenerator
  66 }
  67
  68 func (loggingRouter *LoggingRESTRouter) ServeHTTP(wrappedResp http.ResponseWriter, req *http.Request) {
  69         tStart := time.Now()
  70
  71         // Attach a requestID-aware logger to the request context.
  72         lgr := log.WithField("RequestID", loggingRouter.idGenerator.Next())
  73         ctx := context.WithValue(req.Context(), "logger", lgr)
  74         req = req.WithContext(ctx)
  75
  76         lgr = lgr.WithFields(log.Fields{
  77                 "remoteAddr":      req.RemoteAddr,
  78                 "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
  79                 "reqMethod":       req.Method,
  80                 "reqPath":         req.URL.Path[1:],
  81                 "reqBytes":        req.ContentLength,
  82         })
  83         lgr.Debug("request")
  84
  85         resp := LoggingResponseWriter{http.StatusOK, 0, wrappedResp, "", zeroTime}
  86         loggingRouter.router.ServeHTTP(&resp, req)
  87         tDone := time.Now()
  88
  89         statusText := http.StatusText(resp.Status)
  90         if resp.Status >= 400 {
  91                 statusText = strings.Replace(resp.ResponseBody, "\n", "", -1)
  92         }
  93         if resp.sentHdr == zeroTime {
  94                 // Nobody changed status or wrote any data, i.e., we
  95                 // returned a 200 response with no body.
  96                 resp.sentHdr = tDone
  97         }
  98
  99         lgr.WithFields(log.Fields{
 100                 "timeTotal":      stats.Duration(tDone.Sub(tStart)),
 101                 "timeToStatus":   stats.Duration(resp.sentHdr.Sub(tStart)),
 102                 "timeWriteBody":  stats.Duration(tDone.Sub(resp.sentHdr)),
 103                 "respStatusCode": resp.Status,
 104                 "respStatus":     statusText,
 105                 "respBytes":      resp.Length,
 106         }).Info("response")
 107 }