8460: Merge branch 'master' into 8460-websocket-go
[arvados.git] / 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 }