Repository: linkerd/linkerd2
Pull request #3990 (2020-01-29 10:30:03)

Update identity to make certs more diagnosable
fixes https://github.com/linkerd/linkerd2/issues/3980

Update identity controller to make issuer certificates diagnosable if
cert validity is causing error

- Add expiry time in identity log message
- Add current time in identity log message
- Emit k8s event with appropriate message

On certificate expiry, the logs at `linkerd-identity` pod now look like :
```bash
time="2020-02-12T11:45:05Z" level=error msg="could not process CSR because of CA cert validation failure: x509: certificate has expired or is not yet valid - Current Time : 2020-02-12 11:45:05.461157338 +0000 UTC m=+69.039740599 - Invalid before 2020-02-12 11:42:00 +0000 UTC - Invalid After 2020-02-12 11:45:00 +0000 UTC - CSR Identity : linkerd-identity.linkerd.serviceaccount.identity.linkerd.cluster.local"
```
Event emitted for `linkerd-identity` deployment:
|Type|Reason|Age|From|Message|
|------|-----------|------|------|-------------|
|Warning|IssuerValidationFailed|5m54s|linkerd-identity|x509: certificate has expired or is not yet valid - Current Time : 2020-02-12 11:45:05.461157338 +0000 UTC m=+69.039740599 - Invalid before 2020-02-12 11:42:00 +0000 UTC - Invalid After 2020-02-12 11:45:00 +0000 UTC - CSR Identity : linkerd-identity.linkerd.serviceaccount.identity.linkerd.cluster.local|

Signed-off-by: Mayank Shah <mayankshah1614@gmail.com>

<!--  Thanks for sending a pull request!

If you already have a well-structured git commit message, chances are GitHub
set the title and description of this PR to the git commit message subject and
body, respectively. If so, you may delete these instructions and submit your PR.

If this is your first time, please read our contributor guide:
https://github.com/linkerd/linkerd2/blob/master/CONTRIBUTING.md

The title and description of your Pull Request should match the git commit
subject and body, respectively. Git commit messages are structured as follows:

```
Subject

Problem

Solution

Validation

Fixes #[GitHub issue ID]

DCO Sign off
```

Example git commit message:

```
Introduce Pull Request Template

GitHub's community guidelines recommend a pull request template, the repo was
lacking one.

Introduce a `PULL_REQUEST_TEMPLATE.md` file.

Once merged, the
[Community profile checklist](https://github.com/linkerd/linkerd2/community)
should indicate the repo now provides a pull request template.

Fixes #3321

Signed-off-by: Jane Smith <jane.smith@example.com>
```

Note the git commit message subject becomes the pull request title.

For more details around git commits, see the section on Committing in our
contributor guide:
https://github.com/linkerd/linkerd2/blob/master/CONTRIBUTING.md#committing
-->


mayankshah1607: @zaharidichev @adleong left a small note; might need some suggestions on that. Also, I haven't yet tested these changes as I was not able to reproduce this error. Could you help me out with that as well?? 
zaharidichev: @mayankshah1607 Do you want me to explain how to test that with unit tests or manually ? 
mayankshah1607: @zaharidichev I think it'll be easier for me to test this out using unit tests. Once the changes look good, I'll try to reproduce the cert expiry scenario manually and make sure it works. WDYT?
zaharidichev: @mayankshah1607 Makes sense! The tests you probably want to take a look at are in service_test.go and cred_test.go. These will require some modification to make them test that code path. Let me know if you need help :) 
mayankshah1607: @zaharidichev I've made the required changes. Also added a test in `creds_test.go`. Everything seems to be working as expected! Could you take a look?
If things look good, I'll try and replicate the expiry situation manually on a cluster to see if the k8s event is being emitted. :smile: 
zaharidichev: @adleong you mentioned in the original issue that 

> the linkerd-identity controller's logs fill up with this error message

