Feat 31/logging (#35)

* response writer interface update

* mod wrap method

* add hlog package for logging at the http layer

net/http/httputil/hlog/limit_reader.go

@@ -0,0 +1,37 @@
+package hlog
+
+import (
+	"bytes"
+	"io"
+)
+
+// limitBuffer is used to pipe response body information from the
+// response writer to a certain limit amount. The idea is to read
+// a portion of the response body such as an error response so we
+// may log it.
+type limitBuffer struct {
+	*bytes.Buffer
+	limit int
+}
+
+func newLimitBuffer(size int) io.ReadWriter {
+	return limitBuffer{
+		Buffer: bytes.NewBuffer(make([]byte, 0, size)),
+		limit:  size,
+	}
+}
+
+func (b limitBuffer) Write(p []byte) (n int, err error) {
+	if b.Buffer.Len() >= b.limit {
+		return len(p), nil
+	}
+	limit := b.limit
+	if len(p) < limit {
+		limit = len(p)
+	}
+	return b.Buffer.Write(p[:limit])
+}
+
+func (b limitBuffer) Read(p []byte) (n int, err error) {
+	return b.Buffer.Read(p)
+}

net/http/httputil/hlog/log.go

@@ -1,38 +1,89 @@
 package hlog
 
 import (
+	"context"
+	"io"
 	"log/slog"
 	"net/http"
+	"os"
+	"strings"
 	"time"
 
 	"go.adoublef.dev/sdk/net/http/httputil"
 )
 
-// Log wraps a http.Handler with a request logger.
-func Log(h http.Handler) http.Handler {
+type contextKey struct{ string }
+
+func (k *contextKey) String() string { return "hlog: context value " + k.string }
+
+var (
+	LoggerContextKey = &contextKey{"http-log"}
+)
+
+func LogHandler(h http.Handler, sl *slog.Logger) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		rw := httputil.Wrap(w, r)
+		l := newLogger(sl, r)
+		ww := httputil.Wrap(w, r)
 
-		start := time.Now()
+		buf := newLimitBuffer(512)
+		ww.Tee(buf)
+
+		t1 := time.Now()
 		defer func() {
-			duration := time.Since(start)
-
-			slog.LogAttrs(
-				r.Context(),
-				statusLevel(rw.Status()),
-				"http request",
-				slog.String("method", r.Method),
-				slog.Int64("time_ms", int64(duration/time.Millisecond)),
-				slog.String("path", r.URL.Path),
-				slog.Int("status", rw.Status()),
-				slog.String("duration", duration.String()),
-			)
+			var error []byte
+			if ww.Status() >= 400 {
+				error, _ = io.ReadAll(buf) // lorem is 3091
+			}
+			l.Write(ww.Status(), ww.Size(), ww.Header(), time.Since(t1), error)
 		}()
-
-		h.ServeHTTP(rw, r)
+		ctx := context.WithValue(r.Context(), LoggerContextKey, l)
+		h.ServeHTTP(ww, r.WithContext(ctx))
 	})
 }
 
+// Logger returns the in-context Logger for a request.
+func Logger(r *http.Request) *slog.Logger {
+	entry, ok := r.Context().Value(LoggerContextKey).(*logger)
+	if !ok || entry == nil {
+		opts := &slog.HandlerOptions{
+			AddSource: true,
+			// LevelError+1 will be higher than all levels
+			// hence logs would be skipped
+			Level: slog.LevelError + 1,
+		}
+		return slog.New(slog.NewTextHandler(os.Stderr, opts))
+	} else {
+		return entry.l
+	}
+}
+
+type logger struct {
+	l *slog.Logger
+}
+
+func newLogger(l *slog.Logger, r *http.Request) *logger {
+	// request can be passed via context
+	l = l.With(
+		slog.String("path", r.URL.Path),
+		slog.String("method", r.Method),
+		slog.String("remoteIP", r.RemoteAddr),
+	)
+	return &logger{l: l}
+}
+
+func (l *logger) Write(status, bytes int, header http.Header, elapsed time.Duration, body []byte) {
+	// response
+	l.l = l.l.With(
+		slog.Int("status", status),
+		slog.Int("bytes", bytes),
+		slog.Duration("elapsed", elapsed),
+	)
+	if status >= 400 {
+		l.l = l.l.With(slog.String("body", strings.TrimSpace(string(body))))
+	}
+	l.l.Log(context.Background(), statusLevel(status), statusLabel(status))
+}
+
 func statusLevel(status int) slog.Level {
 	switch {
 	case status <= 0:
@@ -48,3 +99,22 @@ func statusLevel(status int) slog.Level {
 		return slog.LevelInfo
 	}
 }
+
+func statusLabel(status int) string {
+	switch {
+	case status >= 100 && status < 300:
+		return "OK"
+	case status >= 300 && status < 400:
+		return "Redirect"
+	case status >= 400 && status < 500:
+		return "Client Error"
+	case status >= 500:
+		return "Server Error"
+	default:
+		return "Unknown"
+	}
+}
+
+func ErrAttr(err error) slog.Attr {
+	return slog.Any("err", err)
+}

net/http/httputil/response_writer.go

@@ -3,8 +3,10 @@ package httputil
 import (
 	"bufio"
 	"errors"
+	"io"
 	"net"
 	"net/http"
+	"sync"
 )
 
 type ResponseWriter interface {
@@ -17,13 +19,24 @@ type ResponseWriter interface {
 	// Size returns the size of the response body.
 	Size() int
 	Unwrap() http.ResponseWriter
+	// Tee allows the caller to write to multiple writers.
+	Tee(w io.Writer)
 }
 
 type response struct {
 	http.ResponseWriter
 	method string
 	status int
 	size   int
+	mu     sync.Mutex
+	tee    io.Writer
+}
+
+// Tee implements ResponseWriter.
+func (r *response) Tee(w io.Writer) {
+	r.mu.Lock()
+	r.tee = w
+	r.mu.Unlock()
 }
 
 // Size implements ResponseWriter.
@@ -48,14 +61,22 @@ func (rw *response) Status() int {
 
 // Write implements ResponseWriter.
 // Subtle: this method shadows the method (ResponseWriter).Write of response.ResponseWriter.
-func (rw *response) Write(b []byte) (size int, err error) {
-	if !rw.Written() {
+func (r *response) Write(b []byte) (size int, err error) {
+	if !r.Written() {
 		// The status will be StatusOK if WriteHeader has not been called yet
-		rw.WriteHeader(http.StatusOK)
+		r.WriteHeader(http.StatusOK)
 	}
-	if rw.method != http.MethodHead {
-		size, err = rw.ResponseWriter.Write(b)
-		rw.size += size
+	if r.method != http.MethodHead {
+		size, err = r.ResponseWriter.Write(b)
+		r.mu.Lock()
+		if r.tee != nil {
+			_, err2 := r.tee.Write(b[:size])
+			if err == nil {
+				err = err2
+			}
+		}
+		r.mu.Unlock()
+		r.size += size
 	}
 	return size, err
 }
@@ -99,7 +120,7 @@ func Wrap(w http.ResponseWriter, r *http.Request) ResponseWriter {
 	if rw, ok := w.(ResponseWriter); ok {
 		return rw
 	}
-	return &response{w, r.Method, 0, 0}
+	return &response{ResponseWriter: w, method: r.Method}
 }
 
 var (