Skip to content

Commit e2eb1f2

Browse files
committed
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]>
1 parent 9b08aea commit e2eb1f2

File tree

9 files changed

+208
-8
lines changed

9 files changed

+208
-8
lines changed

catalogd/cmd/catalogd/main.go

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@ import (
2929

3030
"github.com/containers/image/v5/types"
3131
"github.com/go-logr/logr"
32+
"github.com/sirupsen/logrus"
3233
"github.com/spf13/pflag"
3334
corev1 "k8s.io/api/core/v1"
3435
"k8s.io/apimachinery/pkg/fields"
@@ -120,6 +121,7 @@ func main() {
120121
flag.StringVar(&globalPullSecret, "global-pull-secret", "", "The <namespace>/<name> of the global pull secret that is going to be used to pull bundle images.")
121122

122123
klog.InitFlags(flag.CommandLine)
124+
logrus.SetLevel(logrus.DebugLevel)
123125

124126
// Combine both flagsets and parse them
125127
pflag.CommandLine.AddGoFlagSet(flag.CommandLine)

catalogd/internal/controllers/core/clustercatalog_controller.go

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,7 @@ import (
4040
catalogdv1 "github.com/operator-framework/operator-controller/catalogd/api/v1"
4141
"github.com/operator-framework/operator-controller/catalogd/internal/source"
4242
"github.com/operator-framework/operator-controller/catalogd/internal/storage"
43+
"github.com/operator-framework/operator-controller/internal/httputil"
4344
)
4445

4546
const (
@@ -229,6 +230,20 @@ func (r *ClusterCatalogReconciler) reconcile(ctx context.Context, catalog *catal
229230

230231
unpackResult, err := r.Unpacker.Unpack(ctx, catalog)
231232
if err != nil {
233+
// Log any CertificateVerificationErrors, and log Docker Certificates if necessary
234+
l := ctrl.Log.WithName("catalogd-unpacker")
235+
if httputil.LogCertificateVerificationError(err, l) {
236+
if cir, ok := r.Unpacker.(*source.ContainersImageRegistry); ok {
237+
src, srcErr := cir.SourceContextFunc(l)
238+
if srcErr == nil {
239+
httputil.LogDockerCertificates(src.DockerCertPath, l)
240+
} else {
241+
l.Error(srcErr, "unable to determine DockerCertPath")
242+
}
243+
} else {
244+
l.Info("error: unable to determine DockerCertPath")
245+
}
246+
}
232247
unpackErr := fmt.Errorf("source catalog content: %w", err)
233248
updateStatusProgressing(&catalog.Status, catalog.GetGeneration(), unpackErr)
234249
return ctrl.Result{}, unpackErr

cmd/operator-controller/main.go

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@ import (
2929

3030
"github.com/containers/image/v5/types"
3131
"github.com/go-logr/logr"
32+
"github.com/sirupsen/logrus"
3233
"github.com/spf13/pflag"
3334
corev1 "k8s.io/api/core/v1"
3435
apiextensionsv1client "k8s.io/apiextensions-apiserver/pkg/client/clientset/clientset/typed/apiextensions/v1"
@@ -121,6 +122,7 @@ func main() {
121122
flag.StringVar(&globalPullSecret, "global-pull-secret", "", "The <namespace>/<name> of the global pull secret that is going to be used to pull bundle images.")
122123

123124
klog.InitFlags(flag.CommandLine)
125+
logrus.SetLevel(logrus.DebugLevel)
124126

125127
pflag.CommandLine.AddGoFlagSet(flag.CommandLine)
126128
features.OperatorControllerFeatureGate.AddFlag(pflag.CommandLine)

go.mod

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ require (
2222
github.com/operator-framework/helm-operator-plugins v0.8.0
2323
github.com/operator-framework/operator-registry v1.50.0
2424
github.com/prometheus/client_golang v1.20.5
25+
github.com/sirupsen/logrus v1.9.3
2526
github.com/spf13/pflag v1.0.6
2627
github.com/stretchr/testify v1.10.0
2728
golang.org/x/exp v0.0.0-20241009180824-f66d83c29e7c
@@ -194,7 +195,6 @@ require (
194195
github.com/sigstore/fulcio v1.6.4 // indirect
195196
github.com/sigstore/rekor v1.3.6 // indirect
196197
github.com/sigstore/sigstore v1.8.9 // indirect
197-
github.com/sirupsen/logrus v1.9.3 // indirect
198198
github.com/spf13/cast v1.7.0 // indirect
199199
github.com/spf13/cobra v1.8.1 // indirect
200200
github.com/stefanberger/go-pkcs11uri v0.0.0-20230803200340-78284954bff6 // indirect

internal/catalogmetadata/client/client.go

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,10 +11,12 @@ import (
1111

1212
"k8s.io/apimachinery/pkg/api/meta"
1313
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
14+
ctrl "sigs.k8s.io/controller-runtime"
1415

1516
"github.com/operator-framework/operator-registry/alpha/declcfg"
1617

1718
catalogd "github.com/operator-framework/operator-controller/catalogd/api/v1"
19+
"github.com/operator-framework/operator-controller/internal/httputil"
1820
)
1921

2022
const (
@@ -133,6 +135,7 @@ func (c *Client) doRequest(ctx context.Context, catalog *catalogd.ClusterCatalog
133135

134136
resp, err := client.Do(req)
135137
if err != nil {
138+
_ = httputil.LogCertificateVerificationError(err, ctrl.Log.WithName("catalog-client"))
136139
return nil, fmt.Errorf("error performing request: %v", err)
137140
}
138141

internal/controllers/clusterextension_controller.go

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -53,8 +53,10 @@ import (
5353
"github.com/operator-framework/operator-controller/internal/bundleutil"
5454
"github.com/operator-framework/operator-controller/internal/conditionsets"
5555
"github.com/operator-framework/operator-controller/internal/contentmanager"
56+
"github.com/operator-framework/operator-controller/internal/httputil"
5657
"github.com/operator-framework/operator-controller/internal/labels"
5758
"github.com/operator-framework/operator-controller/internal/resolve"
59+
"github.com/operator-framework/operator-controller/internal/rukpak/source"
5860
rukpaksource "github.com/operator-framework/operator-controller/internal/rukpak/source"
5961
)
6062

@@ -259,6 +261,20 @@ func (r *ClusterExtensionReconciler) reconcile(ctx context.Context, ext *ocv1.Cl
259261
// and will be removing the .status.resolution field from the ClusterExtension status API
260262
setStatusProgressing(ext, wrapErrorWithResolutionInfo(resolvedBundleMetadata, err))
261263
setInstalledStatusFromBundle(ext, installedBundle)
264+
// Log any CertificateVerificationErrors, and log Docker Certificates if necessary
265+
l := ctrl.Log.WithName("operator-controller-unpacker")
266+
if httputil.LogCertificateVerificationError(err, l) {
267+
if cir, ok := r.Unpacker.(*source.ContainersImageRegistry); ok {
268+
src, srcErr := cir.SourceContextFunc(l)
269+
if srcErr == nil {
270+
httputil.LogDockerCertificates(src.DockerCertPath, l)
271+
} else {
272+
l.Error(srcErr, "unable to determine DockerCertPath")
273+
}
274+
} else {
275+
l.Info("error: unable to determine DockerCertPath")
276+
}
277+
}
262278
return ctrl.Result{}, err
263279
}
264280

internal/httputil/certlog.go

Lines changed: 159 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,159 @@
1+
package httputil
2+
3+
import (
4+
"crypto/tls"
5+
"crypto/x509"
6+
"encoding/pem"
7+
"errors"
8+
"fmt"
9+
"os"
10+
"path/filepath"
11+
12+
"github.com/go-logr/logr"
13+
)
14+
15+
const (
16+
defaultLogLevel = 0 // 4
17+
)
18+
19+
// Log the certificates that would be used for docker pull operations
20+
// Assumes a /etc/docker/certs.d like path, where the directory contains
21+
// <hostname>:<port> directories in which a CA certificate (generally
22+
// named "ca.crt") is located.
23+
func LogDockerCertificates(path string, log logr.Logger) {
24+
var paths []string
25+
if path == "" {
26+
paths = []string{"/etc/docker/certs.d", "/etc/containers/certs.d"}
27+
} else {
28+
paths = []string{path}
29+
}
30+
for _, path := range paths {
31+
fi, err := os.Stat(path)
32+
if err != nil {
33+
log.Error(err, "statting directory", "directory", path)
34+
continue
35+
}
36+
if !fi.IsDir() {
37+
log.V(defaultLogLevel).V(1).Info("not a directory", "directory", path)
38+
continue
39+
}
40+
dirEntries, err := os.ReadDir(path)
41+
if err != nil {
42+
log.Error(err, "reading directory", "directory", path)
43+
continue
44+
}
45+
count := 0
46+
for _, e := range dirEntries {
47+
hostPath := filepath.Join(path, e.Name())
48+
fi, err := os.Stat(hostPath)
49+
count++
50+
if err != nil {
51+
log.Error(err, "dumping certs", "path", hostPath)
52+
continue
53+
}
54+
if !fi.IsDir() {
55+
log.V(defaultLogLevel).V(1).Info("ignoring non-directory", "path", hostPath)
56+
continue
57+
}
58+
logPath(hostPath, "dump docker certs", log)
59+
}
60+
}
61+
}
62+
63+
// This function unwraps the given error to find an CertificateVerificationError.
64+
// It then logs the list of certificates found in the unwrapped error
65+
// Returns:
66+
// * true if a CertificateVerificationError is found
67+
// * false if no CertificateVerificationError is found
68+
func LogCertificateVerificationError(err error, log logr.Logger) bool {
69+
for err != nil {
70+
var cvErr *tls.CertificateVerificationError
71+
if errors.As(err, &cvErr) {
72+
n := 1
73+
for _, cert := range cvErr.UnverifiedCertificates {
74+
log.Error(err, "unverified cert", "n", n, "subject", cert.Subject, "issuer", cert.Issuer, "DNSNames", cert.DNSNames, "serial", cert.SerialNumber)
75+
n = n + 1
76+
}
77+
return true
78+
}
79+
err = errors.Unwrap(err)
80+
}
81+
return false
82+
}
83+
84+
func logPath(path, action string, log logr.Logger) {
85+
fi, err := os.Stat(path)
86+
if err != nil {
87+
log.Error(err, "error in os.Stat()", "path", path)
88+
return
89+
}
90+
if !fi.IsDir() {
91+
logFile(path, "", fmt.Sprintf("%s file", action), log)
92+
return
93+
}
94+
action = fmt.Sprintf("%s directory", action)
95+
dirEntries, err := os.ReadDir(path)
96+
if err != nil {
97+
log.Error(err, "error in os.ReadDir()", "path", path)
98+
return
99+
}
100+
for _, e := range dirEntries {
101+
file := filepath.Join(path, e.Name())
102+
fi, err := os.Stat(file)
103+
if err != nil {
104+
log.Error(err, "error in os.Stat()", "file", file)
105+
continue
106+
}
107+
if fi.IsDir() {
108+
log.V(defaultLogLevel).V(1).Info("ignoring subdirectory", "directory", file)
109+
continue
110+
}
111+
logFile(e.Name(), path, action, log)
112+
}
113+
}
114+
115+
func logFile(filename, path, action string, log logr.Logger) {
116+
filepath := filepath.Join(path, filename)
117+
_, err := os.Stat(filepath)
118+
if err != nil {
119+
log.Error(err, "statting file", "file", filepath)
120+
return
121+
}
122+
data, err := os.ReadFile(filepath)
123+
if err != nil {
124+
log.Error(err, "error in os.ReadFile()", "file", filepath)
125+
return
126+
}
127+
logPem(data, filename, path, action, log)
128+
}
129+
130+
func logPem(data []byte, filename, path, action string, log logr.Logger) {
131+
for len(data) > 0 {
132+
var block *pem.Block
133+
block, data = pem.Decode(data)
134+
if block == nil {
135+
log.Info("error: no block returned from pem.Decode()", "file", filename)
136+
return
137+
}
138+
crt, err := x509.ParseCertificate(block.Bytes)
139+
if err != nil {
140+
log.Error(err, "error in x509.ParseCertificate()", "file", filename)
141+
return
142+
}
143+
144+
args := []any{}
145+
if path != "" {
146+
args = append(args, "directory", path)
147+
}
148+
// Find an appopriate certificate identifier
149+
args = append(args, "file", filename)
150+
if s := crt.Subject.String(); s != "" {
151+
args = append(args, "subject", s)
152+
} else if crt.DNSNames != nil {
153+
args = append(args, "DNSNames", crt.DNSNames)
154+
} else if s := crt.SerialNumber.String(); s != "" {
155+
args = append(args, "serial", s)
156+
}
157+
log.V(defaultLogLevel).Info(action, args...)
158+
}
159+
}

internal/httputil/certpoolwatcher.go

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -50,8 +50,12 @@ func NewCertPoolWatcher(caDir string, log logr.Logger) (*CertPoolWatcher, error)
5050
// If the SSL_CERT_DIR or SSL_CERT_FILE environment variables are
5151
// specified, this means that we have some control over the system root
5252
// location, thus they may change, thus we should watch those locations.
53-
watchPaths := strings.Split(os.Getenv("SSL_CERT_DIR"), ":")
54-
watchPaths = append(watchPaths, caDir, os.Getenv("SSL_CERT_FILE"))
53+
sslCertDir := os.Getenv("SSL_CERT_DIR")
54+
sslCertFile := os.Getenv("SSL_CERT_FILE")
55+
log.V(defaultLogLevel).Info("SSL environment", "SSL_CERT_DIR", sslCertDir, "SSL_CERT_FILE", sslCertFile)
56+
57+
watchPaths := strings.Split(sslCertDir, ":")
58+
watchPaths = append(watchPaths, caDir, sslCertFile)
5559
watchPaths = slices.DeleteFunc(watchPaths, func(p string) bool {
5660
if p == "" {
5761
return true
@@ -66,6 +70,7 @@ func NewCertPoolWatcher(caDir string, log logr.Logger) (*CertPoolWatcher, error)
6670
if err := watcher.Add(p); err != nil {
6771
return nil, err
6872
}
73+
logPath(p, "watching certificate", log)
6974
}
7075

7176
cpw := &CertPoolWatcher{

internal/httputil/certutil.go

Lines changed: 3 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,6 @@ import (
55
"fmt"
66
"os"
77
"path/filepath"
8-
"time"
98

109
"github.com/go-logr/logr"
1110
)
@@ -24,7 +23,6 @@ func NewCertPool(caDir string, log logr.Logger) (*x509.CertPool, error) {
2423
return nil, err
2524
}
2625
count := 0
27-
firstExpiration := time.Time{}
2826

2927
for _, e := range dirEntries {
3028
file := filepath.Join(caDir, e.Name())
@@ -34,10 +32,10 @@ func NewCertPool(caDir string, log logr.Logger) (*x509.CertPool, error) {
3432
return nil, err
3533
}
3634
if fi.IsDir() {
37-
log.Info("skip directory", "name", e.Name())
35+
log.V(defaultLogLevel).V(1).Info("skip directory", "name", e.Name())
3836
continue
3937
}
40-
log.Info("load certificate", "name", e.Name())
38+
log.V(defaultLogLevel).V(1).Info("load certificate", "name", e.Name())
4139
data, err := os.ReadFile(file)
4240
if err != nil {
4341
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) {
4644
if caCertPool.AppendCertsFromPEM(data) {
4745
count++
4846
}
47+
logPem(data, e.Name(), caDir, "loading certificate file", log)
4948
}
5049

5150
// Found no certs!
5251
if count == 0 {
5352
return nil, fmt.Errorf("no certificates found in %q", caDir)
5453
}
5554

56-
log.Info("first expiration", "time", firstExpiration.Format(time.RFC3339))
5755
return caCertPool, nil
5856
}

0 commit comments

Comments
 (0)