use slog

Author: SVilgelm

config.go

@@ -1,9 +1,10 @@
 package main
 
 import (
-	"log"
 	"net/http"
 	"os"
+
+	"golang.org/x/exp/slog"
 )
 
 type Config struct {
@@ -27,7 +28,7 @@ type Response struct {
 	IsJSON  bool        `json:"is_json,omitempty" yaml:"is_json,omitempty"`
 }
 
-func responsesWriter(responses []Response) http.HandlerFunc {
+func responsesWriter(responses []Response, log *slog.Logger) http.HandlerFunc {
 	var i int
 	return func(writer http.ResponseWriter, request *http.Request) {
 		for {
@@ -70,7 +71,7 @@ func responsesWriter(responses []Response) http.HandlerFunc {
 
 			if len(data) > 0 {
 				if _, err := writer.Write(data); err != nil {
-					log.Printf("sending response failed: %+v", err)
+					log.Error("sending response failed", err)
 				}
 			}
 			return

go.mod

@@ -5,5 +5,6 @@ go 1.20
 require (
 	github.com/go-chi/chi/v5 v5.0.8
 	github.com/spf13/pflag v1.0.5
+	golang.org/x/exp v0.0.0-20230203172020-98cc5a0785f9
 	gopkg.in/yaml.v3 v3.0.1
 )

go.sum

@@ -2,6 +2,8 @@ github.com/go-chi/chi/v5 v5.0.8 h1:lD+NLqFcAi1ovnVZpsnObHGW4xb4J8lNmoYVfECH1Y0=
 github.com/go-chi/chi/v5 v5.0.8/go.mod h1:DslCQbL2OYiznFReuXYUmQ2hGd1aDpCnlMNITLSKoi8=
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
 github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=
+golang.org/x/exp v0.0.0-20230203172020-98cc5a0785f9 h1:frX3nT9RkKybPnjyI+yvZh6ZucTZatCCEm9D47sZ2zo=
+golang.org/x/exp v0.0.0-20230203172020-98cc5a0785f9/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=

log.go

@@ -0,0 +1,111 @@
+package main
+
+import (
+	"fmt"
+	"net/http"
+	"os"
+	"time"
+
+	"github.com/go-chi/chi/v5/middleware"
+	"golang.org/x/exp/slog"
+)
+
+func LogHandler() *slog.JSONHandler {
+	// Setup a JSON handler for the new log/slog library
+	return slog.HandlerOptions{
+		// Remove default time slog.Attr, we create our own later
+		ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
+			if a.Key == slog.TimeKey {
+				return slog.Attr{}
+			}
+			return a
+		},
+	}.NewJSONHandler(os.Stdout)
+}
+
+// StructuredLogger is a simple, but powerful implementation of a custom structured
+// logger backed on log/slog. I encourage users to copy it, adapt it and make it their
+// own. Also take a look at https://github.com/go-chi/httplog for a dedicated pkg based
+// on this work, designed for context-based http routers.
+
+func NewStructuredLogger(handler slog.Handler) func(next http.Handler) http.Handler {
+	return middleware.RequestLogger(&StructuredLogger{Logger: handler})
+}
+
+type StructuredLogger struct {
+	Logger slog.Handler
+}
+
+func (l *StructuredLogger) NewLogEntry(r *http.Request) middleware.LogEntry {
+	var logFields []slog.Attr
+	logFields = append(logFields, slog.String("ts", time.Now().UTC().Format(time.RFC1123)))
+
+	if reqID := middleware.GetReqID(r.Context()); reqID != "" {
+		logFields = append(logFields, slog.String("req_id", reqID))
+	}
+
+	scheme := "http"
+	if r.TLS != nil {
+		scheme = "https"
+	}
+
+	handler := l.Logger.WithAttrs(append(logFields,
+		slog.String("http_scheme", scheme),
+		slog.String("http_proto", r.Proto),
+		slog.String("http_method", r.Method),
+		slog.String("remote_addr", r.RemoteAddr),
+		slog.String("user_agent", r.UserAgent()),
+		slog.String("uri", fmt.Sprintf("%s://%s%s", scheme, r.Host, r.RequestURI)),
+	))
+
+	entry := StructuredLoggerEntry{Logger: slog.New(handler)}
+
+	entry.Logger.LogAttrs(slog.LevelInfo, "request started")
+
+	return &entry
+}
+
+type StructuredLoggerEntry struct {
+	Logger *slog.Logger
+}
+
+func (l *StructuredLoggerEntry) Write(status, bytes int, header http.Header, elapsed time.Duration, extra interface{}) {
+	l.Logger.LogAttrs(slog.LevelInfo, "request complete",
+		slog.Int("resp_status", status),
+		slog.Int("resp_byte_length", bytes),
+		slog.Float64("resp_elapsed_ms", float64(elapsed.Nanoseconds())/1000000.0),
+	)
+}
+
+func (l *StructuredLoggerEntry) Panic(v interface{}, stack []byte) {
+	l.Logger.LogAttrs(slog.LevelInfo, "",
+		slog.String("stack", string(stack)),
+		slog.String("panic", fmt.Sprintf("%+v", v)),
+	)
+}
+
+// Helper methods used by the application to get the request-scoped
+// logger entry and set additional fields between handlers.
+//
+// This is a useful pattern to use to set state on the entry as it
+// passes through the handler chain, which at any point can be logged
+// with a call to .Print(), .Info(), etc.
+
+func GetLogEntry(r *http.Request) *slog.Logger {
+	entry := middleware.GetLogEntry(r).(*StructuredLoggerEntry)
+	return entry.Logger
+}
+
+func LogEntrySetField(r *http.Request, key string, value interface{}) {
+	if entry, ok := r.Context().Value(middleware.LogEntryCtxKey).(*StructuredLoggerEntry); ok {
+		entry.Logger = entry.Logger.With(key, value)
+	}
+}
+
+func LogEntrySetFields(r *http.Request, fields map[string]interface{}) {
+	if entry, ok := r.Context().Value(middleware.LogEntryCtxKey).(*StructuredLoggerEntry); ok {
+		for k, v := range fields {
+			entry.Logger = entry.Logger.With(k, v)
+		}
+	}
+}

main.go

@@ -4,7 +4,6 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log"
 	"net/http"
 	"os"
 	"os/signal"
@@ -15,10 +14,13 @@ import (
 	"github.com/go-chi/chi/v5"
 	"github.com/go-chi/chi/v5/middleware"
 	flag "github.com/spf13/pflag"
+	"golang.org/x/exp/slog"
 	"gopkg.in/yaml.v3"
 )
 
 func main() {
+	logHandler := LogHandler()
+	log := slog.New(logHandler)
 	conf := flag.StringP("config", "c", "config.yaml", "config file")
 	port := flag.IntP("port", "p", 8080, "http port")
 	flag.Parse()
@@ -29,21 +31,24 @@ func main() {
 	if v := os.Getenv("PORT"); v != "" && !flag.Lookup("port").Changed {
 		p, err := strconv.Atoi(v)
 		if err != nil {
-			log.Fatal(err)
+			log.Error(fmt.Sprintf("wrong value %q of env variable PORT", v), err)
+			os.Exit(1)
 		}
 		port = &p
 	}
 
 	f, err := os.Open(*conf)
 	if err != nil {
-		log.Fatal(err)
+		log.Error(fmt.Sprintf("wrong config file %q", *conf), err)
+		os.Exit(1)
 	}
 
 	var config Config
 	d := yaml.NewDecoder(f)
 	d.KnownFields(true)
 	if err := d.Decode(&config); err != nil {
-		panic(err)
+		log.Error("decoding config failed", err)
+		os.Exit(1)
 	}
 	if config.Port != 0 {
 		port = &config.Port
@@ -52,7 +57,11 @@ func main() {
 	if config.RequestIDHeader != "" {
 		middleware.RequestIDHeader = config.RequestIDHeader
 	}
-	r := chi.NewRouter().With(middleware.Logger, middleware.RequestID)
+
+	r := chi.NewMux().With(middleware.RequestID, NewStructuredLogger(LogHandler()))
+	r.NotFound(func(writer http.ResponseWriter, request *http.Request) {
+		http.NotFound(writer, request)
+	})
 	for _, route := range config.Routes {
 		if route.Method == "" {
 			route.Method = "GET"
@@ -62,7 +71,7 @@ func main() {
 		if route.Pattern == "" {
 			route.Pattern = "/"
 		}
-		r.MethodFunc(route.Method, route.Pattern, responsesWriter(route.Responses))
+		r.MethodFunc(route.Method, route.Pattern, responsesWriter(route.Responses, log))
 	}
 
 	server := &http.Server{
@@ -83,22 +92,23 @@ func main() {
 		go func() {
 			<-shutdownCtx.Done()
 			if errors.Is(shutdownCtx.Err(), context.DeadlineExceeded) {
-				log.Fatal("graceful shutdown timed out.. forcing exit.")
+				log.Error("graceful shutdown timed out.. forcing exit.", nil)
+				os.Exit(1)
 			}
 		}()
 
 		// Trigger graceful shutdown
-		err := server.Shutdown(shutdownCtx)
-		if err != nil {
-			log.Fatal(err)
+		if err := server.Shutdown(shutdownCtx); err != nil {
+			log.Error("graceful shutdown failed", err)
 		}
 		serverStopCtx()
 	}()
 
 	// Run the server
-	log.Printf("Listen on http://localhost:%d\n", *port)
+	log.Info(fmt.Sprintf("Listen on http://localhost:%d", *port))
 	if err := server.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) {
-		log.Fatal(err)
+		log.Error("starting failed", err)
+		os.Exit(1)
 	}
 
 	// Wait for server context to be stopped