Merge pull request #3930 from Azure/fix-slog

Moved loggers from instance variables back to usage from context

Author: openshift-merge-bot[bot]

admin/server/cmd/server/cmd.go

@@ -16,8 +16,13 @@ package server
 
 import (
 	"fmt"
+	"log/slog"
+	"os"
 
+	"github.com/go-logr/logr"
 	"github.com/spf13/cobra"
+
+	"github.com/Azure/ARO-HCP/internal/utils"
 )
 
 func NewCommand() (*cobra.Command, error) {
@@ -37,11 +42,17 @@ func NewCommand() (*cobra.Command, error) {
 		if err != nil {
 			return err
 		}
-		completed, err := validated.Complete(cmd.Context())
+
+		// Create a logr.Logger and add it to context for use throughout the application
+		handlerOptions := &slog.HandlerOptions{Level: slog.Level(validated.LogVerbosity * -1)}
+		logrLogger := logr.FromSlogHandler(slog.NewJSONHandler(os.Stdout, handlerOptions))
+		ctx := utils.ContextWithLogger(cmd.Context(), logrLogger)
+
+		completed, err := validated.Complete(ctx)
 		if err != nil {
 			return err
 		}
-		return completed.Run(cmd.Context())
+		return completed.Run(ctx)
 	}
 
 	return cmd, nil

admin/server/cmd/server/health.go

@@ -15,54 +15,55 @@
 package server
 
 import (
+	"context"
 	"fmt"
-	"log/slog"
 	"net/http"
 	"strconv"
 	"time"
 
 	"github.com/Azure/ARO-HCP/admin/server/interrupts"
+	"github.com/Azure/ARO-HCP/internal/utils"
 )
 
 // Health keeps a request multiplexer for health liveness and readiness endpoints
 type Health struct {
 	healthMux *http.ServeMux
-	logger    *slog.Logger
 }
 
 // NewHealth creates a new health request multiplexer and starts serving the liveness endpoint
 // on the given port
-func NewHealthOnPort(logger *slog.Logger, port int) *Health {
+func NewHealthOnPort(ctx context.Context, port int) *Health {
+	logger := utils.LoggerFromContext(ctx)
 	healthMux := http.NewServeMux()
 	healthMux.HandleFunc("/healthz", func(w http.ResponseWriter, r *http.Request) {
 		if _, err := fmt.Fprint(w, "OK"); err != nil {
-			logger.Error("failed to write health response", "error", err)
+			logger.Error(err, "failed to write health response")
 		}
 	})
 	server := &http.Server{Addr: ":" + strconv.Itoa(port), Handler: healthMux}
 	interrupts.ListenAndServe(server, 5*time.Second)
 	return &Health{
 		healthMux: healthMux,
-		logger:    logger,
 	}
 }
 
 type ReadinessCheck func() bool
 
 // ServeReady starts serving the readiness endpoint
-func (h *Health) ServeReady(readinessChecks ...ReadinessCheck) {
+func (h *Health) ServeReady(ctx context.Context, readinessChecks ...ReadinessCheck) {
+	logger := utils.LoggerFromContext(ctx)
 	h.healthMux.HandleFunc("/healthz/ready", func(w http.ResponseWriter, r *http.Request) {
 		for _, readinessCheck := range readinessChecks {
 			if !readinessCheck() {
 				w.WriteHeader(http.StatusServiceUnavailable)
 				if _, err := fmt.Fprint(w, "ReadinessCheck failed"); err != nil {
-					h.logger.Error("failed to write health response", "error", err)
+					logger.Error(err, "failed to write health response")
 				}
 				return
 			}
 		}
 		if _, err := fmt.Fprint(w, "OK"); err != nil {
-			h.logger.Error("failed to write health response", "error", err)
+			logger.Error(err, "failed to write health response")
 		}
 	})
 }

admin/server/cmd/server/options.go

@@ -17,7 +17,6 @@ package server
 import (
 	"context"
 	"fmt"
-	"log/slog"
 	"net"
 	"net/http"
 	"os"
@@ -38,10 +37,10 @@ import (
 	"github.com/Azure/ARO-HCP/admin/server/handlers/hcp"
 	"github.com/Azure/ARO-HCP/admin/server/interrupts"
 	"github.com/Azure/ARO-HCP/admin/server/middleware"
-	"github.com/Azure/ARO-HCP/admin/server/pkg/logging"
 	"github.com/Azure/ARO-HCP/internal/database"
 	"github.com/Azure/ARO-HCP/internal/fpa"
 	"github.com/Azure/ARO-HCP/internal/ocm"
+	"github.com/Azure/ARO-HCP/internal/utils"
 )
 
 func DefaultOptions() *RawOptions {
@@ -104,7 +103,6 @@ type completedOptions struct {
 	DbClient               database.DBClient
 	KustoClient            *kusto.Client
 	FpaCredentialRetriever fpa.FirstPartyApplicationTokenCredentialRetriever
-	Logger                 *slog.Logger
 }
 
 type Options struct {
@@ -133,8 +131,6 @@ func (o *RawOptions) Validate() (*ValidatedOptions, error) {
 }
 
 func (o *ValidatedOptions) Complete(ctx context.Context) (*Options, error) {
-	logger := logging.New(o.LogVerbosity)
-
 	// Create CS client
 	csConnection, err := sdk.NewUnauthenticatedConnectionBuilder().
 		URL(o.ClustersServiceURL).
@@ -179,12 +175,12 @@ func (o *ValidatedOptions) Complete(ctx context.Context) (*Options, error) {
 	}
 
 	// Create FPA TokenCredentials with watching and caching
-	certReader, err := fpa.NewWatchingFileCertificateReader(ctx, o.FpaCertBundlePath, 30*time.Minute, logger)
+	certReader, err := fpa.NewWatchingFileCertificateReader(ctx, o.FpaCertBundlePath, 30*time.Minute)
 	if err != nil {
 		return nil, fmt.Errorf("failed to create certificate reader: %w", err)
 	}
 
-	fpaCredentialRetriever, err := fpa.NewFirstPartyApplicationTokenCredentialRetriever(logger, o.FpaClientID, certReader, azcore.ClientOptions{})
+	fpaCredentialRetriever, err := fpa.NewFirstPartyApplicationTokenCredentialRetriever(o.FpaClientID, certReader, azcore.ClientOptions{})
 	if err != nil {
 		return nil, fmt.Errorf("failed to create the FPA token credentials: %w", err)
 	}
@@ -198,16 +194,15 @@ func (o *ValidatedOptions) Complete(ctx context.Context) (*Options, error) {
 			DbClient:               dbClient,
 			KustoClient:            kustoClient,
 			FpaCredentialRetriever: fpaCredentialRetriever,
-			Logger:                 logger,
 		},
 	}, nil
 }
 
 func (opts *Options) Run(ctx context.Context) error {
-	logger := opts.Logger
+	logger := utils.LoggerFromContext(ctx)
 	logger.Info("Reporting health.", "port", opts.HealthPort)
-	health := NewHealthOnPort(logger, opts.HealthPort)
-	health.ServeReady(func() bool {
+	health := NewHealthOnPort(ctx, opts.HealthPort)
+	health.ServeReady(ctx, func() bool {
 		// todo: add real readiness checks
 		return true
 	})
@@ -225,7 +220,7 @@ func (opts *Options) Run(ctx context.Context) error {
 
 	s := http.Server{
 		Addr:    net.JoinHostPort("", strconv.Itoa(opts.Port)),
-		Handler: middleware.WithClientPrincipal(middleware.WithLowercaseURLPathValue(middleware.WithLogger(logger, rootMux))),
+		Handler: middleware.WithClientPrincipal(middleware.WithLowercaseURLPathValue(middleware.WithLogger(ctx, rootMux))),
 	}
 	interrupts.ListenAndServe(&s, 5*time.Second)
 	interrupts.WaitForGracefulShutdown()

admin/server/go.mod

@@ -7,6 +7,7 @@ require (
 	github.com/Azure/azure-kusto-go v0.16.1
 	github.com/Azure/azure-sdk-for-go/sdk/azcore v1.20.0
 	github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/network/armnetwork/v6 v6.2.0
+	github.com/go-logr/logr v1.4.3
 	github.com/openshift-online/ocm-sdk-go v0.1.480
 	github.com/prometheus/client_golang v1.23.2
 	github.com/spf13/cobra v1.10.2
@@ -27,7 +28,6 @@ require (
 	github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc // indirect
 	github.com/evanphx/json-patch v5.9.11+incompatible // indirect
 	github.com/fxamacker/cbor/v2 v2.9.0 // indirect
-	github.com/go-logr/logr v1.4.3 // indirect
 	github.com/go-logr/stdr v1.2.2 // indirect
 	github.com/go-task/slim-sprig/v3 v3.0.0 // indirect
 	github.com/gogo/protobuf v1.3.2 // indirect

admin/server/interrupts/interrupts.go

@@ -17,27 +17,28 @@ package interrupts
 
 import (
 	"context"
-	"log/slog"
 	"net/http"
 	"os"
 	"os/signal"
 	"sync"
 	"syscall"
 	"time"
 
-	"github.com/Azure/ARO-HCP/admin/server/pkg/logging"
+	"github.com/go-logr/logr"
+
+	"github.com/Azure/ARO-HCP/internal/utils"
 )
 
 // only one instance of the manager ever exists
 var single *manager
 
 // logger is a dedicated logger for the interrupts package, separate from the application logger
 // we want this logger to be in place even before main starts running
-var logger *slog.Logger
+var logger logr.Logger
 
 func init() {
 	// Initialize a basic logger for interrupts package only
-	logger = logging.New(0)
+	logger = utils.DefaultLogger()
 
 	m := sync.Mutex{}
 	single = &manager{
@@ -66,7 +67,7 @@ func handleInterrupt() {
 	sigChan := signals()
 	signalsLock.Unlock()
 	s := <-sigChan
-	logger.Info("Received signal.", "signal", s)
+	logger.Info("Received signal", "signal", s)
 	single.c.L.Lock()
 	single.seenSignal = true
 	single.c.Broadcast()
@@ -111,7 +112,7 @@ var gracePeriod = 1 * time.Minute
 // blocking.
 func WaitForGracefulShutdown() {
 	wait(func() {
-		logger.Info("Interrupt received.")
+		logger.Info("Interrupt received")
 	})
 	finished := make(chan struct{})
 	go func() {
@@ -120,9 +121,9 @@ func WaitForGracefulShutdown() {
 	}()
 	select {
 	case <-finished:
-		logger.Info("All workers gracefully terminated, exiting.")
+		logger.Info("All workers gracefully terminated, exiting")
 	case <-time.After(gracePeriod):
-		logger.Info("Timed out waiting for workers to gracefully terminate, exiting.")
+		logger.Info("Timed out waiting for workers to gracefully terminate, exiting")
 	}
 }
 
@@ -174,9 +175,9 @@ func ListenAndServe(server ListenAndServer, gracePeriod time.Duration) {
 		defer single.wg.Done()
 		err := server.ListenAndServe()
 		if err != nil {
-			logger.Error("Server exited.", "error", err)
+			logger.Error(err, "Server exited")
 		} else {
-			logger.Info("Server exited.")
+			logger.Info("Server exited")
 		}
 	}()
 
@@ -193,9 +194,9 @@ func ListenAndServeTLS(server *http.Server, certFile, keyFile string, gracePerio
 		defer single.wg.Done()
 		err := server.ListenAndServeTLS(certFile, keyFile)
 		if err != nil {
-			logger.Error("Server exited.", "error", err)
+			logger.Error(err, "Server exited")
 		} else {
-			logger.Info("Server exited.")
+			logger.Info("Server exited")
 		}
 	}()
 
@@ -213,7 +214,7 @@ func shutdown(server Shutdownable, gracePeriod time.Duration) func() {
 		logger.Info("Server shutting down...")
 		ctx, cancel := context.WithTimeout(context.Background(), gracePeriod)
 		if err := server.Shutdown(ctx); err != nil {
-			logger.Error("Error shutting down server...", "error", err)
+			logger.Error(err, "Error shutting down server")
 		}
 		cancel()
 	}
@@ -233,7 +234,7 @@ func Tick(work func(), interval func() time.Duration) {
 			nextInterval := interval()
 			nextTick := before.Add(nextInterval)
 			sleep := time.Until(nextTick)
-			logger.Debug("Resolved next tick interval.",
+			logger.V(1).Info("Resolved next tick interval",
 				"before", before,
 				"interval", nextInterval,
 				"sleep", sleep,

admin/server/middleware/context.go

@@ -41,7 +41,6 @@ const (
 	contextKeyUrlPathValue         = contextKey("url_path.value")
 	contextKeyHCPResourceID        = contextKey("hcp_resource_id")
 	contextKeyClientPrincipalName  = contextKey("client_principal_name")
-	contextKeyLogger               = contextKey("logger")
 )
 
 func ContextWithOriginalUrlPathValue(ctx context.Context, originalUrlPathValue string) context.Context {

admin/server/middleware/logger.go

@@ -16,28 +16,24 @@ package middleware
 
 import (
 	"context"
-	"log/slog"
 	"net/http"
 	"time"
+
+	"github.com/Azure/ARO-HCP/internal/utils"
 )
 
-// WithLogger creates a middleware that attaches a logger to the request context.
-func WithLogger(logger *slog.Logger, next http.Handler) http.Handler {
+// WithLogger creates a middleware that attaches a request-specific logger to the request context.
+// It expects the provided context to already have a logger via utils.ContextWithLogger.
+func WithLogger(ctx context.Context, next http.Handler) http.Handler {
+	baseLogger := utils.LoggerFromContext(ctx)
 	return http.HandlerFunc(func(writer http.ResponseWriter, request *http.Request) {
 		start := time.Now()
-		requestLogger := logger.With("path", request.URL.Path, "method", request.Method)
+		requestLogger := baseLogger.WithValues("path", request.URL.Path, "method", request.Method)
 		requestLogger.Info("Got request.")
 
-		ctx := context.WithValue(request.Context(), contextKeyLogger, requestLogger)
-		next.ServeHTTP(writer, request.WithContext(ctx))
+		requestCtx := utils.ContextWithLogger(request.Context(), requestLogger)
+		next.ServeHTTP(writer, request.WithContext(requestCtx))
 
 		requestLogger.Info("Completed request.", "duration", time.Since(start).String())
 	})
 }
-
-func LoggerFromContext(ctx context.Context) *slog.Logger {
-	if logger, ok := ctx.Value(contextKeyLogger).(*slog.Logger); ok {
-		return logger
-	}
-	return slog.Default()
-}

internal/fpa/token_credential_retriever.go

@@ -16,7 +16,6 @@ package fpa
 
 import (
 	"fmt"
-	"log/slog"
 
 	"github.com/Azure/azure-sdk-for-go/sdk/azcore"
 	"github.com/Azure/azure-sdk-for-go/sdk/azidentity"
@@ -30,13 +29,11 @@ type firstPartyApplicationTokenCredentialRetriever struct {
 	clientOpts azcore.ClientOptions
 	clientID   string
 	certReader CertificateReader
-	logger     *slog.Logger
 }
 
-func NewFirstPartyApplicationTokenCredentialRetriever(logger *slog.Logger, clientID string, certReader CertificateReader, clientOptions azcore.ClientOptions) (FirstPartyApplicationTokenCredentialRetriever, error) {
+func NewFirstPartyApplicationTokenCredentialRetriever(clientID string, certReader CertificateReader, clientOptions azcore.ClientOptions) (FirstPartyApplicationTokenCredentialRetriever, error) {
 	credentialRetriever := &firstPartyApplicationTokenCredentialRetriever{
 		clientID:   clientID,
-		logger:     logger,
 		certReader: certReader,
 		clientOpts: clientOptions,
 	}

internal/fpa/token_credential_retriever_test.go

@@ -17,8 +17,6 @@ package fpa
 import (
 	"crypto"
 	"crypto/x509"
-	"log/slog"
-	"os"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
@@ -53,7 +51,6 @@ func TestCredentialRetrieverLoadsInitialCertificate(t *testing.T) {
 	}
 
 	retriever, err := NewFirstPartyApplicationTokenCredentialRetriever(
-		slog.New(slog.NewTextHandler(os.Stdout, nil)),
 		"11111111-1111-1111-1111-111111111111",
 		mockReader,
 		azcore.ClientOptions{},