Implement httplog.LogRequestBody(ctx) and Resp overrides

Author: VojtechVitek

README.md

@@ -12,15 +12,17 @@ A small but powerful structured logging package for HTTP request logging, built
 
 ## Example
 
-See [_example/main.go](./_example/main.go) and try running it locally:
+See [_example/main.go](./_example/main.go). Try running it locally:
 ```sh
-$ go run github.com/golang-cz/httplog/_example
+$ ENV=production go run github.com/golang-cz/httplog/_example
 
 $ ENV=localhost go run github.com/golang-cz/httplog/_example
 ```
 
 ## Usage
 
+`go get github.com/golang-cz/httplog@latest`
+
 ```go
 package main
 
@@ -48,16 +50,16 @@ func main() {
 
 	// Request logger
 	r.Use(httplog.RequestLogger(logger, &httplog.Options{
-		// Level defines the verbosity of the requests logs:
+		// Level defines the verbosity of the request logs:
 		// slog.LevelDebug - log both request starts & responses (incl. OPTIONS)
-		// slog.LevelInfo  - log responses (excl. OPTIONS)
+		// slog.LevelInfo  - log all responses (excl. OPTIONS)
 		// slog.LevelWarn  - log 4xx and 5xx responses only (except for 429)
 		// slog.LevelError - log 5xx responses only
 		Level: slog.LevelInfo,
 
 		// Concise mode causes fewer log attributes to be printed in request logs.
 		// This is useful if your console is too noisy during development.
-		Concise: isLocalhost,
+		Concise: false,
 
 		// RecoverPanics recovers from panics occurring in the underlying HTTP handlers
 		// and middlewares. It returns HTTP 500 unless response status was already set.
@@ -66,12 +68,12 @@ func main() {
 		RecoverPanics: true,
 
 		// Select request/response headers to be logged explicitly.
-		ReqHeaders:  []string{"User-Agent", "Origin", "Referer", traceid.Header},
-		RespHeaders: []string{traceid.Header},
+		LogRequestHeaders:  []string{"User-Agent", "Origin", "Referer"},
+		LogResponseHeaders: []string{},
 
 		// You can log request/request body. Useful for debugging.
-		ReqBody:  false,
-		RespBody: false,
+		LogRequestBody:  false,
+		LogResponseBody: false,
 	}))
 
 	r.Get("/", func(w http.ResponseWriter, r *http.Request) {

_example/main.go

@@ -48,9 +48,9 @@ func main() {
 
 	// Request logger
 	r.Use(httplog.RequestLogger(logger, &httplog.Options{
-		// Level defines the verbosity of the requests logs:
+		// Level defines the verbosity of the request logs:
 		// slog.LevelDebug - log both request starts & responses (incl. OPTIONS)
-		// slog.LevelInfo  - log responses (excl. OPTIONS)
+		// slog.LevelInfo  - log all responses (excl. OPTIONS)
 		// slog.LevelWarn  - log 4xx and 5xx responses only (except for 429)
 		// slog.LevelError - log 5xx responses only
 		Level: slog.LevelInfo,
@@ -66,12 +66,12 @@ func main() {
 		RecoverPanics: true,
 
 		// Select request/response headers to be logged explicitly.
-		ReqHeaders:  []string{"User-Agent", "Origin", "Referer", traceid.Header},
-		RespHeaders: []string{traceid.Header},
+		LogRequestHeaders:  []string{"User-Agent", "Origin", "Referer", traceid.Header},
+		LogResponseHeaders: []string{traceid.Header},
 
 		// You can log request/request body. Useful for debugging.
-		ReqBody:  false,
-		RespBody: false,
+		LogRequestBody:  false,
+		LogResponseBody: false,
 	}))
 
 	r.Use(func(next http.Handler) http.Handler {
@@ -124,6 +124,18 @@ func main() {
 		w.Write([]byte("oops, err \n"))
 	})
 
+	r.Post("/body", func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
+
+		// Log request/response bodies for Admin requests.
+		if r.Header.Get("Authorization") == "Bearer ADMIN-SECRET" {
+			httplog.LogRequestBody(ctx)
+			httplog.LogResponseBody(ctx)
+		}
+
+		w.Write([]byte(`{"response": "payload"}`))
+	})
+
 	fmt.Println("Enable pretty logs with:")
 	fmt.Println("  ENV=localhost go run ./")
 	fmt.Println()
@@ -133,6 +145,8 @@ func main() {
 	fmt.Println("  curl -v http://localhost:8000/info")
 	fmt.Println("  curl -v http://localhost:8000/warn")
 	fmt.Println("  curl -v http://localhost:8000/err")
+	fmt.Println(`  curl -v http://localhost:8000/body -X POST --data '{"request": "data"}'`)
+	fmt.Println(`  curl -v http://localhost:8000/body -X POST --data '{"request": "data"}' -H "Authorization: Bearer ADMIN-SECRET"`)
 	fmt.Println()
 
 	if err := http.ListenAndServe("localhost:8000", r); err != http.ErrAbortHandler {

context.go

@@ -2,6 +2,8 @@ package httplog
 
 import (
 	"context"
+	"fmt"
+	"io"
 	"log/slog"
 )
 
@@ -35,3 +37,28 @@ func SetLevel(ctx context.Context, level slog.Level) {
 	}
 	log.Level = level
 }
