Merge branch 'main' into add-jitter-ari-retry-after-header

Author: maen-bn

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/ca_test.go

@@ -157,7 +157,6 @@ func newCAArgs(t *testing.T) *caArgs {
 	issuers := make([]*issuance.Issuer, 4)
 	for i, name := range []string{"int-r3", "int-r4", "int-e1", "int-e2"} {
 		issuers[i], err = issuance.LoadIssuer(issuance.IssuerConfig{
-			Active:     true,
 			IssuerURL:  fmt.Sprintf("http://not-example.com/i/%s", name),
 			CRLURLBase: fmt.Sprintf("http://not-example.com/c/%s/", name),
 			CRLShards:  10,
@@ -880,16 +879,19 @@ func TestPickIssuer_Inactive(t *testing.T) {
 	// Load our own set of issuers, but with half of them inactive.
 	var issuers []*issuance.Issuer
 	for i, name := range []string{"int-r3", "int-r4", "int-e1", "int-e2"} {
+		var profiles []string
+		if i%2 == 0 {
+			profiles = []string{"legacy", "modern"}
+		}
 		issuer, err := issuance.LoadIssuer(issuance.IssuerConfig{
-			Active:     i%2 == 0,
 			IssuerURL:  fmt.Sprintf("http://not-example.com/i/%s", name),
 			CRLURLBase: fmt.Sprintf("http://not-example.com/c/%s/", name),
 			CRLShards:  10,
 			Location: issuance.IssuerLoc{
 				File:     fmt.Sprintf("../test/hierarchy/%s.key.pem", name),
 				CertFile: fmt.Sprintf("../test/hierarchy/%s.cert.pem", name),
 			},
-			Profiles: []string{"legacy", "modern"},
+			Profiles: profiles,
 		}, cargs.clk)
 		if err != nil {
 			t.Fatalf("loading test issuer: %s", err)

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() {