New logging middleware that captures response

go.mod

@@ -2,10 +2,7 @@ module git.nice.net.nz/hads/snice
 
 go 1.21.3
 
-require (
-	github.com/urfave/cli/v2 v2.25.7
-	golang.org/x/exp v0.0.0-20231006140011-7918f672742d
-)
+require github.com/urfave/cli/v2 v2.25.7
 
 require (
 	github.com/cpuguy83/go-md2man/v2 v2.0.2 // indirect

go.sum

@@ -6,5 +6,3 @@ github.com/urfave/cli/v2 v2.25.7 h1:VAzn5oq403l5pHjc4OhD54+XGO9cdKVL/7lDjF+iKUs=
 github.com/urfave/cli/v2 v2.25.7/go.mod h1:8qnjx1vcq5s2/wpsqoZFndg2CE5tNFyrTvS6SinrnYQ=
 github.com/xrash/smetrics v0.0.0-20201216005158-039620a65673 h1:bAn7/zixMGCfxrRTfdpNzjtPYqr8smhKouy9mxVdGPU=
 github.com/xrash/smetrics v0.0.0-20201216005158-039620a65673/go.mod h1:N3UwUGtsrSj3ccvlPHLoLsHnpR27oXr4ZE984MbSER8=
-golang.org/x/exp v0.0.0-20231006140011-7918f672742d h1:jtJma62tbqLibJ5sFQz8bKtEM8rJBtfilJ2qTU199MI=
-golang.org/x/exp v0.0.0-20231006140011-7918f672742d/go.mod h1:ldy0pHrwJyGW56pPQzzkH36rKxoZW1tw7ZJpeKx+hdo=

main.go

@@ -3,33 +3,97 @@ package main
 import (
 	"fmt"
 	"log"
+	"log/slog"
 	"net"
 	"net/http"
 	"os"
-	"strings"
 	"time"
 
 	"github.com/urfave/cli/v2"
-	"golang.org/x/exp/slog"
 )
 
-func serveLogger(logger *log.Logger, next http.Handler) http.Handler {
+type (
+	// struct for holding response details
+	responseData struct {
+		status int
+		size   int
+	}
+
+	// our http.ResponseWriter implementation
+	loggingResponseWriter struct {
+		http.ResponseWriter // compose original http.ResponseWriter
+		responseData        *responseData
+	}
+)
+
+func (r *loggingResponseWriter) Write(b []byte) (int, error) {
+	size, err := r.ResponseWriter.Write(b) // write response using original http.ResponseWriter
+	r.responseData.size += size            // capture size
+	return size, err
+}
+
+func (r *loggingResponseWriter) WriteHeader(statusCode int) {
+	r.ResponseWriter.WriteHeader(statusCode) // write status code using original http.ResponseWriter
+	r.responseData.status = statusCode       // capture status code
+}
+
+func WithLogging(h http.Handler) http.Handler {
+	loggingFn := func(w http.ResponseWriter, r *http.Request) {
+		start := time.Now()
+
+		responseData := &responseData{
+			status: 0,
+			size:   0,
+		}
+		lrw := loggingResponseWriter{
+			ResponseWriter: w, // compose original http.ResponseWriter
+			responseData:   responseData,
+		}
+		h.ServeHTTP(&lrw, r) // inject our implementation of http.ResponseWriter
+
+		duration := time.Since(start)
+
+		slog.Info("Request:",
+			slog.String("method", r.Method),
+			slog.String("path", r.RequestURI),
+			slog.String("url", r.URL.Path),
+			slog.String("host", r.Host),
+			slog.Int("status", responseData.status),
+			slog.Int64("duration", duration.Microseconds()),
+			slog.Int("size", responseData.size),
+		)
+
+	}
+	return http.HandlerFunc(loggingFn)
+}
+
+func LoggingMiddleware(logger *slog.Logger, next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		remoteHost, _, _ := strings.Cut(r.RemoteAddr, ":")
-		logger.Printf("%v %v %v\n", remoteHost, r.Method, r.URL.Path)
 		next.ServeHTTP(w, r)
+		logger.Info("Request:",
+			slog.String("method", r.Method),
+			slog.String("path", r.RequestURI),
+			slog.String("url", r.URL.Path),
+			slog.String("host", r.Host),
+		)
+
 	})
 }
 
-func timeHandler(w http.ResponseWriter, r *http.Request) {
-	fmt.Fprint(w, time.Now().Format("02 Jan 2006 15:04:05 MST"))
+func pingHandler(w http.ResponseWriter, r *http.Request) {
+	w.Write([]byte("OK"))
 }
 
 func main() {
-	// handler := slog.NewJSONHandler(os.Stdout, nil)
-	handler := slog.NewTextHandler(os.Stdout, nil)
-	slog.SetDefault(slog.New(handler))
-	logger := slog.NewLogLogger(handler, slog.LevelError)
+	logLevel := &slog.LevelVar{} // INFO
+
+	opts := slog.HandlerOptions{
+		Level: logLevel,
+	}
+	logLevel.Set(slog.LevelDebug)
+	handler := slog.NewTextHandler(os.Stdout, &opts)
+	logger := slog.New(handler)
+	slog.SetDefault(logger)
 
 	var host string
 	var port string
@@ -49,23 +113,21 @@ func main() {
 					var addr string = host + ":" + port
 
 					srv := &http.Server{
-						Addr:     addr,
-						ErrorLog: logger,
+						Addr: addr,
 					}
 					mux := http.NewServeMux()
-					mux.HandleFunc("/time", timeHandler)
-					fileHandler := serveLogger(logger, http.FileServer(http.Dir(directory)))
+					mux.Handle("/ping", http.HandlerFunc(pingHandler))
+					fileHandler := http.FileServer(http.Dir(directory))
 					mux.Handle("/", fileHandler)
-					srv.Handler = mux
+					srv.Handler = WithLogging(mux)
 					listener, err := net.Listen("tcp", addr)
 					if err != nil {
-						logger.Println(err)
+						logger.Error("Listen error", err)
 					}
-					scheme := "http://"
-					logger.Printf("Serving directory %q on %v%v", directory, scheme, listener.Addr())
+					logger.Info(fmt.Sprintf("Serving directory %q on http://%v", directory, listener.Addr()))
 					err = srv.Serve(listener)
 					if err != nil {
-						logger.Println(err)
+						logger.Error("Serve error", err)
 					}
 					return nil
 				},
@@ -81,7 +143,7 @@ func main() {
 					&cli.StringFlag{
 						Name:        "host",
 						EnvVars:     []string{"HOST"},
-						Value:       "127.0.0.1",
+						Value:       "0.0.0.0",
 						Usage:       "Host to listen on",
 						Destination: &host,
 					}},
@@ -91,10 +153,11 @@ func main() {
 				Aliases: []string{"hc"},
 				Usage:   "Call healthcheck endpoint",
 				Action: func(cCtx *cli.Context) error {
-					_, err := http.Get(fmt.Sprintf("http://127.0.0.1:%s/health", port))
+					_, err := http.Get(fmt.Sprintf("http://127.0.0.1:%s/ping", port))
 					if err != nil {
 						os.Exit(1)
 					}
+					os.Exit(0)
 					return nil
 				}}},
 		Flags: []cli.Flag{