ca: log cert signing using JSON objects (#7742)

This makes the log events easier to parse, and makes it easier to
consistently use the correct fields from the issuance request.

Also, reduce the number of fields that are logged on error events.
Logging just the serial and the error in most cases should suffice to
cross-reference the error with the item that we attempted to sign.

One downside is that this increases the total log size (10kB above, vs
7kB from a similar production issuance) due in part to more repetition.
For example, both the "signing cert" and "signing cert success" log
lines include the full precert DER.

Note that our long-term plan for more structured logs is to have a
unique event id to join logs on, which can avoid this repetition. But
since we don't currently have convenient ways to do that join, some
duplication (as we currently have in the logs) seems reasonable.

Author: jsha

ca/ca.go

@@ -15,7 +15,6 @@ import (
 	"fmt"
 	"math/big"
 	mrand "math/rand/v2"
-	"strings"
 	"time"
 
 	ct "github.com/google/certificate-transparency-go"
@@ -51,6 +50,25 @@ const (
 	certType    = certificateType("certificate")
 )
 
+// issuanceEvent is logged before and after issuance of precertificates and certificates.
+// The `omitempty` fields are not always present.
+// CSR, Precertificate, and Certificate are hex-encoded DER bytes to make it easier to
+// ad-hoc search for sequences or OIDs in logs. Other data, like public key within CSR,
+// is logged as base64 because it doesn't have interesting DER structure.
+type issuanceEvent struct {
+	CSR             string `json:",omitempty"`
+	IssuanceRequest *issuance.IssuanceRequest
+	Issuer          string
+	OrderID         int64
+	Profile         string
+	ProfileHash     string
+	Requester       int64
+	Result          struct {
+		Precertificate string `json:",omitempty"`
+		Certificate    string `json:",omitempty"`
+	}
+}
+
 // Two maps of keys to Issuers. Lookup by PublicKeyAlgorithm is useful for
 // determining the set of issuers which can sign a given (pre)cert, based on its
 // PublicKeyAlgorithm. Lookup by NameID is useful for looking up a specific
@@ -428,17 +446,22 @@ func (ca *certificateAuthorityImpl) IssueCertificateForPrecertificate(ctx contex
 		return nil, err
 	}
 
-	names := strings.Join(issuanceReq.DNSNames, ", ")
-	ca.log.AuditInfof("Signing cert: issuer=[%s] serial=[%s] regID=[%d] names=[%s] certProfileName=[%s] certProfileHash=[%x] precert=[%s]",
-		issuer.Name(), serialHex, req.RegistrationID, names, certProfile.name, certProfile.hash, hex.EncodeToString(precert.Raw))
-
 	lintCertBytes, issuanceToken, err := issuer.Prepare(certProfile.profile, issuanceReq)
 	if err != nil {
-		ca.log.AuditErrf("Preparing cert failed: issuer=[%s] serial=[%s] regID=[%d] names=[%s] certProfileName=[%s] certProfileHash=[%x] err=[%v]",
-			issuer.Name(), serialHex, req.RegistrationID, names, certProfile.name, certProfile.hash, err)
+		ca.log.AuditErrf("Preparing cert failed: serial=[%s] err=[%v]", serialHex, err)
 		return nil, berrors.InternalServerError("failed to prepare certificate signing: %s", err)
 	}
 
+	logEvent := issuanceEvent{
+		IssuanceRequest: issuanceReq,
+		Issuer:          issuer.Name(),
+		OrderID:         req.OrderID,
+		Profile:         certProfile.name,
+		ProfileHash:     hex.EncodeToString(certProfile.hash[:]),
+		Requester:       req.RegistrationID,
+	}
+	ca.log.AuditObject("Signing cert", logEvent)
+
 	_, span := ca.tracer.Start(ctx, "signing cert", trace.WithAttributes(
 		attribute.String("serial", serialHex),
 		attribute.String("issuer", issuer.Name()),
@@ -448,8 +471,7 @@ func (ca *certificateAuthorityImpl) IssueCertificateForPrecertificate(ctx contex
 	certDER, err := issuer.Issue(issuanceToken)
 	if err != nil {
 		ca.metrics.noteSignError(err)
-		ca.log.AuditErrf("Signing cert failed: issuer=[%s] serial=[%s] regID=[%d] names=[%s] certProfileName=[%s] certProfileHash=[%x] err=[%v]",
-			issuer.Name(), serialHex, req.RegistrationID, names, certProfile.name, certProfile.hash, err)
+		ca.log.AuditErrf("Signing cert failed: serial=[%s] err=[%v]", serialHex, err)
 		span.SetStatus(codes.Error, err.Error())
 		span.End()
 		return nil, berrors.InternalServerError("failed to sign certificate: %s", err)
@@ -462,17 +484,16 @@ func (ca *certificateAuthorityImpl) IssueCertificateForPrecertificate(ctx contex
 	}
 
 	ca.metrics.signatureCount.With(prometheus.Labels{"purpose": string(certType), "issuer": issuer.Name()}).Inc()
-	ca.log.AuditInfof("Signing cert success: issuer=[%s] serial=[%s] regID=[%d] names=[%s] certificate=[%s] certProfileName=[%s] certProfileHash=[%x]",
-		issuer.Name(), serialHex, req.RegistrationID, names, hex.EncodeToString(certDER), certProfile.name, certProfile.hash)
+	logEvent.Result.Certificate = hex.EncodeToString(certDER)
+	ca.log.AuditObject("Signing cert success", logEvent)
 
 	_, err = ca.sa.AddCertificate(ctx, &sapb.AddCertificateRequest{
 		Der:    certDER,
 		RegID:  req.RegistrationID,
 		Issued: timestamppb.New(ca.clk.Now()),
 	})
 	if err != nil {
-		ca.log.AuditErrf("Failed RPC to store at SA: issuer=[%s] serial=[%s] cert=[%s] regID=[%d] orderID=[%d] certProfileName=[%s] certProfileHash=[%x] err=[%v]",
-			issuer.Name(), serialHex, hex.EncodeToString(certDER), req.RegistrationID, req.OrderID, certProfile.name, certProfile.hash, err)
+		ca.log.AuditErrf("Failed RPC to store at SA: serial=[%s] err=[%v]", serialHex, hex.EncodeToString(certDER))
 		return nil, err
 	}
 
@@ -568,7 +589,7 @@ func (ca *certificateAuthorityImpl) issuePrecertificateInner(ctx context.Context
 
 	names := csrlib.NamesFromCSR(csr)
 	req := &issuance.IssuanceRequest{
-		PublicKey:         csr.PublicKey,
+		PublicKey:         issuance.MarshalablePublicKey{PublicKey: csr.PublicKey},
 		SubjectKeyId:      subjectKeyId,
 		Serial:            serialBigInt.Bytes(),
 		DNSNames:          names.SANs,
@@ -579,13 +600,9 @@ func (ca *certificateAuthorityImpl) issuePrecertificateInner(ctx context.Context
 		NotAfter:          notAfter,
 	}
 
-	ca.log.AuditInfof("Signing precert: serial=[%s] regID=[%d] names=[%s] csr=[%s]",
-		serialHex, issueReq.RegistrationID, strings.Join(req.DNSNames, ", "), hex.EncodeToString(csr.Raw))
-
 	lintCertBytes, issuanceToken, err := issuer.Prepare(certProfile.profile, req)
 	if err != nil {
-		ca.log.AuditErrf("Preparing precert failed: issuer=[%s] serial=[%s] regID=[%d] names=[%s] certProfileName=[%s] certProfileHash=[%x] err=[%v]",
-			issuer.Name(), serialHex, issueReq.RegistrationID, strings.Join(req.DNSNames, ", "), certProfile.name, certProfile.hash, err)
+		ca.log.AuditErrf("Preparing precert failed: serial=[%s] err=[%v]", serialHex, err)
 		if errors.Is(err, linter.ErrLinting) {
 			ca.metrics.lintErrorCount.Inc()
 		}
@@ -608,6 +625,17 @@ func (ca *certificateAuthorityImpl) issuePrecertificateInner(ctx context.Context
 		return nil, nil, err
 	}
 
+	logEvent := issuanceEvent{
+		CSR:             hex.EncodeToString(csr.Raw),
+		IssuanceRequest: req,
+		Issuer:          issuer.Name(),
+		Profile:         certProfile.name,
+		ProfileHash:     hex.EncodeToString(certProfile.hash[:]),
+		Requester:       issueReq.RegistrationID,
+		OrderID:         issueReq.OrderID,
+	}
+	ca.log.AuditObject("Signing precert", logEvent)
+
 	_, span := ca.tracer.Start(ctx, "signing precert", trace.WithAttributes(
 		attribute.String("serial", serialHex),
 		attribute.String("issuer", issuer.Name()),
@@ -617,8 +645,7 @@ func (ca *certificateAuthorityImpl) issuePrecertificateInner(ctx context.Context
 	certDER, err := issuer.Issue(issuanceToken)
 	if err != nil {
 		ca.metrics.noteSignError(err)
-		ca.log.AuditErrf("Signing precert failed: issuer=[%s] serial=[%s] regID=[%d] names=[%s] certProfileName=[%s] certProfileHash=[%x] err=[%v]",
-			issuer.Name(), serialHex, issueReq.RegistrationID, strings.Join(req.DNSNames, ", "), certProfile.name, certProfile.hash, err)
+		ca.log.AuditErrf("Signing precert failed: serial=[%s] err=[%v]", serialHex, err)
 		span.SetStatus(codes.Error, err.Error())
 		span.End()
 		return nil, nil, berrors.InternalServerError("failed to sign precertificate: %s", err)
@@ -631,8 +658,11 @@ func (ca *certificateAuthorityImpl) issuePrecertificateInner(ctx context.Context
 	}
 
 	ca.metrics.signatureCount.With(prometheus.Labels{"purpose": string(precertType), "issuer": issuer.Name()}).Inc()
-	ca.log.AuditInfof("Signing precert success: issuer=[%s] serial=[%s] regID=[%d] names=[%s] precert=[%s] certProfileName=[%s] certProfileHash=[%x]",
-		issuer.Name(), serialHex, issueReq.RegistrationID, strings.Join(req.DNSNames, ", "), hex.EncodeToString(certDER), certProfile.name, certProfile.hash)
+
+	logEvent.Result.Precertificate = hex.EncodeToString(certDER)
+	// The CSR is big and not that informative, so don't log it a second time.
+	logEvent.CSR = ""
+	ca.log.AuditObject("Signing precert success", logEvent)
 
 	return certDER, &certProfileWithID{certProfile.name, certProfile.hash, nil}, nil
 }

ca/ca_test.go

@@ -332,7 +332,6 @@ func TestIssuePrecertificate(t *testing.T) {
 
 				var certDER []byte
 				response, err := ca.IssuePrecertificate(ctx, issueReq)
-
 				test.AssertNotError(t, err, "Failed to issue precertificate")
 				certDER = response.DER
 

issuance/cert.go

@@ -9,6 +9,7 @@ import (
 	"crypto/x509"
 	"crypto/x509/pkix"
 	"encoding/asn1"
+	"encoding/json"
 	"errors"
 	"fmt"
 	"math/big"
@@ -153,7 +154,7 @@ func (p *Profile) GenerateValidity(now time.Time) (time.Time, time.Time) {
 // requestValid verifies the passed IssuanceRequest against the profile. If the
 // request doesn't match the signing profile an error is returned.
 func (i *Issuer) requestValid(clk clock.Clock, prof *Profile, req *IssuanceRequest) error {
-	switch req.PublicKey.(type) {
+	switch req.PublicKey.PublicKey.(type) {
 	case *rsa.PublicKey, *ecdsa.PublicKey:
 	default:
 		return errors.New("unsupported public key type")
@@ -261,12 +262,36 @@ var mustStapleExt = pkix.Extension{
 	Value: []byte{0x30, 0x03, 0x02, 0x01, 0x05},
 }
 
+// MarshalablePublicKey is a wrapper for crypto.PublicKey with a custom JSON
+// marshaller that encodes the public key as a DER-encoded SubjectPublicKeyInfo.
+type MarshalablePublicKey struct {
+	crypto.PublicKey
+}
+
+func (pk MarshalablePublicKey) MarshalJSON() ([]byte, error) {
+	keyDER, err := x509.MarshalPKIXPublicKey(pk.PublicKey)
+	if err != nil {
+		return nil, err
+	}
+	return json.Marshal(keyDER)
+}
+
+type HexMarshalableBytes []byte
+
+func (h HexMarshalableBytes) MarshalJSON() ([]byte, error) {
+	return json.Marshal(fmt.Sprintf("%x", h))
+}
+
 // IssuanceRequest describes a certificate issuance request
+//
+// It can be marshaled as JSON for logging purposes, though note that sctList and precertDER
+// will be omitted from the marshaled output because they are unexported.
 type IssuanceRequest struct {
-	PublicKey    crypto.PublicKey
-	SubjectKeyId []byte
+	// PublicKey is of type MarshalablePublicKey so we can log an IssuanceRequest as a JSON object.
+	PublicKey    MarshalablePublicKey
+	SubjectKeyId HexMarshalableBytes
 
-	Serial []byte
+	Serial HexMarshalableBytes
 
 	NotBefore time.Time
 	NotAfter  time.Time
@@ -294,7 +319,7 @@ type IssuanceRequest struct {
 type issuanceToken struct {
 	mu       sync.Mutex
 	template *x509.Certificate
-	pubKey   any
+	pubKey   MarshalablePublicKey
 	// A pointer to the issuer that created this token. This token may only
 	// be redeemed by the same issuer.
 	issuer *Issuer
@@ -335,7 +360,7 @@ func (i *Issuer) Prepare(prof *Profile, req *IssuanceRequest) ([]byte, *issuance
 	}
 	template.DNSNames = req.DNSNames
 
-	switch req.PublicKey.(type) {
+	switch req.PublicKey.PublicKey.(type) {
 	case *rsa.PublicKey:
 		if prof.omitKeyEncipherment {
 			template.KeyUsage = x509.KeyUsageDigitalSignature
@@ -371,7 +396,7 @@ func (i *Issuer) Prepare(prof *Profile, req *IssuanceRequest) ([]byte, *issuance
 
 	// check that the tbsCertificate is properly formed by signing it
 	// with a throwaway key and then linting it using zlint
-	lintCertBytes, err := i.Linter.Check(template, req.PublicKey, prof.lints)
+	lintCertBytes, err := i.Linter.Check(template, req.PublicKey.PublicKey, prof.lints)
 	if err != nil {
 		return nil, nil, fmt.Errorf("tbsCertificate linting failed: %w", err)
 	}
@@ -406,7 +431,7 @@ func (i *Issuer) Issue(token *issuanceToken) ([]byte, error) {
 		return nil, errors.New("tried to redeem issuance token with the wrong issuer")
 	}
 
-	return x509.CreateCertificate(rand.Reader, template, i.Cert.Certificate, token.pubKey, i.Signer)
+	return x509.CreateCertificate(rand.Reader, template, i.Cert.Certificate, token.pubKey.PublicKey, i.Signer)
 }
 
 // ContainsMustStaple returns true if the provided set of extensions includes
@@ -441,7 +466,7 @@ func RequestFromPrecert(precert *x509.Certificate, scts []ct.SignedCertificateTi
 		return nil, errors.New("provided certificate doesn't contain the CT poison extension")
 	}
 	return &IssuanceRequest{
-		PublicKey:         precert.PublicKey,
+		PublicKey:         MarshalablePublicKey{precert.PublicKey},
 		SubjectKeyId:      precert.SubjectKeyId,
 		Serial:            precert.SerialNumber.Bytes(),
 		NotBefore:         precert.NotBefore,