Upgrade all audit log lines to structured json (#8595)

In the log package, remove all audit-level helper functions except for
AuditErr and AuditObject, and rename the latter to AuditInfo to reflect
its log level. Update both of those helpers to take arbitrary sets of
key-value pairs (a map in the case of AuditErr, or any object in the
case of AuditInfo to support our existing logEvent structs), which they
then log as a JSON object.

Throughout the rest of the code base, modify all audit log calls which
are broken by the above change. In some cases, downgrade the log line
from an audit log to a normal log, as it does not represent an event
which the BRs require us to log and which we are not already logging
elsewhere. In other cases, provide a map of key-value pairs to be
included in the log message.

Finally, update a small number of tests that were expecting very
specific log message formats to be emitted.

Fixes #8554

Author: aarongable

ca/ca.go

@@ -312,7 +312,7 @@ func (ca *certificateAuthorityImpl) IssueCertificate(ctx context.Context, req *c
 
 	lintPrecertDER, issuanceToken, err := issuer.Prepare(profile, precertReq)
 	if err != nil {
-		ca.log.AuditErrf("Preparing precert failed: serial=[%s] err=[%v]", serialHex, err)
+		ca.log.AuditErr("Preparing precert failed", err, map[string]any{"serial": serialHex})
 		if errors.Is(err, linter.ErrLinting) {
 			ca.metrics.lintErrorCount.Inc()
 		}
@@ -334,7 +334,7 @@ func (ca *certificateAuthorityImpl) IssueCertificate(ctx context.Context, req *c
 		return nil, fmt.Errorf("persisting linting precert to database: %w", err)
 	}
 
-	ca.log.AuditObject("Signing precert", issuanceEvent{
+	ca.log.AuditInfo("Signing precert", issuanceEvent{
 		Requester:       req.RegistrationID,
 		OrderID:         req.OrderID,
 		Profile:         req.CertProfileName,
@@ -346,12 +346,12 @@ func (ca *certificateAuthorityImpl) IssueCertificate(ctx context.Context, req *c
 	precertDER, err := issuer.Issue(issuanceToken)
 	if err != nil {
 		ca.metrics.noteSignError(err)
-		ca.log.AuditErrf("Signing precert failed: serial=[%s] err=[%v]", serialHex, err)
+		ca.log.AuditErr("Signing precert failed", err, map[string]any{"serial": serialHex})
 		return nil, fmt.Errorf("failed to sign precertificate: %w", err)
 	}
 	ca.metrics.signatureCount.With(prometheus.Labels{"purpose": string(precertType), "issuer": issuer.Name()}).Inc()
 
-	ca.log.AuditObject("Signing precert success", issuanceEvent{
+	ca.log.AuditInfo("Signing precert success", issuanceEvent{
 		Requester:       req.RegistrationID,
 		OrderID:         req.OrderID,
 		Profile:         req.CertProfileName,
@@ -408,11 +408,11 @@ func (ca *certificateAuthorityImpl) IssueCertificate(ctx context.Context, req *c
 
 	lintCertDER, issuanceToken, err := issuer.Prepare(profile, certReq)
 	if err != nil {
-		ca.log.AuditErrf("Preparing cert failed: serial=[%s] err=[%v]", serialHex, err)
+		ca.log.AuditErr("Preparing cert failed", err, map[string]any{"serial": serialHex})
 		return nil, fmt.Errorf("failed to prepare certificate signing: %w", err)
 	}
 
-	ca.log.AuditObject("Signing cert", issuanceEvent{
+	ca.log.AuditInfo("Signing cert", issuanceEvent{
 		Requester:       req.RegistrationID,
 		OrderID:         req.OrderID,
 		Profile:         req.CertProfileName,
@@ -423,13 +423,13 @@ func (ca *certificateAuthorityImpl) IssueCertificate(ctx context.Context, req *c
 	certDER, err := issuer.Issue(issuanceToken)
 	if err != nil {
 		ca.metrics.noteSignError(err)
-		ca.log.AuditErrf("Signing cert failed: serial=[%s] err=[%v]", serialHex, err)
+		ca.log.AuditErr("Signing cert failed", err, map[string]any{"serial": serialHex})
 		return nil, fmt.Errorf("failed to sign certificate: %w", err)
 	}
 	ca.metrics.signatureCount.With(prometheus.Labels{"purpose": string(certType), "issuer": issuer.Name()}).Inc()
 	ca.metrics.certificates.With(prometheus.Labels{"profile": req.CertProfileName}).Inc()
 
-	ca.log.AuditObject("Signing cert success", issuanceEvent{
+	ca.log.AuditInfo("Signing cert success", issuanceEvent{
 		Requester:       req.RegistrationID,
 		OrderID:         req.OrderID,
 		Profile:         req.CertProfileName,
@@ -449,7 +449,7 @@ func (ca *certificateAuthorityImpl) IssueCertificate(ctx context.Context, req *c
 		Issued: timestamppb.New(ca.clk.Now()),
 	})
 	if err != nil {
-		ca.log.AuditErrf("Failed RPC to store at SA: serial=[%s] err=[%v]", serialHex, err)
+		ca.log.AuditErr("Storing cert failed", err, map[string]any{"serial": serialHex})
 		return nil, fmt.Errorf("persisting cert to database: %w", err)
 	}
 
@@ -491,7 +491,7 @@ func (ca *certificateAuthorityImpl) generateSerialNumber() (*big.Int, error) {
 	_, err := rand.Read(serialBytes[1:])
 	if err != nil {
 		err = berrors.InternalServerError("failed to generate serial: %s", err)
-		ca.log.AuditErrf("Serial randomness failed, err=[%v]", err)
+		ca.log.AuditErr("Serial randomness failed", err, nil)
 		return nil, err
 	}
 	serialBigInt := big.NewInt(0)

ca/crl.go

@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"io"
 	"strings"
+	"time"
 
 	"google.golang.org/grpc"
 
@@ -117,28 +118,32 @@ func (ci *crlImpl) GenerateCRL(stream grpc.BidiStreamingServer[capb.GenerateCRLR
 	// Compute a unique ID for this issuer-number-shard combo, to tie together all
 	// the audit log lines related to its issuance.
 	logID := blog.LogLineChecksum(fmt.Sprintf("%d", issuer.NameID()) + req.Number.String() + fmt.Sprintf("%d", req.Shard))
-	ci.log.AuditInfof(
-		"Signing CRL: logID=[%s] issuer=[%s] number=[%s] shard=[%d] thisUpdate=[%s] numEntries=[%d]",
-		logID, issuer.Cert.Subject.CommonName, req.Number.String(), req.Shard, req.ThisUpdate, len(rcs),
-	)
+	ci.log.AuditInfo("Signing CRL", map[string]any{
+		"logID":      logID,
+		"issuer":     issuer.Cert.Subject.CommonName,
+		"number":     req.Number.String(),
+		"shard":      req.Shard,
+		"thisUpdate": req.ThisUpdate.Format(time.RFC3339),
+		"numEntries": len(rcs),
+	})
 
 	if len(rcs) > 0 {
 		builder := strings.Builder{}
 		for i := range len(rcs) {
-			if builder.Len() == 0 {
-				fmt.Fprintf(&builder, "Signing CRL: logID=[%s] entries=[", logID)
-			}
-
-			fmt.Fprintf(&builder, "%x:%d,", rcs[i].SerialNumber.Bytes(), rcs[i].ReasonCode)
+			fmt.Fprintf(&builder, "\"%x:%d\",", rcs[i].SerialNumber.Bytes(), rcs[i].ReasonCode)
 
 			if builder.Len() >= ci.maxLogLen {
-				fmt.Fprint(&builder, "]")
-				ci.log.AuditInfo(builder.String())
+				ci.log.AuditInfo("Signing CRL entries", map[string]string{
+					"logID":   logID,
+					"entries": fmt.Sprintf("[%s]", strings.TrimSuffix(builder.String(), ",")),
+				})
 				builder = strings.Builder{}
 			}
 		}
-		fmt.Fprint(&builder, "]")
-		ci.log.AuditInfo(builder.String())
+		ci.log.AuditInfo("Signing CRL entries", map[string]any{
+			"logID":   logID,
+			"entries": fmt.Sprintf("[%s]", strings.TrimSuffix(builder.String(), ",")),
+		})
 	}
 
 	req.Entries = rcs
@@ -151,10 +156,11 @@ func (ci *crlImpl) GenerateCRL(stream grpc.BidiStreamingServer[capb.GenerateCRLR
 	ci.metrics.signatureCount.With(prometheus.Labels{"purpose": "crl", "issuer": issuer.Name()}).Inc()
 
 	hash := sha256.Sum256(crlBytes)
-	ci.log.AuditInfof(
-		"Signing CRL success: logID=[%s] size=[%d] hash=[%x]",
-		logID, len(crlBytes), hash,
-	)
+	ci.log.AuditInfo("Signing CRL success", map[string]any{
+		"logID": logID,
+		"size":  len(crlBytes),
+		"hash":  fmt.Sprintf("%x", hash),
+	})
 
 	for i := 0; i < len(crlBytes); i += 1000 {
 		j := min(i+1000, len(crlBytes))

cmd/admin/key.go

@@ -180,7 +180,7 @@ func (a *admin) spkiHashFromCSRPEM(filename string, checkSignature bool, expecte
 		return nil, fmt.Errorf("no PEM data found in %q", filename)
 	}
 
-	a.log.AuditInfof("Parsing key to block from CSR PEM: %x", data)
+	a.log.Debugf("Parsing key to block from CSR PEM: %x", data)
 
 	csr, err := x509.ParseCertificateRequest(data.Bytes)
 	if err != nil {

cmd/admin/main.go

@@ -131,18 +131,18 @@ func main() {
 
 	// Finally, run the selected subcommand.
 	if *dryRun {
-		a.log.AuditInfof("admin tool executing a dry-run with the following arguments: %q", strings.Join(os.Args, " "))
+		a.log.Infof("admin tool executing a dry-run with the following arguments: %q", strings.Join(os.Args, " "))
 	} else {
-		a.log.AuditInfof("admin tool executing with the following arguments: %q", strings.Join(os.Args, " "))
+		a.log.AuditInfo("admin tool beginning execution", map[string]any{"cmd": strings.Join(os.Args, " ")})
 	}
 
 	err = subcommand.Run(context.Background(), a)
 	cmd.FailOnError(err, "executing subcommand")
 
 	if *dryRun {
-		a.log.AuditInfof("admin tool has successfully completed executing a dry-run with the following arguments: %q", strings.Join(os.Args, " "))
+		a.log.Infof("admin tool has successfully completed executing a dry-run with the following arguments: %q", strings.Join(os.Args, " "))
 		a.log.Info("Dry run complete. Pass -dry-run=false to mutate the database.")
 	} else {
-		a.log.AuditInfof("admin tool has successfully completed executing with the following arguments: %q", strings.Join(os.Args, " "))
+		a.log.AuditInfo("admin tool completed successfully", map[string]any{"cmd": strings.Join(os.Args, " ")})
 	}
 }

cmd/admin/overrides_import.go

@@ -7,9 +7,10 @@ import (
 	"fmt"
 	"sync"
 
+	"google.golang.org/protobuf/types/known/durationpb"
+
 	"github.com/letsencrypt/boulder/ratelimits"
 	sapb "github.com/letsencrypt/boulder/sa/proto"
-	"google.golang.org/protobuf/types/known/durationpb"
 )
 
 type subcommandImportOverrides struct {
@@ -70,7 +71,7 @@ func (c *subcommandImportOverrides) Run(ctx context.Context, a *admin) error {
 	for range overrideCount {
 		result := <-results
 		if result.err != nil {
-			a.log.AuditErrf("failed to add override: key=%q limit=%d: %s", result.ov.BucketKey, result.ov.LimitEnum, result.err)
+			a.log.Errf("failed to add override: key=%q limit=%d: %s", result.ov.BucketKey, result.ov.LimitEnum, result.err)
 			errorCount++
 		}
 	}

cmd/bad-key-revoker/main.go

@@ -194,21 +194,29 @@ func (bkr *badKeyRevoker) revokeCerts(certs []unrevokedCertificate) error {
 
 // invoke exits early and returns true if there is no work to be done.
 // Otherwise, it processes a single key in the blockedKeys table and returns false.
-func (bkr *badKeyRevoker) invoke(ctx context.Context) (bool, error) {
+func (bkr *badKeyRevoker) invoke(ctx context.Context) (work bool, err error) {
+	logEvent := make(map[string]any)
+	defer func() {
+		if err != nil {
+			bkr.logger.AuditErr("Error while processing bad key", err, logEvent)
+		} else {
+			bkr.logger.AuditInfo("Processed bad key", logEvent)
+		}
+	}()
+
 	// Gather a count of rows to be processed.
 	uncheckedCount, err := bkr.countUncheckedKeys(ctx)
 	if err != nil {
 		return false, err
 	}
+	logEvent["keysToProcess"] = uncheckedCount
 
 	// Set the gauge to the number of rows to be processed (max:
 	// blockedKeysGaugeLimit).
 	bkr.keysToProcess.Set(float64(uncheckedCount))
 
 	if uncheckedCount >= blockedKeysGaugeLimit {
-		bkr.logger.AuditInfof("found >= %d unchecked blocked keys left to process", uncheckedCount)
-	} else {
-		bkr.logger.AuditInfof("found %d unchecked blocked keys left to process", uncheckedCount)
+		logEvent["keysToProcessOverflow"] = true
 	}
 
 	// select a row to process
@@ -219,17 +227,17 @@ func (bkr *badKeyRevoker) invoke(ctx context.Context) (bool, error) {
 		}
 		return false, err
 	}
-	bkr.logger.AuditInfof("found unchecked block key to work on: %s", unchecked)
+	logEvent["keyHash"] = fmt.Sprintf("%x", unchecked.KeyHash)
+	logEvent["revokedBy"] = unchecked.RevokedBy
 
 	// select all unrevoked, unexpired serials associated with the blocked key hash
 	unrevokedCerts, err := bkr.findUnrevoked(ctx, unchecked)
 	if err != nil {
-		bkr.logger.AuditInfof("finding unrevoked certificates related to %s: %s", unchecked, err)
 		return false, err
 	}
+	logEvent["certsToProcess"] = len(unrevokedCerts)
+
 	if len(unrevokedCerts) == 0 {
-		bkr.logger.AuditInfof("found no certificates that need revoking related to %s, marking row as checked", unchecked)
-		// mark row as checked
 		err = bkr.markRowChecked(ctx, unchecked)
 		if err != nil {
 			return false, err
@@ -241,7 +249,7 @@ func (bkr *badKeyRevoker) invoke(ctx context.Context) (bool, error) {
 	for _, cert := range unrevokedCerts {
 		serials = append(serials, cert.Serial)
 	}
-	bkr.logger.AuditInfof("revoking serials %v for key with hash %x", serials, unchecked.KeyHash)
+	logEvent["serials"] = serials
 
 	// revoke each certificate
 	err = bkr.revokeCerts(unrevokedCerts)
@@ -384,13 +392,11 @@ func main() {
 		noWork, err := bkr.invoke(context.Background())
 		if err != nil {
 			keysProcessed.WithLabelValues("error").Inc()
-			logger.AuditErrf("failed to process blockedKeys row: %s", err)
 			// Calculate and sleep for a backoff interval
 			bkr.backoff()
 			continue
 		}
 		if noWork {
-			logger.Info("no work to do")
 			// Calculate and sleep for a backoff interval
 			bkr.backoff()
 		} else {

cmd/cert-checker/main.go

@@ -172,7 +172,11 @@ func (c *certChecker) findStartingID(ctx context.Context, begin, end time.Time)
 			},
 		)
 		if err != nil {
-			c.logger.AuditErrf("finding starting certificate: %s", err)
+			c.logger.AuditErr("finding starting certificate", err, map[string]any{
+				"begin":   queryBegin.Format(time.RFC3339),
+				"end":     queryEnd.Format(time.RFC3339),
+				"attempt": retries + 1,
+			})
 			retries++
 			time.Sleep(core.RetryBackoff(retries, time.Second, time.Minute, 2))
 			continue
@@ -234,7 +238,12 @@ func (c *certChecker) getCerts(ctx context.Context) error {
 			},
 		)
 		if err != nil {
-			c.logger.AuditErrf("selecting certificates: %s", err)
+			c.logger.AuditErr("selecting certificates", err, map[string]any{
+				"begin":        c.issuedReport.begin.Format(time.RFC3339),
+				"end":          c.issuedReport.end.Format(time.RFC3339),
+				"batchStartID": batchStartID,
+				"attempt":      retries + 1,
+			})
 			retries++
 			time.Sleep(core.RetryBackoff(retries, time.Second, time.Minute, 2))
 			continue
@@ -519,7 +528,7 @@ func (c *certChecker) checkCert(ctx context.Context, cert *corepb.Certificate) (
 				for _, ident := range idents {
 					identValues = append(identValues, ident.Value)
 				}
-				c.logger.AuditErrf("Certificate %s %s: %s", cert.Serial, identValues, err)
+				c.logger.Warningf("Certificate %s %s: %s", cert.Serial, identValues, err)
 			}
 		}
 	}

cmd/crl-checker/main.go

@@ -139,9 +139,12 @@ func main() {
 		cmd.Fail(fmt.Sprintf("Encountered %d errors", errCount))
 	}
 
-	logger.AuditInfof(
-		"Validated %d CRLs, %d serials, %d bytes. Oldest CRL: %s",
-		len(urls), len(seenSerials), totalBytes, oldestTimestamp.Format(time.RFC3339))
+	logger.AuditInfo("CRL checking complete", map[string]string{
+		"numCRLs":    fmt.Sprintf("%d", len(urls)),
+		"numSerials": fmt.Sprintf("%d", len(seenSerials)),
+		"numBytes":   fmt.Sprintf("%d", totalBytes),
+		"oldestCRL":  oldestTimestamp.Format(time.RFC3339),
+	})
 }
 
 func init() {

cmd/shell.go

@@ -304,10 +304,7 @@ func newStatsRegistry(addr string, logger blog.Logger) prometheus.Registerer {
 	}
 	go func() {
 		err := server.ListenAndServe()
-		if err != nil {
-			logger.AuditErrf("Unable to boot debug server on %s: %v", addr, err)
-			os.Exit(1)
-		}
+		FailOnError(err, "Unable to boot debug server")
 	}()
 	return registry
 }
@@ -362,7 +359,7 @@ func AuditPanic() {
 	err := recover()
 	// No panic, no problem
 	if err == nil {
-		blog.Get().AuditObject("Process exiting normally", info())
+		blog.Get().AuditInfo("Process exiting normally", info())
 		return
 	}
 	// Get the global logger if it's initialized, or create a default one if not.
@@ -372,12 +369,14 @@ func AuditPanic() {
 	// For the special type `failure`, audit log the message and exit quietly
 	fail, ok := err.(failure)
 	if ok {
-		log.AuditErr(fail.msg)
+		log.AuditErr(fail.msg, nil, nil)
 	} else {
-		// For all other values passed to `panic`, log them and a stack trace
-		log.AuditErrf("Panic caused by err: %s", err)
-
-		log.AuditErrf("Stack Trace (Current goroutine) %s", debug.Stack())
+		// For all other values (which might not be an error) passed to `panic`, log
+		// them and a stack trace
+		log.AuditErr("Panic", nil, map[string]any{
+			"panic": fmt.Sprintf("%#v", err),
+			"stack": string(debug.Stack()),
+		})
 	}
 	// Because this function is deferred as early as possible, there's no further defers to run after this one
 	// So it is safe to os.Exit to set the exit code and exit without losing any defers we haven't executed.
@@ -550,7 +549,7 @@ func info() buildInfo {
 }
 
 func LogStartup(logger blog.Logger) {
-	logger.AuditObject("Process starting", info())
+	logger.AuditInfo("Process starting", info())
 }
 
 // CatchSignals blocks until a SIGTERM, SIGINT, or SIGHUP is received, then

cmd/shell_test.go

@@ -309,6 +309,6 @@ func TestPanicStackTrace(t *testing.T) {
 	output, err := cmd.CombinedOutput()
 	test.AssertError(t, err, "running a failing program")
 	test.AssertContains(t, string(output), "nil pointer dereference")
-	test.AssertContains(t, string(output), "Stack Trace")
+	test.AssertContains(t, string(output), "runtime/debug.Stack()")
 	test.AssertContains(t, string(output), "cmd/shell_test.go:")
 }