X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/02ce18b74c42b34a86208a713e00dfa0e0fe39de..bf08477c7e766c7692731c08212c8d1c3c5628ea:/sdk/go/httpserver/logger.go diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go index decb2ff28b..f64708454c 100644 --- a/sdk/go/httpserver/logger.go +++ b/sdk/go/httpserver/logger.go @@ -9,52 +9,78 @@ import ( "net/http" "time" + "git.curoverse.com/arvados.git/sdk/go/ctxlog" "git.curoverse.com/arvados.git/sdk/go/stats" - log "github.com/Sirupsen/logrus" + "github.com/sirupsen/logrus" ) type contextKey struct { name string } -var requestTimeContextKey = contextKey{"requestTime"} +var ( + requestTimeContextKey = contextKey{"requestTime"} +) + +// HandlerWithContext returns an http.Handler that changes the request +// context to ctx (replacing http.Server's default +// context.Background()), then calls next. +func HandlerWithContext(ctx context.Context, next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next.ServeHTTP(w, r.WithContext(ctx)) + }) +} // LogRequests wraps an http.Handler, logging each request and -// response via logrus. +// response. func LogRequests(h http.Handler) http.Handler { return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) { w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)} - req = req.WithContext(context.WithValue(req.Context(), &requestTimeContextKey, time.Now())) - lgr := log.WithFields(log.Fields{ + lgr := ctxlog.FromContext(req.Context()).WithFields(logrus.Fields{ "RequestID": req.Header.Get("X-Request-Id"), "remoteAddr": req.RemoteAddr, "reqForwardedFor": req.Header.Get("X-Forwarded-For"), "reqMethod": req.Method, + "reqHost": req.Host, "reqPath": req.URL.Path[1:], + "reqQuery": req.URL.RawQuery, "reqBytes": req.ContentLength, }) + ctx := req.Context() + ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now()) + ctx = ctxlog.Context(ctx, lgr) + req = req.WithContext(ctx) + logRequest(w, req, lgr) defer logResponse(w, req, lgr) h.ServeHTTP(w, req) }) } -func logRequest(w *responseTimer, req *http.Request, lgr *log.Entry) { +func Logger(req *http.Request) logrus.FieldLogger { + return ctxlog.FromContext(req.Context()) +} + +func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) { lgr.Info("request") } -func logResponse(w *responseTimer, req *http.Request, lgr *log.Entry) { +func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) { if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok { tDone := time.Now() - lgr = lgr.WithFields(log.Fields{ + lgr = lgr.WithFields(logrus.Fields{ "timeTotal": stats.Duration(tDone.Sub(tStart)), "timeToStatus": stats.Duration(w.writeTime.Sub(tStart)), "timeWriteBody": stats.Duration(tDone.Sub(w.writeTime)), }) } - lgr.WithFields(log.Fields{ - "respStatusCode": w.WroteStatus(), - "respStatus": http.StatusText(w.WroteStatus()), + respCode := w.WroteStatus() + if respCode == 0 { + respCode = http.StatusOK + } + lgr.WithFields(logrus.Fields{ + "respStatusCode": respCode, + "respStatus": http.StatusText(respCode), "respBytes": w.WroteBodyBytes(), }).Info("response") } @@ -65,6 +91,13 @@ type responseTimer struct { writeTime time.Time } +func (rt *responseTimer) CloseNotify() <-chan bool { + if cn, ok := rt.ResponseWriter.(http.CloseNotifier); ok { + return cn.CloseNotify() + } + return nil +} + func (rt *responseTimer) WriteHeader(code int) { if !rt.wrote { rt.wrote = true