🌱 Add logging to certpoolwatcher and client #1684

tmshort · 2025-01-31T16:31:57Z

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

Update:

Remove firstExpiration as it's no longer calculated
Default logging to V(4), using a constant
Add cert logging for catalogd pull failure

Log when an unknown server cert is encountered:

E0203 20:46:01.629763       1 client.go:124] "unverified cert" err="Get \"https://catalogd-service.olmv1-system.svc/catalogs/operatorhubio/api/v1/all\": tls: failed to verify certificate: x509: certificate signed by unknown authority" logger="catalog-client" n=1 subject="" issuer="CN=olmv1-ca" DNSNames=["localhost","catalogd-service.olmv1-system.svc","catalogd-service.olmv1-system.svc.cluster.local"] serial="197916310015755767059581167694871409392"

Loading and Watching certificates:

I0203 20:29:03.579864       1 certlog.go:81] "loading certificate file" logger="cert-pool" directory="/var/certs" file="olm-ca.crt" subject="CN=olmv1-ca"
I0203 20:29:03.580046       1 certlog.go:81] "watching certificate directory" logger="cert-pool" directory="/var/certs" file="olm-ca.crt" subject="CN=olmv1-ca"
I0203 20:29:03.580236       1 certlog.go:81] "watching certificate file" logger="cert-pool" file="/etc/ssl/certs/ca-certificates.crt" subject="CN=ACCVRAIZ1,OU=PKIACCV,O=ACCV,C=ES"
I0203 20:29:03.580264       1 certlog.go:81] "watching certificate file" logger="cert-pool" file="/etc/ssl/certs/ca-certificates.crt" subject="OU=AC RAIZ FNMT-RCM,O=FNMT-RCM,C=ES"

netlify · 2025-01-31T16:32:13Z

✅ Deploy Preview for olmv1 ready!

Name	Link
🔨 Latest commit	`3773bb6`
🔍 Latest deploy log	https://app.netlify.com/sites/olmv1/deploys/67aa63fd974407000840081f
😎 Deploy Preview	https://deploy-preview-1684--olmv1.netlify.app
📱 Preview on mobile	Toggle QR Code... Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify site configuration.

codecov · 2025-01-31T16:45:32Z

Codecov Report

Attention: Patch coverage is 46.76259% with 74 lines in your changes missing coverage. Please review.

Project coverage is 67.70%. Comparing base (6ca68c4) to head (3773bb6).
Report is 3 commits behind head on main.

Files with missing lines	Patch %	Lines
internal/httputil/certlog.go	41.50%	54 Missing and 8 partials ⚠️
catalogd/cmd/catalogd/main.go	0.00%	3 Missing ⚠️
catalogd/internal/source/containers_image.go	62.50%	2 Missing and 1 partial ⚠️
cmd/operator-controller/main.go	0.00%	2 Missing and 1 partial ⚠️
internal/rukpak/source/containers_image.go	62.50%	2 Missing and 1 partial ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #1684      +/-   ##
==========================================
- Coverage   68.24%   67.70%   -0.54%     
==========================================
  Files          58       59       +1     
  Lines        4988     5128     +140     
==========================================
+ Hits         3404     3472      +68     
- Misses       1342     1403      +61     
- Partials      242      253      +11

Flag	Coverage Δ
e2e	`52.58% <46.09%> (-0.35%)`	⬇️
unit	`55.01% <36.69%> (-0.45%)`	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

perdasilva

lgtm ^^

perdasilva · 2025-01-31T18:01:09Z

you may need to rebase to pick up the upgrade-e2e mitigations =S

joelanford · 2025-01-31T23:34:35Z

Would you mind adding some example output to the description of the PR?

internal/httputil/certpoolwatcher.go

tmshort · 2025-02-03T20:42:58Z

Example logging at start:

I0203 20:29:03.579864       1 certlog.go:81] "loading certificate file" logger="cert-pool" directory="/var/certs" file="olm-ca.crt" subject="CN=olmv1-ca"
I0203 20:29:03.579910       1 certlog.go:81] "loading certificate file" logger="cert-pool" directory="/var/certs" file="tls.cert" DNSNames=["operator-controller-service.olmv1-system.svc","operator-controller-service.olmv1-system.svc.cluster.local"]
E0203 20:29:03.579947       1 certlog.go:64] "error in x509.ParseCertificate()" err="x509: malformed tbs certificate" logger="cert-pool" file="tls.key"
I0203 20:29:03.580012       1 certlog.go:37] "ignoring subdirectory" logger="cert-pool" directory="/var/certs/..2025_02_03_20_29_03.3099064557"
I0203 20:29:03.580020       1 certlog.go:37] "ignoring subdirectory" logger="cert-pool" directory="/var/certs/..data"
I0203 20:29:03.580046       1 certlog.go:81] "watching certificate directory" logger="cert-pool" directory="/var/certs" file="olm-ca.crt" subject="CN=olmv1-ca"
I0203 20:29:03.580084       1 certlog.go:81] "watching certificate directory" logger="cert-pool" directory="/var/certs" file="tls.cert" DNSNames=["operator-controller-service.olmv1-system.svc","operator-controller-service.olmv1-system.svc.cluster.local"]
E0203 20:29:03.580106       1 certlog.go:64] "error in x509.ParseCertificate()" err="x509: malformed tbs certificate" logger="cert-pool" file="tls.key"
I0203 20:29:03.580236       1 certlog.go:81] "watching certificate file" logger="cert-pool" file="/etc/ssl/certs/ca-certificates.crt" subject="CN=ACCVRAIZ1,OU=PKIACCV,O=ACCV,C=ES"
I0203 20:29:03.580264       1 certlog.go:81] "watching certificate file" logger="cert-pool" file="/etc/ssl/certs/ca-certificates.crt" subject="OU=AC RAIZ FNMT-RCM,O=FNMT-RCM,C=ES"
...

