Fix OCSP log queue blocking when maxLogLen = 0. (letsencrypt#5230)

jsha · web-flow · commit 9464d025d1e3 · 2021-01-15T11:32:00.000-08:00
Move responsibility for handling the default path (maxLogLen = 0) from the ocspLogQueue component to CertificateAuthorityImpl. Now the ocspLogQueue isn't constructed at all unless we configure it to be used. Also, remove buffer from OCSP audit log chan. The bug this fixes was hidden by the large buffer, and on reconsideration the large buffer was unnecessary. Verified that with the buffer removed, the integration test fails. Then adding the fixes to the maxLogLen = 0 case fixes the integration test. Fixes letsencrypt#5228
diff --git a/ca/ca.go b/ca/ca.go
@@ -360,7 +360,10 @@ func NewCertificateAuthorityImpl(
 	}, []string{"type"})
 	stats.MustRegister(signErrorCounter)
 
-	ocspLogQueue := newOCSPLogQueue(ocspLogMaxLength, ocspLogPeriod, stats, logger)
+	var ocspLogQueue *ocspLogQueue
+	if ocspLogMaxLength > 0 {
+		ocspLogQueue = newOCSPLogQueue(ocspLogMaxLength, ocspLogPeriod, stats, logger)
+	}
 
 	ca = &CertificateAuthorityImpl{
 		sa:                 sa,
@@ -533,7 +536,9 @@ func (ca *CertificateAuthorityImpl) GenerateOCSP(ctx context.Context, req *capb.
 		tbsResponse.RevocationReason = int(req.Reason)
 	}
 
-	ca.ocspLogQueue.enqueue(serial.Bytes(), now, ocsp.ResponseStatus(tbsResponse.Status))
+	if ca.ocspLogQueue != nil {
+		ca.ocspLogQueue.enqueue(serial.Bytes(), now, ocsp.ResponseStatus(tbsResponse.Status))
+	}
 
 	ocspResponse, err := ocsp.CreateResponse(issuer.cert.Certificate, issuer.cert.Certificate, tbsResponse, issuer.ocspSigner)
 	ca.noteSignError(err)
@@ -943,15 +948,19 @@ func (ca *CertificateAuthorityImpl) OrphanIntegrationLoop() {
 // LogOCSPLoop collects OCSP generation log events into bundles, and logs
 // them periodically.
 func (ca *CertificateAuthorityImpl) LogOCSPLoop() {
-	ca.ocspLogQueue.loop()
+	if ca.ocspLogQueue != nil {
+		ca.ocspLogQueue.loop()
+	}
 }
 
 // Stop asks this CertificateAuthorityImpl to shut down. It must be called
 // after the corresponding RPC service is shut down and there are no longer
 // any inflight RPCs. It will attempt to drain any logging queues (which may
 // block), and will return only when done.
 func (ca *CertificateAuthorityImpl) Stop() {
-	ca.ocspLogQueue.stop()
+	if ca.ocspLogQueue != nil {
+		ca.ocspLogQueue.stop()
+	}
 }
 
 // integrateOrpan removes an orphan from the queue and adds it to the database. The
diff --git a/ca/ocsp.go b/ca/ocsp.go
@@ -23,7 +23,8 @@ import (
 // 3900 bytes per log line.
 // Summary of log line usage:
 // serial in hex: 36 bytes, separator characters: 2 bytes, status: 1 byte
-// If maxLogLen is 0, do not perform any accumulation or logging.
+// If maxLogLen is less than the length of a single log item, generate
+// one log line for every item.
 type ocspLogQueue struct {
 	// Maximum length, in bytes, of a single log line.
 	maxLogLen int
@@ -58,7 +59,7 @@ func newOCSPLogQueue(
 	olq := ocspLogQueue{
 		maxLogLen: maxLogLen,
 		period:    period,
-		queue:     make(chan ocspLog, 1000),
+		queue:     make(chan ocspLog),
 		wg:        sync.WaitGroup{},
 		depth:     depth,
 		logger:    logger,
@@ -85,9 +86,6 @@ const ocspSingleLogEntryLen = 39
 // whichever comes first.
 func (olq *ocspLogQueue) loop() {
 	defer olq.wg.Done()
-	if olq.maxLogLen == 0 {
-		return
-	}
 	done := false
 	for !done {
 		var builder strings.Builder
@@ -106,7 +104,7 @@ func (olq *ocspLogQueue) loop() {
 			case <-deadline:
 				break inner
 			}
-			if builder.Len()+ocspSingleLogEntryLen > olq.maxLogLen {
+			if builder.Len()+ocspSingleLogEntryLen >= olq.maxLogLen {
 				break
 			}
 		}
@@ -123,9 +121,6 @@ func (olq *ocspLogQueue) loop() {
 // If this is called without previously starting a goroutine running `.loop()`,
 // it will block forever.
 func (olq *ocspLogQueue) stop() {
-	if olq.maxLogLen == 0 {
-		return
-	}
 	close(olq.queue)
 	olq.wg.Wait()
 }
diff --git a/ca/ocsp_test.go b/ca/ocsp_test.go
@@ -97,17 +97,20 @@ func TestOcspNoEmptyLines(t *testing.T) {
 	test.AssertDeepEquals(t, log.GetAll(), []string{})
 }
 
-// If the maxLogLen is 0, don't log anything.
-func TestOcspLogMaxLenZeroMeansNoLog(t *testing.T) {
+// If the maxLogLen is shorter than one entry, log everything immediately.
+func TestOcspLogWhenMaxLogLenIsShort(t *testing.T) {
 	t.Parallel()
 	log := blog.NewMock()
 	stats := metrics.NoopRegisterer
-	queue := newOCSPLogQueue(0, 10000*time.Millisecond, stats, log)
+	queue := newOCSPLogQueue(3, 10000*time.Millisecond, stats, log)
 	go queue.loop()
 	queue.enqueue(serial(t), time.Now(), ocsp.ResponseStatus(ocsp.Good))
 	queue.stop()
 
-	test.AssertDeepEquals(t, log.GetAll(), []string{})
+	expected := []string{
+		"INFO: [AUDIT] OCSP signed: aabbccddeeffaabbccddeeff000102030405:0,",
+	}
+	test.AssertDeepEquals(t, log.GetAll(), expected)
 }
 
 // Enqueueing entries after stop causes panic.
