Reduce chance of log-validator having runaway output. (#4926)

cmd/log-validator/main.go

@@ -8,6 +8,7 @@ import (
 	"io/ioutil"
 	"os"
 	"strings"
+	"time"
 
 	"github.com/hpcloud/tail"
 	"github.com/prometheus/client_golang/prometheus"
@@ -36,16 +37,23 @@ func lineValid(text string) error {
 	//   timestamp hostname datacenter syslogseverity binary-name[pid]: checksum msg
 
 	fields := strings.Split(text, " ")
+	const errorPrefix = "log-validator: "
 	// Extract checksum from line
 	if len(fields) < 6 {
-		return errors.New("line doesn't match expected format")
+		return fmt.Errorf("%sline doesn't match expected format", errorPrefix)
 	}
 	checksum := fields[5]
 	// Reconstruct just the message portion of the line
 	line := strings.Join(fields[6:], " ")
+
+	// If we are fed our own output, treat it as always valid. This
+	// prevents runaway scenarios where we generate ever-longer output.
+	if strings.Contains(text, errorPrefix) {
+		return nil
+	}
 	// Check the extracted checksum against the computed checksum
 	if computedChecksum := blog.LogLineChecksum(line); checksum != computedChecksum {
-		return fmt.Errorf("invalid checksum (expected %q, got %q)", computedChecksum, checksum)
+		return fmt.Errorf("%s invalid checksum (expected %q, got %q)", errorPrefix, computedChecksum, checksum)
 	}
 	return nil
 }
@@ -133,6 +141,11 @@ func main() {
 	}, []string{"filename", "status"})
 	stats.MustRegister(lineCounter)
 
+	// Emit no more than 1 error line per second. This prevents consuming large
+	// amounts of disk space in case there is problem that causes all log lines to
+	// be invalid.
+	outputLimiter := time.NewTicker(time.Second)
+
 	var tailers []*tail.Tail
 	for _, filename := range config.Files {
 		t, err := tail.TailFile(filename, tail.Config{
@@ -151,7 +164,11 @@ func main() {
 				}
 				if err := lineValid(line.Text); err != nil {
 					lineCounter.WithLabelValues(t.Filename, "bad").Inc()
-					logger.Errf("%s: %s %q", t.Filename, err, line.Text)
+					select {
+					case <-outputLimiter.C:
+						logger.Errf("%s: %s %q", t.Filename, err, line.Text)
+					default:
+					}
 				} else {
 					lineCounter.WithLabelValues(t.Filename, "ok").Inc()
 				}

cmd/log-validator/main_test.go

@@ -0,0 +1,26 @@
+package main
+
+import (
+	"testing"
+
+	"github.com/letsencrypt/boulder/test"
+)
+
+func TestLineValidAccepts(t *testing.T) {
+	err := lineValid("2020-07-06T18:07:43.109389+00:00 70877f679c72 datacenter 6 boulder-wfe[1595]: kKG6cwA Caught SIGTERM")
+	test.AssertNotError(t, err, "errored on valid checksum")
+}
+
+func TestLineValidRejects(t *testing.T) {
+	err := lineValid("2020-07-06T18:07:43.109389+00:00 70877f679c72 datacenter 6 boulder-wfe[1595]: xxxxxxx Caught SIGTERM")
+	test.AssertError(t, err, "didn't error on invalid checksum")
+}
+
+func TestLineValidNonOurobouros(t *testing.T) {
+	err := lineValid("2020-07-06T18:07:43.109389+00:00 70877f679c72 datacenter 6 boulder-wfe[1595]: xxxxxxx Caught SIGTERM")
+	test.AssertError(t, err, "didn't error on invalid checksum")
+
+	selfOutput := "2020-07-06T18:07:43.109389+00:00 70877f679c72 datacenter 6 log-validator[1337]: xxxxxxx " + err.Error()
+	err2 := lineValid(selfOutput)
+	test.AssertNotError(t, err2, "expected no error when feeding lineValid's error output into itself")
+}