From 3773bb652d17a659efee6b0e0cac03c0217774bf Mon Sep 17 00:00:00 2001 From: Todd Short Date: Thu, 30 Jan 2025 16:43:01 -0500 Subject: [PATCH] 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 --- catalogd/cmd/catalogd/main.go | 4 + catalogd/internal/source/containers_image.go | 13 ++ cmd/operator-controller/main.go | 4 + go.mod | 2 +- internal/catalogmetadata/client/client.go | 3 + internal/httputil/certlog.go | 157 +++++++++++++++++++ internal/httputil/certpoolwatcher.go | 9 +- internal/httputil/certutil.go | 8 +- internal/rukpak/source/containers_image.go | 12 ++ 9 files changed, 204 insertions(+), 8 deletions(-) create mode 100644 internal/httputil/certlog.go diff --git a/catalogd/cmd/catalogd/main.go b/catalogd/cmd/catalogd/main.go index 4904857e99..e8099c44e2 100644 --- a/catalogd/cmd/catalogd/main.go +++ b/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 / 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 --git a/catalogd/internal/source/containers_image.go b/catalogd/internal/source/containers_image.go index 362cc649f3..64520955c2 100644 --- a/catalogd/internal/source/containers_image.go +++ b/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 --git a/cmd/operator-controller/main.go b/cmd/operator-controller/main.go index d9a5443717..1675468008 100644 --- a/cmd/operator-controller/main.go +++ b/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 / 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 --git a/go.mod b/go.mod index eb27d1ed74..8444fdcac4 100644 --- a/go.mod +++ b/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 --git a/internal/catalogmetadata/client/client.go b/internal/catalogmetadata/client/client.go index 7daddaaec6..a8e1387638 100644 --- a/internal/catalogmetadata/client/client.go +++ b/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 --git a/internal/httputil/certlog.go b/internal/httputil/certlog.go new file mode 100644 index 0000000000..beeb3e0555 --- /dev/null +++ b/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 +// : 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 --git a/internal/httputil/certpoolwatcher.go b/internal/httputil/certpoolwatcher.go index 0cce70312d..646c09b000 100644 --- a/internal/httputil/certpoolwatcher.go +++ b/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 --git a/internal/httputil/certutil.go b/internal/httputil/certutil.go index a6cd9f98eb..d6732e7d83 100644 --- a/internal/httputil/certutil.go +++ b/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,6 +44,7 @@ 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! @@ -53,6 +52,5 @@ func NewCertPool(caDir string, log logr.Logger) (*x509.CertPool, error) { return nil, fmt.Errorf("no certificates found in %q", caDir) } - log.Info("first expiration", "time", firstExpiration.Format(time.RFC3339)) return caCertPool, nil } diff --git a/internal/rukpak/source/containers_image.go b/internal/rukpak/source/containers_image.go index 01eb55a8b5..08d353f5b9 100644 --- a/internal/rukpak/source/containers_image.go +++ b/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.