From 94b21b286edff37496a2fe481963625ac01c30a1 Mon Sep 17 00:00:00 2001 From: Alan Pearce Date: Mon, 1 Jul 2024 22:15:06 +0200 Subject: feat: more structured logging --- internal/server/dev.go | 34 +++++++++++++++++++--------------- internal/server/error.go | 5 +++-- internal/server/logging.go | 15 +++++++++------ internal/server/mux.go | 28 ++++++++++------------------ internal/server/server.go | 23 +++++++++++++++-------- 5 files changed, 56 insertions(+), 49 deletions(-) (limited to 'internal/server') 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) -- cgit 1.4.1