Add type logging to certificate manager

Kubelet cert rotation involves two certificate manager instances
(one for client and one for server certs) and the log lines are
identical and confusing. Since certificate manager is a utility
library it is also inappropriate to simply assume klog output is
sufficient.

certificate.Manager now accepts a Name and Logf function on its
config struct to identify the purpose of the manager and to
provide a way to redirect where output should go. If Name is
absent, the name is defaulted from the SignerName, and if that
is not found then the name is set to "client auth" if that is
a provided key usage, or "certificate" otherwise. If Logf is
not provided it defaults to klog.V(2). as today. The name is printed
in "foo: bar" form on every line, but can be converted to structured
logging in the future. The log level is not customizable and it
is up to the caller to decide whether that is an issue.

Some log messages are slightly cleaned up to more clearly indicate
their intent. One log message is removed in a utility function that
was already at v(4) and less likely to be needed.

The default behavior of the certificate manager is as before and
the kubelet now identifies the server and client signerName as
separate entities:

I0414 19:07:33.590419    1539 certificate_manager.go:263] kubernetes.io/kube-apiserver-client-kubelet: Rotating certificates
E0414 19:07:33.594154    1539 certificate_manager.go:464] kubernetes.io/kube-apiserver-client-kubelet: Failed while requesting a signed certificate from the master: cannot create certificate signing request: Post "https://...
This commit is contained in:
Clayton Coleman 2021-04-14 13:30:46 -04:00
parent 4925cb66c9
commit 64c669bd0a
No known key found for this signature in database
GPG Key ID: 3D16906B4F1C5CB3
2 changed files with 67 additions and 26 deletions

View File

