diff --git a/catalogd/internal/serverutil/serverutil.go b/catalogd/internal/serverutil/serverutil.go index 614da2b8b..1dcaa9282 100644 --- a/catalogd/internal/serverutil/serverutil.go +++ b/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) + }) +} diff --git a/go.mod b/go.mod index f5ce19cca..0fab3290f 100644 --- a/go.mod +++ b/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 diff --git a/internal/resolve/catalog.go b/internal/resolve/catalog.go index ea7cf6e32..31b3d15ec 100644 --- a/internal/resolve/catalog.go +++ b/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 +}