logging: move to zlog throughout

This also does some log print cleanups, like fixing "component" names and using `Stringer(..., val)` in place of `String(..., val.String())` where appropriate. Signed-off-by: Hank Donnay <hdonnay@redhat.com>
quay · Mar 12, 2021 · 9f3d167 · 9f3d167
1 parent 8a2df09
commit 9f3d167
Show file tree

Hide file tree

Showing 21 changed files with 386 additions and 346 deletions.
diff --git a/cmd/clair/main.go b/cmd/clair/main.go
@@ -11,7 +11,9 @@ import (
 	"time"
 
 	_ "github.com/quay/claircore/updater/defaults"
-	"github.com/rs/zerolog"
+	"github.com/quay/zlog"
+	"go.opentelemetry.io/otel/baggage"
+	"go.opentelemetry.io/otel/label"
 	"golang.org/x/sync/errgroup"
 	yaml "gopkg.in/yaml.v3"
 
@@ -59,35 +61,36 @@ func main() {
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 
-	ctx, err = initialize.Logging(ctx, &conf)
-	if err != nil {
+	if err := initialize.Logging(ctx, &conf); err != nil {
 		golog.Fatalf("failed to set up logging: %v", err)
 	}
-	logger := zerolog.Ctx(ctx).With().Str("component", "main").Logger()
-	logger.Info().Str("version", Version).Msg("starting")
+	ctx = baggage.ContextWithValues(ctx, label.String("component", "main"))
+	zlog.Info(ctx).
+		Str("version", Version).
+		Msg("starting")
 
 	// Some machinery for starting and stopping server goroutines
 	down := &Shutdown{}
 	srvs, srvctx := errgroup.WithContext(ctx)
 
 	srvs.Go(func() (_ error) {
-		logger.Info().Msg("launching introspection server")
+		zlog.Info(ctx).Msg("launching introspection server")
 		i, err := introspection.New(ctx, conf, nil)
 		if err != nil {
-			logger.Warn().
+			zlog.Warn(ctx).
 				Err(err).Msg("introspection server configuration failed. continuing anyway")
 			return
 		}
 		down.Add(i.Server)
 		if err := i.ListenAndServe(); err != http.ErrServerClosed {
-			logger.Warn().
+			zlog.Warn(ctx).
 				Err(err).Msg("introspection server failed to launch. continuing anyway")
 		}
 		return
 	})
 
 	srvs.Go(func() error {
-		logger.Info().Msg("launching http transport")
+		zlog.Info(ctx).Msg("launching http transport")
 		srvs, err := initialize.Services(ctx, &conf)
 		if err != nil {
 			return fmt.Errorf("service initialization failed: %w", err)
@@ -105,21 +108,21 @@ func main() {
 
 	c := make(chan os.Signal, 1)
 	signal.Notify(c, os.Interrupt)
-	logger.Info().Msg("registered signal handler")
-	logger.Info().Str("version", Version).Msg("ready")
+	zlog.Info(ctx).Msg("registered signal handler")
+	zlog.Info(ctx).Str("version", Version).Msg("ready")
 	select {
 	case sig := <-c:
-		logger.Info().
-			Str("signal", sig.String()).
+		zlog.Info(ctx).
+			Stringer("signal", sig).
 			Msg("gracefully shutting down")
 		tctx, done := context.WithTimeout(ctx, 10*time.Second)
 		err := down.Shutdown(tctx)
 		done()
 		if err != nil {
-			logger.Error().Err(err).Msg("error shutting down server")
+			zlog.Error(ctx).Err(err).Msg("error shutting down server")
 		}
 	case <-srvctx.Done():
-		logger.Error().Err(srvctx.Err()).Msg("initialization failed")
+		zlog.Error(ctx).Err(srvctx.Err()).Msg("initialization failed")
 		os.Exit(1)
 	}
 }
diff --git a/go.sum b/go.sum
diff --git a/httptransport/affectedmanifesthandler.go b/httptransport/affectedmanifesthandler.go
@@ -5,7 +5,6 @@ import (
 
 	"github.com/quay/claircore"
 	"github.com/quay/claircore/pkg/jsonerr"
-	"github.com/rs/zerolog"
 
 	"github.com/quay/clair/v4/indexer"
 	"github.com/quay/clair/v4/internal/codec"
@@ -14,11 +13,6 @@ import (
 func AffectedManifestHandler(serv indexer.Affected) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		ctx := r.Context()
-		log := zerolog.Ctx(ctx).With().
-			Str("method", "index").
-			Logger()
-		ctx = log.WithContext(ctx)
-
 		if r.Method != http.MethodPost {
 			resp := &jsonerr.Response{
 				Code:    "method-not-allowed",

diff --git a/httptransport/notificationshandler.go b/httptransport/notificationshandler.go
@@ -8,7 +8,9 @@ import (
 
 	"github.com/google/uuid"
 	je "github.com/quay/claircore/pkg/jsonerr"
-	"github.com/rs/zerolog"
+	"github.com/quay/zlog"
+	"go.opentelemetry.io/otel/baggage"
+	"go.opentelemetry.io/otel/label"
 
 	"github.com/quay/clair/v4/internal/codec"
 	"github.com/quay/clair/v4/notifier"
@@ -50,8 +52,9 @@ func (h *NotifHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 }
 
 func (h *NotifHandler) Delete(w http.ResponseWriter, r *http.Request) {
-	ctx := r.Context()
-	log := zerolog.Ctx(ctx)
+	ctx := baggage.ContextWithValues(r.Context(),
+		label.String("component", "httptransport/NotifHander.Delete"),
+	)
 	path := r.URL.Path
 	id := filepath.Base(path)
 	notificationID, err := uuid.Parse(id)
@@ -60,7 +63,7 @@ func (h *NotifHandler) Delete(w http.ResponseWriter, r *http.Request) {
 			Code:    "bad-request",
 			Message: fmt.Sprintf("could not parse notification id: %v", err),
 		}
-		log.Warn().Err(err).Msg("could not parse notification id")
+		zlog.Warn(ctx).Err(err).Msg("could not parse notification id")
 		je.Error(w, resp, http.StatusBadRequest)
 		return
 	}
@@ -71,15 +74,16 @@ func (h *NotifHandler) Delete(w http.ResponseWriter, r *http.Request) {
 			Code:    "internal-server-error",
 			Message: fmt.Sprintf("could not delete notification: %v", err),
 		}
-		log.Warn().Err(err).Msg("could not delete notification")
+		zlog.Warn(ctx).Err(err).Msg("could not delete notification")
 		je.Error(w, resp, http.StatusInternalServerError)
 	}
 }
 
-// NotificaitonsHandler will return paginated notifications to the caller.
+// Get will return paginated notifications to the caller.
 func (h *NotifHandler) Get(w http.ResponseWriter, r *http.Request) {
-	ctx := r.Context()
-	log := zerolog.Ctx(ctx)
+	ctx := baggage.ContextWithValues(r.Context(),
+		label.String("component", "httptransport/NotifHander.Get"),
+	)
 	path := r.URL.Path
 	id := filepath.Base(path)
 	notificationID, err := uuid.Parse(id)
@@ -88,7 +92,7 @@ func (h *NotifHandler) Get(w http.ResponseWriter, r *http.Request) {
 			Code:    "bad-request",
 			Message: fmt.Sprintf("could not parse notification id: %v", err),
 		}
-		log.Warn().Err(err).Msg("could not parse notification id")
+		zlog.Warn(ctx).Err(err).Msg("could not parse notification id")
 		je.Error(w, resp, http.StatusBadRequest)
 		return
 	}

diff --git a/httptransport/server.go b/httptransport/server.go
@@ -5,9 +5,11 @@ import (
 	"net"
 	"net/http"
 
-	"github.com/rs/zerolog"
+	"github.com/quay/zlog"
 	othttp "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
 	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/baggage"
+	"go.opentelemetry.io/otel/label"
 
 	clairerror "github.com/quay/clair/v4/clair-error"
 	"github.com/quay/clair/v4/config"
@@ -52,11 +54,6 @@ type Server struct {
 }
 
 func New(ctx context.Context, conf config.Config, indexer indexer.Service, matcher matcher.Service, notifier notifier.Service) (*Server, error) {
-	log := zerolog.Ctx(ctx).With().
-		Str("component", "init/NewHttpTransport").
-		Logger()
-	ctx = log.WithContext(ctx)
-
 	serv := &http.Server{
 		Addr: conf.HTTPListenAddr,
 		// use the passed in global context as the base context
@@ -73,11 +70,14 @@ func New(ctx context.Context, conf config.Config, indexer indexer.Service, match
 		notifier: notifier,
 		traceOpt: othttp.WithTracerProvider(otel.GetTracerProvider()),
 	}
+	ctx = baggage.ContextWithValues(ctx,
+		label.String("component", "httptransport/New"),
+	)
 
 	if err := t.configureDiscovery(ctx); err != nil {
-		log.Warn().Err(err).Msg("configuring openapi discovery failed")
+		zlog.Warn(ctx).Err(err).Msg("configuring openapi discovery failed")
 	} else {
-		log.Info().Str("path", OpenAPIV1Path).Msg("openapi discovery configured")
+		zlog.Info(ctx).Str("path", OpenAPIV1Path).Msg("openapi discovery configured")
 	}
 
 	var e error
@@ -112,7 +112,9 @@ func New(ctx context.Context, conf config.Config, indexer indexer.Service, match
 	if conf.Auth.Any() {
 		err := t.configureWithAuth(ctx)
 		if err != nil {
-			log.Warn().Err(err).Msg("received error configuring auth middleware")
+			zlog.Warn(ctx).
+				Err(err).
+				Msg("received error configuring auth middleware")
 		}
 	}
 

diff --git a/httptransport/updateoperationhandler.go b/httptransport/updateoperationhandler.go
@@ -9,7 +9,9 @@ import (
 	"github.com/google/uuid"
 	"github.com/quay/claircore/libvuln/driver"
 	je "github.com/quay/claircore/pkg/jsonerr"
-	"github.com/rs/zerolog"
+	"github.com/quay/zlog"
+	"go.opentelemetry.io/otel/baggage"
+	"go.opentelemetry.io/otel/label"
 
 	"github.com/quay/clair/v4/internal/codec"
 	"github.com/quay/clair/v4/matcher"
@@ -56,7 +58,9 @@ func (h *UOHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 // Clients may provide an 'If-None-Match' header with the etag value to receive
 // a StatusNotModified when no new UpdateOperations have been created.
 func (h *UOHandler) Get(w http.ResponseWriter, r *http.Request) {
-	ctx := r.Context()
+	ctx := baggage.ContextWithValues(r.Context(),
+		label.String("component", "httptransport/UOHandler.Get"),
+	)
 	// handle conditional request. this is an optimization
 	if ref, err := h.serv.LatestUpdateOperation(ctx); err == nil {
 		validator := `"` + ref.String() + `"`
@@ -93,8 +97,9 @@ func (h *UOHandler) Get(w http.ResponseWriter, r *http.Request) {
 
 // Delete removes an UpdateOperation models from the system.
 func (h *UOHandler) Delete(w http.ResponseWriter, r *http.Request) {
-	ctx := r.Context()
-	log := zerolog.Ctx(ctx)
+	ctx := baggage.ContextWithValues(r.Context(),
+		label.String("component", "httptransport/UOHandler.Delete"),
+	)
 	path := r.URL.Path
 	id := filepath.Base(path)
 	uuid, err := uuid.Parse(id)
@@ -103,7 +108,7 @@ func (h *UOHandler) Delete(w http.ResponseWriter, r *http.Request) {
 			Code:    "bad-request",
 			Message: fmt.Sprintf("could not deserialize manifest: %v", err),
 		}
-		log.Warn().Err(err).Msg("could not deserialize manifest")
+		zlog.Warn(ctx).Err(err).Msg("could not deserialize manifest")
 		je.Error(w, resp, http.StatusBadRequest)
 		return
 	}

diff --git a/initialize/logging.go b/initialize/logging.go
@@ -5,43 +5,41 @@ import (
 	"os"
 	"strings"
 
+	"github.com/quay/zlog"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
 
 	"github.com/quay/clair/v4/config"
 )
 
-// LogLevel does a string-to-level mapping.
-func LogLevel(level string) zerolog.Level {
-	level = strings.ToLower(level)
-	switch level {
+// Logging configures zlog according to the provided configuration.
+func Logging(ctx context.Context, cfg *config.Config) error {
+	l := zerolog.New(os.Stderr)
+	switch strings.ToLower(cfg.LogLevel) {
 	case "debug-color":
-		// set global logger to use ConsoleWriter for colorized output
-		log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr})
-		return zerolog.DebugLevel
+		// set logger to use ConsoleWriter for colorized output
+		l = l.Level(zerolog.DebugLevel).
+			Output(zerolog.ConsoleWriter{Out: os.Stderr})
 	case "debug":
-		return zerolog.DebugLevel
+		l = l.Level(zerolog.DebugLevel)
 	case "info":
-		return zerolog.InfoLevel
+		l = l.Level(zerolog.InfoLevel)
 	case "warn":
-		return zerolog.WarnLevel
+		l = l.Level(zerolog.WarnLevel)
 	case "error":
-		return zerolog.ErrorLevel
+		l = l.Level(zerolog.ErrorLevel)
 	case "fatal":
-		return zerolog.FatalLevel
+		l = l.Level(zerolog.FatalLevel)
 	case "panic":
-		return zerolog.PanicLevel
+		l = l.Level(zerolog.PanicLevel)
 	default:
-		return zerolog.InfoLevel
+		l = l.Level(zerolog.InfoLevel)
 	}
-}
-
-// Logging configures a logger according to the provided configuration and returns
-// a configured Context.
-func Logging(ctx context.Context, cfg *config.Config) (context.Context, error) {
-	zerolog.SetGlobalLevel(LogLevel(cfg.LogLevel))
-	l := log.With().Timestamp().Logger()
-	ctx = l.WithContext(ctx)
+	l = l.With().
+		Timestamp().
+		Logger()
+	zlog.Set(&l)
+	log.Logger = zerolog.Nop()
 	l.Debug().Str("component", "initialize/Logging").Msg("logging initialized")
-	return ctx, nil
+	return nil
 }
diff --git a/initialize/services.go b/initialize/services.go
@@ -9,7 +9,9 @@ import (
 	"github.com/quay/claircore/libindex"
 	"github.com/quay/claircore/libvuln"
 	"github.com/quay/claircore/libvuln/driver"
-	"github.com/rs/zerolog"
+	"github.com/quay/zlog"
+	"go.opentelemetry.io/otel/baggage"
+	"go.opentelemetry.io/otel/label"
 	"gopkg.in/square/go-jose.v2/jwt"
 
 	clairerror "github.com/quay/clair/v4/clair-error"
@@ -45,9 +47,11 @@ type Srv struct {
 // Services configures the services needed for a given mode according to the
 // provided configuration.
 func Services(ctx context.Context, cfg *config.Config) (*Srv, error) {
-	log := zerolog.Ctx(ctx).With().Str("component", "init/Services").Logger()
-	log.Info().Msg("begin service initialization")
-	defer log.Info().Msg("end service initialization")
+	ctx = baggage.ContextWithValues(ctx,
+		label.String("component", "initialize/Services"),
+	)
+	zlog.Info(ctx).Msg("begin service initialization")
+	defer zlog.Info(ctx).Msg("end service initialization")
 
 	var srv Srv
 	var err error