client-go certificate: context-aware APIs and logging #129338

pohly · 2024-12-20T17:41:07Z

What type of PR is this?

/kind cleanup

What this PR does / why we need it:

Special notes for your reviewer:

For NewManager, the Config struct gets changed (not extended!) so that the caller can provide a logger instead of just a logging function. Breaking the API was chosen because it avoids having to maintain two different log calls in various places (one for printf-style logging, one for structured logging).

RequestCertificateWithContext is an extension. It enables getting rid of context.TODO calls.

NewFileStoreWithLogger also is an extension.

Does this PR introduce a user-facing change?

NONE

/wg structured-logging

pohly · 2024-12-20T18:59:58Z

/retest

pod scheduling timeouts

fedebongio · 2025-01-02T21:15:41Z

/assign @liggitt
Jordan, who could be another good person for reviewing this? Thanks!
/triage accepted

ibihim · 2025-02-24T17:15:38Z

/assign @stlaz

stlaz · 2025-02-25T13:32:16Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

@@ -385,29 +402,26 @@ func (m *manager) ServerHealthy() bool {
 func (m *manager) Stop() {
 	m.clientAccessLock.Lock()


I think you don't need the lock anymore, either - while its description says otherwise, as far as I can tell it was overloaded here only to prevent concurrent access to the stopped variable. Cancelling a context should be thread-safe.

True. Removed.

stlaz · 2025-02-25T14:03:52Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

-	if m.logf == nil {
-		m.logf = func(format string, args ...interface{}) { klog.V(2).Infof(format, args...) }
+	// The name gets included through contextual logging.
+	logger := klog.Background().V(2)


As far as I understand, if I wanted to do a debug print further in the code using level 4 as the debug level, with this default logger that's V(2), whereas with the logger imported from context that's V(4).

The verbose level should likely be explicitly specified everywhere, or we should keep logf in some shape and form for logging.

The verbose level should likely be explicitly specified everywhere

Okay. It's a bit more obvious that way.

I didn't do it before because theoretically, a user could have provided a config.Logf implementation which logged at a verbosity higher than V(2). This is not supported anymore because the caller can only make a logger less verbose, but not more verbose (go-logr/logr#335 (comment)).

But I think that's fine.

stlaz · 2025-02-25T14:15:17Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

+		// we need to map it's cancellation to our Done method.
+		go func() {
+			<-ctx.Done()
+			m.Stop()


this is sad but seems necessary 🙁

stlaz · 2025-02-25T14:25:29Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

-	}
-	close(m.stopCh)
-	m.stopped = true
+	m.cancel(errors.New("asked to stop"))
 }

 // Start will start the background work of rotating the certificates.
 func (m *manager) Start() {


If we followed the common pattern from Kube controllers, this would be the place where you'd wire in your context.

Would this be an unacceptable API break? (/me is fearfully looking back at 1.18's https://github.com/kubernetes/enhancements/tree/master/keps/sig-api-machinery/1601-client-go-context)

It would be an API break, which is why I decided to not do it. It would break existing users, too (just picking one example):
https://github.com/kubevirt/kubevirt/blob/4af3a3b5901e412327cf211ed1446891d49d3183/cmd/virt-exportproxy/virt-exportproxy.go#L87

This is similar to how http.Request was extended in the standard library: a request can optionally be constructed with a context, which then gets stored and used by methods.

stlaz · 2025-02-25T14:26:31Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

+	if config.Ctx != nil && (*config.Ctx).Done() != nil {
+		ctx := *config.Ctx
+		// If we have been passed a context and it has a Done channel, then
+		// we need to map it's cancellation to our Done method.


typo

Suggested change

// we need to map it's cancellation to our Done method.

// we need to map its cancellation to our Done method.

stlaz · 2025-02-25T14:47:21Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

 			return false
 		}
 	}

 	return true
 }

-func (m *manager) certSatisfiesTemplate() bool {
+func (m *manager) certSatisfiesTemplate(ctx context.Context) bool {


this only needs the logger, not the full context

stlaz · 2025-02-25T14:48:40Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

 		if sleepInterval := deadline.Sub(m.now()); sleepInterval > 0 {
-			m.logf("%s: Waiting %v for next certificate rotation", m.name, sleepInterval)
+			logger.Info("Waiting for next certificate rotation", "delay", sleepInterval)


nit: I think this would help me a bit more when debugging

Suggested change

logger.Info("Waiting for next certificate rotation", "delay", sleepInterval)

logger.Info("Waiting for next certificate rotation", "sleep", sleepInterval)

stlaz · 2025-02-25T14:56:34Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

@@ -606,22 +622,23 @@ func (m *manager) rotateCerts() (bool, error) {
 // the template will not trigger a renewal.
 //
 // Requires certAccessLock to be locked.
-func (m *manager) certSatisfiesTemplateLocked() bool {
+func (m *manager) certSatisfiesTemplateLocked(ctx context.Context) bool {


this only needs the logger, not the full context

True. This also rippled through to some other internal methods, which is fine.

stlaz · 2025-02-25T15:02:05Z

staging/src/k8s.io/client-go/util/certificate/certificate_store.go

@@ -127,7 +144,7 @@ func (s *fileStore) Current() (*tls.Certificate, error) {
 	if pairFileExists, err := fileExists(pairFile); err != nil {
 		return nil, err
 	} else if pairFileExists {
-		klog.Infof("Loading cert/key pair from %q.", pairFile)
+		s.logger.Info("Loading cert/key pair", "file", pairFile)


nit

Suggested change

s.logger.Info("Loading cert/key pair", "file", pairFile)

s.logger.Info("Loading cert/key pair from a file", "filePath", pairFile)

stlaz · 2025-02-25T15:05:31Z

staging/src/k8s.io/client-go/util/certificate/certificate_store.go

@@ -67,14 +68,30 @@ type FileStore interface {
 // updates will be written to the ${certDirectory} directory and
 // ${certDirectory}/${pairNamePrefix}-current.pem will be created as a soft
 // link to the currently selected cert/key pair.
+//
+// Contextual logging: NewFileStoreWithLogger should be used instead of NewFileStore in code which supports contextual logging.


Is this one not getting deprecated?

No, not all users are required to support contextual logging. For those who don't care, continuing to use NewFileStore is fine. We don't want to create unnecessary churn in the ecosystem.

pohly · 2025-02-27T10:36:59Z

@stlaz: Thanks for the review! I think I addressed all of your comments, please take another look.

pohly · 2025-02-27T11:29:56Z

/test pull-kubernetes-apidiff

Incompatible changes:
- ./util/certificate.Config.Logf: removed

That was a conscious choice, because maintaining Logf would make the code more complex and this should break less consumers.

pohly · 2025-02-27T12:05:21Z

/test pull-kubernetes-unit

    queueset_test.go:382: TestTooWide client 0 last=true expectFair=true margin=0.33 got an Average of 1.3955555555555557 and the expected average was 1.2

Looks like performance wasn't as expected. Unrelated, right?

stlaz

Thank you for addressing the comments. Mostly only nits now.

It might be worth checking if we can unit test the Config.Ctx (nil, non-nil) is being passed properly through.

stlaz · 2025-02-27T13:11:12Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

@@ -732,22 +746,22 @@ func (m *manager) generateCSR() (template *x509.CertificateRequest, csrPEM []byt
 	// Generate a new private key.
 	privateKey, err := ecdsa.GenerateKey(elliptic.P256(), cryptorand.Reader)
 	if err != nil {
-		return nil, nil, nil, nil, fmt.Errorf("%s: unable to generate a new private key: %v", m.name, err)
+		return nil, nil, nil, nil, fmt.Errorf("unable to generate a new private key: %v", err)


since we're fixing these parts, let's also use %w instead of just %v for errors

Okay, but then let's also do it consistently everywhere (there was one additional line that I hadn't touched): https://github.com/kubernetes/kubernetes/compare/5cbf34e8cf258aa9f97b7c5cb8b3747236d6dc3b..f9051901cee8d8ff4aed3db27ff495a706f1a487

FWIW, I am not a fan of this blanket "always wrap errors" linter check because it should be a case-by-case decision ("does the caller need to know about the underlying error?"). In this case, it might actually be useful.

stlaz · 2025-02-27T13:11:51Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

 	}
 	der, err := x509.MarshalECPrivateKey(privateKey)
 	if err != nil {
-		return nil, nil, nil, nil, fmt.Errorf("%s: unable to marshal the new key to DER: %v", m.name, err)
+		return nil, nil, nil, nil, fmt.Errorf("unable to marshal the new key to DER: %v", err)


use %w instead of just %v for errors

stlaz · 2025-02-27T13:12:07Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager.go

 	}
 	csrPEM, err = cert.MakeCSRFromTemplate(privateKey, template)
 	if err != nil {
-		return nil, nil, nil, nil, fmt.Errorf("%s: unable to create a csr from the private key: %v", m.name, err)
+		return nil, nil, nil, nil, fmt.Errorf("unable to create a csr from the private key: %v", err)


use %w instead of just %v for errors

stlaz · 2025-02-27T13:58:08Z

staging/src/k8s.io/client-go/util/certificate/certificate_manager_test.go

@@ -38,6 +38,7 @@ import (
 	"k8s.io/client-go/kubernetes/fake"
 	certificatesclient "k8s.io/client-go/kubernetes/typed/certificates/v1beta1"
 	clienttesting "k8s.io/client-go/testing"
+	"k8s.io/klog/v2/ktesting"


It looks like we're not testing that the Config.Ctx is actually being successfully passed through since Start() is historically untested via unit tests. Ot's likely subject to integration tests though.

Is unit testing the Start() method something that we could now reasonably do, at least in terms of the context and logger?

Yes, this seems like a gap, also without this PR.

I added two tests, TestStop (no context) and TestContext (with context). Both are similar (start with no certificate, depend on background goroutine to retrieve cert), with TestContext using context cancellation and checking that contextual logging works. Here's its output:

go test -v -run=TestContext === RUN TestContext certificate_manager.go:422: I0228 10:24:54.718214] certificate: Certificate rotation is enabled certificate_manager.go:566: I0228 10:24:54.718442] certificate: Rotating certificates reflector.go:430: I0228 10:24:54.719542] certificate: Caches populated type="*v1.CertificateSigningRequest" reflector="k8s.io/client-go/tools/watch/informerwatcher.go:162" csr.go:270: I0228 10:24:54.719780] certificate: Certificate signing request is issued csr="" certificate_manager_test.go:1170: Waiting for manager to stop... --- PASS: TestContext (0.00s) PASS ok k8s.io/client-go/util/certificate 0.026s

I could have use goleak to check that goroutines spawned by Start really stopped, but that's ugly. Instead I turned Start into run with tracking of worker goroutines. This could be added to the public API, except that extending an interface is also an API break - not worth it.

Many thanks for this. I know the Start() method wasn't really tested, which is awkward, and so I'm really happy about the test changes you made 👍

stlaz · 2025-02-27T14:10:52Z

/test pull-kubernetes-unit
failed to find an available node

For NewManager, the Config struct gets changed (not extended!) so that the caller can provide a logger instead of just a logging function. Breaking the API was chosen because it avoids having to maintain two different log calls in various places (one for printf-style logging, one for structured logging). RequestCertificateWithContext is an extension. It enables getting rid of context.TODO calls. NewFileStoreWithLogger also is an extension.

pohly · 2025-02-28T09:42:55Z

@stlaz: updated.

Can I perhaps motivate you to look at some of the other related pending PRs in https://github.com/kubernetes/kubernetes/pulls?q=is%3Aopen+is%3Apr+author%3Apohly+label%3Awg%2Fstructured-logging? 😄

k8s-ci-robot · 2025-02-28T09:59:36Z

@pohly: The following tests failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
pull-kubernetes-apidiff	`6e0fde9`	link	false	`/test pull-kubernetes-apidiff`
pull-kubernetes-apidiff-client-go	`f905190`	link	false	`/test pull-kubernetes-apidiff-client-go`
pull-kubernetes-linter-hints	`f905190`	link	false	`/test pull-kubernetes-linter-hints`

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. I understand the commands that are listed here.

stlaz · 2025-02-28T12:55:00Z

/lgtm
Happy to see the unit tests improvements.

I'm not sure I'll be able to look into your other PRs today but I'll see what I can do next week 🙂

k8s-ci-robot · 2025-02-28T12:55:06Z

LGTM label has been added.

Git tree hash: b074d99f7b3bce024d2a133fccba1d40cab5473a

pohly · 2025-02-28T13:32:28Z

/assign @sttts

For approval. Review is done.

sttts · 2025-02-28T13:58:50Z

/approve

k8s-ci-robot · 2025-02-28T13:59:05Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: pohly, sttts

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~staging/src/k8s.io/client-go/util/certificate/OWNERS~~ [sttts]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

k8s-ci-robot requested review from deads2k and liggitt December 20, 2024 17:41

k8s-ci-robot added sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. sig/auth Categorizes an issue or PR as relevant to SIG Auth. labels Dec 20, 2024

pohly added a commit to pohly/kubernetes that referenced this pull request Dec 20, 2024

merge log-client-go-certificates (kubernetes#129338)

a4495ed

k8s-ci-robot assigned liggitt Jan 2, 2025

k8s-ci-robot added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Jan 2, 2025

pohly added a commit to pohly/kubernetes that referenced this pull request Jan 14, 2025

merge log-client-go-certificates (kubernetes#129338)

5d4f50c

pohly added a commit to pohly/kubernetes that referenced this pull request Jan 14, 2025

merge log-client-go-certificates (kubernetes#129338)

204f4cc

pohly added a commit to pohly/kubernetes that referenced this pull request Jan 20, 2025

merge log-client-go-certificates (kubernetes#129338)

cbef1f7

pohly added a commit to pohly/kubernetes that referenced this pull request Jan 22, 2025

merge log-client-go-certificates (kubernetes#129338)

d2a57c5

pohly added a commit to pohly/kubernetes that referenced this pull request Jan 28, 2025

merge log-client-go-certificates (kubernetes#129338)

b90b36c

pohly added a commit to pohly/kubernetes that referenced this pull request Feb 7, 2025

merge log-client-go-certificates (kubernetes#129338)

d9b9599

k8s-ci-robot assigned stlaz Feb 24, 2025

stlaz reviewed Feb 25, 2025

View reviewed changes

pohly force-pushed the log-client-go-certificates branch from 4176039 to e00d62c Compare February 27, 2025 10:35

pohly force-pushed the log-client-go-certificates branch from e00d62c to 6e0fde9 Compare February 27, 2025 10:40

stlaz reviewed Feb 27, 2025

View reviewed changes

pohly force-pushed the log-client-go-certificates branch from 6e0fde9 to 5cbf34e Compare February 28, 2025 09:27

pohly force-pushed the log-client-go-certificates branch from 5cbf34e to f905190 Compare February 28, 2025 09:37

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Feb 28, 2025

k8s-ci-robot assigned sttts Feb 28, 2025

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Feb 28, 2025

k8s-ci-robot merged commit c92dde6 into kubernetes:master Feb 28, 2025
13 of 15 checks passed

k8s-ci-robot added this to the v1.33 milestone Feb 28, 2025

github-project-automation bot moved this from Changes Requested to Closed / Done in SIG Auth Feb 28, 2025

pohly added a commit to pohly/kubernetes that referenced this pull request Apr 16, 2025

merge log-client-go-certificates (kubernetes#129338)

721416f

		@@ -385,29 +402,26 @@ func (m *manager) ServerHealthy() bool {
		func (m *manager) Stop() {
		m.clientAccessLock.Lock()

	// we need to map it's cancellation to our Done method.
	// we need to map its cancellation to our Done method.

	logger.Info("Waiting for next certificate rotation", "delay", sleepInterval)
	logger.Info("Waiting for next certificate rotation", "sleep", sleepInterval)

	s.logger.Info("Loading cert/key pair", "file", pairFile)
	s.logger.Info("Loading cert/key pair from a file", "filePath", pairFile)

client-go certificate: context-aware APIs and logging #129338

client-go certificate: context-aware APIs and logging #129338

Uh oh!

Conversation

pohly commented Dec 20, 2024

What type of PR is this?

What this PR does / why we need it:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

Uh oh!

pohly commented Dec 20, 2024

Uh oh!

fedebongio commented Jan 2, 2025

Uh oh!

ibihim commented Feb 24, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pohly commented Feb 27, 2025

Uh oh!

pohly commented Feb 27, 2025

Uh oh!

pohly commented Feb 27, 2025

Uh oh!

stlaz left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

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

stlaz commented Feb 27, 2025 •

edited

Loading