Add logging to certpoolwatcher and client (#1684)

Logging now indicates what certificate (by file and X.509 name) is being watched

When an unverified certificate error is returned to the client, log the cert

Signed-off-by: Todd Short <[email protected]>

Author: tmshort

Diff for: catalogd/cmd/catalogd/main.go

@@ -29,6 +29,7 @@ import (
 
 	"github.com/containers/image/v5/types"
 	"github.com/go-logr/logr"
+	"github.com/sirupsen/logrus"
 	"github.com/spf13/pflag"
 	corev1 "k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/fields"
@@ -120,6 +121,9 @@ func main() {
 	flag.StringVar(&globalPullSecret, "global-pull-secret", "", "The <namespace>/<name> of the global pull secret that is going to be used to pull bundle images.")
 
 	klog.InitFlags(flag.CommandLine)
+	if klog.V(4).Enabled() {
+		logrus.SetLevel(logrus.DebugLevel)
+	}
 
 	// Combine both flagsets and parse them
 	pflag.CommandLine.AddGoFlagSet(flag.CommandLine)

Diff for: catalogd/internal/source/containers_image.go

@@ -23,6 +23,7 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 
 	catalogdv1 "github.com/operator-framework/operator-controller/catalogd/api/v1"
+	"github.com/operator-framework/operator-controller/internal/httputil"
 	fsutil "github.com/operator-framework/operator-controller/internal/util/fs"
 	imageutil "github.com/operator-framework/operator-controller/internal/util/image"
 )
@@ -54,6 +55,18 @@ func (i *ContainersImageRegistry) Unpack(ctx context.Context, catalog *catalogdv
 	if err != nil {
 		return nil, err
 	}
+
+	res, err := i.unpack(ctx, catalog, srcCtx, l)
+	if err != nil {
+		// Log any CertificateVerificationErrors, and log Docker Certificates if necessary
+		if httputil.LogCertificateVerificationError(err, l) {
+			httputil.LogDockerCertificates(srcCtx.DockerCertPath, l)
+		}
+	}
+	return res, err
+}
+
+func (i *ContainersImageRegistry) unpack(ctx context.Context, catalog *catalogdv1.ClusterCatalog, srcCtx *types.SystemContext, l logr.Logger) (*Result, error) {
 	//////////////////////////////////////////////////////
 	//
 	// Resolve a canonical reference for the image.

Diff for: cmd/operator-controller/main.go

@@ -29,6 +29,7 @@ import (
 
 	"github.com/containers/image/v5/types"
 	"github.com/go-logr/logr"
+	"github.com/sirupsen/logrus"
 	"github.com/spf13/pflag"
 	corev1 "k8s.io/api/core/v1"
 	apiextensionsv1client "k8s.io/apiextensions-apiserver/pkg/client/clientset/clientset/typed/apiextensions/v1"
@@ -121,6 +122,9 @@ func main() {
 	flag.StringVar(&globalPullSecret, "global-pull-secret", "", "The <namespace>/<name> of the global pull secret that is going to be used to pull bundle images.")
 
 	klog.InitFlags(flag.CommandLine)
+	if klog.V(4).Enabled() {
+		logrus.SetLevel(logrus.DebugLevel)
+	}
 
 	pflag.CommandLine.AddGoFlagSet(flag.CommandLine)
 	features.OperatorControllerFeatureGate.AddFlag(pflag.CommandLine)

Diff for: go.mod

@@ -22,6 +22,7 @@ require (
 	github.com/operator-framework/helm-operator-plugins v0.8.0
 	github.com/operator-framework/operator-registry v1.50.0
 	github.com/prometheus/client_golang v1.20.5
+	github.com/sirupsen/logrus v1.9.3
 	github.com/spf13/pflag v1.0.6
 	github.com/stretchr/testify v1.10.0
 	golang.org/x/exp v0.0.0-20241009180824-f66d83c29e7c
@@ -195,7 +196,6 @@ require (
 	github.com/sigstore/fulcio v1.6.4 // indirect
 	github.com/sigstore/rekor v1.3.6 // indirect
 	github.com/sigstore/sigstore v1.8.9 // indirect
-	github.com/sirupsen/logrus v1.9.3 // indirect
 	github.com/spf13/cast v1.7.0 // indirect
 	github.com/spf13/cobra v1.8.1 // indirect
 	github.com/stefanberger/go-pkcs11uri v0.0.0-20230803200340-78284954bff6 // indirect

Diff for: internal/catalogmetadata/client/client.go

@@ -11,10 +11,12 @@ import (
 
 	"k8s.io/apimachinery/pkg/api/meta"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	ctrl "sigs.k8s.io/controller-runtime"
 
 	"github.com/operator-framework/operator-registry/alpha/declcfg"
 
 	catalogd "github.com/operator-framework/operator-controller/catalogd/api/v1"
+	"github.com/operator-framework/operator-controller/internal/httputil"
 )
 
 const (
@@ -133,6 +135,7 @@ func (c *Client) doRequest(ctx context.Context, catalog *catalogd.ClusterCatalog
 
 	resp, err := client.Do(req)
 	if err != nil {
+		_ = httputil.LogCertificateVerificationError(err, ctrl.Log.WithName("catalog-client"))
 		return nil, fmt.Errorf("error performing request: %v", err)
 	}
 

Diff for: internal/httputil/certlog.go

@@ -0,0 +1,157 @@
+package httputil
+
+import (
+	"crypto/tls"
+	"crypto/x509"
+	"encoding/pem"
+	"errors"
+	"fmt"
+	"os"
+	"path/filepath"
+
+	"github.com/go-logr/logr"
+)
+
+const (
+	defaultLogLevel = 4
+)
+
+// Log the certificates that would be used for docker pull operations
+// Assumes a /etc/docker/certs.d like path, where the directory contains
+// <hostname>:<port> directories in which a CA certificate (generally
+// named "ca.crt") is located.
+func LogDockerCertificates(path string, log logr.Logger) {
+	// These are the default paths that containers/images looks at for host:port certs
+	// See containers/images: docker/docker_client.go
+	paths := []string{"/etc/docker/certs.d", "/etc/containers/certs.d"}
+	if path != "" {
+		paths = []string{path}
+	}
+	for _, path := range paths {
+		fi, err := os.Stat(path)
+		if err != nil {
+			log.Error(err, "statting directory", "directory", path)
+			continue
+		}
+		if !fi.IsDir() {
+			log.V(defaultLogLevel+1).Info("not a directory", "directory", path)
+			continue
+		}
+		dirEntries, err := os.ReadDir(path)
+		if err != nil {
+			log.Error(err, "reading directory", "directory", path)
+			continue
+		}
+		for _, e := range dirEntries {
+			hostPath := filepath.Join(path, e.Name())
+			fi, err := os.Stat(hostPath)
+			if err != nil {
+				log.Error(err, "dumping certs", "path", hostPath)
+				continue
+			}
+			if !fi.IsDir() {
+				log.V(defaultLogLevel+1).Info("ignoring non-directory", "path", hostPath)
+				continue
+			}
+			logPath(hostPath, "dump docker certs", log)
+		}
+	}
+}
+
+// This function unwraps the given error to find an CertificateVerificationError.
+// It then logs the list of certificates found in the unwrapped error
+// Returns:
+// * true if a CertificateVerificationError is found
+// * false if no CertificateVerificationError is found
+func LogCertificateVerificationError(err error, log logr.Logger) bool {
+	for err != nil {
+		var cvErr *tls.CertificateVerificationError
+		if errors.As(err, &cvErr) {
+			n := 1
+			for _, cert := range cvErr.UnverifiedCertificates {
+				log.Error(err, "unverified cert", "n", n, "subject", cert.Subject, "issuer", cert.Issuer, "DNSNames", cert.DNSNames, "serial", cert.SerialNumber)
+				n = n + 1
+			}
+			return true
+		}
+		err = errors.Unwrap(err)
+	}
+	return false
+}
+
+func logPath(path, action string, log logr.Logger) {
+	fi, err := os.Stat(path)
+	if err != nil {
+		log.Error(err, "error in os.Stat()", "path", path)
+		return
+	}
+	if !fi.IsDir() {
+		logFile(path, "", fmt.Sprintf("%s file", action), log)
+		return
+	}
+	action = fmt.Sprintf("%s directory", action)
+	dirEntries, err := os.ReadDir(path)
+	if err != nil {
+		log.Error(err, "error in os.ReadDir()", "path", path)
+		return
+	}
+	for _, e := range dirEntries {
+		file := filepath.Join(path, e.Name())
+		fi, err := os.Stat(file)
+		if err != nil {
+			log.Error(err, "error in os.Stat()", "file", file)
+			continue
+		}
+		if fi.IsDir() {
+			log.V(defaultLogLevel+1).Info("ignoring subdirectory", "directory", file)
+			continue
+		}
+		logFile(e.Name(), path, action, log)
+	}
+}
+
+func logFile(filename, path, action string, log logr.Logger) {
+	filepath := filepath.Join(path, filename)
+	_, err := os.Stat(filepath)
+	if err != nil {
+		log.Error(err, "statting file", "file", filepath)
+		return
+	}
+	data, err := os.ReadFile(filepath)
+	if err != nil {
+		log.Error(err, "error in os.ReadFile()", "file", filepath)
+		return
+	}
+	logPem(data, filename, path, action, log)
+}
+
+func logPem(data []byte, filename, path, action string, log logr.Logger) {
+	for len(data) > 0 {
+		var block *pem.Block
+		block, data = pem.Decode(data)
+		if block == nil {
+			log.Info("error: no block returned from pem.Decode()", "file", filename)
+			return
+		}
+		crt, err := x509.ParseCertificate(block.Bytes)
+		if err != nil {
+			log.Error(err, "error in x509.ParseCertificate()", "file", filename)
+			return
+		}
+
+		args := []any{}
+		if path != "" {
+			args = append(args, "directory", path)
+		}
+		// Find an appopriate certificate identifier
+		args = append(args, "file", filename)
+		if s := crt.Subject.String(); s != "" {
+			args = append(args, "subject", s)
+		} else if crt.DNSNames != nil {
+			args = append(args, "DNSNames", crt.DNSNames)
+		} else if s := crt.SerialNumber.String(); s != "" {
+			args = append(args, "serial", s)
+		}
+		log.V(defaultLogLevel).Info(action, args...)
+	}
+}

Diff for: internal/httputil/certpoolwatcher.go

@@ -50,8 +50,12 @@ func NewCertPoolWatcher(caDir string, log logr.Logger) (*CertPoolWatcher, error)
 	// If the SSL_CERT_DIR or SSL_CERT_FILE environment variables are
 	// specified, this means that we have some control over the system root
 	// location, thus they may change, thus we should watch those locations.
-	watchPaths := strings.Split(os.Getenv("SSL_CERT_DIR"), ":")
-	watchPaths = append(watchPaths, caDir, os.Getenv("SSL_CERT_FILE"))
+	sslCertDir := os.Getenv("SSL_CERT_DIR")
+	sslCertFile := os.Getenv("SSL_CERT_FILE")
+	log.V(defaultLogLevel).Info("SSL environment", "SSL_CERT_DIR", sslCertDir, "SSL_CERT_FILE", sslCertFile)
+
+	watchPaths := strings.Split(sslCertDir, ":")
+	watchPaths = append(watchPaths, caDir, sslCertFile)
 	watchPaths = slices.DeleteFunc(watchPaths, func(p string) bool {
 		if p == "" {
 			return true
@@ -66,6 +70,7 @@ func NewCertPoolWatcher(caDir string, log logr.Logger) (*CertPoolWatcher, error)
 		if err := watcher.Add(p); err != nil {
 			return nil, err
 		}
+		logPath(p, "watching certificate", log)
 	}
 
 	cpw := &CertPoolWatcher{

Diff for: internal/httputil/certutil.go

@@ -5,7 +5,6 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
-	"time"
 
 	"github.com/go-logr/logr"
 )
@@ -24,7 +23,6 @@ func NewCertPool(caDir string, log logr.Logger) (*x509.CertPool, error) {
 		return nil, err
 	}
 	count := 0
-	firstExpiration := time.Time{}
 
 	for _, e := range dirEntries {
 		file := filepath.Join(caDir, e.Name())
@@ -34,10 +32,10 @@ func NewCertPool(caDir string, log logr.Logger) (*x509.CertPool, error) {
 			return nil, err
 		}
 		if fi.IsDir() {
-			log.Info("skip directory", "name", e.Name())
+			log.V(defaultLogLevel+1).Info("skip directory", "name", e.Name())
 			continue
 		}
-		log.Info("load certificate", "name", e.Name())
+		log.V(defaultLogLevel+1).Info("load certificate", "name", e.Name())
 		data, err := os.ReadFile(file)
 		if err != nil {
 			return nil, fmt.Errorf("error reading cert file %q: %w", file, err)
@@ -46,13 +44,13 @@ func NewCertPool(caDir string, log logr.Logger) (*x509.CertPool, error) {
 		if caCertPool.AppendCertsFromPEM(data) {
 			count++
 		}
+		logPem(data, e.Name(), caDir, "loading certificate file", log)
 	}
 
 	// Found no certs!
 	if count == 0 {
 		return nil, fmt.Errorf("no certificates found in %q", caDir)
 	}
 
-	log.Info("first expiration", "time", firstExpiration.Format(time.RFC3339))
 	return caCertPool, nil
 }

Diff for: internal/rukpak/source/containers_image.go

@@ -20,6 +20,7 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 
+	"github.com/operator-framework/operator-controller/internal/httputil"
 	fsutil "github.com/operator-framework/operator-controller/internal/util/fs"
 	imageutil "github.com/operator-framework/operator-controller/internal/util/image"
 )
@@ -50,6 +51,17 @@ func (i *ContainersImageRegistry) Unpack(ctx context.Context, bundle *BundleSour
 		return nil, err
 	}
 
+	res, err := i.unpack(ctx, bundle, srcCtx, l)
+	if err != nil {
+		// Log any CertificateVerificationErrors, and log Docker Certificates if necessary
+		if httputil.LogCertificateVerificationError(err, l) {
+			httputil.LogDockerCertificates(srcCtx.DockerCertPath, l)
+		}
+	}
+	return res, err
+}
+
+func (i *ContainersImageRegistry) unpack(ctx context.Context, bundle *BundleSource, srcCtx *types.SystemContext, l logr.Logger) (*Result, error) {
 	//////////////////////////////////////////////////////
 	//
 	// Resolve a canonical reference for the image.