Add waiting mock log writer (#5359)

Add a mock log buffer that is able to wait for a regex match in the
log buffer or timeout and error.

Fixes #5310

ca/ocsp_test.go

@@ -60,26 +60,17 @@ func TestOcspFlushOnLength(t *testing.T) {
 // Ensure log lines are sent after a timeout.
 func TestOcspFlushOnTimeout(t *testing.T) {
 	t.Parallel()
-	log := blog.NewMock()
+	log := blog.NewWaitingMock()
 	stats := metrics.NoopRegisterer
 	queue := newOCSPLogQueue(90000, 10*time.Millisecond, stats, log)
 
 	go queue.loop()
 	queue.enqueue(serial(t), time.Now(), ocsp.ResponseStatus(ocsp.Good))
-	// This gets a little tricky: Each iteration of the `select` in
-	// queue.loop() is a race between the channel that receives log
-	// events and the `<-clk.After(n)` timer. Even if we used
-	// a fake clock, our loop here would often win that race, producing
-	// inconsistent logging results. For instance, it would be entirely
-	// possible for all of these `enqueues` to win the race, putting
-	// all log entries on one line.
-	// To avoid that, sleep using the wall clock for 50ms.
-	time.Sleep(50 * time.Millisecond)
 
-	expected := []string{
-		"INFO: [AUDIT] OCSP signed: aabbccddeeffaabbccddeeff000102030405:0,",
-	}
-	test.AssertDeepEquals(t, log.GetAll(), expected)
+	expected := "INFO: [AUDIT] OCSP signed: aabbccddeeffaabbccddeeff000102030405:0,"
+	logLines, err := log.WaitForMatch("OCSP signed", 50*time.Millisecond)
+	test.AssertNotError(t, err, "error in mock log")
+	test.AssertDeepEquals(t, logLines, expected)
 	queue.stop()
 }
 

log/mock.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"log/syslog"
 	"regexp"
+	"time"
 )
 
 // UseMock sets a mock logger as the default logger, and returns it.
@@ -18,12 +19,24 @@ func NewMock() *Mock {
 	return &Mock{impl{newMockWriter()}}
 }
 
+// NewWaitingMock creates a mock logger implementing the writer interface.
+// It stores all logged messages in a buffer for inspection by test
+// functions.
+func NewWaitingMock() *WaitingMock {
+	return &WaitingMock{impl{newWaitingMockWriter()}}
+}
+
 // Mock is a logger that stores all log messages in memory to be examined by a
 // test.
 type Mock struct {
 	impl
 }
 
+// WaitingMock is a logger that stores all messages in memory to be examined by a test with methods
+type WaitingMock struct {
+	impl
+}
+
 // Mock implements the writer interface. It
 // stores all logged messages in a buffer for inspection by test
 // functions (via GetAll()) instead of sending them to syslog.
@@ -108,3 +121,39 @@ func (m *Mock) Clear() {
 	w := m.w.(*mockWriter)
 	w.clearChan <- struct{}{}
 }
+
+type waitingMockWriter struct {
+	logChan chan string
+}
+
+// newWaitingMockWriter returns a new waitingMockWriter
+func newWaitingMockWriter() *waitingMockWriter {
+	logChan := make(chan string, 1000)
+	return &waitingMockWriter{
+		logChan,
+	}
+}
+
+func (m *waitingMockWriter) logAtLevel(p syslog.Priority, msg string) {
+	m.logChan <- fmt.Sprintf("%s: %s", levelName[p&7], msg)
+}
+
+// WaitForMatch returns the first log line matching a regex. It accepts a
+// regexp string and timeout. If the timeout value is met before the
+// matching pattern is read from the channel, an error is returned.
+func (m *WaitingMock) WaitForMatch(reString string, timeout time.Duration) (string, error) {
+	w := m.w.(*waitingMockWriter)
+	deadline := time.After(timeout)
+	re := regexp.MustCompile(reString)
+	for {
+		select {
+		case logLine := <-w.logChan:
+			if re.MatchString(logLine) {
+				close(w.logChan)
+				return logLine, nil
+			}
+		case <-deadline:
+			return "", fmt.Errorf("timeout waiting for match: %q", reString)
+		}
+	}
+}