tmshort · 2025-02-03T20:46:58Z

Example logging of an unknown certificate:

E0203 20:46:01.629763       1 client.go:124] "Unverified Cert" err="Get \"https://catalogd-service.olmv1-system.svc/catalogs/operatorhubio/api/v1/all\": tls: failed to verify certificate: x509: certificate signed by unknown authority" logger="catalog-client" n=1 subject="" issuer="CN=olmv1-ca" DNSNames=["localhost","catalogd-service.olmv1-system.svc","catalogd-service.olmv1-system.svc.cluster.local"] serial="197916310015755767059581167694871409392"
I0203 20:46:01.629867       1 clustercatalog_controller.go:87] "reconcile ending" logger="cluster-catalog" controller="clustercatalog" controllerGroup="olm.operatorframework.io" controllerKind="ClusterCatalog" ClusterCatalog="operatorhubio" namespace="" name="operatorhubio" reconcileID="b5c3fd7f-0bc5-447e-a2cf-ab7bc08d86e5"
E0203 20:46:01.629929       1 controller.go:316] "Reconciler error" err="error populating cache for catalog \"operatorhubio\": error performing request: Get \"https://catalogd-service.olmv1-system.svc/catalogs/operatorhubio/api/v1/all\": tls: failed to verify certificate: x509: certificate signed by unknown authority" controller="clustercatalog" controllerGroup="olm.operatorframework.io" controllerKind="ClusterCatalog" ClusterCatalog="operatorhubio" namespace="" name="operatorhubio" reconcileID="b5c3fd7f-0bc5-447e-a2cf-ab7bc08d86e5"

internal/catalogmetadata/client/client.go

catalogd/internal/controllers/core/clustercatalog_controller.go

internal/httputil/certlog.go

internal/controllers/clusterextension_controller.go

internal/httputil/certlog.go

catalogd/internal/controllers/core/clustercatalog_controller.go

LalatenduMohanty · 2025-02-07T19:34:38Z

internal/httputil/certlog.go

@@ -0,0 +1,157 @@
+package httputil


it kind if weird that the certlog is in httputil pkg. Should we keep outside of httputil? Same comment for internal/httputil/certutil.go.

It is nit pick and not blocker for this PR.

I was thinking of moving the cert utility stuff into it's own package, but that can be done later.

internal/httputil/certlog.go

catalogd/internal/source/containers_image.go

internal/httputil/certutil.go

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]>

LalatenduMohanty · 2025-02-10T21:42:31Z

internal/catalogmetadata/client/client.go

@@ -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"))


Why are we ignoring the return here?

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

Because we don't need to log certs in /etc/docker here, because this is used for catalogd connections, not pulling images, The other places this is called, the return is used to determine if we want to look at /etc/docker

I see, so we just called the function to log error in to the logfile.

LalatenduMohanty

/lgtm

tmshort requested a review from a team as a code owner January 31, 2025 16:31

perdasilva previously approved these changes Jan 31, 2025

View reviewed changes

tmshort force-pushed the cert-watcher-logging branch from 906bb34 to d20ad5f Compare January 31, 2025 21:42

joelanford reviewed Jan 31, 2025

View reviewed changes

internal/httputil/certpoolwatcher.go Outdated Show resolved Hide resolved

joelanford reviewed Jan 31, 2025

View reviewed changes

internal/httputil/certpoolwatcher.go Outdated Show resolved Hide resolved

tmshort dismissed perdasilva’s stale review via 9eebd85 February 3, 2025 20:41

tmshort force-pushed the cert-watcher-logging branch from d20ad5f to 9eebd85 Compare February 3, 2025 20:41

tmshort closed this Feb 3, 2025

tmshort reopened this Feb 3, 2025

tmshort force-pushed the cert-watcher-logging branch 2 times, most recently from 0d53099 to cf71d8f Compare February 3, 2025 20:55

