19675: Merge branch '19675-instance-types-panel' from arvados-workbench2.git
[arvados.git] / sdk / go / httpserver / logger.go
1 // Copyright (C) The Arvados Authors. All rights reserved.
2 //
3 // SPDX-License-Identifier: Apache-2.0
4
5 package httpserver
6
7 import (
8         "bufio"
9         "context"
10         "net"
11         "net/http"
12         "sync"
13         "time"
14
15         "git.arvados.org/arvados.git/sdk/go/ctxlog"
16         "git.arvados.org/arvados.git/sdk/go/stats"
17         "github.com/sirupsen/logrus"
18 )
19
20 type contextKey struct {
21         name string
22 }
23
24 var (
25         requestTimeContextKey       = contextKey{"requestTime"}
26         responseLogFieldsContextKey = contextKey{"responseLogFields"}
27         mutexContextKey             = contextKey{"mutex"}
28 )
29
30 type hijacker interface {
31         http.ResponseWriter
32         http.Hijacker
33 }
34
35 // hijackNotifier wraps a ResponseWriter, calling the provided
36 // Notify() func if/when the wrapped Hijacker is hijacked.
37 type hijackNotifier struct {
38         hijacker
39         hijacked chan<- bool
40 }
41
42 func (hn hijackNotifier) Hijack() (net.Conn, *bufio.ReadWriter, error) {
43         close(hn.hijacked)
44         return hn.hijacker.Hijack()
45 }
46
47 // HandlerWithDeadline cancels the request context if the request
48 // takes longer than the specified timeout without having its
49 // connection hijacked.
50 //
51 // If timeout is 0, there is no deadline: HandlerWithDeadline is a
52 // no-op.
53 func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler {
54         if timeout == 0 {
55                 return next
56         }
57         return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
58                 ctx, cancel := context.WithCancel(r.Context())
59                 defer cancel()
60                 nodeadline := make(chan bool)
61                 go func() {
62                         select {
63                         case <-nodeadline:
64                         case <-ctx.Done():
65                         case <-time.After(timeout):
66                                 cancel()
67                         }
68                 }()
69                 if hj, ok := w.(hijacker); ok {
70                         w = hijackNotifier{hj, nodeadline}
71                 }
72                 next.ServeHTTP(w, r.WithContext(ctx))
73         })
74 }
75
76 func SetResponseLogFields(ctx context.Context, fields logrus.Fields) {
77         m, _ := ctx.Value(&mutexContextKey).(*sync.Mutex)
78         c, _ := ctx.Value(&responseLogFieldsContextKey).(logrus.Fields)
79         if m == nil || c == nil {
80                 return
81         }
82         m.Lock()
83         defer m.Unlock()
84         for k, v := range fields {
85                 c[k] = v
86         }
87 }
88
89 // LogRequests wraps an http.Handler, logging each request and
90 // response.
91 func LogRequests(h http.Handler) http.Handler {
92         return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
93                 w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
94                 lgr := ctxlog.FromContext(req.Context()).WithFields(logrus.Fields{
95                         "RequestID":       req.Header.Get("X-Request-Id"),
96                         "remoteAddr":      req.RemoteAddr,
97                         "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
98                         "reqMethod":       req.Method,
99                         "reqHost":         req.Host,
100                         "reqPath":         req.URL.Path[1:],
101                         "reqQuery":        req.URL.RawQuery,
102                         "reqBytes":        req.ContentLength,
103                 })
104                 ctx := req.Context()
105                 ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
106                 ctx = context.WithValue(ctx, &responseLogFieldsContextKey, logrus.Fields{})
107                 ctx = context.WithValue(ctx, &mutexContextKey, &sync.Mutex{})
108                 ctx = ctxlog.Context(ctx, lgr)
109                 req = req.WithContext(ctx)
110
111                 logRequest(w, req, lgr)
112                 defer logResponse(w, req, lgr)
113                 h.ServeHTTP(rewrapResponseWriter(w, wrapped), req)
114         })
115 }
116
117 // Rewrap w to restore additional interfaces provided by wrapped.
118 func rewrapResponseWriter(w http.ResponseWriter, wrapped http.ResponseWriter) http.ResponseWriter {
119         if hijacker, ok := wrapped.(http.Hijacker); ok {
120                 return struct {
121                         http.ResponseWriter
122                         http.Hijacker
123                 }{w, hijacker}
124         }
125         return w
126 }
127
128 func Logger(req *http.Request) logrus.FieldLogger {
129         return ctxlog.FromContext(req.Context())
130 }
131
132 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
133         lgr.Info("request")
134 }
135
136 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
137         if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
138                 tDone := time.Now()
139                 writeTime := w.writeTime
140                 if !w.wrote {
141                         // Empty response body. Header was sent when
142                         // handler exited.
143                         writeTime = tDone
144                 }
145                 lgr = lgr.WithFields(logrus.Fields{
146                         "timeTotal":     stats.Duration(tDone.Sub(tStart)),
147                         "timeToStatus":  stats.Duration(writeTime.Sub(tStart)),
148                         "timeWriteBody": stats.Duration(tDone.Sub(writeTime)),
149                 })
150         }
151         if responseLogFields, ok := req.Context().Value(&responseLogFieldsContextKey).(logrus.Fields); ok {
152                 lgr = lgr.WithFields(responseLogFields)
153         }
154         respCode := w.WroteStatus()
155         if respCode == 0 {
156                 respCode = http.StatusOK
157         }
158         fields := logrus.Fields{
159                 "respStatusCode": respCode,
160                 "respStatus":     http.StatusText(respCode),
161                 "respBytes":      w.WroteBodyBytes(),
162         }
163         if respCode >= 400 {
164                 fields["respBody"] = string(w.Sniffed())
165         }
166         lgr.WithFields(fields).Info("response")
167 }
168
169 type responseTimer struct {
170         ResponseWriter
171         wrote     bool
172         writeTime time.Time
173 }
174
175 func (rt *responseTimer) CloseNotify() <-chan bool {
176         if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
177                 return cn.CloseNotify()
178         }
179         return nil
180 }
181
182 func (rt *responseTimer) WriteHeader(code int) {
183         if !rt.wrote {
184                 rt.wrote = true
185                 rt.writeTime = time.Now()
186         }
187         rt.ResponseWriter.WriteHeader(code)
188 }
189
190 func (rt *responseTimer) Write(p []byte) (int, error) {
191         if !rt.wrote {
192                 rt.wrote = true
193                 rt.writeTime = time.Now()
194         }
195         return rt.ResponseWriter.Write(p)
196 }