Make caa-log-checker run over docker logs (#6388)

This uncovered a bug! The stdout logger was truncating the microseconds part
of its timestamp if the last digit was zero. Fixed that. Also coerced the
stdout logger to use UTC.

To run the checker over our integration test logs, I changed t.sh to use
an explicit name for the container that runs boulder during the tests,
and pulled logs from that container after the tests.

.github/workflows/boulder-ci.yml

@@ -42,7 +42,7 @@ jobs:
         tests:
           # Run ./test.sh --help for a description of each of the flags.
           - "./t.sh --lints --generate --make-artifacts"
-          - "./t.sh --integration"
+          - "./t.sh --integration && ./test/test-caa-log-checker.sh"
           # Testing Config Changes:
           # Config changes that have landed in main but not yet been applied to
           # production can be made in `test/config-next/<component>.json`.

log/log.go

@@ -250,7 +250,7 @@ func (w *stdoutWriter) logAtLevel(level syslog.Priority, msg string) {
 
 		if _, err := fmt.Fprintf(output, "%s%s %s %d %s %s%s\n",
 			color,
-			w.clk.Now().Format("2006-01-02T15:04:05.999999+07:00"),
+			w.clk.Now().UTC().Format("2006-01-02T15:04:05.000000+00:00Z"),
 			w.prefix,
 			int(level),
 			path.Base(os.Args[0]),

log/log_test.go

@@ -99,8 +99,8 @@ func TestStdoutLogger(t *testing.T) {
 	logger.Warning("Warning log")
 	logger.Info("Info log")
 
-	test.AssertEquals(t, stdout.String(), "1970-01-01T00:00:00+07:00  6 log.test pcbo7wk Info log\n")
-	test.AssertEquals(t, stderr.String(), "1970-01-01T00:00:00+07:00  3 log.test 46_ghQg [AUDIT] Error Audit\n1970-01-01T00:00:00+07:00  4 log.test 97r2xAw Warning log\n")
+	test.AssertEquals(t, stdout.String(), "1970-01-01T00:00:00.000000+00:00Z  6 log.test pcbo7wk Info log\n")
+	test.AssertEquals(t, stderr.String(), "1970-01-01T00:00:00.000000+00:00Z  3 log.test 46_ghQg [AUDIT] Error Audit\n1970-01-01T00:00:00.000000+00:00Z  4 log.test 97r2xAw Warning log\n")
 }
 
 func TestSyslogMethods(t *testing.T) {

t.sh

@@ -5,4 +5,7 @@
 if type realpath >/dev/null 2>&1 ; then
   cd "$(realpath -- $(dirname -- "$0"))"
 fi
-exec docker-compose run boulder ./test.sh "$@"
+# Use a predictable name for the container so we can grab the logs later
+# for use when testing logs analysis tools.
+docker rm boulder_tests
+exec docker-compose run --name boulder_tests boulder ./test.sh "$@"

test/test-caa-log-checker.sh

@@ -0,0 +1,30 @@
+#!/usr/bin/env bash
+#
+# Run the CAA log checker over logs from an integration tests run.
+#
+# We verify two things:
+#  - It should succeed when given the full output as both RA logs and VA logs.
+#  - It should fail when given RA logs (containing issuances) but empty VA logs
+#    (containing CAA checks).
+#
+
+set -x
+
+LOGFILE=/tmp/boulder.log
+
+# We rely on the integration tests previously having been run with a container
+# name of "boulder_tests". See ../t.sh.
+docker logs boulder_tests > ${LOGFILE}
+
+# Expect success
+./bin/caa-log-checker -ra-log ${LOGFILE} -va-logs ${LOGFILE}
+
+# Expect error
+./bin/caa-log-checker -ra-log ${LOGFILE} -va-logs /dev/null >/tmp/output 2>&1 &&
+  (echo "caa-log-checker succeeded when it should have failed. Output:";
+   cat /tmp/output;
+   exit 9)
+
+# Explicitly exit zero so the status code from the intentionally-erroring last
+# command doesn't wind up as the overall status code for this script.
+exit 0