Fix error logging in issueCertificate. (#3534)

The logEvent setup we had in issueCertificate depending on all error
handling code setting logEvent.Error in addition to returning the error.
Since this is not the common pattern in Go, there were a few places
where logEvent.Error wasn't set, making it hard to find the root cause
of errors in the RA logs (though the errors would get propagated to the
WFE for logging). This change wraps issueCertificate such that all
errors returned get logged.

ra/ra.go

@@ -960,32 +960,42 @@ func (ra *RegistrationAuthorityImpl) NewCertificate(ctx context.Context, req cor
 type accountID int64
 type orderID int64
 
-// issueCertificate handles the common aspects of certificate issuance used by
-// both the "classic" NewCertificate endpoint (for ACME v1) and the
-// FinalizeOrder endpoint (for ACME v2).
+// issueCertificate sets up a log event structure and captures any errors
+// encountered during issuance, then calls issueCertificateInner.
 func (ra *RegistrationAuthorityImpl) issueCertificate(
 	ctx context.Context,
 	req core.CertificateRequest,
 	acctID accountID,
 	oID orderID) (core.Certificate, error) {
-	emptyCert := core.Certificate{}
-
-	// Assume the worst
-	logEventResult := "error"
-
 	// Construct the log event
 	logEvent := certificateRequestEvent{
 		ID:          core.NewToken(),
 		OrderID:     int64(oID),
 		Requester:   int64(acctID),
 		RequestTime: ra.clk.Now(),
 	}
+	var result string
+	cert, err := ra.issueCertificateInner(ctx, req, acctID, oID, &logEvent)
+	if err != nil {
+		logEvent.Error = err.Error()
+		result = "error"
+	} else {
+		result = "successful"
+	}
+	ra.log.AuditObject(fmt.Sprintf("Certificate request - %s", result), logEvent)
+	return cert, err
+}
 
-	// No matter what, log the request
-	defer func() {
-		ra.log.AuditObject(fmt.Sprintf("Certificate request - %s", logEventResult), logEvent)
-	}()
-
+// issueCertificateInner handles the common aspects of certificate issuance used by
+// both the "classic" NewCertificate endpoint (for ACME v1) and the
+// FinalizeOrder endpoint (for ACME v2).
+func (ra *RegistrationAuthorityImpl) issueCertificateInner(
+	ctx context.Context,
+	req core.CertificateRequest,
+	acctID accountID,
+	oID orderID,
+	logEvent *certificateRequestEvent) (core.Certificate, error) {
+	emptyCert := core.Certificate{}
 	if acctID <= 0 {
 		return emptyCert, berrors.MalformedError("invalid account ID: %d", acctID)
 	}
@@ -998,7 +1008,6 @@ func (ra *RegistrationAuthorityImpl) issueCertificate(
 
 	account, err := ra.SA.GetRegistration(ctx, int64(acctID))
 	if err != nil {
-		logEvent.Error = err.Error()
 		return emptyCert, err
 	}
 
@@ -1011,16 +1020,14 @@ func (ra *RegistrationAuthorityImpl) issueCertificate(
 	copy(names, csr.DNSNames)
 
 	if core.KeyDigestEquals(csr.PublicKey, account.Key) {
-		err = berrors.MalformedError("certificate public key must be different than account key")
-		return emptyCert, err
+		return emptyCert, berrors.MalformedError("certificate public key must be different than account key")
 	}
 
 	// Check rate limits before checking authorizations. If someone is unable to
 	// issue a cert due to rate limiting, we don't want to tell them to go get the
 	// necessary authorizations, only to later fail the rate limit check.
 	err = ra.checkLimits(ctx, names, account.ID)
 	if err != nil {
-		logEvent.Error = err.Error()
 		return emptyCert, err
 	}
 
@@ -1035,7 +1042,6 @@ func (ra *RegistrationAuthorityImpl) issueCertificate(
 		err = ra.checkOrderAuthorizations(ctx, names, acctID, oID)
 	}
 	if err != nil {
-		logEvent.Error = err.Error()
 		return emptyCert, err
 	}
 
@@ -1052,7 +1058,6 @@ func (ra *RegistrationAuthorityImpl) issueCertificate(
 	}
 	cert, err := ra.CA.IssueCertificate(ctx, issueReq)
 	if err != nil {
-		logEvent.Error = err.Error()
 		return emptyCert, err
 	}
 
@@ -1069,14 +1074,11 @@ func (ra *RegistrationAuthorityImpl) issueCertificate(
 	if err != nil {
 		// berrors.InternalServerError because the certificate from the CA should be
 		// parseable.
-		err = berrors.InternalServerError("failed to parse certificate: %s", err.Error())
-		logEvent.Error = err.Error()
-		return emptyCert, err
+		return emptyCert, berrors.InternalServerError("failed to parse certificate: %s", err.Error())
 	}
 
 	err = ra.MatchesCSR(parsedCertificate, csr)
 	if err != nil {
-		logEvent.Error = err.Error()
 		return emptyCert, err
 	}
 
@@ -1087,8 +1089,6 @@ func (ra *RegistrationAuthorityImpl) issueCertificate(
 	logEvent.NotAfter = parsedCertificate.NotAfter
 	logEvent.ResponseTime = now
 
-	logEventResult = "successful"
-
 	issuanceExpvar.Set(now.Unix())
 	ra.stats.Inc("NewCertificates", 1)
 	return cert, nil