I wonder , would it make sense to put some kind of throttle somewhere, slowing doesn the rate at which these CSRs are issued in case the identitiy service fails to serve it correctly. Otherwise I would assume that we are still going to see quite a bit of log messages + k8s events? 
adleong: I think we'll see this error message once for each time a proxy in the cluster attempts to get its identity.  That can be quite a lot, but I don't see any particular reason why we need to throttle it.  Do you think there might be other useful log lines that could get buried or hidden by this one?
mayankshah1607: @adleong @zaharidichev Might need some help with replicating cert expiry error manually to capture the logs and event. Any suggestions on how I can kill the certs manually on a test cluster?
adleong: I think the way I've tested this in the past is to [generate a certificate manually](https://linkerd.io/2/tasks/generate-certificates/) with a very short expiry (around 1 to 5 minutes) and then pass that to `linkerd install`.  The cert will be valid during install, but will expire shortly after.  We should then start seeing these errors.
mayankshah1607: @zaharidichev @adleong I have updated the tests according to @zaharidichev 's suggestion. Please have a look now. :smile: 
I've also updated the PR description and included the log message and emitted k8s event. 
mayankshah1607: @zaharidichev done! :)

Patch:
diff --git a/cli/cmd/upgrade.go b/cli/cmd/upgrade.go
index 1ae754be7..19470eb24 100644
--- a/cli/cmd/upgrade.go
+++ b/cli/cmd/upgrade.go
@@ -7,6 +7,7 @@ import (
 	"io/ioutil"
 	"os"
 	"strings"
+	"time"
 
 	"github.com/linkerd/linkerd2/pkg/config"
 	"github.com/linkerd/linkerd2/pkg/issuercerts"
@@ -399,7 +400,7 @@ func ensureIssuerCertWorksWithAllProxies(k kubernetes.Interface, cred *tls.Cred)
 		roots, err := tls.DecodePEMCertPool(pod.Anchors)
 
 		if roots != nil {
-			err = cred.Verify(roots, "")
+			err = cred.Verify(roots, "", time.Time{})
 		}
 
 		if err != nil {
@@ -546,7 +547,7 @@ func verifyWebhookTLS(value *charts.TLS, webhook string) error {
 		return err
 	}
 	roots := crt.CertPool()
-	if err := crt.Verify(roots, webhookCommonName(webhook)); err != nil {
+	if err := crt.Verify(roots, webhookCommonName(webhook), time.Time{}); err != nil {
 		return err
 	}
 
diff --git a/pkg/healthcheck/healthcheck.go b/pkg/healthcheck/healthcheck.go
index 27cdd4d38..c8d3a688b 100644
--- a/pkg/healthcheck/healthcheck.go
+++ b/pkg/healthcheck/healthcheck.go
@@ -972,7 +972,7 @@ func (hc *HealthChecker) allCategories() []category {
 					description: "issuer cert is issued by the trust root",
 					hintAnchor:  "l5d-identity-issuer-cert-issued-by-trust-root",
 					check: func(ctx context.Context) error {
-						return hc.issuerCert.Verify(tls.CertificatesToPool(hc.roots), hc.issuerIdentity())
+						return hc.issuerCert.Verify(tls.CertificatesToPool(hc.roots), hc.issuerIdentity(), time.Time{})
 					},
 				},
 			},
diff --git a/pkg/identity/service.go b/pkg/identity/service.go
index 1914832e3..208eefefa 100644
--- a/pkg/identity/service.go
+++ b/pkg/identity/service.go
@@ -29,6 +29,7 @@ const (
 	EnvTrustAnchors  = "LINKERD2_PROXY_IDENTITY_TRUST_ANCHORS"
 	eventTypeSkipped = "IssuerUpdateSkipped"
 	eventTypeUpdated = "IssuerUpdated"
+	eventTypeFailed  = "IssuerValidationFailed"
 )
 
 type (
@@ -113,7 +114,7 @@ func (svc *Service) loadCredentials() (tls.Issuer, error) {
 		return nil, fmt.Errorf("failed to read CA from disk: %s", err)
 	}
 
-	if err := creds.Crt.Verify(svc.trustAnchors, svc.expectedName); err != nil {
+	if err := creds.Crt.Verify(svc.trustAnchors, svc.expectedName, time.Time{}); err != nil {
 		return nil, fmt.Errorf("failed to verify issuer credentials for '%s' with trust anchors: %s", svc.expectedName, err)
 	}
 
@@ -148,7 +149,7 @@ func (svc *Service) ensureIssuerStillValid() error {
 	issuer := *svc.issuer
 	switch is := issuer.(type) {
 	case *tls.CA:
-		return is.Cred.Verify(svc.trustAnchors, svc.expectedName)
+		return is.Cred.Verify(svc.trustAnchors, svc.expectedName, time.Time{})
 	default:
 		return fmt.Errorf("unsupported issuer type. Expected *tls.CA, got %v", is)
 	}
@@ -171,7 +172,9 @@ func (svc *Service) Certify(ctx context.Context, req *pb.CertifyRequest) (*pb.Ce
 	}
 
 	if err := svc.ensureIssuerStillValid(); err != nil {
-		log.Errorf("could not process CSR because of CA cert validation failure: %s", err)
+		log.Errorf("could not process CSR because of CA cert validation failure: %s - CSR Identity : %s", err, reqIdentity)
+		message := fmt.Sprintf("%s - CSR Identity : %s", err.Error(), reqIdentity)
+		svc.recordEvent(v1.EventTypeWarning, eventTypeFailed, message)
 		return nil, err
 	}
 
diff --git a/pkg/issuercerts/issuercerts.go b/pkg/issuercerts/issuercerts.go
index ad1b853f6..50262d7df 100644
--- a/pkg/issuercerts/issuercerts.go
+++ b/pkg/issuercerts/issuercerts.go
@@ -169,7 +169,7 @@ func (ic *IssuerCertData) VerifyAndBuildCreds(dnsName string) (*tls.Cred, error)
 		return nil, err
 	}
 
-	if err := creds.Verify(roots, dnsName); err != nil {
+	if err := creds.Verify(roots, dnsName, time.Time{}); err != nil {
 		return nil, err
 	}
 
diff --git a/pkg/tls/cred.go b/pkg/tls/cred.go
index d46218a6c..d88da77fc 100644
--- a/pkg/tls/cred.go
+++ b/pkg/tls/cred.go
@@ -10,6 +10,7 @@ import (
 	"errors"
 	"fmt"
 	"io/ioutil"
+	"time"
 )
 
 type (
@@ -83,13 +84,21 @@ func (crt *Crt) CertPool() *x509.CertPool {
 }
 
 // Verify the validity of the provided certificate
-func (crt *Crt) Verify(roots *x509.CertPool, name string) error {
+func (crt *Crt) Verify(roots *x509.CertPool, name string, currentTime time.Time) error {
 	i := x509.NewCertPool()
 	for _, c := range crt.TrustChain {
 		i.AddCert(c)
 	}
-	vo := x509.VerifyOptions{Roots: roots, Intermediates: i, DNSName: name}
+	vo := x509.VerifyOptions{Roots: roots, Intermediates: i, DNSName: name, CurrentTime: currentTime}
 	_, err := crt.Certificate.Verify(vo)
+
+	if currentTime.IsZero() {
+		currentTime = time.Now()
+	}
+
+	if crtExpiryError(err) {
+		return fmt.Errorf("%s - Current Time : %s - Invalid before %s - Invalid After %s", err, currentTime, crt.Certificate.NotBefore, crt.Certificate.NotAfter)
+	}
 	return err
 }
 
@@ -221,3 +230,12 @@ func DecodePEMCrt(txt string) (*Crt, error) {
 
 	return &crt, nil
 }
+
+func crtExpiryError(err error) bool {
+	switch v := err.(type) {
+	case x509.CertificateInvalidError:
+		return v.Reason == x509.Expired
+	default:
+		return false
+	}
+}


Test patch:
diff --git a/pkg/tls/cred_test.go b/pkg/tls/cred_test.go
index 576bf942c..a888cc6c0 100644
--- a/pkg/tls/cred_test.go
+++ b/pkg/tls/cred_test.go
@@ -1,7 +1,10 @@
 package tls
 
 import (
+	"crypto/x509"
+	"fmt"
 	"testing"
+	"time"
 )
 
 func newRoot(t *testing.T) CA {
@@ -26,7 +29,7 @@ func TestCrtRoundtrip(t *testing.T) {
 		t.Fatalf("Failed to decode PEM Crt: %s", err)
 	}
 
-	if err := crt.Verify(rootTrust, "endentity.test"); err != nil {
+	if err := crt.Verify(rootTrust, "endentity.test", time.Time{}); err != nil {
 		t.Fatal("Failed to verify round-tripped certificate")
 	}
 }
@@ -47,3 +50,71 @@ func TestCredEncodeCertificateAndTrustChain(t *testing.T) {
 		t.Errorf("Encoded Certificate And TrustChain does not match expected output")
 	}
 }
+
+func TestCrtExpiry(t *testing.T) {
+	root := newRoot(t)
+	rootTrust := root.Cred.Crt.CertPool()
+
+	cred, err := root.GenerateEndEntityCred("expired.test")
+	if err != nil {
+		t.Fatalf("failed to create end entity cred: %s", err)
+	}
+
+	crt, err := DecodePEMCrt(cred.Crt.EncodePEM())
+	if err != nil {
+		t.Fatalf("Failed to decode PEM Crt: %s", err)
+	}
+
+	fakeExpiryError := x509.CertificateInvalidError{Reason: x509.Expired}
+
+	//need to remove seconds and nanoseconds for testing returned error
+	now := time.Now()
+
+	testCases := []struct {
+		currentTime time.Time
+		notBefore   time.Time
+		notAfter    time.Time
+		expected    string
+	}{
+		//cert not valid yet
+		{
+			currentTime: now,
+			notAfter:    now.AddDate(0, 0, 20),
+			notBefore:   now.AddDate(0, 0, 10),
+			expected:    fmt.Sprintf("%s - Current Time : %s - Invalid before %s - Invalid After %s", fakeExpiryError.Error(), now, now.AddDate(0, 0, 10), now.AddDate(0, 0, 20)),
+		},
+		//cert has expired
+		{
+			currentTime: now,
+			notAfter:    now.AddDate(0, 0, -10),
+			notBefore:   now.AddDate(0, 0, -20),
+			expected:    fmt.Sprintf("%s - Current Time : %s - Invalid before %s - Invalid After %s", fakeExpiryError.Error(), now, now.AddDate(0, 0, -20), now.AddDate(0, 0, -10)),
+		},
+		// cert is valid
+		{
+			currentTime: time.Time{},
+			notAfter:    crt.Certificate.NotAfter,
+			notBefore:   crt.Certificate.NotBefore,
+			expected:    "",
+		},
+	}
+
+	for i, tc := range testCases {
+		tc := tc //pin
+		t.Run(fmt.Sprintf("%d", i), func(t *testing.T) {
+			//explicitly kill the certificate
+			crt.Certificate.NotBefore = tc.notBefore
+			crt.Certificate.NotAfter = tc.notAfter
+
+			if err := crt.Verify(rootTrust, "expired.test", tc.currentTime); err != nil {
+				if err.Error() != tc.expected {
+					t.Logf("Returned error : %s\n", err)
+					t.Logf("Expected error : %s\n", tc.expected)
+					t.Fatal("test case failed")
+				}
+			} else {
+				t.Log("no error on verification")
+			}
+		})
+	}
+}