From e8133e46fb1e9028c2c66ac57befe70c344d32c4 Mon Sep 17 00:00:00 2001 From: Johannes Edmeier Date: Wed, 23 Aug 2023 15:59:23 +0200 Subject: [PATCH] refa: use structured logging for http request logging --- exthttp/exthttp.go | 103 +++++++++++++++++---------------------------- go.mod | 1 + go.sum | 1 + 3 files changed, 40 insertions(+), 65 deletions(-) diff --git a/exthttp/exthttp.go b/exthttp/exthttp.go index b89645d..78a0eb9 100644 --- a/exthttp/exthttp.go +++ b/exthttp/exthttp.go @@ -8,11 +8,10 @@ package exthttp import ( "encoding/json" - "github.com/google/uuid" "github.com/rs/zerolog" + "github.com/rs/zerolog/hlog" "github.com/rs/zerolog/log" "github.com/steadybit/extension-kit" - "github.com/steadybit/extension-kit/extutil" "io" "net/http" "runtime/debug" @@ -33,36 +32,16 @@ func GetterAsHandler[T any](handler func() T) func(w http.ResponseWriter, r *htt } } -func PanicRecovery(next func(w http.ResponseWriter, r *http.Request)) http.HandlerFunc { - return func(w http.ResponseWriter, r *http.Request) { +func PanicRecovery(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { defer func() { if err := recover(); err != nil { log.Error().Msgf("Panic: %v\n %s", err, string(debug.Stack())) WriteError(w, extension_kit.ToError("Internal Server Error", nil)) } }() - next(w, r) - } -} - -type LoggingHttpResponseWriter struct { - delegate http.ResponseWriter - reqId string -} - -func (w *LoggingHttpResponseWriter) Header() http.Header { - return w.delegate.Header() -} - -func (w *LoggingHttpResponseWriter) Write(bytes []byte) (int, error) { - log.Debug().Msgf("Req %s response body length: %d bytes", w.reqId, len(bytes)) - log.Trace().Msgf("Req %s response body: %s", w.reqId, bytes) - return w.delegate.Write(bytes) -} - -func (w *LoggingHttpResponseWriter) WriteHeader(statusCode int) { - log.Debug().Msgf("Req %s response status code: %d", w.reqId, statusCode) - w.delegate.WriteHeader(statusCode) + next.ServeHTTP(w, r) + }) } func RequestTimeoutHeaderAware(next func(w http.ResponseWriter, r *http.Request)) http.HandlerFunc { @@ -83,51 +62,45 @@ func RequestTimeoutHeaderAware(next func(w http.ResponseWriter, r *http.Request) } } -func LogRequest(next func(w http.ResponseWriter, r *http.Request, body []byte)) http.HandlerFunc { - return LogRequestWithLevelFunc(next, func(r *http.Request) zerolog.Level { +func LogRequest(next func(w http.ResponseWriter, r *http.Request, body []byte)) http.Handler { + var handler http.Handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + level := zerolog.InfoLevel if r.Method == "GET" { - return zerolog.DebugLevel - } else { - return zerolog.InfoLevel - } - }) -} - -func LogRequestWithLevelFunc(next func(w http.ResponseWriter, r *http.Request, body []byte), level func(r *http.Request) zerolog.Level) http.HandlerFunc { - return func(w http.ResponseWriter, r *http.Request) { - reqId := uuid.New().String() - if strings.HasPrefix(r.Header.Get("Content-Type"), "multipart/form-data") { - log.WithLevel(level(r)).Msgf("Req %s: %s %s (Multipart)", reqId, r.Method, r.URL) - next(extutil.Ptr(LoggingHttpResponseWriter{ - delegate: w, - reqId: reqId, - }), r, nil) - return + level = zerolog.DebugLevel } - body, bodyReadErr := io.ReadAll(r.Body) - if bodyReadErr != nil { - http.Error(w, bodyReadErr.Error(), http.StatusBadRequest) - return - } - - bodyLength := len(body) - if bodyLength == 0 { - log.WithLevel(level(r)).Msgf("Req %s: %s %s", reqId, r.Method, r.URL) - } else { - log.WithLevel(level(r)).Msgf("Req %s: %s %s with %d byte body", reqId, r.Method, r.URL, bodyLength) + var reqBody []byte = nil + if !strings.HasPrefix(r.Header.Get("Content-Type"), "multipart/form-data") { + if bytes, err := io.ReadAll(r.Body); err != nil { + http.Error(w, err.Error(), http.StatusBadRequest) + } else { + reqBody = bytes + } } - log.Debug().Msgf("Req %s body: %s", reqId, body) - next(extutil.Ptr(LoggingHttpResponseWriter{ - delegate: w, - reqId: reqId, - }), r, body) - } -} + hlog.FromRequest(r).Debug(). + Str("method", r.Method). + Stringer("url", r.URL). + Int("req_size", len(reqBody)). + Bytes("body", reqBody). + Msg("Request received") + + hlog.AccessHandler(func(r *http.Request, status, size int, duration time.Duration) { + hlog.FromRequest(r).WithLevel(level). + Str("method", r.Method). + Stringer("url", r.URL). + Int("res_size", size). + Int("req_size", len(reqBody)). + Dur("duration", duration). + Msg("") + })(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next(w, r, reqBody) + })).ServeHTTP(w, r) + }) -func LogRequestWithLevel(next func(w http.ResponseWriter, r *http.Request, body []byte), level zerolog.Level) http.HandlerFunc { - return LogRequestWithLevelFunc(next, func(r *http.Request) zerolog.Level { return level }) + handler = hlog.RequestIDHandler("req_id", "Request-Id")(handler) + handler = hlog.NewHandler(log.Logger)(handler) + return handler } // WriteError writes the error as the HTTP response body with status code 500. diff --git a/go.mod b/go.mod index a7cc583..bef7ee7 100644 --- a/go.mod +++ b/go.mod @@ -16,6 +16,7 @@ require ( github.com/mattn/go-colorable v0.1.12 // indirect github.com/mattn/go-isatty v0.0.14 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect + github.com/rs/xid v1.3.0 // indirect golang.org/x/sys v0.1.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 1ebe71c..1f54497 100644 --- a/go.sum +++ b/go.sum @@ -18,6 +18,7 @@ github.com/phayes/freeport v0.0.0-20220201140144-74d24b5ae9f5/go.mod h1:iIss55rK github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/rs/xid v1.3.0 h1:6NjYksEUlhurdVehpc7S7dk6DAmcKv8V9gG0FsVN2U4= github.com/rs/xid v1.3.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= github.com/rs/zerolog v1.27.0 h1:1T7qCieN22GVc8S4Q2yuexzBb1EqjbgjSH9RohbMjKs= github.com/rs/zerolog v1.27.0/go.mod h1:7frBqO0oezxmnO7GF86FY++uy8I0Tk/If5ni1G9Qc0U=