services/keepstore/logging_router.go

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