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         log "github.com/Sirupsen/logrus"
  14 )
  15
  16 type contextKey struct {
  17         name string
  18 }
  19
  20 var requestTimeContextKey = contextKey{"requestTime"}
  21
  22 // LogRequests wraps an http.Handler, logging each request and
  23 // response via logrus.
  24 func LogRequests(h http.Handler) http.Handler {
  25         return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
  26                 w := WrapResponseWriter(wrapped)
  27                 req = req.WithContext(context.WithValue(req.Context(), &requestTimeContextKey, time.Now()))
  28                 lgr := log.WithFields(log.Fields{
  29                         "RequestID":       req.Header.Get("X-Request-Id"),
  30                         "remoteAddr":      req.RemoteAddr,
  31                         "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
  32                         "reqMethod":       req.Method,
  33                         "reqPath":         req.URL.Path[1:],
  34                         "reqBytes":        req.ContentLength,
  35                 })
  36                 logRequest(w, req, lgr)
  37                 defer logResponse(w, req, lgr)
  38                 h.ServeHTTP(w, req)
  39         })
  40 }
  41
  42 func logRequest(w ResponseWriter, req *http.Request, lgr *log.Entry) {
  43         lgr.Info("request")
  44 }
  45
  46 func logResponse(w ResponseWriter, req *http.Request, lgr *log.Entry) {
  47         if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
  48                 tDone := time.Now()
  49                 lgr = lgr.WithFields(log.Fields{
  50                         "timeTotal": stats.Duration(tDone.Sub(tStart)),
  51                         // TODO: track WriteHeader timing
  52                         // "timeToStatus":  stats.Duration(w.sentHdr.Sub(tStart)),
  53                         // "timeWriteBody": stats.Duration(tDone.Sub(w.sentHdr)),
  54                 })
  55         }
  56         lgr.WithFields(log.Fields{
  57                 "respStatusCode": w.WroteStatus(),
  58                 "respStatus":     http.StatusText(w.WroteStatus()),
  59                 "respBytes":      w.WroteBodyBytes(),
  60         }).Info("response")
  61 }