Add caa-log-checker tool (letsencrypt#4804)

Adds a productionized version of our internal tooling to the tree. The
major differences are: it doesn't skip certs with only one name, it
doesn't read in all the va logs in parallel, it only supports reading
one ra log at a time, and it adds unit tests.

Probably it should include a integration test, but that requires
capturing logs on the docker container, which I don't think we currently
do? Probably would make for a good follow-up issue.

Fixes letsencrypt#4698.

cmd/caa-log-checker/main.go

@@ -0,0 +1,172 @@
+package main
+
+import (
+	"bufio"
+	"compress/gzip"
+	"encoding/json"
+	"flag"
+	"fmt"
+	"io"
+	"os"
+	"regexp"
+	"strings"
+	"time"
+
+	"github.com/letsencrypt/boulder/cmd"
+)
+
+func openFile(path string) (*bufio.Scanner, error) {
+	f, err := os.Open(path)
+	if err != nil {
+		return nil, err
+	}
+	var reader io.Reader
+	reader = f
+	if strings.HasSuffix(path, ".gz") {
+		reader, err = gzip.NewReader(f)
+		if err != nil {
+			return nil, err
+		}
+	}
+	scanner := bufio.NewScanner(reader)
+	return scanner, nil
+}
+
+type issuanceEvent struct {
+	SerialNumber string
+	Names        []string
+	Requester    int64
+
+	issuanceTime time.Time
+}
+
+var raIssuanceLineRE = regexp.MustCompile(`Certificate request - successful JSON=(.*)`)
+
+func parseTimestamp(line string) (time.Time, error) {
+	datestampText := line[0:32]
+	datestamp, err := time.Parse(time.RFC3339, datestampText)
+	if err != nil {
+		return time.Time{}, err
+	}
+	return datestamp, nil
+}
+
+func checkIssuances(scanner *bufio.Scanner, checkedMap map[string][]time.Time, stderr *os.File) error {
+	lNum := 0
+	for scanner.Scan() {
+		lNum++
+		line := scanner.Text()
+		matches := raIssuanceLineRE.FindStringSubmatch(line)
+		if matches == nil {
+			continue
+		}
+		if len(matches) != 2 {
+			return fmt.Errorf("line %d: unexpected number of regex matches", lNum)
+		}
+		var ie issuanceEvent
+		err := json.Unmarshal([]byte(matches[1]), &ie)
+		if err != nil {
+			return fmt.Errorf("line %d: failed to unmarshal JSON: %s", lNum, err)
+		}
+
+		// populate the issuance time from the syslog timestamp, rather than the ResponseTime
+		// member of the JSON. This makes testing a lot simpler because of how we mess with
+		// time sometimes. Given these timestamps are generated on the same system they should
+		// be tightly coupled anyway.
+		ie.issuanceTime, err = parseTimestamp(line)
+		if err != nil {
+			return fmt.Errorf("line %d: failed to parse timestamp: %s", lNum, err)
+		}
+
+		var badNames []string
+		for _, name := range ie.Names {
+			nameOk := false
+			for _, t := range checkedMap[name] {
+				if t.Before(ie.issuanceTime) && t.After(ie.issuanceTime.Add(-8*time.Hour)) {
+					nameOk = true
+				}
+			}
+			if !nameOk {
+				badNames = append(badNames, name)
+			}
+		}
+		if len(badNames) > 0 {
+			fmt.Fprintf(stderr, "Issuance missing CAA checks: issued at=%s, serial=%s, requester=%d, names=%s, missing checks for names=%s\n", ie.issuanceTime, ie.SerialNumber, ie.Requester, ie.Names, badNames)
+		}
+	}
+	if err := scanner.Err(); err != nil {
+		return err
+	}
+	return nil
+}
+
+var vaCAALineRE = regexp.MustCompile(`Checked CAA records for ([a-z0-9-.*]+), \[Present: (true|false)`)
+
+func processVALog(checkedMap map[string][]time.Time, scanner *bufio.Scanner) error {
+	lNum := 0
+	for scanner.Scan() {
+		lNum++
+		line := scanner.Text()
+		matches := vaCAALineRE.FindStringSubmatch(line)
+		if matches == nil {
+			continue
+		}
+		if len(matches) != 3 {
+			return fmt.Errorf("line %d: unexpected number of regex matches", lNum)
+		}
+		domain := matches[1]
+		labels := strings.Split(domain, ".")
+		present := matches[2]
+
+		datestamp, err := parseTimestamp(line)
+		if err != nil {
+			return fmt.Errorf("line %d: failed to parse timestamp: %s", lNum, err)
+		}
+
+		checkedMap[domain] = append(checkedMap[domain], datestamp)
+		// If we checked x.y.z, and the result was Present: false, that means we
+		// also checked y.z and z, and found no records there.
+		// We'll add y.z to the map, but not z (to save memory space, since we don't issue
+		// for z).
+		if present == "false" {
+			for i := 1; i < len(labels)-1; i++ {
+				parent := strings.Join(labels[i:], ".")
+				checkedMap[parent] = append(checkedMap[parent], datestamp)
+			}
+		}
+	}
+	return scanner.Err()
+}
+
+func loadMap(paths []string) (map[string][]time.Time, error) {
+	var checkedMap = make(map[string][]time.Time)
+
+	for _, path := range paths {
+		scanner, err := openFile(path)
+		if err != nil {
+			return nil, fmt.Errorf("failed to open %q: %s", path, err)
+		}
+		if err = processVALog(checkedMap, scanner); err != nil {
+			return nil, fmt.Errorf("failed to process %q: %s", path, err)
+		}
+	}
+
+	return checkedMap, nil
+}
+
+func main() {
+	raLog := flag.String("ra-log", "", "Path to a single boulder-ra log file")
+	vaLogs := flag.String("va-logs", "", "List of paths to boulder-va logs, separated by commas")
+	flag.Parse()
+
+	// Build a map from hostnames to a list of times those hostnames were checked
+	// for CAA.
+	checkedMap, err := loadMap(strings.Split(*vaLogs, ","))
+	cmd.FailOnError(err, "failed while loading VA logs")
+
+	raScanner, err := openFile(*raLog)
+	cmd.FailOnError(err, fmt.Sprintf("failed to open %q", *raLog))
+
+	err = checkIssuances(raScanner, checkedMap, os.Stderr)
+	cmd.FailOnError(err, "failed while processing RA log")
+}

cmd/caa-log-checker/main_test.go

@@ -0,0 +1,126 @@
+package main
+
+import (
+	"bufio"
+	"bytes"
+	"compress/gzip"
+	"fmt"
+	"io/ioutil"
+	"os"
+	"testing"
+	"time"
+
+	"github.com/letsencrypt/boulder/test"
+)
+
+func TestOpenFile(t *testing.T) {
+	tmpPlain, err := ioutil.TempFile(os.TempDir(), "plain")
+	test.AssertNotError(t, err, "failed to create temporary file")
+	defer os.Remove(tmpPlain.Name())
+	_, err = tmpPlain.Write([]byte("test-1\ntest-2"))
+	test.AssertNotError(t, err, "failed to write to temp file")
+	tmpPlain.Close()
+
+	tmpGzip, err := ioutil.TempFile(os.TempDir(), "gzip-*.gz")
+	test.AssertNotError(t, err, "failed to create temporary file")
+	defer os.Remove(tmpGzip.Name())
+	gzipWriter := gzip.NewWriter(tmpGzip)
+	_, err = gzipWriter.Write([]byte("test-1\ntest-2"))
+	test.AssertNotError(t, err, "failed to write to temp file")
+	gzipWriter.Flush()
+	gzipWriter.Close()
+	tmpGzip.Close()
+
+	checkFile := func(path string) {
+		t.Helper()
+		scanner, err := openFile(path)
+		test.AssertNotError(t, err, fmt.Sprintf("failed to open %q", path))
+		var lines []string
+		for scanner.Scan() {
+			lines = append(lines, scanner.Text())
+		}
+		test.AssertNotError(t, scanner.Err(), fmt.Sprintf("failed to read from %q", path))
+		test.AssertEquals(t, len(lines), 2)
+		test.AssertDeepEquals(t, lines, []string{"test-1", "test-2"})
+	}
+
+	checkFile(tmpPlain.Name())
+	checkFile(tmpGzip.Name())
+}
+
+func TestLoadMap(t *testing.T) {
+	testTime := time.Time{}.Add(time.Hour).Add(time.Nanosecond * 123456000)
+	testTime = testTime.In(time.FixedZone("UTC-8", -8*60*60))
+
+	tmpA, err := ioutil.TempFile(os.TempDir(), "va-a")
+	test.AssertNotError(t, err, "failed to create temporary file")
+	defer os.Remove(tmpA.Name())
+	formattedTime := testTime.Format(time.RFC3339Nano)
+	_, err = tmpA.Write([]byte(fmt.Sprintf(`random
+%s Checked CAA records for example.com, [Present: true, asd
+random
+%s Checked CAA records for beep.boop.com, [Present: false, asd`, formattedTime, formattedTime)))
+	test.AssertNotError(t, err, "failed to write to temp file")
+	tmpA.Close()
+	tmpB, err := ioutil.TempFile(os.TempDir(), "va-b")
+	test.AssertNotError(t, err, "failed to create temporary file")
+	defer os.Remove(tmpB.Name())
+	formattedTime = testTime.Add(time.Hour).Format(time.RFC3339Nano)
+	_, err = tmpB.Write([]byte(fmt.Sprintf(`random
+%s Checked CAA records for example.com, [Present: true, asd
+random
+%s Checked CAA records for beep.boop.com, [Present: false, asd`, formattedTime, formattedTime)))
+	test.AssertNotError(t, err, "failed to write to temp file")
+	tmpB.Close()
+
+	m, err := loadMap([]string{tmpA.Name(), tmpB.Name()})
+	test.AssertNotError(t, err, "fail to load log files")
+	test.AssertEquals(t, len(m), 3)
+	test.Assert(t, m["example.com"][0].Equal(testTime), "wrong time")
+	test.Assert(t, m["example.com"][1].Equal(testTime.Add(time.Hour)), "wrong time")
+	test.Assert(t, m["beep.boop.com"][0].Equal(testTime), "wrong time")
+	test.Assert(t, m["beep.boop.com"][1].Equal(testTime.Add(time.Hour)), "wrong time")
+	test.Assert(t, m["boop.com"][0].Equal(testTime), "wrong time")
+	test.Assert(t, m["boop.com"][1].Equal(testTime.Add(time.Hour)), "wrong time")
+}
+
+func TestCheckIssuances(t *testing.T) {
+	testTime := time.Time{}.Add(time.Hour).Add(time.Nanosecond * 123456000)
+	testTime = testTime.In(time.FixedZone("UTC-8", -8*60*60))
+
+	checkedMap := map[string][]time.Time{
+		"example.com": {
+			testTime.Add(time.Hour),
+			testTime.Add(3 * time.Hour),
+		},
+		"2.example.com": {
+			testTime.Add(time.Hour),
+		},
+		"4.example.com": {
+			testTime.Add(time.Hour),
+		},
+	}
+
+	raBuf := bytes.NewBuffer([]byte(fmt.Sprintf(`random
+%s Certificate request - successful JSON={"SerialNumber": "1", "Names":["example.com"], "Requester":0}
+random
+%s Certificate request - successful JSON={"SerialNumber": "2", "Names":["2.example.com", "3.example.com"], "Requester":0}
+%s Certificate request - successful JSON={"SerialNumber": "3", "Names":["4.example.com"], "Requester":0}
+random`,
+		testTime.Add(time.Hour*2).Format(time.RFC3339Nano),
+		testTime.Add(time.Hour*2).Format(time.RFC3339Nano),
+		testTime.Format(time.RFC3339Nano),
+	)))
+	raScanner := bufio.NewScanner(raBuf)
+
+	stderr, err := ioutil.TempFile(os.TempDir(), "stderr")
+	test.AssertNotError(t, err, "failed creating temporary file")
+	defer os.Remove(stderr.Name())
+
+	err = checkIssuances(raScanner, checkedMap, stderr)
+	test.AssertNotError(t, err, "checkIssuances failed")
+
+	stderrCont, err := ioutil.ReadFile(stderr.Name())
+	test.AssertNotError(t, err, "failed to read temporary file")
+	test.AssertEquals(t, string(stderrCont), "Issuance missing CAA checks: issued at=0000-12-31 19:00:00.123456 -0800 -0800, serial=2, requester=0, names=[2.example.com 3.example.com], missing checks for names=[3.example.com]\nIssuance missing CAA checks: issued at=0000-12-31 17:00:00.123456 -0800 -0800, serial=3, requester=0, names=[4.example.com], missing checks for names=[4.example.com]\n")
+}

test/integration/caa_test.go

@@ -0,0 +1,53 @@
+// +build integration
+
+package integration
+
+import (
+	"bytes"
+	"io/ioutil"
+	"os"
+	"os/exec"
+	"testing"
+
+	"github.com/letsencrypt/boulder/test"
+)
+
+func TestCAALogChecker(t *testing.T) {
+	t.Parallel()
+
+	os.Setenv("DIRECTORY", "http://boulder:4001/directory")
+	c, err := makeClient()
+	test.AssertNotError(t, err, "makeClient failed")
+
+	domains := []string{random_domain()}
+	result, err := authAndIssue(c, nil, domains)
+	test.AssertNotError(t, err, "authAndIssue failed")
+	test.AssertEquals(t, result.Order.Status, "valid")
+	test.AssertEquals(t, len(result.Order.Authorizations), 1)
+
+	// Should be no specific output, since everything is good
+	cmd := exec.Command("bin/caa-log-checker", "-ra-log", "/var/log/boulder-ra.log", "-va-logs", "/var/log/boulder-va.log")
+	var stdErr bytes.Buffer
+	cmd.Stderr = &stdErr
+	out, err := cmd.Output()
+	test.AssertNotError(t, err, "caa-log-checker failed")
+	test.AssertEquals(t, string(out), "")
+	test.AssertEquals(t, stdErr.String(), "")
+
+	// Should be output, issuances in boulder-ra.log won't match an empty
+	// va log. Because we can't control what happens before this test
+	// we don't know how many issuances there have been. We just
+	// test for caa-log-checker outputting _something_ since any
+	// output, with a 0 exit code, indicates it's found bad issuances.
+	tmp, err := ioutil.TempFile(os.TempDir(), "boulder-va-empty")
+	test.AssertNotError(t, err, "failed to create temporary file")
+	defer os.Remove(tmp.Name())
+	cmd = exec.Command("bin/caa-log-checker", "-ra-log", "/var/log/boulder-ra.log", "-va-logs", tmp.Name())
+	stdErr.Reset()
+	cmd.Stderr = &stdErr
+	out, err = cmd.Output()
+	test.AssertNotError(t, err, "caa-log-checker failed")
+
+	test.AssertEquals(t, string(out), "")
+	test.AssertNotEquals(t, stdErr.String(), "")
+}