Skip to content

Commit de4fe9d

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 de4fe9d

File tree

9 files changed

+178
-8
lines changed

9 files changed

+178
-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: 5 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,10 @@ func (r *ClusterCatalogReconciler) reconcile(ctx context.Context, catalog *catal
229230

230231
unpackResult, err := r.Unpacker.Unpack(ctx, catalog)
231232
if err != nil {
233+
l := ctrl.Log.WithName("catalog-unpacker")
234+
if httputil.LogUnverifiedCertificate(err, l) {
235+
httputil.DumpCertificates("/etc/docker/certs.d", l)
236+
}
232237
unpackErr := fmt.Errorf("source catalog content: %w", err)
233238
updateStatusProgressing(&catalog.Status, catalog.GetGeneration(), unpackErr)
234239
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.LogUnverifiedCertificate(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: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -53,6 +53,7 @@ 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"
5859
rukpaksource "github.com/operator-framework/operator-controller/internal/rukpak/source"
@@ -257,6 +258,10 @@ func (r *ClusterExtensionReconciler) reconcile(ctx context.Context, ext *ocv1.Cl
257258
// Wrap the error passed to this with the resolution information until we have successfully
258259
// installed since we intend for the progressing condition to replace the resolved condition
259260
// and will be removing the .status.resolution field from the ClusterExtension status API
261+
l := ctrl.Log.WithName("operator-controller-unpacker")
262+
if httputil.LogUnverifiedCertificate(err, l) {
263+
httputil.DumpCertificates("/etc/docker/certs.d", l)
264+
}
260265
setStatusProgressing(ext, wrapErrorWithResolutionInfo(resolvedBundleMetadata, err))
261266
setInstalledStatusFromBundle(ext, installedBundle)
262267
return ctrl.Result{}, err

internal/httputil/certlog.go

Lines changed: 150 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,150 @@
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+
func DumpCertificates(path string, log logr.Logger) {
20+
paths := []string{}
21+
if path == "" {
22+
paths = []string{"/etc/docker/certs.d", "/etc/containers/certs.d"}
23+
} else {
24+
paths = []string{path}
25+
}
26+
for _, path := range paths {
27+
fi, err := os.Stat(path)
28+
if err != nil {
29+
log.Error(err, "statting directory", "directory", path)
30+
continue
31+
}
32+
if !fi.IsDir() {
33+
log.V(defaultLogLevel).V(1).Info("not a directory", "directory", path)
34+
continue
35+
}
36+
dirEntries, err := os.ReadDir(path)
37+
if err != nil {
38+
log.Error(err, "reading directory", "directory", path)
39+
continue
40+
}
41+
count := 0
42+
for _, e := range dirEntries {
43+
hostPath := filepath.Join(path, e.Name())
44+
fi, err := os.Stat(hostPath)
45+
count++
46+
if err != nil {
47+
log.Error(err, "dumping certs", "path", hostPath)
48+
continue
49+
}
50+
if !fi.IsDir() {
51+
log.V(defaultLogLevel).V(1).Info("ignoring non-directory", "path", hostPath)
52+
continue
53+
}
54+
logPath(hostPath, "dump docker certs", log)
55+
}
56+
}
57+
}
58+
59+
func LogUnverifiedCertificate(err error, log logr.Logger) bool {
60+
for err != nil {
61+
var cvErr *tls.CertificateVerificationError
62+
if errors.As(err, &cvErr) {
63+
n := 1
64+
for _, cert := range cvErr.UnverifiedCertificates {
65+
log.Error(err, "unverified cert", "n", n, "subject", cert.Subject, "issuer", cert.Issuer, "DNSNames", cert.DNSNames, "serial", cert.SerialNumber)
66+
n = n + 1
67+
}
68+
return true
69+
}
70+
err = errors.Unwrap(err)
71+
}
72+
return false
73+
}
74+
75+
func logPath(path, action string, log logr.Logger) {
76+
fi, err := os.Stat(path)
77+
if err != nil {
78+
log.Error(err, "error in os.Stat()", "path", path)
79+
return
80+
}
81+
if !fi.IsDir() {
82+
logFile(path, "", fmt.Sprintf("%s file", action), log)
83+
return
84+
}
85+
action = fmt.Sprintf("%s directory", action)
86+
dirEntries, err := os.ReadDir(path)
87+
if err != nil {
88+
log.Error(err, "error in os.ReadDir()", "path", path)
89+
return
90+
}
91+
for _, e := range dirEntries {
92+
file := filepath.Join(path, e.Name())
93+
fi, err := os.Stat(file)
94+
if err != nil {
95+
log.Error(err, "error in os.Stat()", "file", file)
96+
continue
97+
}
98+
if fi.IsDir() {
99+
log.V(defaultLogLevel).V(1).Info("ignoring subdirectory", "directory", file)
100+
continue
101+
}
102+
logFile(e.Name(), path, action, log)
103+
}
104+
}
105+
106+
func logFile(filename, path, action string, log logr.Logger) {
107+
filepath := filepath.Join(path, filename)
108+
_, err := os.Stat(filepath)
109+
if err != nil {
110+
log.Error(err, "statting file", "file", filepath)
111+
return
112+
}
113+
data, err := os.ReadFile(filepath)
114+
if err != nil {
115+
log.Error(err, "error in os.ReadFile()", "file", filepath)
116+
return
117+
}
118+
logPem(data, filename, path, action, log)
119+
}
120+
121+
func logPem(data []byte, filename, path, action string, log logr.Logger) {
122+
for len(data) > 0 {
123+
var block *pem.Block
124+
block, data = pem.Decode(data)
125+
if block == nil {
126+
log.Info("error: no block returned from pem.Decode()", "file", filename)
127+
return
128+
}
129+
crt, err := x509.ParseCertificate(block.Bytes)
130+
if err != nil {
131+
log.Error(err, "error in x509.ParseCertificate()", "file", filename)
132+
return
133+
}
134+
135+
args := []any{}
136+
if path != "" {
137+
args = append(args, "directory", path)
138+
}
139+
// Find an appopriate certificate identifier
140+
args = append(args, "file", filename)
141+
if s := crt.Subject.String(); s != "" {
142+
args = append(args, "subject", s)
143+
} else if crt.DNSNames != nil {
144+
args = append(args, "DNSNames", crt.DNSNames)
145+
} else if s := crt.SerialNumber.String(); s != "" {
146+
args = append(args, "serial", s)
147+
}
148+
log.V(defaultLogLevel).Info(action, args...)
149+
}
150+
}

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)