tmshort changed the title ~~🌱 Add logging to certpoolwatcher~~ 🌱 Add logging to certpoolwatcher and client Feb 3, 2025

joelanford reviewed Feb 4, 2025

View reviewed changes

internal/catalogmetadata/client/client.go Outdated Show resolved Hide resolved

joelanford reviewed Feb 4, 2025

View reviewed changes

internal/catalogmetadata/client/client.go Outdated Show resolved Hide resolved

tmshort force-pushed the cert-watcher-logging branch 3 times, most recently from c80561b to 01f38e7 Compare February 5, 2025 16:11

joelanford reviewed Feb 5, 2025

View reviewed changes

catalogd/internal/controllers/core/clustercatalog_controller.go Outdated Show resolved Hide resolved

tmshort force-pushed the cert-watcher-logging branch 3 times, most recently from de4fe9d to b778a9f Compare February 6, 2025 21:54

camilamacedo86 reviewed Feb 6, 2025

View reviewed changes

internal/httputil/certlog.go Outdated Show resolved Hide resolved

camilamacedo86 reviewed Feb 6, 2025

View reviewed changes

internal/controllers/clusterextension_controller.go Outdated Show resolved Hide resolved

camilamacedo86 reviewed Feb 7, 2025

View reviewed changes

internal/httputil/certlog.go Outdated Show resolved Hide resolved

tmshort force-pushed the cert-watcher-logging branch 5 times, most recently from 228010b to 3405fad Compare February 7, 2025 18:46

joelanford reviewed Feb 7, 2025

View reviewed changes

catalogd/internal/controllers/core/clustercatalog_controller.go Outdated Show resolved Hide resolved

LalatenduMohanty reviewed Feb 7, 2025

View reviewed changes

LalatenduMohanty requested changes Feb 7, 2025

View reviewed changes

internal/httputil/certlog.go Outdated Show resolved Hide resolved

tmshort force-pushed the cert-watcher-logging branch 2 times, most recently from a48c266 to 7da2528 Compare February 7, 2025 21:01

openshift-merge-robot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Feb 7, 2025

tmshort force-pushed the cert-watcher-logging branch from 7da2528 to 5a10b3d Compare February 7, 2025 21:19

openshift-merge-robot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Feb 7, 2025

joelanford reviewed Feb 7, 2025

View reviewed changes

catalogd/internal/source/containers_image.go Outdated Show resolved Hide resolved

joelanford reviewed Feb 7, 2025

View reviewed changes

internal/httputil/certutil.go Outdated Show resolved Hide resolved

Add logging to certpoolwatcher and client

3773bb6

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]>

tmshort force-pushed the cert-watcher-logging branch from 5a10b3d to 3773bb6 Compare February 10, 2025 20:39

joelanford approved these changes Feb 10, 2025

View reviewed changes

LalatenduMohanty reviewed Feb 10, 2025

View reviewed changes

LalatenduMohanty approved these changes Feb 10, 2025

View reviewed changes

openshift-ci bot assigned LalatenduMohanty Feb 10, 2025

openshift-ci bot added the lgtm Indicates that a PR is ready to be merged. label Feb 10, 2025

tmshort added this pull request to the merge queue Feb 11, 2025

github-merge-queue bot removed this pull request from the merge queue due to failed status checks Feb 11, 2025

tmshort added this pull request to the merge queue Feb 11, 2025

Merged via the queue into operator-framework:main with commit c451127 Feb 11, 2025
21 of 23 checks passed

tmshort deleted the cert-watcher-logging branch February 11, 2025 15:08

🌱 Add logging to certpoolwatcher and client #1684

🌱 Add logging to certpoolwatcher and client #1684

Uh oh!

Conversation

tmshort commented Jan 31, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

netlify bot commented Jan 31, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

✅ Deploy Preview for olmv1 ready!

Uh oh!

codecov bot commented Jan 31, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

perdasilva left a comment

Choose a reason for hiding this comment

Uh oh!

perdasilva commented Jan 31, 2025

Uh oh!

joelanford commented Jan 31, 2025

Uh oh!

Uh oh!

Uh oh!

tmshort commented Feb 3, 2025

Uh oh!

tmshort commented Feb 3, 2025

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

LalatenduMohanty Feb 7, 2025

Choose a reason for hiding this comment

Uh oh!

tmshort Feb 7, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

LalatenduMohanty Feb 10, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tmshort Feb 10, 2025

Choose a reason for hiding this comment

Uh oh!

LalatenduMohanty Feb 10, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

LalatenduMohanty left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

tmshort commented Jan 31, 2025 •

edited

Loading

netlify bot commented Jan 31, 2025 •

edited

Loading

codecov bot commented Jan 31, 2025 •

edited

Loading

LalatenduMohanty Feb 10, 2025 •

edited

Loading

LalatenduMohanty Feb 10, 2025 •

edited

Loading