1 // Copyright (C) The Arvados Authors. All rights reserved.
3 // SPDX-License-Identifier: Apache-2.0
15 "git.arvados.org/arvados.git/sdk/go/ctxlog"
16 "git.arvados.org/arvados.git/sdk/go/stats"
17 "github.com/sirupsen/logrus"
20 type contextKey struct {
25 requestTimeContextKey = contextKey{"requestTime"}
26 responseLogFieldsContextKey = contextKey{"responseLogFields"}
27 mutexContextKey = contextKey{"mutex"}
30 type hijacker interface {
35 // hijackNotifier wraps a ResponseWriter, calling the provided
36 // Notify() func if/when the wrapped Hijacker is hijacked.
37 type hijackNotifier struct {
42 func (hn hijackNotifier) Hijack() (net.Conn, *bufio.ReadWriter, error) {
44 return hn.hijacker.Hijack()
47 // HandlerWithDeadline cancels the request context if the request
48 // takes longer than the specified timeout without having its
49 // connection hijacked.
50 func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler {
51 return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
52 ctx, cancel := context.WithCancel(r.Context())
54 nodeadline := make(chan bool)
59 case <-time.After(timeout):
63 if hj, ok := w.(hijacker); ok {
64 w = hijackNotifier{hj, nodeadline}
66 next.ServeHTTP(w, r.WithContext(ctx))
70 func SetResponseLogFields(ctx context.Context, fields logrus.Fields) {
71 m := ctx.Value(&mutexContextKey)
72 if mutex, ok := m.(sync.Mutex); ok {
75 ctxfields := ctx.Value(&responseLogFieldsContextKey)
76 if c, ok := ctxfields.(logrus.Fields); ok {
77 for k, v := range fields {
82 // We can't lock, don't set the fields
86 // LogRequests wraps an http.Handler, logging each request and
88 func LogRequests(h http.Handler) http.Handler {
89 return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
90 w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
91 lgr := ctxlog.FromContext(req.Context()).WithFields(logrus.Fields{
92 "RequestID": req.Header.Get("X-Request-Id"),
93 "remoteAddr": req.RemoteAddr,
94 "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
95 "reqMethod": req.Method,
97 "reqPath": req.URL.Path[1:],
98 "reqQuery": req.URL.RawQuery,
99 "reqBytes": req.ContentLength,
102 ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
103 ctx = context.WithValue(ctx, &responseLogFieldsContextKey, logrus.Fields{})
104 ctx = context.WithValue(ctx, &mutexContextKey, sync.Mutex{})
105 ctx = ctxlog.Context(ctx, lgr)
106 req = req.WithContext(ctx)
108 logRequest(w, req, lgr)
109 defer logResponse(w, req, lgr)
110 h.ServeHTTP(rewrapResponseWriter(w, wrapped), req)
114 // Rewrap w to restore additional interfaces provided by wrapped.
115 func rewrapResponseWriter(w http.ResponseWriter, wrapped http.ResponseWriter) http.ResponseWriter {
116 if hijacker, ok := wrapped.(http.Hijacker); ok {
125 func Logger(req *http.Request) logrus.FieldLogger {
126 return ctxlog.FromContext(req.Context())
129 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
133 func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
134 if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
136 writeTime := w.writeTime
138 // Empty response body. Header was sent when
142 lgr = lgr.WithFields(logrus.Fields{
143 "timeTotal": stats.Duration(tDone.Sub(tStart)),
144 "timeToStatus": stats.Duration(writeTime.Sub(tStart)),
145 "timeWriteBody": stats.Duration(tDone.Sub(writeTime)),
148 if responseLogFields, ok := req.Context().Value(&responseLogFieldsContextKey).(logrus.Fields); ok {
149 lgr = lgr.WithFields(responseLogFields)
151 respCode := w.WroteStatus()
153 respCode = http.StatusOK
155 fields := logrus.Fields{
156 "respStatusCode": respCode,
157 "respStatus": http.StatusText(respCode),
158 "respBytes": w.WroteBodyBytes(),
161 fields["respBody"] = string(w.Sniffed())
163 lgr.WithFields(fields).Info("response")
166 type responseTimer struct {
172 func (rt *responseTimer) CloseNotify() <-chan bool {
173 if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok {
174 return cn.CloseNotify()
179 func (rt *responseTimer) WriteHeader(code int) {
182 rt.writeTime = time.Now()
184 rt.ResponseWriter.WriteHeader(code)
187 func (rt *responseTimer) Write(p []byte) (int, error) {
190 rt.writeTime = time.Now()
192 return rt.ResponseWriter.Write(p)