From 875658531b4bb83660549a5c4834e4b10b2b421f Mon Sep 17 00:00:00 2001
From: vishalnayak <vishalnayakv@gmail.com>
Date: Tue, 2 May 2017 17:56:15 -0400
Subject: [PATCH] Do not duplicate log lines for invalid leases

---
 vault/expiration.go      |  7 ++--
 vault/expiration_test.go | 79 ++++++++++++++++++++++++++++++++++++++++
 2 files changed, 82 insertions(+), 4 deletions(-)

diff --git a/vault/expiration.go b/vault/expiration.go
index f6ca1211c..52e8f6d41 100644
--- a/vault/expiration.go
+++ b/vault/expiration.go
@@ -156,7 +156,7 @@ func (m *ExpirationManager) Tidy() error {
 		var isValid, ok bool
 		revokeLease := false
 		if le.ClientToken == "" {
-			m.logger.Debug("expiration: lease has an empty token", "lease_id", leaseID)
+			m.logger.Debug("expiration: revoking lease which has an empty token", "lease_id", leaseID)
 			revokeLease = true
 			goto REVOKE_CHECK
 		}
@@ -175,7 +175,7 @@ func (m *ExpirationManager) Tidy() error {
 			}
 
 			if te == nil {
-				m.logger.Debug("expiration: lease has an invalid token", "lease_id", leaseID)
+				m.logger.Debug("expiration: revoking lease which holds an invalid token", "lease_id", leaseID)
 				revokeLease = true
 				tokenCache[le.ClientToken] = false
 			} else {
@@ -185,14 +185,13 @@ func (m *ExpirationManager) Tidy() error {
 			if isValid {
 				return
 			} else {
-				m.logger.Debug("expiration: lease has an invalid token", "lease_id", leaseID)
+				m.logger.Debug("expiration: revoking lease which contains an invalid token", "lease_id", leaseID)
 				revokeLease = true
 			}
 		}
 
 	REVOKE_CHECK:
 		if revokeLease {
-			m.logger.Debug("expiration: invalid lease is being revoked", "lease_id", leaseID)
 			// Force the revocation and skip going through the token store
 			// again
 			err = m.revokeCommon(leaseID, true, true)
diff --git a/vault/expiration_test.go b/vault/expiration_test.go
index 79a93bf04..2b685acf4 100644
--- a/vault/expiration_test.go
+++ b/vault/expiration_test.go
@@ -78,6 +78,9 @@ func TestExpiration_Tidy(t *testing.T) {
 
 	// Run the tidy operation
 	err = exp.Tidy()
+	if err != nil {
+		t.Fatal(err)
+	}
 
 	count = 0
 	if err := logical.ScanView(exp.idView, countFunc); err != nil {
@@ -110,12 +113,20 @@ func TestExpiration_Tidy(t *testing.T) {
 
 	// Run the tidy operation
 	err = exp.Tidy()
+	if err != nil {
+		t.Fatal(err)
+	}
 
 	count = 0
 	if err = logical.ScanView(exp.idView, countFunc); err != nil {
 		t.Fatal(err)
 	}
 
+	// Post the tidy operation, the invalid lease entry should have been gone
+	if count != 0 {
+		t.Fatalf("bad: lease count; expected:0 actual:%d", count)
+	}
+
 	// Attach an invalid token with 2 leases
 	if err = exp.persistEntry(le); err != nil {
 		t.Fatalf("error persisting entry: %v", err)
@@ -128,11 +139,79 @@ func TestExpiration_Tidy(t *testing.T) {
 
 	// Run the tidy operation
 	err = exp.Tidy()
+	if err != nil {
+		t.Fatal(err)
+	}
 
 	count = 0
 	if err = logical.ScanView(exp.idView, countFunc); err != nil {
 		t.Fatal(err)
 	}
+
+	// Post the tidy operation, the invalid lease entry should have been gone
+	if count != 0 {
+		t.Fatalf("bad: lease count; expected:0 actual:%d", count)
+	}
+
+	for i := 0; i < 1000; i++ {
+		req := &logical.Request{
+			Operation: logical.ReadOperation,
+			Path:      "invalid/lease/" + fmt.Sprintf("%d", i+1),
+		}
+		resp := &logical.Response{
+			Secret: &logical.Secret{
+				LeaseOptions: logical.LeaseOptions{
+					TTL: 100 * time.Millisecond,
+				},
+			},
+			Data: map[string]interface{}{
+				"test_key": "test_value",
+			},
+		}
+		_, err := exp.Register(req, resp)
+		if err != nil {
+			t.Fatalf("err: %v", err)
+		}
+	}
+
+	count = 0
+	if err = logical.ScanView(exp.idView, countFunc); err != nil {
+		t.Fatal(err)
+	}
+
+	// Check that there are 1000 leases now
+	if count != 1000 {
+		t.Fatalf("bad: lease count; expected:1000 actual:%d", count)
+	}
+
+	errCh1 := make(chan error)
+	errCh2 := make(chan error)
+
+	// Initiate tidy of the above 1000 invalid leases in quick succession. Only
+	// one tidy operation can be in flight at any time. One of these requests
+	// should error out.
+	go func() {
+		errCh1 <- exp.Tidy()
+	}()
+
+	go func() {
+		errCh2 <- exp.Tidy()
+	}()
+
+	var err1, err2 error
+
+	for i := 0; i < 2; i++ {
+		select {
+		case err1 = <-errCh1:
+			fmt.Printf("err1 received: %#v\n", err1)
+		case err2 = <-errCh2:
+			fmt.Printf("err2 received: %#v\n", err2)
+		}
+	}
+
+	if err1 == nil && err2 == nil {
+		t.Fatal("expected error")
+	}
 }
 
 func BenchmarkExpiration_Restore_Etcd(b *testing.B) {