UPSTREAM: <drop>: Add logging to certpoolwatcher and client

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

internal/catalogmetadata/client/client.go

@@ -2,15 +2,18 @@ package client
 
 import (
 	"context"
+	"crypto/tls"
 	"errors"
 	"fmt"
 	"io"
 	"io/fs"
 	"net/http"
 	"net/url"
 
+	"github.com/go-logr/logr"
 	"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"
 
@@ -111,6 +114,17 @@ func (c *Client) PopulateCache(ctx context.Context, catalog *catalogd.ClusterCat
 	return c.cache.Put(catalog.Name, catalog.Status.ResolvedSource.Image.Ref, resp.Body, nil)
 }
 
+func logX509Error(err error, l logr.Logger) {
+	var cvErr *tls.CertificateVerificationError
+	if errors.As(err, &cvErr) {
+		n := 1
+		for _, cert := range cvErr.UnverifiedCertificates {
+			l.Error(err, "unverified cert", "n", n, "subject", cert.Subject, "issuer", cert.Issuer, "DNSNames", cert.DNSNames, "serial", cert.SerialNumber)
+			n = n + 1
+		}
+	}
+}
+
 func (c *Client) doRequest(ctx context.Context, catalog *catalogd.ClusterCatalog) (*http.Response, error) {
 	if catalog.Status.URLs == nil {
 		return nil, fmt.Errorf("error: catalog %q has a nil status.urls value", catalog.Name)
@@ -133,6 +147,7 @@ func (c *Client) doRequest(ctx context.Context, catalog *catalogd.ClusterCatalog
 
 	resp, err := client.Do(req)
 	if err != nil {
+		logX509Error(err, ctrl.Log.WithName("catalog-client"))
 		return nil, fmt.Errorf("error performing request: %v", err)
 	}
 

internal/httputil/certlog.go

@@ -0,0 +1,83 @@
+package httputil
+
+import (
+	"crypto/x509"
+	"encoding/pem"
+	"fmt"
+	"os"
+	"path/filepath"
+
+	"github.com/go-logr/logr"
+)
+
+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.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)
+	data, err := os.ReadFile(filepath)
+	if err != nil {
+		log.Error(err, "error in os.ReadFile()", "file", filename)
+		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.Info(action, args...)
+	}
+}

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.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{

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())
@@ -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
 }