@ -124,6 +124,14 @@ type Config struct {
// CertifcateRenewFailure will record a metric that keeps track of
// certificate renewal failures.
CertificateRenewFailure Counter
// Name is an optional string that will be used when writing log output
// or returning errors from manager methods. If not set, SignerName will
// be used, if SignerName is not set, if Usages includes client auth the
// name will be "client auth", otherwise the value will be "server".
Name string
// Logf is an optional function that log output will be sent to from the
// certificate manager. If not set it will use klog.V(2)
Logf func(format string, args ...interface{})
}
// Store is responsible for getting and updating the current certificate.
@ -199,6 +207,9 @@ type manager struct {
// Set to time.Now but can be stubbed out for testing
now func() time.Time
name string
logf func(format string, args ...interface{})
}
// NewManager returns a new certificate manager. A certificate manager is
@ -233,6 +244,25 @@ func NewManager(config *Config) (Manager, error) {
now: time.Now,
}
name := config.Name
if len(name) == 0 {
name = m.signerName
}
if len(name) == 0 {
switch {
case hasKeyUsage(config.Usages, certificates.UsageClientAuth):
name = string(certificates.UsageClientAuth)
default:
name = "certificate"
}
}
m.name = name
m.logf = config.Logf
if m.logf == nil {
m.logf = func(format string, args ...interface{}) { klog.V(2).Infof(format, args...) }
}
return &m, nil
}
@ -244,7 +274,7 @@ func (m *manager) Current() *tls.Certificate {
m.certAccessLock.RLock()
defer m.certAccessLock.RUnlock()
if m.cert != nil && m.cert.Leaf != nil && m.now().After(m.cert.Leaf.NotAfter) {
klog.V(2).Infof("Current certificate is expired.")
m.logf("%s: Current certificate is expired", m.name)
return nil
}
return m.cert
@ -275,17 +305,16 @@ func (m *manager) Start() {
// signing API, so don't start the certificate manager if we don't have a
// client.
if m.clientsetFn == nil {
klog.V(2).Infof("Certificate rotation is not enabled, no connection to the apiserver.")
m.logf("%s: Certificate rotation is not enabled, no connection to the apiserver", m.name)
return
}
klog.V(2).Infof("Certificate rotation is enabled.")
m.logf("%s: Certificate rotation is enabled", m.name)
templateChanged := make(chan struct{})
go wait.Until(func() {
deadline := m.nextRotationDeadline()
if sleepInterval := deadline.Sub(m.now()); sleepInterval > 0 {
klog.V(2).Infof("Waiting %v for next certificate rotation", sleepInterval)
m.logf("%s: Waiting %v for next certificate rotation", m.name, sleepInterval)
timer := time.NewTimer(sleepInterval)
defer timer.Stop()
@ -299,7 +328,7 @@ func (m *manager) Start() {
// if the template now matches what we last requested, restart the rotation deadline loop
return
}
klog.V(2).Infof("Certificate template changed, rotating")
m.logf("%s: Certificate template changed, rotating", m.name)
}
}
@ -315,7 +344,7 @@ func (m *manager) Start() {
Steps: 5,
}
if err := wait.ExponentialBackoff(backoff, m.rotateCerts); err != nil {
utilruntime.HandleError(fmt.Errorf("Reached backoff limit, still unable to rotate certs: %v", err))
utilruntime.HandleError(fmt.Errorf("%s: Reached backoff limit, still unable to rotate certs: %v", m.name, err))
wait.PollInfinite(32*time.Second, m.rotateCerts)
}
}, time.Second, m.stopCh)
@ -381,8 +410,6 @@ func getCurrentCertificateOrBootstrap(
if _, err := store.Update(bootstrapCertificatePEM, bootstrapKeyPEM); err != nil {
utilruntime.HandleError(fmt.Errorf("Unable to set the cert/key pair to the bootstrap certificate: %v", err))
} else {
klog.V(4).Infof("Updated the store to contain the initial bootstrap certificate")
}
return &bootstrapCert, true, nil
@ -409,11 +436,11 @@ func (m *manager) RotateCerts() (bool, error) {
// from the server on the various calls it makes.
// TODO: return errors, have callers handle and log them correctly
func (m *manager) rotateCerts() (bool, error) {
klog.V(2).Infof("Rotating certificates")
m.logf("%s: Rotating certificates", m.name)
template, csrPEM, keyPEM, privateKey, err := m.generateCSR()
if err != nil {
utilruntime.HandleError(fmt.Errorf("Unable to generate a certificate signing request: %v", err))
utilruntime.HandleError(fmt.Errorf("%s: Unable to generate a certificate signing request: %v", m.name, err))
if m.certificateRenewFailure != nil {
m.certificateRenewFailure.Inc()
}
@ -423,7 +450,7 @@ func (m *manager) rotateCerts() (bool, error) {
// request the client each time
clientSet, err := m.getClientset()
if err != nil {
utilruntime.HandleError(fmt.Errorf("Unable to load a client to request certificates: %v", err))
utilruntime.HandleError(fmt.Errorf("%s: Unable to load a client to request certificates: %v", m.name, err))
if m.certificateRenewFailure != nil {
m.certificateRenewFailure.Inc()
}
@ -434,7 +461,7 @@ func (m *manager) rotateCerts() (bool, error) {
// new private key.
reqName, reqUID, err := csr.RequestCertificate(clientSet, csrPEM, "", m.signerName, m.usages, privateKey)
if err != nil {
utilruntime.HandleError(fmt.Errorf("Failed while requesting a signed certificate from the master: %v", err))
utilruntime.HandleError(fmt.Errorf("%s: Failed while requesting a signed certificate from the control plane: %v", m.name, err))
if m.certificateRenewFailure != nil {
m.certificateRenewFailure.Inc()
}
@ -451,7 +478,7 @@ func (m *manager) rotateCerts() (bool, error) {
// is a remainder after the old design using raw watch wrapped with backoff.
crtPEM, err := csr.WaitForCertificate(ctx, clientSet, reqName, reqUID)
if err != nil {
utilruntime.HandleError(fmt.Errorf("certificate request was not signed: %v", err))
utilruntime.HandleError(fmt.Errorf("%s: certificate request was not signed: %v", m.name, err))
if m.certificateRenewFailure != nil {
m.certificateRenewFailure.Inc()
}
@ -460,7 +487,7 @@ func (m *manager) rotateCerts() (bool, error) {
cert, err := m.certStore.Update(crtPEM, keyPEM)
if err != nil {
utilruntime.HandleError(fmt.Errorf("Unable to store the new cert/key pair: %v", err))
utilruntime.HandleError(fmt.Errorf("%s: Unable to store the new cert/key pair: %v", m.name, err))
if m.certificateRenewFailure != nil {
m.certificateRenewFailure.Inc()
}
@ -488,7 +515,7 @@ func (m *manager) certSatisfiesTemplateLocked() bool {
if template := m.getTemplate(); template != nil {
if template.Subject.CommonName != m.cert.Leaf.Subject.CommonName {
klog.V(2).Infof("Current certificate CN (%s) does not match requested CN (%s)", m.cert.Leaf.Subject.CommonName, template.Subject.CommonName)
m.logf("%s: Current certificate CN (%s) does not match requested CN (%s)", m.name, m.cert.Leaf.Subject.CommonName, template.Subject.CommonName)
return false
}
@ -496,7 +523,7 @@ func (m *manager) certSatisfiesTemplateLocked() bool {
desiredDNSNames := sets.NewString(template.DNSNames...)
missingDNSNames := desiredDNSNames.Difference(currentDNSNames)
if len(missingDNSNames) > 0 {
klog.V(2).Infof("Current certificate is missing requested DNS names %v", missingDNSNames.List())
m.logf("%s: Current certificate is missing requested DNS names %v", m.name, missingDNSNames.List())
return false
}
@ -510,7 +537,7 @@ func (m *manager) certSatisfiesTemplateLocked() bool {
}
missingIPs := desiredIPs.Difference(currentIPs)
if len(missingIPs) > 0 {
klog.V(2).Infof("Current certificate is missing requested IP addresses %v", missingIPs.List())
m.logf("%s: Current certificate is missing requested IP addresses %v", m.name, missingIPs.List())
return false
}
@ -518,7 +545,7 @@ func (m *manager) certSatisfiesTemplateLocked() bool {
desiredOrgs := sets.NewString(template.Subject.Organization...)
missingOrgs := desiredOrgs.Difference(currentOrgs)
if len(missingOrgs) > 0 {
klog.V(2).Infof("Current certificate is missing requested orgs %v", missingOrgs.List())
m.logf("%s: Current certificate is missing requested orgs %v", m.name, missingOrgs.List())
return false
}
}
@ -553,7 +580,7 @@ func (m *manager) nextRotationDeadline() time.Time {
totalDuration := float64(notAfter.Sub(m.cert.Leaf.NotBefore))
deadline := m.cert.Leaf.NotBefore.Add(jitteryDuration(totalDuration))
klog.V(2).Infof("Certificate expiration is %v, rotation deadline is %v", notAfter, deadline)
m.logf("%s: Certificate expiration is %v, rotation deadline is %v", m.name, notAfter, deadline)
return deadline
}
@ -607,22 +634,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("unable to generate a new private key: %v", err)
return nil, nil, nil, nil, fmt.Errorf("%s: unable to generate a new private key: %v", m.name, err)
}
der, err := x509.MarshalECPrivateKey(privateKey)
if err != nil {
return nil, nil, nil, nil, fmt.Errorf("unable to marshal the new key to DER: %v", err)
return nil, nil, nil, nil, fmt.Errorf("%s: unable to marshal the new key to DER: %v", m.name, err)
}
keyPEM = pem.EncodeToMemory(&pem.Block{Type: keyutil.ECPrivateKeyBlockType, Bytes: der})
template = m.getTemplate()
if template == nil {
return nil, nil, nil, nil, fmt.Errorf("unable to create a csr, no template available")
return nil, nil, nil, nil, fmt.Errorf("%s: unable to create a csr, no template available", m.name)
}
csrPEM, err = cert.MakeCSRFromTemplate(privateKey, template)
if err != nil {
return nil, nil, nil, nil, fmt.Errorf("unable to create a csr from the private key: %v", err)
return nil, nil, nil, nil, fmt.Errorf("%s: unable to create a csr from the private key: %v", m.name, err)
}
return template, csrPEM, keyPEM, privateKey, nil
}
@ -639,3 +666,12 @@ func (m *manager) setLastRequest(cancel context.CancelFunc, r *x509.CertificateR
m.lastRequestCancel = cancel
m.lastRequest = r
}
func hasKeyUsage(usages []certificates.KeyUsage, usage certificates.KeyUsage) bool {
for _, u := range usages {
if u == usage {
return true
}
}
return false
}

View File

@ -279,6 +279,7 @@ func TestSetRotationDeadline(t *testing.T) {
getTemplate: func() *x509.CertificateRequest { return &x509.CertificateRequest{} },
usages: []certificatesv1.KeyUsage{},
now: func() time.Time { return now },
logf: t.Logf,
}
jitteryDuration = func(float64) time.Duration { return time.Duration(float64(tc.notAfter.Sub(tc.notBefore)) * 0.7) }
lowerBound := tc.notBefore.Add(time.Duration(float64(tc.notAfter.Sub(tc.notBefore)) * 0.7))
@ -451,6 +452,7 @@ func TestCertSatisfiesTemplate(t *testing.T) {
cert: tlsCert,
getTemplate: func() *x509.CertificateRequest { return tc.template },
now: time.Now,
logf: t.Logf,
}
result := m.certSatisfiesTemplate()
@ -475,7 +477,8 @@ func TestRotateCertCreateCSRError(t *testing.T) {
clientsetFn: func(_ *tls.Certificate) (clientset.Interface, error) {
return newClientset(fakeClient{failureType: createError}), nil
},
now: func() time.Time { return now },
now: func() time.Time { return now },
logf: t.Logf,
}
if success, err := m.rotateCerts(); success {
@ -499,7 +502,8 @@ func TestRotateCertWaitingForResultError(t *testing.T) {
clientsetFn: func(_ *tls.Certificate) (clientset.Interface, error) {
return newClientset(fakeClient{failureType: watchError}), nil
},
now: func() time.Time { return now },
now: func() time.Time { return now },
logf: t.Logf,
}
defer func(t time.Duration) { certificateWaitTimeout = t }(certificateWaitTimeout)
@ -1058,6 +1062,7 @@ func TestRotationLogsDuration(t *testing.T) {
},
certificateRotation: &h,
now: func() time.Time { return now },
logf: t.Logf,
}
ok, err := m.rotateCerts()
if err != nil || !ok {