+
+func LogRequestBody(ctx context.Context) {
+	log, ok := ctx.Value(logCtxKey{}).(*Log)
+	if !ok {
+		// Panic to stress test the use of this function. Later, we can return error.
+		panic("use of httplog.SetLevel() outside of context set by httplog.RequestLogger")
+	}
+	if !log.LogRequestBody {
+		fmt.Println("doing it now...")
+		log.LogRequestBody = true
+		log.Req.Body = io.NopCloser(io.TeeReader(log.Req.Body, &log.ReqBody))
+	}
+}
+
+func LogResponseBody(ctx context.Context) {
+	log, ok := ctx.Value(logCtxKey{}).(*Log)
+	if !ok {
+		// Panic to stress test the use of this function. Later, we can return error.
+		panic("use of httplog.SetLevel() outside of context set by httplog.RequestLogger")
+	}
+	if !log.LogResponseBody {
+		log.LogResponseBody = true
+		log.WW.Tee(&log.RespBody)
+	}
+}

handler.go

@@ -30,59 +30,66 @@ func (h *Handler) Enabled(ctx context.Context, level slog.Level) bool {
 	return level >= h.opts.Level
 }
 
-func (h *Handler) Handle(ctx context.Context, r slog.Record) error {
+func (h *Handler) Handle(ctx context.Context, rec slog.Record) error {
 	log, ok := ctx.Value(logCtxKey{}).(*Log)
 	if !ok {
 		// Panic to stress test the use of this handler. Later, we can return error.
 		panic("use of httplog.DefaultHandler outside of context set by http.RequestLogger middleware")
 	}
 
+	// r := log.Req
+
+	scheme := "http"
+	if log.Req.TLS != nil {
+		scheme = "https"
+	}
+
 	if h.opts.Concise {
-		r.AddAttrs(slog.Any("requestHeaders", slog.GroupValue(getHeaderAttrs(log.Req.Header, h.opts.ReqHeaders)...)))
-		if h.opts.ReqBody && log.Resp != nil {
-			r.AddAttrs(slog.String("requestBody", log.Req.Body.String()))
-			if !log.Req.BodyFullyRead {
-				r.AddAttrs(slog.Bool("requestBodyFullyRead", false))
+		rec.AddAttrs(slog.Any("requestHeaders", slog.GroupValue(getHeaderAttrs(log.Req.Header, h.opts.LogRequestHeaders)...)))
+		if log.LogRequestBody && log.Resp != nil {
+			rec.AddAttrs(slog.String("requestBody", log.ReqBody.String()))
+			if !log.ReqBodyFullyRead {
+				rec.AddAttrs(slog.Bool("requestBodyFullyRead", false))
 			}
 		}
 
 		if log.Resp != nil {
-			r.Message = fmt.Sprintf("HTTP %v (%v): %s %s", log.Resp.Status, log.Resp.Duration, log.Req.Method, log.Req.URL)
-			r.AddAttrs(slog.Any("responseHeaders", slog.GroupValue(getHeaderAttrs(log.Resp.Header(), h.opts.RespHeaders)...)))
-			if h.opts.RespBody {
-				r.AddAttrs(slog.String("responseBody", log.Resp.Body.String()))
+			rec.Message = fmt.Sprintf("HTTP %v (%v): %s %s", log.WW.Status(), log.Resp.Duration, log.Req.Method, log.Req.URL)
+			rec.AddAttrs(slog.Any("responseHeaders", slog.GroupValue(getHeaderAttrs(log.Resp.Header(), h.opts.LogResponseHeaders)...)))
+			if log.LogResponseBody {
+				rec.AddAttrs(slog.String("responseBody", log.RespBody.String()))
 			}
 		} else {
-			r.Message = fmt.Sprintf("%s %s://%s%s", log.Req.Method, log.Req.Scheme, log.Req.Host, log.Req.URL)
+			rec.Message = fmt.Sprintf("%s %s://%s%s", log.Req.Method, scheme, log.Req.Host, log.Req.URL)
 		}
 	} else {
 		reqAttrs := []slog.Attr{
-			slog.String("url", fmt.Sprintf("%s://%s%s", log.Req.Scheme, log.Req.Host, log.Req.URL)),
+			slog.String("url", fmt.Sprintf("%s://%s%s", scheme, log.Req.Host, log.Req.URL)),
 			slog.String("method", log.Req.Method),
 			slog.String("path", log.Req.URL.Path),
 			slog.String("remoteIp", log.Req.RemoteAddr),
 			slog.String("proto", log.Req.Proto),
-			slog.Any("headers", slog.GroupValue(getHeaderAttrs(log.Req.Header, h.opts.ReqHeaders)...)),
+			slog.Any("headers", slog.GroupValue(getHeaderAttrs(log.Req.Header, h.opts.LogRequestHeaders)...)),
 		}
-		if h.opts.ReqBody && log.Resp != nil {
-			reqAttrs = append(reqAttrs, slog.String("body", log.Req.Body.String()))
-			if !log.Req.BodyFullyRead {
+		if log.LogRequestBody && log.Resp != nil {
+			reqAttrs = append(reqAttrs, slog.String("body", log.ReqBody.String()))
+			if !log.ReqBodyFullyRead {
 				reqAttrs = append(reqAttrs, slog.Bool("bodyFullyRead", false))
 			}
 		}
-		r.AddAttrs(slog.Any("request", slog.GroupValue(reqAttrs...)))
+		rec.AddAttrs(slog.Any("request", slog.GroupValue(reqAttrs...)))
 
 		if log.Resp != nil {
 			respAttrs := []slog.Attr{
-				slog.Any("headers", slog.GroupValue(getHeaderAttrs(log.Resp.Header(), h.opts.RespHeaders)...)),
-				slog.Int("status", log.Resp.Status),
-				slog.Int("bytes", log.Resp.Bytes),
+				slog.Any("headers", slog.GroupValue(getHeaderAttrs(log.Resp.Header(), h.opts.LogResponseHeaders)...)),
+				slog.Int("status", log.WW.Status()),
+				slog.Int("bytes", log.WW.BytesWritten()),
 				slog.Float64("duration", float64(log.Resp.Duration.Nanoseconds()/1000000.0)), // in milliseconds
 			}
-			if h.opts.RespBody {
-				respAttrs = append(respAttrs, slog.String("body", log.Resp.Body.String()))
+			if log.LogResponseBody {
+				respAttrs = append(respAttrs, slog.String("body", log.RespBody.String()))
 			}
-			r.AddAttrs(slog.Any("response", slog.GroupValue(respAttrs...)))
+			rec.AddAttrs(slog.Any("response", slog.GroupValue(respAttrs...)))
 		}
 	}
 
@@ -99,16 +106,16 @@ func (h *Handler) Handle(ctx context.Context, r slog.Record) error {
 				break
 			}
 		}
-		r.AddAttrs(
+		rec.AddAttrs(
 			slog.Any("panic", log.Panic),
 			slog.Any("panicStack", stackValues),
 		)
 	}
 
-	r.AddAttrs(h.attrs...)
-	r.AddAttrs(log.Attrs...)
+	rec.AddAttrs(h.attrs...)
+	rec.AddAttrs(log.Attrs...)
 
-	return h.Handler.Handle(ctx, r)
+	return h.Handler.Handle(ctx, rec)
 }
 
 func (c *Handler) WithAttrs(attrs []slog.Attr) slog.Handler {