improve logging: catalog http server, op-con resolver (#1564)

Signed-off-by: Joe Lanford <[email protected]>

Author: joelanford

catalogd/internal/serverutil/serverutil.go

@@ -3,10 +3,13 @@ package serverutil
 import (
 	"crypto/tls"
 	"fmt"
+	"io"
 	"net"
 	"net/http"
 	"time"
 
+	"github.com/go-logr/logr"
+	"github.com/gorilla/handlers"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/certwatcher"
 	"sigs.k8s.io/controller-runtime/pkg/manager"
@@ -40,12 +43,16 @@ func AddCatalogServerToManager(mgr ctrl.Manager, cfg CatalogServerConfig, tlsFil
 
 	shutdownTimeout := 30 * time.Second
 
+	l := mgr.GetLogger().WithName("catalogd-http-server")
+	handler := catalogdmetrics.AddMetricsToHandler(cfg.LocalStorage.StorageServerHandler())
+	handler = logrLoggingHandler(l, handler)
+
 	catalogServer := manager.Server{
 		Name:                "catalogs",
 		OnlyServeWhenLeader: true,
 		Server: &http.Server{
 			Addr:        cfg.CatalogAddr,
-			Handler:     catalogdmetrics.AddMetricsToHandler(cfg.LocalStorage.StorageServerHandler()),
+			Handler:     handler,
 			ReadTimeout: 5 * time.Second,
 			// TODO: Revert this to 10 seconds if/when the API
 			// evolves to have significantly smaller responses
@@ -62,3 +69,31 @@ func AddCatalogServerToManager(mgr ctrl.Manager, cfg CatalogServerConfig, tlsFil
 
 	return nil
 }
+
+func logrLoggingHandler(l logr.Logger, handler http.Handler) http.Handler {
+	return handlers.CustomLoggingHandler(nil, handler, func(_ io.Writer, params handlers.LogFormatterParams) {
+		// extract parameters used in apache common log format, but then log using `logr` to remain consistent
+		// with other loggers used in this codebase.
+		username := "-"
+		if params.URL.User != nil {
+			if name := params.URL.User.Username(); name != "" {
+				username = name
+			}
+		}
+
+		host, _, err := net.SplitHostPort(params.Request.RemoteAddr)
+		if err != nil {
+			host = params.Request.RemoteAddr
+		}
+
+		uri := params.Request.RequestURI
+		if params.Request.ProtoMajor == 2 && params.Request.Method == http.MethodConnect {
+			uri = params.Request.Host
+		}
+		if uri == "" {
+			uri = params.URL.RequestURI()
+		}
+
+		l.Info("handled request", "host", host, "username", username, "method", params.Request.Method, "uri", uri, "protocol", params.Request.Proto, "status", params.StatusCode, "size", params.Size)
+	})
+}

go.mod

@@ -13,6 +13,7 @@ require (
 	github.com/go-logr/logr v1.4.2
 	github.com/google/go-cmp v0.6.0
 	github.com/google/go-containerregistry v0.20.3
+	github.com/gorilla/handlers v1.5.2
 	github.com/klauspost/compress v1.17.11
 	github.com/onsi/ginkgo/v2 v2.22.2
 	github.com/onsi/gomega v1.36.2

internal/resolve/catalog.go

@@ -39,6 +39,7 @@ type foundBundle struct {
 
 // Resolve returns a Bundle from a catalog that needs to get installed on the cluster.
 func (r *CatalogResolver) Resolve(ctx context.Context, ext *ocv1.ClusterExtension, installedBundle *ocv1.BundleMetadata) (*declcfg.Bundle, *bsemver.Version, *declcfg.Deprecation, error) {
+	l := log.FromContext(ctx)
 	packageName := ext.Spec.Source.Catalog.PackageName
 	versionRange := ext.Spec.Source.Catalog.Version
 	channels := ext.Spec.Source.Catalog.Channels
@@ -65,6 +66,15 @@ func (r *CatalogResolver) Resolve(ctx context.Context, ext *ocv1.ClusterExtensio
 		}
 	}
 
+	type catStat struct {
+		CatalogName    string `json:"catalogName"`
+		PackageFound   bool   `json:"packageFound"`
+		TotalBundles   int    `json:"totalBundles"`
+		MatchedBundles int    `json:"matchedBundles"`
+	}
+
+	var catStats []*catStat
+
 	resolvedBundles := []foundBundle{}
 	var priorDeprecation *declcfg.Deprecation
 
@@ -76,6 +86,16 @@ func (r *CatalogResolver) Resolve(ctx context.Context, ext *ocv1.ClusterExtensio
 			return fmt.Errorf("error getting package %q from catalog %q: %w", packageName, cat.Name, err)
 		}
 
+		cs := catStat{CatalogName: cat.Name}
+		catStats = append(catStats, &cs)
+
+		if isFBCEmpty(packageFBC) {
+			return nil
+		}
+
+		cs.PackageFound = true
+		cs.TotalBundles = len(packageFBC.Bundles)
+
 		var predicates []filter.Predicate[declcfg.Bundle]
 		if len(channels) > 0 {
 			channelSet := sets.New(channels...)
@@ -99,6 +119,7 @@ func (r *CatalogResolver) Resolve(ctx context.Context, ext *ocv1.ClusterExtensio
 
 		// Apply the predicates to get the candidate bundles
 		packageFBC.Bundles = filter.Filter(packageFBC.Bundles, filter.And(predicates...))
+		cs.MatchedBundles = len(packageFBC.Bundles)
 		if len(packageFBC.Bundles) == 0 {
 			return nil
 		}
@@ -158,6 +179,7 @@ func (r *CatalogResolver) Resolve(ctx context.Context, ext *ocv1.ClusterExtensio
 
 	// Check for ambiguity
 	if len(resolvedBundles) != 1 {
+		l.Info("resolution failed", "stats", catStats)
 		return nil, nil, nil, resolutionError{
 			PackageName:     packageName,
 			Version:         versionRange,
@@ -174,12 +196,15 @@ func (r *CatalogResolver) Resolve(ctx context.Context, ext *ocv1.ClusterExtensio
 
 	// Run validations against the resolved bundle to ensure only valid resolved bundles are being returned
 	// Open Question: Should we grab the first valid bundle earlier?
+	//        Answer: No, that would be a hidden resolution input, which we should avoid at all costs; the query can be
+	//                constrained in order to eliminate the invalid bundle from the resolution.
 	for _, validation := range r.Validations {
 		if err := validation(resolvedBundle); err != nil {
 			return nil, nil, nil, fmt.Errorf("validating bundle %q: %w", resolvedBundle.Name, err)
 		}
 	}
 
+	l.V(4).Info("resolution succeeded", "stats", catStats)
 	return resolvedBundle, resolvedBundleVersion, priorDeprecation, nil
 }
 
@@ -257,6 +282,9 @@ func CatalogWalker(
 			return false
 		})
 
+		availableCatalogNames := mapSlice(catalogs, func(c catalogd.ClusterCatalog) string { return c.Name })
+		l.Info("using ClusterCatalogs for resolution", "catalogs", availableCatalogNames)
+
 		for i := range catalogs {
 			cat := &catalogs[i]
 
@@ -271,3 +299,18 @@ func CatalogWalker(
 		return nil
 	}
 }
+
+func isFBCEmpty(fbc *declcfg.DeclarativeConfig) bool {
+	if fbc == nil {
+		return true
+	}
+	return len(fbc.Packages) == 0 && len(fbc.Channels) == 0 && len(fbc.Bundles) == 0 && len(fbc.Deprecations) == 0 && len(fbc.Others) == 0
+}
+
+func mapSlice[I any, O any](in []I, f func(I) O) []O {
+	out := make([]O, len(in))
+	for i := range in {
+		out[i] = f(in[i])
+	}
+	return out
+}