Merge pull request #10 from wallrj/4-events

Generate Kubernetes Events

README.md

@@ -415,7 +415,60 @@ The `--cluster-resource-namespace` is the namespace where the issuer will look f
 since `ClusterIssuer` is cluster-scoped.
 The default value of the flag is the namespace where the issuer is running in the cluster.
 
-#### End-to-end tests
+### Logging and Events
+
+We want to make it easy to debug problems with the issuer,
+so in addition to setting Conditions on the Issuer, ClusterIssuer and CertificateRequest,
+we can provide more feedback to the user by logging Kubernetes Events.
+You may want to read more about [Application Introspection and Debugging][] before continuing.
+
+[Application Introspection and Debugging]: https://kubernetes.io/docs/tasks/debug-application-cluster/debug-application-introspection/
+
+Kubernetes Events are saved to the API server on a best-effort basis,
+they are (usually) associated with some other Kubernetes resource,
+and they are temporary; old Events are periodically purged from the API server.
+This allows tools such as `kubectl describe <resource-kind> <resource-name>` to show not only the resource details,
+but also a table of the recent events associated with that resource.
+
+The aim is to produce helpful debug output that looks like this:
+
+```
+$ kubectl describe clusterissuers.sample-issuer.example.com clusterissuer-sample
+...
+    Type:                  Ready
+Events:
+  Type     Reason            Age                From                    Message
+  ----     ------            ----               ----                    -------
+  Normal   IssuerReconciler  13s                sample-external-issuer  First seen
+  Warning  IssuerReconciler  13s (x3 over 13s)  sample-external-issuer  Temporary error. Retrying: failed to get Secret containing Issuer credentials, secret name: sample-external-issuer-system/clusterissuer-sample-credentials, reason: Secret "clusterissuer-sample-credentials" not found
+  Normal   IssuerReconciler  13s (x3 over 13s)  sample-external-issuer  Success
+```
+And this:
+
+```
+$ kubectl describe certificaterequests.cert-manager.io issuer-sample
+...
+Events:
+  Type     Reason                        Age   From                    Message
+  ----     ------                        ----  ----                    -------
+  Normal   CertificateRequestReconciler  23m   sample-external-issuer  Initialising Ready condition
+  Warning  CertificateRequestReconciler  23m   sample-external-issuer  Temporary error. Retrying: error getting issuer: Issuer.sample-issuer.example.com "issuer-sample" not found
+  Normal   CertificateRequestReconciler  23m   sample-external-issuer  Signed
+
+```
+
+First add [record.EventRecorder][] attributes to the `IssuerReconciler` and to the `CertificateRequestReconciler`.
+And then in the Reconciler code, you can then generate an event by executing `r.recorder.Eventf(...)` whenever a significant change is made to the resource.
+
+[record.EventRecorder]: https://pkg.go.dev/k8s.io/client-go/tools/record#EventRecorder
+
+You can also write unit tests to verify the Reconciler events by using a [record.FakeRecorder][].
+
+[record.FakeRecorder]: https://pkg.go.dev/k8s.io/client-go/tools/record#FakeRecorder
+
+See [PR 10: Generate Kubernetes Events](https://github.com/cert-manager/sample-external-issuer/pull/10) for an example of how you might generate events in your issuer.
+
+### End-to-end tests
 
 Now our issuer is almost feature complete and it should be possible to write an end-to-end test that
 deploys a cert-manager `Certificate`

api/v1alpha1/types.go

@@ -0,0 +1,23 @@
+/*
+Copyright 2021 The cert-manager Authors
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package v1alpha1
+
+const (
+	EventSource                             = "sample-external-issuer"
+	EventReasonCertificateRequestReconciler = "CertificateRequestReconciler"
+	EventReasonIssuerReconciler             = "IssuerReconciler"
+)

config/rbac/role.yaml

@@ -5,6 +5,13 @@ metadata:
   creationTimestamp: null
   name: manager-role
 rules:
+- apiGroups:
+  - ""
+  resources:
+  - events
+  verbs:
+  - create
+  - patch
 - apiGroups:
   - ""
   resources:

internal/controllers/certificaterequest_controller.go

@@ -29,6 +29,7 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/types"
 	utilerrors "k8s.io/apimachinery/pkg/util/errors"
+	"k8s.io/client-go/tools/record"
 	"k8s.io/utils/clock"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -55,11 +56,13 @@ type CertificateRequestReconciler struct {
 
 	Clock                  clock.Clock
 	CheckApprovedCondition bool
+	recorder               record.EventRecorder
 }
 
 // +kubebuilder:rbac:groups=cert-manager.io,resources=certificaterequests,verbs=get;list;watch
 // +kubebuilder:rbac:groups=cert-manager.io,resources=certificaterequests/status,verbs=get;update;patch
 // +kubebuilder:rbac:groups="",resources=secrets,verbs=get;list;watch
+// +kubebuilder:rbac:groups="",resources=events,verbs=create;patch
 
 func (r *CertificateRequestReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, err error) {
 	log := ctrl.LoggerFrom(ctx)
@@ -107,9 +110,35 @@ func (r *CertificateRequestReconciler) Reconcile(ctx context.Context, req ctrl.R
 		return ctrl.Result{}, nil
 	}
 
-	// We now have a CertificateRequest that belongs to us so we are responsible
-	// for updating its Ready condition.
-	setReadyCondition := func(status cmmeta.ConditionStatus, reason, message string) {
+	if r.CheckApprovedCondition {
+		// If CertificateRequest has not been approved, exit early.
+		if !cmutil.CertificateRequestIsApproved(&certificateRequest) {
+			log.Info("CertificateRequest has not been approved yet. Ignoring.")
+			return ctrl.Result{}, nil
+		}
+	}
+
+	// report gives feedback by updating the Ready Condition of the Certificate Request.
+	// For added visibility we also log a message and create a Kubernetes Event.
+	report := func(reason, message string, err error) {
+		status := cmmeta.ConditionFalse
+		if reason == cmapi.CertificateRequestReasonIssued {
+			status = cmmeta.ConditionTrue
+		}
+		eventType := corev1.EventTypeNormal
+		if err != nil {
+			log.Error(err, message)
+			eventType = corev1.EventTypeWarning
+			message = fmt.Sprintf("%s: %v", message, err)
+		} else {
+			log.Info(message)
+		}
+		r.recorder.Event(
+			&certificateRequest,
+			eventType,
+			sampleissuerapi.EventReasonCertificateRequestReconciler,
+			message,
+		)
 		cmutil.SetCertificateRequestCondition(
 			&certificateRequest,
 			cmapi.CertificateRequestConditionReady,
@@ -122,7 +151,7 @@ func (r *CertificateRequestReconciler) Reconcile(ctx context.Context, req ctrl.R
 	// Always attempt to update the Ready condition
 	defer func() {
 		if err != nil {
-			setReadyCondition(cmmeta.ConditionFalse, cmapi.CertificateRequestReasonPending, err.Error())
+			report(cmapi.CertificateRequestReasonPending, "Temporary error. Retrying", err)
 		}
 		if updateErr := r.Status().Update(ctx, &certificateRequest); updateErr != nil {
 			err = utilerrors.NewAggregate([]error{err, updateErr})
@@ -141,32 +170,21 @@ func (r *CertificateRequestReconciler) Reconcile(ctx context.Context, req ctrl.R
 		}
 
 		message := "The CertificateRequest was denied by an approval controller"
-		setReadyCondition(cmmeta.ConditionFalse, cmapi.CertificateRequestReasonDenied, message)
+		report(cmapi.CertificateRequestReasonDenied, message, nil)
 		return ctrl.Result{}, nil
 	}
 
-	if r.CheckApprovedCondition {
-		// If CertificateRequest has not been approved, exit early.
-		if !cmutil.CertificateRequestIsApproved(&certificateRequest) {
-			log.Info("CertificateRequest has not been approved yet. Ignoring.")
-			return ctrl.Result{}, nil
-		}
-	}
-
 	// Add a Ready condition if one does not already exist
 	if ready := cmutil.GetCertificateRequestCondition(&certificateRequest, cmapi.CertificateRequestConditionReady); ready == nil {
-		log.Info("Initialising Ready condition")
-		setReadyCondition(cmmeta.ConditionFalse, cmapi.CertificateRequestReasonPending, "Initialising")
+		report(cmapi.CertificateRequestReasonPending, "Initialising Ready condition", nil)
 		return ctrl.Result{}, nil
 	}
 
 	// Ignore but log an error if the issuerRef.Kind is unrecognised
 	issuerGVK := sampleissuerapi.GroupVersion.WithKind(certificateRequest.Spec.IssuerRef.Kind)
 	issuerRO, err := r.Scheme.New(issuerGVK)
 	if err != nil {
-		err = fmt.Errorf("%w: %v", errIssuerRef, err)
-		log.Error(err, "Unrecognised kind. Ignoring.")
-		setReadyCondition(cmmeta.ConditionFalse, cmapi.CertificateRequestReasonFailed, err.Error())
+		report(cmapi.CertificateRequestReasonFailed, "Unrecognised kind. Ignoring", fmt.Errorf("%w: %v", errIssuerRef, err))
 		return ctrl.Result{}, nil
 	}
 	issuer := issuerRO.(client.Object)
@@ -184,9 +202,7 @@ func (r *CertificateRequestReconciler) Reconcile(ctx context.Context, req ctrl.R
 		secretNamespace = r.ClusterResourceNamespace
 		log = log.WithValues("clusterissuer", issuerName)
 	default:
-		err := fmt.Errorf("unexpected issuer type: %v", t)
-		log.Error(err, "The issuerRef referred to a registered Kind which is not yet handled. Ignoring.")
-		setReadyCondition(cmmeta.ConditionFalse, cmapi.CertificateRequestReasonFailed, err.Error())
+		report(cmapi.CertificateRequestReasonFailed, "The issuerRef referred to a registered Kind which is not yet handled. Ignoring", fmt.Errorf("unexpected issuer type: %v", t))
 		return ctrl.Result{}, nil
 	}
 
@@ -197,8 +213,7 @@ func (r *CertificateRequestReconciler) Reconcile(ctx context.Context, req ctrl.R
 
 	issuerSpec, issuerStatus, err := issuerutil.GetSpecAndStatus(issuer)
 	if err != nil {
-		log.Error(err, "Unable to get the IssuerStatus. Ignoring.")
-		setReadyCondition(cmmeta.ConditionFalse, cmapi.CertificateRequestReasonFailed, err.Error())
+		report(cmapi.CertificateRequestReasonFailed, "Unable to get the IssuerStatus. Ignoring", err)
 		return ctrl.Result{}, nil
 	}
 
@@ -227,11 +242,12 @@ func (r *CertificateRequestReconciler) Reconcile(ctx context.Context, req ctrl.R
 	}
 	certificateRequest.Status.Certificate = signed
 
-	setReadyCondition(cmmeta.ConditionTrue, cmapi.CertificateRequestReasonIssued, "Signed")
+	report(cmapi.CertificateRequestReasonIssued, "Signed", nil)
 	return ctrl.Result{}, nil
 }
 
 func (r *CertificateRequestReconciler) SetupWithManager(mgr ctrl.Manager) error {
+	r.recorder = mgr.GetEventRecorderFor(sampleissuerapi.EventSource)
 	return ctrl.NewControllerManagedBy(mgr).
 		For(&cmapi.CertificateRequest{}).
 		Complete(r)

internal/controllers/certificaterequest_controller_test.go

@@ -3,6 +3,7 @@ package controllers
 import (
 	"context"
 	"errors"
+	"fmt"
 	"testing"
 	"time"
 
@@ -19,6 +20,7 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/types"
 	"k8s.io/apimachinery/pkg/util/sets"
+	"k8s.io/client-go/tools/record"
 	clock "k8s.io/utils/clock/testing"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -610,6 +612,7 @@ func TestCertificateRequestReconcile(t *testing.T) {
 
 	for name, tc := range tests {
 		t.Run(name, func(t *testing.T) {
+			eventRecorder := record.NewFakeRecorder(100)
 			fakeClient := fake.NewClientBuilder().
 				WithScheme(scheme).
 				WithObjects(tc.secretObjects...).
@@ -625,31 +628,107 @@ func TestCertificateRequestReconcile(t *testing.T) {
 				SignerBuilder:            tc.signerBuilder,
 				CheckApprovedCondition:   true,
 				Clock:                    fixedClock,
+				recorder:                 eventRecorder,
 			}
-			result, err := controller.Reconcile(
+
+			var crBefore cmapi.CertificateRequest
+			if err := fakeClient.Get(context.TODO(), tc.name, &crBefore); err != nil {
+				require.NoError(t, client.IgnoreNotFound(err), "unexpected error from fake client")
+			}
+
+			result, reconcileErr := controller.Reconcile(
 				ctrl.LoggerInto(context.TODO(), logrtesting.NewTestLogger(t)),
 				reconcile.Request{NamespacedName: tc.name},
 			)
+
+			var actualEvents []string
+			for {
+				select {
+				case e := <-eventRecorder.Events:
+					actualEvents = append(actualEvents, e)
+					continue
+				default:
+					break
+				}
+				break
+			}
 			if tc.expectedError != nil {
-				assertErrorIs(t, tc.expectedError, err)
+				assertErrorIs(t, tc.expectedError, reconcileErr)
 			} else {
-				assert.NoError(t, err)
+				assert.NoError(t, reconcileErr)
 			}
 
 			assert.Equal(t, tc.expectedResult, result, "Unexpected result")
 
-			var cr cmapi.CertificateRequest
-			err = fakeClient.Get(context.TODO(), tc.name, &cr)
-			require.NoError(t, client.IgnoreNotFound(err), "unexpected error from fake client")
-			if err == nil {
-				if tc.expectedReadyConditionStatus != "" {
-					assertCertificateRequestHasReadyCondition(t, tc.expectedReadyConditionStatus, tc.expectedReadyConditionReason, &cr)
+			// For tests where the target CertificateRequest exists, we perform some further checks,
+			// otherwise exit early.
+			var crAfter cmapi.CertificateRequest
+			if err := fakeClient.Get(context.TODO(), tc.name, &crAfter); err != nil {
+				require.NoError(t, client.IgnoreNotFound(err), "unexpected error from fake client")
+				return
+			}
+
+			// If the CR is unchanged after the Reconcile then we expect no
+			// Events and need not perform any further checks.
+			// NB: controller-runtime FakeClient updates the Resource version.
+			if crBefore.ResourceVersion == crAfter.ResourceVersion {
+				assert.Empty(t, actualEvents, "Events should only be created if the CertificateRequest is modified")
+				return
+			}
+
+			// Certificate checks.
+			// Always check the certificate, in case it has been unexpectedly
+			// set without also having first added and updated the Ready
+			// condition.
+			assert.Equal(t, tc.expectedCertificate, crAfter.Status.Certificate)
+
+			if !apiequality.Semantic.DeepEqual(tc.expectedFailureTime, crAfter.Status.FailureTime) {
+				assert.Equal(t, tc.expectedFailureTime, crAfter.Status.FailureTime)
+			}
+
+			// Condition checks
+			condition := cmutil.GetCertificateRequestCondition(&crAfter, cmapi.CertificateRequestConditionReady)
+			// If the CertificateRequest is expected to have a Ready condition then we perform some extra checks.
+			if tc.expectedReadyConditionStatus != "" {
+				if assert.NotNilf(
+					t,
+					condition,
+					"Ready condition was expected but not found: tc.expectedReadyConditionStatus == %v",
+					tc.expectedReadyConditionStatus,
+				) {
+					verifyCertificateRequestReadyCondition(t, tc.expectedReadyConditionStatus, tc.expectedReadyConditionReason, condition)
 				}
-				assert.Equal(t, tc.expectedCertificate, cr.Status.Certificate)
+			} else {
+				assert.Nil(t, condition, "Unexpected Ready condition")
+			}
 
-				if !apiequality.Semantic.DeepEqual(tc.expectedFailureTime, cr.Status.FailureTime) {
-					assert.Equal(t, tc.expectedFailureTime, cr.Status.FailureTime)
+			// Event checks
+			if condition != nil {
+				// The desired Event behaviour is as follows:
+				//
+				// * An Event should always be generated when the Ready condition is set.
+				// * Event contents should match the status and message of the condition.
+				// * Event type should be Warning if the Reconcile failed (temporary error)
+				// * Event type should be warning if the condition status is failed (permanent error)
+				expectedEventType := corev1.EventTypeNormal
+				if reconcileErr != nil || condition.Reason == cmapi.CertificateRequestReasonFailed {
+					expectedEventType = corev1.EventTypeWarning
 				}
+				// If there was a Reconcile error, there will be a retry and
+				// this should be reflected in the Event message.
+				eventMessage := condition.Message
+				if reconcileErr != nil {
+					eventMessage = fmt.Sprintf("Temporary error. Retrying: %v", reconcileErr)
+				}
+				// Each Reconcile should only emit a single Event
+				assert.Equal(
+					t,
+					[]string{fmt.Sprintf("%s %s %s", expectedEventType, sampleissuerapi.EventReasonCertificateRequestReconciler, eventMessage)},
+					actualEvents,
+					"expected a single event matching the condition",
+				)
+			} else {
+				assert.Empty(t, actualEvents, "Found unexpected Events without a corresponding Ready condition")
 			}
 		})
 	}
@@ -662,11 +741,7 @@ func assertErrorIs(t *testing.T, expectedError, actualError error) {
 	assert.Truef(t, errors.Is(actualError, expectedError), "unexpected error type. expected: %v, got: %v", expectedError, actualError)
 }
 
-func assertCertificateRequestHasReadyCondition(t *testing.T, status cmmeta.ConditionStatus, reason string, cr *cmapi.CertificateRequest) {
-	condition := cmutil.GetCertificateRequestCondition(cr, cmapi.CertificateRequestConditionReady)
-	if !assert.NotNil(t, condition, "Ready condition not found") {
-		return
-	}
+func verifyCertificateRequestReadyCondition(t *testing.T, status cmmeta.ConditionStatus, reason string, condition *cmapi.CertificateRequestCondition) {
 	assert.Equal(t, status, condition.Status, "unexpected condition status")
 	validReasons := sets.NewString(
 		cmapi.CertificateRequestReasonPending,