refa: use structured logging for http request logging

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.

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
 )

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=