feat: more structured logging

5 files changed, 56 insertions, 49 deletions

diff --git a/internal/server/dev.go b/internal/server/dev.go
index 17489d3..f5fd4fd 100644
--- a/internal/server/dev.go
+++ b/internal/server/dev.go
@@ -3,37 +3,41 @@ package server
 import (
 	"fmt"
 	"io/fs"
-	"log/slog"
 	"os"
 	"path/filepath"
 	"time"
 
 	"github.com/fsnotify/fsnotify"
 	"github.com/pkg/errors"
+	"go.alanpearce.eu/x/log"
 )
 
 type FileWatcher struct {
-	*fsnotify.Watcher
+	watcher *fsnotify.Watcher
+	log     *log.Logger
 }
 
-func NewFileWatcher() (*FileWatcher, error) {
+func NewFileWatcher(log *log.Logger) (*FileWatcher, error) {
 	watcher, err := fsnotify.NewWatcher()
 	if err != nil {
 		return nil, errors.WithMessage(err, "could not create watcher")
 	}
 
-	return &FileWatcher{watcher}, nil
+	return &FileWatcher{
+		watcher,
+		log,
+	}, nil
 }
 
-func (watcher FileWatcher) AddRecursive(from string) error {
-	slog.Debug(fmt.Sprintf("watching files under %s", from))
+func (i FileWatcher) AddRecursive(from string) error {
+	i.log.Debug(fmt.Sprintf("watching files under %s", from))
 	err := filepath.WalkDir(from, func(path string, entry fs.DirEntry, err error) error {
 		if err != nil {
 			return errors.WithMessagef(err, "could not walk directory %s", path)
 		}
 		if entry.IsDir() {
-			slog.Debug(fmt.Sprintf("adding directory %s to watcher", path))
-			if err = watcher.Add(path); err != nil {
+			i.log.Debug(fmt.Sprintf("adding directory %s to watcher", path))
+			if err = i.watcher.Add(path); err != nil {
 				return errors.WithMessagef(err, "could not add directory %s to watcher", path)
 			}
 		}
@@ -44,18 +48,18 @@ func (watcher FileWatcher) AddRecursive(from string) error {
 	return errors.WithMessage(err, "error walking directory tree")
 }
 
-func (watcher FileWatcher) Start(callback func(string)) {
+func (i FileWatcher) Start(callback func(string)) {
 	for {
 		select {
-		case event := <-watcher.Events:
+		case event := <-i.watcher.Events:
 			if event.Has(fsnotify.Create) || event.Has(fsnotify.Rename) {
 				f, err := os.Stat(event.Name)
 				if err != nil {
-					slog.Error(fmt.Sprintf("error handling %s event: %v", event.Op.String(), err))
+					i.log.Error(fmt.Sprintf("error handling %s event: %v", event.Op.String(), err))
 				} else if f.IsDir() {
-					err = watcher.Add(event.Name)
+					err = i.watcher.Add(event.Name)
 					if err != nil {
-						slog.Error(fmt.Sprintf("error adding new folder to watcher: %v", err))
+						i.log.Error(fmt.Sprintf("error adding new folder to watcher: %v", err))
 					}
 				}
 			}
@@ -63,8 +67,8 @@ func (watcher FileWatcher) Start(callback func(string)) {
 				callback(event.Name)
 				time.Sleep(500 * time.Millisecond)
 			}
-		case err := <-watcher.Errors:
-			slog.Error(fmt.Sprintf("error in watcher: %v", err))
+		case err := <-i.watcher.Errors:
+			i.log.Error(fmt.Sprintf("error in watcher: %v", err))
 		}
 	}
 }
diff --git a/internal/server/error.go b/internal/server/error.go
index d9d6778..1e04bbc 100644
--- a/internal/server/error.go
+++ b/internal/server/error.go
@@ -1,15 +1,16 @@
 package server
 
 import (
-	"log/slog"
 	"net/http"
 
 	"go.alanpearce.eu/searchix/internal/components"
 	"go.alanpearce.eu/searchix/internal/config"
+	"go.alanpearce.eu/x/log"
 )
 
 func createErrorHandler(
 	config *config.Config,
+	log *log.Logger,
 ) func(http.ResponseWriter, *http.Request, string, int) {
 	return func(w http.ResponseWriter, r *http.Request, message string, code int) {
 		var err error
@@ -31,7 +32,7 @@ func createErrorHandler(
 			err = components.ErrorPage(indexData).Render(r.Context(), w)
 		}
 		if err != nil {
-			slog.Error(
+			log.Error(
 				"error rendering error page template",
 				"error",
 				err,
diff --git a/internal/server/logging.go b/internal/server/logging.go
index 372972f..6e2f7c8 100644
--- a/internal/server/logging.go
+++ b/internal/server/logging.go
@@ -1,11 +1,10 @@
 package server
 
 import (
-	"fmt"
-	"io"
 	"net/http"
 
 	"github.com/pkg/errors"
+	"go.alanpearce.eu/x/log"
 )
 
 type LoggingResponseWriter struct {
@@ -42,7 +41,7 @@ func NewLoggingResponseWriter(w http.ResponseWriter) *LoggingResponseWriter {
 
 type wrappedHandlerOptions struct {
 	defaultHostname string
-	logger          io.Writer
+	logger          *log.Logger
 }
 
 func wrapHandlerWithLogging(wrappedHandler http.Handler, opts wrappedHandlerOptions) http.Handler {
@@ -54,13 +53,17 @@ func wrapHandlerWithLogging(wrappedHandler http.Handler, opts wrappedHandlerOpti
 		lw := NewLoggingResponseWriter(w)
 		wrappedHandler.ServeHTTP(lw, r)
 		statusCode := lw.statusCode
-		fmt.Fprintf(
-			opts.logger,
-			"%s %s %d %s %s\n",
+		opts.logger.Info(
+			"http request",
+			"scheme",
 			scheme,
+			"method",
 			r.Method,
+			"code",
 			statusCode,
+			"path",
 			r.URL.Path,
+			"location",
 			lw.Header().Get("Location"),
 		)
 	})
diff --git a/internal/server/mux.go b/internal/server/mux.go
index 16a0150..17445e5 100644
--- a/internal/server/mux.go
+++ b/internal/server/mux.go
@@ -4,12 +4,9 @@ import (
 	"context"
 	"encoding/xml"
 	"fmt"
-	"io"
-	"log/slog"
 	"math"
 	"net/http"
 	"net/url"
-	"os"
 	"path"
 	"strconv"
 	"time"
@@ -19,11 +16,11 @@ import (
 	"go.alanpearce.eu/searchix/internal/config"
 	search "go.alanpearce.eu/searchix/internal/index"
 	"go.alanpearce.eu/searchix/internal/opensearch"
+	"go.alanpearce.eu/x/log"
 
 	sentryhttp "github.com/getsentry/sentry-go/http"
 	"github.com/osdevisnot/sorvor/pkg/livereload"
 	"github.com/pkg/errors"
-	"github.com/shengyanli1982/law"
 )
 
 type HTTPError struct {
@@ -57,6 +54,7 @@ func sortSources(ss map[string]*config.Source) {
 func NewMux(
 	cfg *config.Config,
 	index *search.ReadIndex,
+	log *log.Logger,
 	liveReload bool,
 ) (*http.ServeMux, error) {
 	if cfg == nil {
@@ -70,7 +68,7 @@ func NewMux(
 	})
 	sortSources(cfg.Importer.Sources)
 
-	errorHandler := createErrorHandler(cfg)
+	errorHandler := createErrorHandler(cfg, log)
 
 	top := http.NewServeMux()
 	mux := http.NewServeMux()
@@ -118,7 +116,7 @@ func NewMux(
 
 						return
 					}
-					slog.Error("search error", "error", err)
+					log.Error("search error", "error", err)
 					errorHandler(w, r, err.Error(), http.StatusInternalServerError)
 
 					return
@@ -177,7 +175,7 @@ func NewMux(
 					err = components.ResultsPage(tdata).Render(r.Context(), w)
 				}
 				if err != nil {
-					slog.Error("template error", "template", importerType, "error", err)
+					log.Error("template error", "template", importerType, "error", err)
 					errorHandler(w, r, err.Error(), http.StatusInternalServerError)
 				}
 			} else {
@@ -258,7 +256,7 @@ func NewMux(
 				err = components.DetailPage(tdata.TemplateData, *doc).Render(r.Context(), w)
 			}
 			if err != nil {
-				slog.Error("template error", "template", importerSingular, "error", err)
+				log.Error("template error", "template", importerSingular, "error", err)
 				errorHandler(w, r, err.Error(), http.StatusInternalServerError)
 			}
 		}
@@ -332,7 +330,7 @@ func NewMux(
 		liveReload := livereload.New()
 		liveReload.Start()
 		top.Handle("/livereload", liveReload)
-		fw, err := NewFileWatcher()
+		fw, err := NewFileWatcher(log.Named("watcher"))
 		if err != nil {
 			return nil, errors.WithMessage(err, "could not create file watcher")
 		}
@@ -341,29 +339,23 @@ func NewMux(
 			return nil, errors.WithMessage(err, "could not add directory to file watcher")
 		}
 		go fw.Start(func(filename string) {
-			slog.Debug(fmt.Sprintf("got filename %s", filename))
+			log.Debug(fmt.Sprintf("got filename %s", filename))
 			if match, _ := path.Match("frontend/static/*", filename); match {
 				err := frontend.Rehash()
 				if err != nil {
-					slog.Error("failed to re-hash frontend assets", "error", err)
+					log.Error("failed to re-hash frontend assets", "error", err)
 				}
 			}
 			liveReload.Reload()
 		})
 	}
 
-	var logWriter io.Writer
-	if cfg.Web.Environment == "production" {
-		logWriter = law.NewWriteAsyncer(os.Stdout, nil)
-	} else {
-		logWriter = os.Stdout
-	}
 	top.Handle("/",
 		AddHeadersMiddleware(
 			sentryHandler.Handle(
 				wrapHandlerWithLogging(mux, wrappedHandlerOptions{
 					defaultHostname: cfg.Web.BaseURL.Hostname(),
-					logger:          logWriter,
+					logger:          log,
 				}),
 			),
 			cfg,
diff --git a/internal/server/server.go b/internal/server/server.go
index c3c2a4d..aacef30 100644
--- a/internal/server/server.go
+++ b/internal/server/server.go
@@ -2,7 +2,6 @@ package server
 
 import (
 	"context"
-	"log/slog"
 	"net"
 	"net/http"
 	"strconv"
@@ -10,6 +9,7 @@ import (
 
 	"go.alanpearce.eu/searchix/internal/config"
 	"go.alanpearce.eu/searchix/internal/index"
+	"go.alanpearce.eu/x/log"
 
 	"github.com/pkg/errors"
 	"golang.org/x/net/http2"
@@ -18,18 +18,25 @@ import (
 
 type Server struct {
 	cfg      *config.Config
+	log      *log.Logger
 	server   *http.Server
 	listener net.Listener
 }
 
-func New(conf *config.Config, index *index.ReadIndex, liveReload bool) (*Server, error) {
-	mux, err := NewMux(conf, index, liveReload)
+func New(
+	conf *config.Config,
+	index *index.ReadIndex,
+	log *log.Logger,
+	liveReload bool,
+) (*Server, error) {
+	mux, err := NewMux(conf, index, log, liveReload)
 	if err != nil {
 		return nil, err
 	}
 
 	return &Server{
 		cfg: conf,
+		log: log,
 		server: &http.Server{
 			Handler: http.MaxBytesHandler(
 				h2c.NewHandler(mux, &http2.Server{
@@ -56,7 +63,7 @@ func (s *Server) Start() error {
 	s.listener = l
 
 	if s.cfg.Web.Environment == "development" {
-		slog.Info(
+		s.log.Info(
 			"server listening on",
 			"url",
 			s.cfg.Web.BaseURL.String(),
@@ -71,19 +78,19 @@ func (s *Server) Start() error {
 }
 
 func (s *Server) Stop() chan struct{} {
-	slog.Debug("stop called")
+	s.log.Debug("stop called")
 
 	idleConnsClosed := make(chan struct{})
 
 	go func() {
-		slog.Debug("shutting down server")
+		s.log.Debug("shutting down server")
 		ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
 		defer cancel()
 		err := s.server.Shutdown(ctx)
-		slog.Debug("server shut down")
+		s.log.Debug("server shut down")
 		if err != nil {
 			// Error from closing listeners, or context timeout:
-			slog.Error("error shutting down server", "error", err)
+			s.log.Error("error shutting down server", "error", err)
 		}
 		s.listener.Close()
 		close(idleConnsClosed)