From d1fa9f9db83e287f9a48b9138104fdd6ab459f7d Mon Sep 17 00:00:00 2001
From: Jacob Hoffman-Andrews <github@hoffman-andrews.com>
Date: Mon, 15 Jun 2020 16:24:44 -0700
Subject: [PATCH] Add more logging to bad-key-revoker. (#4871)

---
 cmd/bad-key-revoker/main.go      | 17 ++++++++++++++++-
 cmd/bad-key-revoker/main_test.go | 27 ++++++++++++++++++++++++---
 2 files changed, 40 insertions(+), 4 deletions(-)

diff --git a/cmd/bad-key-revoker/main.go b/cmd/bad-key-revoker/main.go
index e2b593720..187b03083 100644
--- a/cmd/bad-key-revoker/main.go
+++ b/cmd/bad-key-revoker/main.go
@@ -65,6 +65,11 @@ type uncheckedBlockedKey struct {
 	RevokedBy int64
 }
 
+func (ubk uncheckedBlockedKey) String() string {
+	return fmt.Sprintf("[revokedBy: %d, keyHash: %x]",
+		ubk.RevokedBy, ubk.KeyHash)
+}
+
 func (bkr *badKeyRevoker) selectUncheckedKey() (uncheckedBlockedKey, error) {
 	var row uncheckedBlockedKey
 	err := bkr.dbMap.SelectOne(
@@ -258,13 +263,17 @@ func (bkr *badKeyRevoker) invoke() (bool, error) {
 		}
 		return false, err
 	}
+	bkr.logger.AuditInfo(fmt.Sprintf("found unchecked block key to work on: %s", unchecked))
 
 	// select all unrevoked, unexpired serials associated with the blocked key hash
 	unrevokedCerts, err := bkr.findUnrevoked(unchecked)
 	if err != nil {
+		bkr.logger.AuditInfo(fmt.Sprintf("finding unrevoked certificates related to %s: %s",
+			unchecked, err))
 		return false, err
 	}
 	if len(unrevokedCerts) == 0 {
+		bkr.logger.AuditInfo(fmt.Sprintf("found no certificates that need revoking related to %s, marking row as checked", unchecked))
 		// mark row as checked
 		err = bkr.markRowChecked(unchecked)
 		if err != nil {
@@ -306,6 +315,10 @@ func (bkr *badKeyRevoker) invoke() (bool, error) {
 		}
 	}
 
+	revokerEmails := idToEmails[unchecked.RevokedBy]
+	bkr.logger.AuditInfo(fmt.Sprintf("revoking certs. revoked emails=%v, emailsToCerts=%v",
+		revokerEmails, emailsToCerts))
+
 	// revoke each certificate and send emails to their owners
 	err = bkr.revokeCerts(idToEmails[unchecked.RevokedBy], emailsToCerts)
 	if err != nil {
@@ -438,10 +451,12 @@ func main() {
 		noWork, err := bkr.invoke()
 		if err != nil {
 			keysProcessed.WithLabelValues("error").Inc()
-			logger.Errf("failed to process blockedKeys row: %s", err)
+			logger.AuditErrf("failed to process blockedKeys row: %s", err)
 			continue
 		}
 		if noWork {
+			logger.Info(fmt.Sprintf(
+				"No work to do. Sleeping for %s", config.BadKeyRevoker.Interval.Duration))
 			time.Sleep(config.BadKeyRevoker.Interval.Duration)
 		} else {
 			keysProcessed.WithLabelValues("success").Inc()
diff --git a/cmd/bad-key-revoker/main_test.go b/cmd/bad-key-revoker/main_test.go
index 4e7cb8595..5812270eb 100644
--- a/cmd/bad-key-revoker/main_test.go
+++ b/cmd/bad-key-revoker/main_test.go
@@ -14,6 +14,7 @@ import (
 	"github.com/letsencrypt/boulder/core"
 	corepb "github.com/letsencrypt/boulder/core/proto"
 	"github.com/letsencrypt/boulder/db"
+	blog "github.com/letsencrypt/boulder/log"
 	"github.com/letsencrypt/boulder/mocks"
 	rapb "github.com/letsencrypt/boulder/ra/proto"
 	"github.com/letsencrypt/boulder/sa"
@@ -57,7 +58,10 @@ func TestSelectUncheckedRows(t *testing.T) {
 	test.AssertNotError(t, err, "failed setting up db client")
 	defer test.ResetSATestDatabase(t)()
 
-	bkr := &badKeyRevoker{dbMap: dbMap}
+	bkr := &badKeyRevoker{
+		dbMap:  dbMap,
+		logger: blog.NewMock(),
+	}
 
 	hashA, hashB, hashC := randHash(t), randHash(t), randHash(t)
 	insertBlockedRow(t, dbMap, hashA, 1, true)
@@ -248,7 +252,16 @@ func TestInvoke(t *testing.T) {
 
 	mm := &mocks.Mailer{}
 	mr := &mockRevoker{}
-	bkr := &badKeyRevoker{dbMap: dbMap, maxRevocations: 10, serialBatchSize: 1, raClient: mr, mailer: mm, emailSubject: "testing", emailTemplate: testTemplate}
+	bkr := &badKeyRevoker{
+		dbMap:           dbMap,
+		maxRevocations:  10,
+		serialBatchSize: 1,
+		raClient:        mr,
+		mailer:          mm,
+		emailSubject:    "testing",
+		emailTemplate:   testTemplate,
+		logger:          blog.NewMock(),
+	}
 
 	// populate DB with all the test data
 	regIDA := insertRegistration(t, dbMap, "example.com")
@@ -307,7 +320,15 @@ func TestInvokeRevokerHasNoExtantCerts(t *testing.T) {
 
 	mm := &mocks.Mailer{}
 	mr := &mockRevoker{}
-	bkr := &badKeyRevoker{dbMap: dbMap, maxRevocations: 10, serialBatchSize: 1, raClient: mr, mailer: mm, emailSubject: "testing", emailTemplate: testTemplate}
+	bkr := &badKeyRevoker{dbMap: dbMap,
+		maxRevocations:  10,
+		serialBatchSize: 1,
+		raClient:        mr,
+		mailer:          mm,
+		emailSubject:    "testing",
+		emailTemplate:   testTemplate,
+		logger:          blog.NewMock(),
+	}
 
 	// populate DB with all the test data
 	regIDA := insertRegistration(t, dbMap, "a@example.com")