fix: log messages and levels (includes perf optimization) (#1119)

* fix: log messages and levels

* review and optims

* use http.StatusText

* Apply suggestions from code review

Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
Signed-off-by: Kévin Dunglas <kevin@dunglas.fr>

* fix

* cleanup

* refactor

* Update subscription.go

Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
Signed-off-by: Kévin Dunglas <kevin@dunglas.fr>

---------

Signed-off-by: Kévin Dunglas <kevin@dunglas.fr>
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>

Author: dunglas

authorization.go

@@ -194,5 +194,8 @@ func canDispatch(s *TopicSelectorStore, topics, topicSelectors []string) bool {
 func (h *Hub) httpAuthorizationError(w http.ResponseWriter, r *http.Request, err error) {
 	http.Error(w, http.StatusText(http.StatusUnauthorized), http.StatusUnauthorized)
 
-	h.logger.DebugContext(r.Context(), "Topic selectors not matched, not provided or authorization error", slog.Any("error", err))
+	ctx := r.Context()
+	if h.logger.Enabled(ctx, slog.LevelDebug) {
+		h.logger.LogAttrs(ctx, slog.LevelDebug, "Topic selectors not matched, not provided or authorization error", slog.Any("error", err))
+	}
 }

bolt.go

@@ -225,7 +225,10 @@ func (t *BoltTransport) dispatchHistory(ctx context.Context, s *LocalSubscriber,
 				s.HistoryDispatched(responseLastEventID)
 
 				err := fmt.Errorf("unable to unmarshal update: %w", err)
-				t.logger.ErrorContext(ctx, "Unable to unmarshal update coming from the Bolt DB", slog.Any("update", update), slog.Any("error", err))
+
+				if t.logger.Enabled(ctx, slog.LevelError) {
+					t.logger.LogAttrs(ctx, slog.LevelError, "Unable to unmarshal update coming from the Bolt DB", slog.Any("update", update), slog.Any("error", err))
+				}
 
 				return err
 			}
@@ -240,7 +243,9 @@ func (t *BoltTransport) dispatchHistory(ctx context.Context, s *LocalSubscriber,
 		s.HistoryDispatched(responseLastEventID)
 
 		if !afterFromID {
-			t.logger.InfoContext(ctx, "Can't find requested LastEventID")
+			if t.logger.Enabled(ctx, slog.LevelInfo) {
+				t.logger.LogAttrs(ctx, slog.LevelInfo, "Can't find requested LastEventID")
+			}
 		}
 
 		return nil

config_deprecated.go

@@ -274,11 +274,13 @@ func Start() {
 		log.Fatalln(err)
 	}
 
+	ctx := context.Background()
+
 	defer func() {
-		if err := h.transport.Close(context.Background()); err != nil {
+		if err := h.transport.Close(ctx); err != nil {
 			log.Fatalln(err)
 		}
 	}()
 
-	h.Serve()
+	h.Serve(ctx)
 }

demo.go

@@ -10,7 +10,7 @@ import (
 	"time"
 )
 
-const linkSuffix = `>; rel="mercure"`
+const hubLink = "<" + defaultHubURL + `>; rel="mercure"`
 
 // uiContent is our static web server content.
 //
@@ -24,26 +24,24 @@ var uiContent embed.FS
 func (h *Hub) Demo(w http.ResponseWriter, r *http.Request) {
 	// JSON-LD is the preferred format
 	_ = mime.AddExtensionType(".jsonld", "application/ld+json")
-
 	url := r.URL.String()
 	mimeType := mime.TypeByExtension(filepath.Ext(r.URL.Path))
 
 	query := r.URL.Query()
 	body := query.Get("body")
 	jwt := query.Get("jwt")
 
-	hubLink := "<" + defaultHubURL + linkSuffix
-	if h.cookieName != defaultCookieName {
-		hubLink = hubLink + `; cookie-name="` + h.cookieName + `"`
-	}
-
-	header := w.Header()
 	// Several Link headers are set on purpose to allow testing advanced discovery mechanism
-	header.Add("Link", hubLink)
-	header.Add("Link", "<"+url+`>; rel="self"`)
+	header := w.Header()
+
+	if h.cookieName == defaultCookieName {
+		header["Link"] = append(header["Link"], hubLink, "<"+url+`>; rel="self"`)
+	} else {
+		header["Link"] = append(header["Link"], hubLink+`; cookie-name="`+h.cookieName+`"`, "<"+url+`>; rel="self"`)
+	}
 
 	if mimeType != "" {
-		header.Set("Content-Type", mimeType)
+		header["Content-Type"] = []string{mimeType}
 	}
 
 	cookie := &http.Cookie{
@@ -61,6 +59,10 @@ func (h *Hub) Demo(w http.ResponseWriter, r *http.Request) {
 	http.SetCookie(w, cookie)
 
 	if _, err := io.WriteString(w, body); err != nil {
-		h.logger.InfoContext(r.Context(), "Failed to write demo response", slog.Any("error", err))
+		ctx := r.Context()
+
+		if h.logger.Enabled(ctx, slog.LevelInfo) {
+			h.logger.LogAttrs(ctx, slog.LevelInfo, "Failed to write demo response", slog.Any("error", err))
+		}
 	}
 }

demo_test.go

@@ -21,7 +21,7 @@ func TestEmptyBodyAndJWT(t *testing.T) {
 
 	resp := w.Result()
 	assert.Equal(t, "application/ld+json", resp.Header.Get("Content-Type"))
-	assert.Equal(t, []string{"<" + defaultHubURL + linkSuffix, "<https://example.com/demo/foo.jsonld>; rel=\"self\""}, resp.Header["Link"])
+	assert.Equal(t, []string{hubLink, `<https://example.com/demo/foo.jsonld>; rel="self"`}, resp.Header["Link"])
 
 	cookie := resp.Cookies()[0]
 	assert.Equal(t, "mercureAuthorization", cookie.Name)
@@ -47,7 +47,7 @@ func TestBodyAndJWT(t *testing.T) {
 
 	resp := w.Result()
 	assert.Contains(t, resp.Header.Get("Content-Type"), "xml") // Before Go 1.17, the charset wasn't set
-	assert.Equal(t, []string{"<" + defaultHubURL + linkSuffix, "<https://example.com/demo/foo/bar.xml?body=<hello/>&jwt=token>; rel=\"self\""}, resp.Header["Link"])
+	assert.Equal(t, []string{hubLink, `<https://example.com/demo/foo/bar.xml?body=<hello/>&jwt=token>; rel="self"`}, resp.Header["Link"])
 
 	cookie := resp.Cookies()[0]
 	assert.Equal(t, "mercureAuthorization", cookie.Name)

handler.go

@@ -3,6 +3,7 @@ package mercure
 import (
 	"context"
 	"io/fs"
+	"log/slog"
 	"net/http"
 
 	"github.com/gorilla/mux"
@@ -83,7 +84,9 @@ func (h *Hub) registerSubscriptionHandlers(ctx context.Context, r *mux.Router) {
 	}
 
 	if _, ok := h.transport.(TransportSubscribers); !ok {
-		h.logger.ErrorContext(ctx, "The current transport doesn't support subscriptions. Subscription API disabled.")
+		if h.logger.Enabled(ctx, slog.LevelError) {
+			h.logger.LogAttrs(ctx, slog.LevelError, "The current transport doesn't support subscriptions. Subscription API disabled.")
+		}
 
 		return
 	}

handler_deprecated.go

@@ -22,12 +22,12 @@ import (
 // Serve starts the HTTP server.
 //
 // Deprecated: use the Caddy server module or the standalone library instead.
-func (h *Hub) Serve() { //nolint:funlen
+func (h *Hub) Serve(ctx context.Context) { //nolint:funlen
 	addr := h.config.GetString("addr")
 
 	h.server = &http.Server{
 		Addr:              addr,
-		Handler:           h.baseHandler(),
+		Handler:           h.baseHandler(ctx),
 		ReadTimeout:       h.config.GetDuration("read_timeout"),
 		ReadHeaderTimeout: h.config.GetDuration("read_header_timeout"),
 		WriteTimeout:      h.config.GetDuration("write_timeout"),
@@ -44,22 +44,30 @@ func (h *Hub) Serve() { //nolint:funlen
 			WriteTimeout:      h.config.GetDuration("write_timeout"),
 		}
 
-		h.logger.Info("Mercure metrics started", slog.String("addr", addr))
+		if h.logger.Enabled(ctx, slog.LevelInfo) {
+			h.logger.LogAttrs(ctx, slog.LevelInfo, "Mercure metrics started", slog.String("addr", addr))
+		}
 
-		go h.metricsServer.ListenAndServe()
+		go func() {
+			if err := h.metricsServer.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) && h.logger.Enabled(ctx, slog.LevelError) { //nolint:gosec
+				h.logger.LogAttrs(ctx, slog.LevelError, "Mercure metrics server error", slog.Any("error", err))
+			}
+		}()
 	}
 
 	acme := len(h.allowedHosts) > 0
 
 	certFile := h.config.GetString("cert_file")
 	keyFile := h.config.GetString("key_file")
 
-	done := h.listenShutdown()
+	done := h.listenShutdown(ctx)
 
 	var err error
 
 	if !acme && certFile == "" && keyFile == "" { //nolint:nestif
-		h.logger.Info("Mercure started", slog.String("protocol", "http"), slog.String("addr", addr))
+		if h.logger.Enabled(ctx, slog.LevelInfo) {
+			h.logger.LogAttrs(ctx, slog.LevelInfo, "Mercure started", slog.String("protocol", "http"), slog.String("addr", addr))
+		}
 
 		err = h.server.ListenAndServe()
 	} else {
@@ -78,23 +86,30 @@ func (h *Hub) Serve() { //nolint:funlen
 			h.server.TLSConfig = certManager.TLSConfig()
 
 			// Mandatory for Let's Encrypt http-01 challenge
-			go http.ListenAndServe(h.config.GetString("acme_http01_addr"), certManager.HTTPHandler(nil)) //nolint:gosec
+			go func() {
+				//nolint:gosec
+				if err := http.ListenAndServe(h.config.GetString("acme_http01_addr"), certManager.HTTPHandler(nil)); err != nil && !errors.Is(err, http.ErrServerClosed) && h.logger.Enabled(ctx, slog.LevelError) {
+					h.logger.LogAttrs(ctx, slog.LevelError, "Error running HTTP endpoint", slog.Any("error", err))
+				}
+			}()
 		}
 
-		h.logger.Info("Mercure started", slog.String("protocol", "https"), slog.String("addr", addr))
+		if h.logger.Enabled(ctx, slog.LevelInfo) {
+			h.logger.LogAttrs(ctx, slog.LevelInfo, "Mercure started", slog.String("protocol", "https"), slog.String("addr", addr))
+		}
 
 		err = h.server.ListenAndServeTLS(certFile, keyFile)
 	}
 
-	if !errors.Is(err, http.ErrServerClosed) {
-		h.logger.Error("Unexpected error", slog.Any("error", err))
+	if !errors.Is(err, http.ErrServerClosed) && h.logger.Enabled(ctx, slog.LevelError) {
+		h.logger.LogAttrs(ctx, slog.LevelError, "Unexpected error", slog.Any("error", err))
 	}
 
 	<-done
 }
 
 // Deprecated: use the Caddy server module or the standalone library instead.
-func (h *Hub) listenShutdown() <-chan struct{} {
+func (h *Hub) listenShutdown(ctx context.Context) <-chan struct{} {
 	idleConnsClosed := make(chan struct{})
 
 	h.server.RegisterOnShutdown(func() {
@@ -110,17 +125,19 @@ func (h *Hub) listenShutdown() <-chan struct{} {
 		signal.Notify(sigint, os.Interrupt)
 		<-sigint
 
-		if err := h.server.Shutdown(context.Background()); err != nil {
-			h.logger.Error("Unexpected error during server shutdown", slog.Any("error", err))
+		if err := h.server.Shutdown(ctx); err != nil && h.logger.Enabled(ctx, slog.LevelError) {
+			h.logger.LogAttrs(ctx, slog.LevelError, "Unexpected error during server shutdown", slog.Any("error", err))
 		}
 
 		if h.metricsServer != nil {
-			if err := h.metricsServer.Shutdown(context.Background()); err != nil {
-				h.logger.Error("Unexpected error during metrics server shutdown", slog.Any("error", err))
+			if err := h.metricsServer.Shutdown(ctx); err != nil && h.logger.Enabled(ctx, slog.LevelError) {
+				h.logger.LogAttrs(ctx, slog.LevelError, "Unexpected error during metrics server shutdown", slog.Any("error", err))
 			}
 		}
 
-		h.logger.Info("My Baby Shot Me Down")
+		if h.logger.Enabled(ctx, slog.LevelInfo) {
+			h.logger.LogAttrs(ctx, slog.LevelInfo, "My Baby Shot Me Down")
+		}
 
 		select {
 		case <-idleConnsClosed:
@@ -135,9 +152,9 @@ func (h *Hub) listenShutdown() <-chan struct{} {
 // chainHandlers configures and chains handlers.
 //
 // Deprecated: use the Caddy server module or the standalone library instead.
-func (h *Hub) chainHandlers() http.Handler { //nolint:funlen
+func (h *Hub) chainHandlers(ctx context.Context) http.Handler { //nolint:funlen
 	r := mux.NewRouter()
-	h.registerSubscriptionHandlers(context.Background(), r)
+	h.registerSubscriptionHandlers(ctx, r)
 
 	r.HandleFunc(defaultHubURL, h.SubscribeHandler).Methods(http.MethodGet, http.MethodHead)
 	r.HandleFunc(defaultHubURL, h.PublishHandler).Methods(http.MethodPost)
@@ -200,7 +217,7 @@ func (h *Hub) chainHandlers() http.Handler { //nolint:funlen
 
 	var loggingHandler http.Handler
 
-	if h.logger.Enabled(context.Background(), slog.LevelError) {
+	if h.logger.Enabled(ctx, slog.LevelError) {
 		loggingHandler = handlers.CombinedLoggingHandler(os.Stderr, secureHandler)
 	} else {
 		loggingHandler = secureHandler
@@ -215,15 +232,15 @@ func (h *Hub) chainHandlers() http.Handler { //nolint:funlen
 }
 
 // Deprecated: use the Caddy server module or the standalone library instead.
-func (h *Hub) baseHandler() http.Handler {
+func (h *Hub) baseHandler(ctx context.Context) http.Handler {
 	mainRouter := mux.NewRouter()
 	mainRouter.UseEncodedPath()
 	mainRouter.SkipClean(true)
 
 	// Register /healthz (if enabled, in a way that doesn't pollute the HTTP logs).
 	registerHealthz(mainRouter)
 
-	handler := h.chainHandlers()
+	handler := h.chainHandlers(ctx)
 	mainRouter.PathPrefix("/").Handler(handler)
 
 	return mainRouter

localsubscriber.go

@@ -117,7 +117,9 @@ func (s *LocalSubscriber) Disconnect() {
 func (s *LocalSubscriber) handleFullChan(ctx context.Context) {
 	s.doDisconnect()
 
-	s.logger.ErrorContext(ctx, "Subscriber unable to receive updates fast enough")
+	if s.logger.Enabled(ctx, slog.LevelInfo) {
+		s.logger.LogAttrs(ctx, slog.LevelInfo, "Subscriber unable to receive updates fast enough")
+	}
 }
 
 func (s *LocalSubscriber) doDisconnect() {