From 7d04ea98cf4a4300975149f75de3526bc398be30 Mon Sep 17 00:00:00 2001 From: Jeff Hodges Date: Thu, 15 Oct 2015 17:53:50 -0700 Subject: [PATCH 01/25] add context to WFE errors This change makes the use of requestEvent more prominent and provides some nice handler types to make that better. In order to avoid stomping on Error, requestEvent gains an Errors string slice. Fixes #552 --- wfe/context.go | 85 ++++++++ wfe/web-front-end.go | 427 ++++++++++++++++---------------------- wfe/web-front-end_test.go | 87 ++++---- 3 files changed, 317 insertions(+), 282 deletions(-) create mode 100644 wfe/context.go diff --git a/wfe/context.go b/wfe/context.go new file mode 100644 index 000000000..83646e08e --- /dev/null +++ b/wfe/context.go @@ -0,0 +1,85 @@ +package wfe + +import ( + "fmt" + "net/http" + "time" + + "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" + "github.com/letsencrypt/boulder/core" + blog "github.com/letsencrypt/boulder/log" +) + +type requestEvent struct { + ID string `json:",omitempty"` + RealIP string `json:",omitempty"` + ClientAddr string `json:",omitempty"` + Endpoint string `json:",omitempty"` + Method string `json:",omitempty"` + RequestTime time.Time `json:",omitempty"` + ResponseTime time.Time `json:",omitempty"` + Errors []string + Requester int64 `json:",omitempty"` + Contacts []*core.AcmeURL `json:",omitempty"` + + Extra map[string]interface{} `json:",omitempty"` +} + +func (e *requestEvent) AddError(msg string, args ...interface{}) { + e.Errors = append(e.Errors, fmt.Sprintf(msg, args...)) +} + +type wfeHandlerFunc func(*requestEvent, http.ResponseWriter, *http.Request) + +func (f wfeHandlerFunc) ServeHTTP(e *requestEvent, w http.ResponseWriter, r *http.Request) { + f(e, w, r) +} + +type wfeHandler interface { + ServeHTTP(e *requestEvent, w http.ResponseWriter, r *http.Request) +} + +type wfeTopHandler struct { + h wfeHandler + log *blog.AuditLogger + clk clock.Clock +} + +func (t *wfeTopHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { + logEvent := &requestEvent{ + ID: core.NewToken(), + RealIP: r.Header.Get("X-Real-IP"), + ClientAddr: getClientAddr(r), + Method: r.Method, + RequestTime: time.Now(), + Extra: make(map[string]interface{}, 0), + } + if r.URL != nil { + logEvent.Endpoint = r.URL.String() + } + defer t.logEvent(logEvent) + + t.h.ServeHTTP(logEvent, w, r) +} + +func (t *wfeTopHandler) logEvent(logEvent *requestEvent) { + logEvent.ResponseTime = t.clk.Now() + var msg string + if len(logEvent.Errors) != 0 { + msg = "Terminated request" + } else { + msg = "Successful request" + } + t.log.InfoObject(msg, logEvent) +} + +// Comma-separated list of HTTP clients involved in making this +// request, starting with the original requestor and ending with the +// remote end of our TCP connection (which is typically our own +// proxy). +func getClientAddr(r *http.Request) string { + if xff := r.Header.Get("X-Forwarded-For"); xff != "" { + return xff + "," + r.RemoteAddr + } + return r.RemoteAddr +} diff --git a/wfe/web-front-end.go b/wfe/web-front-end.go index b54d45c61..4d78e9cf7 100644 --- a/wfe/web-front-end.go +++ b/wfe/web-front-end.go @@ -19,6 +19,7 @@ import ( "time" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cactus/go-statsd-client/statsd" + "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" jose "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/letsencrypt/go-jose" "github.com/letsencrypt/boulder/core" blog "github.com/letsencrypt/boulder/log" @@ -115,21 +116,6 @@ func statusCodeFromError(err interface{}) int { } } -type requestEvent struct { - ID string `json:",omitempty"` - RealIP string `json:",omitempty"` - ClientAddr string `json:",omitempty"` - Endpoint string `json:",omitempty"` - Method string `json:",omitempty"` - RequestTime time.Time `json:",omitempty"` - ResponseTime time.Time `json:",omitempty"` - Error string `json:",omitempty"` - Requester int64 `json:",omitempty"` - Contacts []*core.AcmeURL `json:",omitempty"` - - Extra map[string]interface{} `json:",omitempty"` -} - // NewWebFrontEndImpl constructs a web service for Boulder func NewWebFrontEndImpl(stats statsd.Statter) (WebFrontEndImpl, error) { logger := blog.GetAuditLogger() @@ -173,7 +159,7 @@ func (mrw BodylessResponseWriter) Write(buf []byte) (int, error) { // * Never send a body in response to a HEAD request. Anything // written by the handler will be discarded if the method is HEAD. // Also, all handlers that accept GET automatically accept HEAD. -func (wfe *WebFrontEndImpl) HandleFunc(mux *http.ServeMux, pattern string, h func(http.ResponseWriter, *http.Request), methods ...string) { +func (wfe *WebFrontEndImpl) HandleFunc(mux *http.ServeMux, pattern string, h wfeHandlerFunc, methods ...string) { methodsMap := make(map[string]bool) for _, m := range methods { methodsMap[m] = true @@ -184,38 +170,41 @@ func (wfe *WebFrontEndImpl) HandleFunc(mux *http.ServeMux, pattern string, h fun methodsMap["HEAD"] = true } methodsStr := strings.Join(methods, ", ") - mux.HandleFunc(pattern, func(response http.ResponseWriter, request *http.Request) { - // We do not propagate errors here, because (1) they should be - // transient, and (2) they fail closed. - nonce, err := wfe.nonceService.Nonce() - if err == nil { - response.Header().Set("Replay-Nonce", nonce) - } + mux.Handle(pattern, &wfeTopHandler{ + log: wfe.log, + clk: clock.Default(), + h: wfeHandlerFunc(func(e *requestEvent, response http.ResponseWriter, request *http.Request) { + // We do not propagate errors here, because (1) they should be + // transient, and (2) they fail closed. + nonce, err := wfe.nonceService.Nonce() + if err == nil { + response.Header().Set("Replay-Nonce", nonce) + } - switch request.Method { - case "HEAD": - // Whether or not we're sending a 405 error, - // we should comply with HTTP spec by not - // sending a body. - response = BodylessResponseWriter{response} - case "OPTIONS": - wfe.Options(response, request, methodsStr, methodsMap) - return - } + switch request.Method { + case "HEAD": + // Whether or not we're sending a 405 error, + // we should comply with HTTP spec by not + // sending a body. + response = BodylessResponseWriter{response} + case "OPTIONS": + wfe.Options(response, request, methodsStr, methodsMap) + return + } - if !methodsMap[request.Method] { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) - logEvent.Error = "Method not allowed" - response.Header().Set("Allow", methodsStr) - wfe.sendError(response, logEvent.Error, request.Method, http.StatusMethodNotAllowed) - return - } + if !methodsMap[request.Method] { + msg := "Method not allowed" + e.AddError(msg) + response.Header().Set("Allow", methodsStr) + wfe.sendError(response, msg, request.Method, http.StatusMethodNotAllowed) + return + } - wfe.setCORSHeaders(response, request, "") + wfe.setCORSHeaders(response, request, "") - // Call the wrapped handler. - h(response, request) + // Call the wrapped handler. + h(e, response, request) + }), }) } @@ -259,29 +248,30 @@ func (wfe *WebFrontEndImpl) Handler() (http.Handler, error) { // We don't use our special HandleFunc for "/" because it matches everything, // meaning we can wind up returning 405 when we mean to return 404. See // https://github.com/letsencrypt/boulder/issues/717 - m.HandleFunc("/", wfe.Index) + m.Handle("/", &wfeTopHandler{ + log: wfe.log, + clk: clock.Default(), + h: wfeHandlerFunc(wfe.Index), + }) return m, nil } // Method implementations // Index serves a simple identification page. It is not part of the ACME spec. -func (wfe *WebFrontEndImpl) Index(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) - +func (wfe *WebFrontEndImpl) Index(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { // http://golang.org/pkg/net/http/#example_ServeMux_Handle // The "/" pattern matches everything, so we need to check // that we're at the root here. if request.URL.Path != "/" { - logEvent.Error = "Resource not found" + logEvent.AddError("Resource not found") http.NotFound(response, request) response.Header().Set("Content-Type", "application/problem+json") return } if request.Method != "GET" { - logEvent.Error = "Bad method" + logEvent.AddError("Bad method") response.Header().Set("Allow", "GET") response.WriteHeader(http.StatusMethodNotAllowed) return @@ -309,7 +299,7 @@ func addCacheHeader(w http.ResponseWriter, age float64) { // Directory is an HTTP request handler that simply provides the directory // object stored in the WFE's DirectoryJSON member. -func (wfe *WebFrontEndImpl) Directory(response http.ResponseWriter, request *http.Request) { +func (wfe *WebFrontEndImpl) Directory(e *requestEvent, response http.ResponseWriter, request *http.Request) { response.Header().Set("Content-Type", "application/json") response.Write(wfe.DirectoryJSON) } @@ -326,39 +316,44 @@ const ( ) // verifyPOST reads and parses the request body, looks up the Registration -// corresponding to its JWK, verifies the JWS signature, -// checks that the resource field is present and correct in the JWS protected -// header, and returns the JWS payload bytes, the key used to verify, and the -// corresponding Registration (or error). -// If regCheck is false, verifyPOST will still try to look up a registration -// object, and will return it if found. However, if no registration object is -// found, verifyPOST will attempt to verify the JWS using the key in the JWS -// headers, and return the key plus a dummy registration if successful. If a -// caller passes regCheck = false, it should plan on validating the key itself. -func (wfe *WebFrontEndImpl) verifyPOST(request *http.Request, regCheck bool, resource core.AcmeResource) ([]byte, *jose.JsonWebKey, core.Registration, error) { +// corresponding to its JWK, verifies the JWS signature, checks that the +// resource field is present and correct in the JWS protected header, and +// returns the JWS payload bytes, the key used to verify, and the corresponding +// Registration (or error). If regCheck is false, verifyPOST will still try to +// look up a registration object, and will return it if found. However, if no +// registration object is found, verifyPOST will attempt to verify the JWS using +// the key in the JWS headers, and return the key plus a dummy registration if +// successful. If a caller passes regCheck = false, it should plan on validating +// the key itself. verifyPOST also appends its errors to requestEvent.Errors so +// code calling it does not need to if they imediately return a response to the +// user. +func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, regCheck bool, resource core.AcmeResource) ([]byte, *jose.JsonWebKey, core.Registration, error) { var err error // TODO: We should return a pointer to a registration, which can be nil, // rather the a registration value with a sentinel value. // https://github.com/letsencrypt/boulder/issues/877 - reg := core.Registration{ID: -1} + reg := core.Registration{ID: 0} if _, ok := request.Header["Content-Length"]; !ok { err = core.LengthRequiredError("Content-Length header is required for POST.") - wfe.log.Debug(err.Error()) + wfe.stats.Inc("WFE.HTTP.ClientErrors.LengthRequiredError", 1, 1.0) + e.AddError("missing Content-Length header on POST") return nil, nil, reg, err } // Read body if request.Body == nil { err = core.MalformedRequestError("No body on POST") - wfe.log.Debug(err.Error()) + wfe.stats.Inc("WFE.Errors.NoPOSTBody", 1, 1.0) + e.AddError("no body on POST") return nil, nil, reg, err } bodyBytes, err := ioutil.ReadAll(request.Body) if err != nil { - err = core.InternalServerError(err.Error()) - wfe.log.Debug(err.Error()) + err = core.InternalServerError("unable to read request body") + wfe.stats.Inc("WFE.Errors.UnableToReadRequestBody", 1, 1.0) + e.AddError("unable to read request body") return nil, nil, reg, err } @@ -367,7 +362,8 @@ func (wfe *WebFrontEndImpl) verifyPOST(request *http.Request, regCheck bool, res parsedJws, err := jose.ParseSigned(body) if err != nil { puberr := core.SignatureValidationError("Parse error reading JWS") - wfe.log.Debug(fmt.Sprintf("%v :: %v", puberr.Error(), err.Error())) + wfe.stats.Inc("WFE.Errors.UnableToParseJWS", 1, 1.0) + e.AddError("could not JSON parse body into JWS: %s", err) return nil, nil, reg, puberr } @@ -378,19 +374,22 @@ func (wfe *WebFrontEndImpl) verifyPOST(request *http.Request, regCheck bool, res // *anyway*, so it could always lie about what key was used by faking // the signature itself. if len(parsedJws.Signatures) > 1 { - err = core.SignatureValidationError("Too many signatures on POST") - wfe.log.Debug(err.Error()) + err = core.SignatureValidationError("Too many signatures in POST body") + wfe.stats.Inc("WFE.Errors.TooManyJWSSignaturesInPOST", 1, 1.0) + e.AddError("too many signatures in POST body: %d", len(parsedJws.Signatures)) return nil, nil, reg, err } if len(parsedJws.Signatures) == 0 { err = core.SignatureValidationError("POST JWS not signed") - wfe.log.Debug(err.Error()) + wfe.stats.Inc("WFE.Errors.JWSNotSignedInPOST", 1, 1.0) + e.AddError("no signatures in POST body") return nil, nil, reg, err } submittedKey := parsedJws.Signatures[0].Header.JsonWebKey if submittedKey == nil { err = core.SignatureValidationError("No JWK in JWS header") - wfe.log.Debug(err.Error()) + wfe.stats.Inc("WFE.Errors.NoJWKInJWSSignatureHeader", 1, 1.0) + e.AddError("no JWK in JWS signature header in POST body") return nil, nil, reg, err } @@ -404,34 +403,46 @@ func (wfe *WebFrontEndImpl) verifyPOST(request *http.Request, regCheck bool, res // are "good". But when we are verifying against any submitted key, we want // to check its quality before doing the verify. if err = core.GoodKey(submittedKey.Key); err != nil { + wfe.stats.Inc("WFE.Errors.JWKRejectedByGoodKey", 1, 1.0) + e.AddError("JWK in request was rejected by GoodKey: %s", err) return nil, nil, reg, err } key = submittedKey } else if err != nil { // For all other errors, or if regCheck is true, return error immediately. + wfe.stats.Inc("WFE.Errors.UnableToGetRegistrationByKey", 1, 1.0) + e.AddError("unable to fetch registration by the given JWK: %s", err) return nil, nil, reg, err } else { // If the lookup was successful, use that key. key = ®.Key + e.Requester = reg.ID + e.Contacts = reg.Contact } payload, header, err := parsedJws.Verify(key) if err != nil { puberr := core.SignatureValidationError("JWS verification error") - wfe.log.Debug(string(body)) - wfe.log.Debug(fmt.Sprintf("%v :: %v", puberr.Error(), err.Error())) + wfe.stats.Inc("WFE.Errors.JWSVerificationFailed", 1, 1.0) + n := len(body) + if n > 100 { + n = 100 + } + e.AddError("verification of JWS with the JWK failed: %v; body: %s", err, body[:n]) return nil, nil, reg, puberr } // Check that the request has a known anti-replay nonce // i.e., Nonce is in protected header and if err != nil || len(header.Nonce) == 0 { + wfe.stats.Inc("WFE.Errors.JWSMissingNonce", 1, 1.0) + e.AddError("JWS is missing an anti-replay nonce") err = core.SignatureValidationError("JWS has no anti-replay nonce") - wfe.log.Debug(err.Error()) return nil, nil, reg, err } else if !wfe.nonceService.Valid(header.Nonce) { + wfe.stats.Inc("WFE.Errors.JWSInvalidNonce", 1, 1.0) + e.AddError("JWS has an invalid anti-replay nonce") err = core.SignatureValidationError(fmt.Sprintf("JWS has invalid anti-replay nonce")) - wfe.log.Debug(err.Error()) return nil, nil, reg, err } @@ -441,17 +452,20 @@ func (wfe *WebFrontEndImpl) verifyPOST(request *http.Request, regCheck bool, res } err = json.Unmarshal([]byte(payload), &parsedRequest) if err != nil { + wfe.stats.Inc("WFE.Errors.UnparsableJWSPayload", 1, 1.0) + e.AddError("unable to JSON parse resource from JWS payload: %s", err) puberr := core.SignatureValidationError("Request payload did not parse as JSON") - wfe.log.Debug(fmt.Sprintf("%v :: %v", puberr.Error(), err.Error())) return nil, nil, reg, puberr } if parsedRequest.Resource == "" { + wfe.stats.Inc("WFE.Errors.NoResourceInJWSPayload", 1, 1.0) + e.AddError("JWS request payload does not specifiy a resource") err = core.MalformedRequestError("Request payload does not specify a resource") - wfe.log.Debug(err.Error()) return nil, nil, reg, err } else if resource != core.AcmeResource(parsedRequest.Resource) { - err = core.MalformedRequestError(fmt.Sprintf("Request payload has invalid resource: %s != %s", parsedRequest.Resource, resource)) - wfe.log.Debug(err.Error()) + wfe.stats.Inc("WFE.Errors.MismatchedResourceInJWSPayload", 1, 1.0) + e.AddError("JWS request payload does not match resource") + err = core.MalformedRequestError(fmt.Sprintf("JWS resource payload does not match the HTTP resource: %s != %s", parsedRequest.Resource, resource)) return nil, nil, reg, err } @@ -517,34 +531,33 @@ func link(url, relation string) string { } // NewRegistration is used by clients to submit a new registration/account -func (wfe *WebFrontEndImpl) NewRegistration(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) +func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { - body, key, _, err := wfe.verifyPOST(request, false, core.ResourceNewReg) + body, key, _, err := wfe.verifyPOST(logEvent, request, false, core.ResourceNewReg) if err != nil { - logEvent.Error = err.Error() + // verifyPOST handles its own setting of logEvent.Errors wfe.sendError(response, malformedJWS, err, statusCodeFromError(err)) return } if existingReg, err := wfe.SA.GetRegistrationByKey(*key); err == nil { - logEvent.Error = "Registration key is already in use" + logEvent.AddError("Registration key is already in use") response.Header().Set("Location", fmt.Sprintf("%s%d", wfe.RegBase, existingReg.ID)) - wfe.sendError(response, logEvent.Error, nil, http.StatusConflict) + wfe.sendError(response, "Registration key is already in use", nil, http.StatusConflict) return } var init core.Registration err = json.Unmarshal(body, &init) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to unmarshal Registration: %s", err) wfe.sendError(response, "Error unmarshaling JSON", err, http.StatusBadRequest) return } if len(init.Agreement) > 0 && init.Agreement != wfe.SubscriberAgreementURL { - logEvent.Error = fmt.Sprintf("Provided agreement URL [%s] does not match current agreement URL [%s]", init.Agreement, wfe.SubscriberAgreementURL) - wfe.sendError(response, logEvent.Error, nil, http.StatusBadRequest) + msg := fmt.Sprintf("Provided agreement URL [%s] does not match current agreement URL [%s]", init.Agreement, wfe.SubscriberAgreementURL) + logEvent.AddError(msg) + wfe.sendError(response, msg, nil, http.StatusBadRequest) return } init.Key = *key @@ -554,15 +567,15 @@ func (wfe *WebFrontEndImpl) NewRegistration(response http.ResponseWriter, reques if err == nil { init.InitialIP = net.ParseIP(host) } else { - logEvent.Error = "Couldn't parse RemoteAddr" - wfe.sendError(response, logEvent.Error, nil, http.StatusInternalServerError) + logEvent.AddError("Couldn't parse RemoteAddr: %s", request.RemoteAddr) + wfe.sendError(response, "couldn't parse the remote (that is, the client's) address", nil, http.StatusInternalServerError) return } } reg, err := wfe.RA.NewRegistration(init) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to create new registration: %s", err) wfe.sendError(response, "Error creating new registration", err, statusCodeFromError(err)) return } @@ -574,7 +587,7 @@ func (wfe *WebFrontEndImpl) NewRegistration(response http.ResponseWriter, reques regURL := fmt.Sprintf("%s%d", wfe.RegBase, reg.ID) responseBody, err := json.Marshal(reg) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to marsh registration: %s", err) // StatusInternalServerError because we just created this registration, it should be OK. wfe.sendError(response, "Error marshaling registration", err, http.StatusInternalServerError) return @@ -592,13 +605,10 @@ func (wfe *WebFrontEndImpl) NewRegistration(response http.ResponseWriter, reques } // NewAuthorization is used by clients to submit a new ID Authorization -func (wfe *WebFrontEndImpl) NewAuthorization(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) - - body, _, currReg, err := wfe.verifyPOST(request, true, core.ResourceNewAuthz) +func (wfe *WebFrontEndImpl) NewAuthorization(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { + body, _, currReg, err := wfe.verifyPOST(logEvent, request, true, core.ResourceNewAuthz) if err != nil { - logEvent.Error = err.Error() + // verifyPOST handles its own setting of logEvent.Errors respMsg := malformedJWS respCode := statusCodeFromError(err) if _, ok := err.(core.NoSuchRegistrationError); ok { @@ -608,20 +618,18 @@ func (wfe *WebFrontEndImpl) NewAuthorization(response http.ResponseWriter, reque wfe.sendError(response, respMsg, err, respCode) return } - logEvent.Requester = currReg.ID - logEvent.Contacts = currReg.Contact // Any version of the agreement is acceptable here. Version match is enforced in // wfe.Registration when agreeing the first time. Agreement updates happen // by mailing subscribers and don't require a registration update. if currReg.Agreement == "" { - logEvent.Error = "Must agree to subscriber agreement before any further actions" - wfe.sendError(response, logEvent.Error, nil, http.StatusForbidden) + logEvent.AddError("Must agree to subscriber agreement before any further actions") + wfe.sendError(response, "Must agree to subscriber agreement before any further actions", nil, http.StatusForbidden) return } var init core.Authorization if err = json.Unmarshal(body, &init); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to JSON unmarshal Authorization: %s", err) wfe.sendError(response, "Error unmarshaling JSON", err, http.StatusBadRequest) return } @@ -630,7 +638,7 @@ func (wfe *WebFrontEndImpl) NewAuthorization(response http.ResponseWriter, reque // Create new authz and return authz, err := wfe.RA.NewAuthorization(init, currReg.ID) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to create new authz: %s", err) wfe.sendError(response, "Error creating new authz", err, statusCodeFromError(err)) return } @@ -641,7 +649,7 @@ func (wfe *WebFrontEndImpl) NewAuthorization(response http.ResponseWriter, reque wfe.prepAuthorizationForDisplay(&authz) responseBody, err := json.Marshal(authz) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to marshal authz: %s", err) // StatusInternalServerError because we generated the authz, it should be OK wfe.sendError(response, "Error marshaling authz", err, http.StatusInternalServerError) return @@ -652,40 +660,36 @@ func (wfe *WebFrontEndImpl) NewAuthorization(response http.ResponseWriter, reque response.Header().Set("Content-Type", "application/json") response.WriteHeader(http.StatusCreated) if _, err = response.Write(responseBody); err != nil { - logEvent.Error = err.Error() + logEvent.AddError(err.Error()) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } } // RevokeCertificate is used by clients to request the revocation of a cert. -func (wfe *WebFrontEndImpl) RevokeCertificate(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) +func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { // We don't ask verifyPOST to verify there is a correponding registration, // because anyone with the right private key can revoke a certificate. - body, requestKey, registration, err := wfe.verifyPOST(request, false, core.ResourceRevokeCert) + body, requestKey, registration, err := wfe.verifyPOST(logEvent, request, false, core.ResourceRevokeCert) if err != nil { - logEvent.Error = err.Error() + // verifyPOST handles its own setting of logEvent.Errors wfe.sendError(response, malformedJWS, err, statusCodeFromError(err)) return } - logEvent.Requester = registration.ID - logEvent.Contacts = registration.Contact type RevokeRequest struct { CertificateDER core.JSONBuffer `json:"certificate"` } var revokeRequest RevokeRequest if err = json.Unmarshal(body, &revokeRequest); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to JSON unmarshal RevokeRequest: %s", err) wfe.log.Debug(fmt.Sprintf("Couldn't unmarshal in revoke request %s", string(body))) wfe.sendError(response, "Unable to read/verify body", err, http.StatusBadRequest) return } providedCert, err := x509.ParseCertificate(revokeRequest.CertificateDER) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to parse revoke certificate DER: %s", err) wfe.log.Debug("Couldn't parse cert in revoke request.") wfe.sendError(response, "Unable to read/verify body", err, http.StatusBadRequest) return @@ -700,7 +704,7 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(response http.ResponseWriter, requ } parsedCertificate, err := x509.ParseCertificate(cert.DER) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to parse certificate DER: %s", err) // InternalServerError because this is a failure to decode from our DB. wfe.sendError(response, "Invalid certificate", err, http.StatusInternalServerError) return @@ -712,25 +716,24 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(response http.ResponseWriter, requ certStatus, err := wfe.SA.GetCertificateStatus(serial) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to get certificate status: %s", err) wfe.sendError(response, "Certificate status not yet available", err, http.StatusNotFound) return } logEvent.Extra["CertificateStatus"] = certStatus.Status if certStatus.Status == core.OCSPStatusRevoked { - logEvent.Error = "Certificate already revoked" - wfe.sendError(response, logEvent.Error, "", http.StatusConflict) + logEvent.AddError("Certificate already revoked: %#v", serial) + wfe.sendError(response, "Certificate already revoked", "", http.StatusConflict) return } // TODO: Implement method of revocation by authorizations on account. if !(core.KeyDigestEquals(requestKey, parsedCertificate.PublicKey) || registration.ID == cert.RegistrationID) { - logEvent.Error = "Revocation request must be signed by private key of cert to be revoked, or by the account key of the account that issued it." - wfe.log.Debug("Key mismatch for revoke") + logEvent.AddError("Revocation request must be signed by private key of cert to be revoked, or by the account key of the account that issued it.") wfe.sendError(response, - logEvent.Error, + "Revocation request must be signed by private key of cert to be revoked, or by the account key of the account that issued it.", requestKey, http.StatusForbidden) return @@ -739,7 +742,7 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(response http.ResponseWriter, requ // Use revocation code 0, meaning "unspecified" err = wfe.RA.RevokeCertificateWithReg(*parsedCertificate, 0, registration.ID) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("failed to revoke certificate: %s", err) wfe.sendError(response, "Failed to revoke certificate", err, statusCodeFromError(err)) } else { wfe.log.Debug(fmt.Sprintf("Revoked %v", serial)) @@ -762,13 +765,10 @@ func (wfe *WebFrontEndImpl) logCsr(request *http.Request, cr core.CertificateReq // NewCertificate is used by clients to request the issuance of a cert for an // authorized identifier. -func (wfe *WebFrontEndImpl) NewCertificate(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) - - body, _, reg, err := wfe.verifyPOST(request, true, core.ResourceNewCert) +func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { + body, _, reg, err := wfe.verifyPOST(logEvent, request, true, core.ResourceNewCert) if err != nil { - logEvent.Error = err.Error() + // verifyPOST handles its own setting of logEvent.Errors respMsg := malformedJWS respCode := statusCodeFromError(err) if _, ok := err.(core.NoSuchRegistrationError); ok { @@ -778,20 +778,18 @@ func (wfe *WebFrontEndImpl) NewCertificate(response http.ResponseWriter, request wfe.sendError(response, respMsg, err, respCode) return } - logEvent.Requester = reg.ID - logEvent.Contacts = reg.Contact // Any version of the agreement is acceptable here. Version match is enforced in // wfe.Registration when agreeing the first time. Agreement updates happen // by mailing subscribers and don't require a registration update. if reg.Agreement == "" { - logEvent.Error = "Must agree to subscriber agreement before any further actions" - wfe.sendError(response, logEvent.Error, nil, http.StatusForbidden) + logEvent.AddError("Must agree to subscriber agreement before any further actions") + wfe.sendError(response, "Must agree to subscriber agreement before any further actions", nil, http.StatusForbidden) return } var certificateRequest core.CertificateRequest if err = json.Unmarshal(body, &certificateRequest); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to JSON unmarshal CertificateRequest: %s", err) wfe.sendError(response, "Error unmarshaling certificate request", err, http.StatusBadRequest) return } @@ -803,7 +801,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(response http.ResponseWriter, request // a bad key from the client is just a malformed request and doesn't need to // be audited. if err = core.GoodKey(certificateRequest.CSR.PublicKey); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("CSR public key failed GoodKey: %s", err) wfe.sendError(response, "Invalid key in certificate request", err, http.StatusBadRequest) return } @@ -819,7 +817,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(response http.ResponseWriter, request // RA for secondary validation. cert, err := wfe.RA.NewCertificate(certificateRequest, reg.ID) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to create new cert: %s", err) wfe.sendError(response, "Error creating new cert", err, statusCodeFromError(err)) return } @@ -830,7 +828,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(response http.ResponseWriter, request // enumerate and mirror our certificates. parsedCertificate, err := x509.ParseCertificate([]byte(cert.DER)) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to parse certificate: %s", err) wfe.sendError(response, "Error creating new cert", err, http.StatusBadRequest) @@ -845,7 +843,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(response http.ResponseWriter, request response.Header().Set("Content-Type", "application/pkix-cert") response.WriteHeader(http.StatusCreated) if _, err = response.Write(cert.DER); err != nil { - logEvent.Error = err.Error() + logEvent.AddError(err.Error()) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } } @@ -853,10 +851,9 @@ func (wfe *WebFrontEndImpl) NewCertificate(response http.ResponseWriter, request // Challenge handles POST requests to challenge URLs. Such requests are clients' // responses to the server's challenges. func (wfe *WebFrontEndImpl) Challenge( + logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) notFound := func() { wfe.sendError(response, "No such registration", request.URL.Path, http.StatusNotFound) @@ -900,10 +897,10 @@ func (wfe *WebFrontEndImpl) Challenge( switch request.Method { case "GET", "HEAD": - wfe.getChallenge(response, request, authz, &challenge, &logEvent) + wfe.getChallenge(response, request, authz, &challenge, logEvent) case "POST": - wfe.postChallenge(response, request, authz, challengeIndex, &logEvent) + wfe.postChallenge(response, request, authz, challengeIndex, logEvent) } } @@ -941,7 +938,7 @@ func (wfe *WebFrontEndImpl) getChallenge( jsonReply, err := json.Marshal(challenge) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to marshal challenge: %s", err) // InternalServerError because this is a failure to decode data passed in // by the caller, which got it from the DB. wfe.sendError(response, "Failed to marshal challenge", err, http.StatusInternalServerError) @@ -955,7 +952,7 @@ func (wfe *WebFrontEndImpl) getChallenge( response.WriteHeader(http.StatusAccepted) if _, err := response.Write(jsonReply); err != nil { wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) - logEvent.Error = err.Error() + logEvent.AddError(err.Error()) return } } @@ -966,9 +963,9 @@ func (wfe *WebFrontEndImpl) postChallenge( authz core.Authorization, challengeIndex int, logEvent *requestEvent) { - body, _, currReg, err := wfe.verifyPOST(request, true, core.ResourceChallenge) + body, _, currReg, err := wfe.verifyPOST(logEvent, request, true, core.ResourceChallenge) if err != nil { - logEvent.Error = err.Error() + // verifyPOST handles its own setting of logEvent.Errors respMsg := malformedJWS respCode := http.StatusBadRequest if _, ok := err.(core.NoSuchRegistrationError); ok { @@ -978,30 +975,28 @@ func (wfe *WebFrontEndImpl) postChallenge( wfe.sendError(response, respMsg, err, respCode) return } - logEvent.Requester = currReg.ID - logEvent.Contacts = currReg.Contact // Any version of the agreement is acceptable here. Version match is enforced in // wfe.Registration when agreeing the first time. Agreement updates happen // by mailing subscribers and don't require a registration update. if currReg.Agreement == "" { - logEvent.Error = "Must agree to subscriber agreement before any further actions" - wfe.sendError(response, logEvent.Error, nil, http.StatusForbidden) + logEvent.AddError("Registration didn't agree to subscriber agreement before any further actions") + wfe.sendError(response, "Registration didn't agree to subscriber agreement before any further actions", nil, http.StatusForbidden) return } // Check that the registration ID matching the key used matches // the registration ID on the authz object if currReg.ID != authz.RegistrationID { - logEvent.Error = fmt.Sprintf("User: %v != Authorization: %v", currReg.ID, authz.RegistrationID) + logEvent.AddError("User registration id: %d != Authorization registration id: %v", currReg.ID, authz.RegistrationID) wfe.sendError(response, "User registration ID doesn't match registration ID in authorization", - logEvent.Error, + "", http.StatusForbidden) return } var challengeUpdate core.Challenge if err = json.Unmarshal(body, &challengeUpdate); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("error JSON unmarshalling challenge response: %s", err) wfe.sendError(response, "Error unmarshaling challenge response", err, http.StatusBadRequest) return } @@ -1009,7 +1004,7 @@ func (wfe *WebFrontEndImpl) postChallenge( // Ask the RA to update this authorization updatedAuthorization, err := wfe.RA.UpdateAuthorization(authz, challengeIndex, challengeUpdate) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to update challenge: %s", err) wfe.sendError(response, "Unable to update challenge", err, statusCodeFromError(err)) return } @@ -1019,7 +1014,7 @@ func (wfe *WebFrontEndImpl) postChallenge( wfe.prepChallengeForDisplay(authz, &challenge) jsonReply, err := json.Marshal(challenge) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("failed to marshal challenge: %s", err) // StatusInternalServerError because we made the challenges, they should be OK wfe.sendError(response, "Failed to marshal challenge", err, http.StatusInternalServerError) return @@ -1031,20 +1026,18 @@ func (wfe *WebFrontEndImpl) postChallenge( response.Header().Add("Link", link(authzURL, "up")) response.WriteHeader(http.StatusAccepted) if _, err = response.Write(jsonReply); err != nil { - logEvent.Error = err.Error() + logEvent.AddError(err.Error()) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) return } } // Registration is used by a client to submit an update to their registration. -func (wfe *WebFrontEndImpl) Registration(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) +func (wfe *WebFrontEndImpl) Registration(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { - body, _, currReg, err := wfe.verifyPOST(request, true, core.ResourceRegistration) + body, _, currReg, err := wfe.verifyPOST(logEvent, request, true, core.ResourceRegistration) if err != nil { - logEvent.Error = err.Error() + // verifyPOST handles its own setting of logEvent.Errors respMsg := malformedJWS respCode := statusCodeFromError(err) if _, ok := err.(core.NoSuchRegistrationError); ok { @@ -1054,38 +1047,37 @@ func (wfe *WebFrontEndImpl) Registration(response http.ResponseWriter, request * wfe.sendError(response, respMsg, err, respCode) return } - logEvent.Requester = currReg.ID - logEvent.Contacts = currReg.Contact // Requests to this handler should have a path that leads to a known // registration idStr := parseIDFromPath(request.URL.Path) id, err := strconv.ParseInt(idStr, 10, 64) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("registration ID must be an integer, was %#v", idStr) wfe.sendError(response, "Registration ID must be an integer", err, http.StatusBadRequest) return } else if id <= 0 { - logEvent.Error = "Registration ID must be a positive non-zero integer" - wfe.sendError(response, logEvent.Error, id, http.StatusBadRequest) + logEvent.AddError("Registration ID must be a positive non-zero integer, was %d", id) + wfe.sendError(response, "Registration ID must be a positive non-zero integer", id, http.StatusBadRequest) return } else if id != currReg.ID { - logEvent.Error = "Request signing key did not match registration key" - wfe.sendError(response, logEvent.Error, "", http.StatusForbidden) + logEvent.AddError("Request signing key did not match registration key: %d != %d", id, currReg.ID) + wfe.sendError(response, "Request signing key did not match registration key", "", http.StatusForbidden) return } var update core.Registration err = json.Unmarshal(body, &update) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to JSON parse registration: %s", err) wfe.sendError(response, "Error unmarshaling registration", err, http.StatusBadRequest) return } if len(update.Agreement) > 0 && update.Agreement != wfe.SubscriberAgreementURL { - logEvent.Error = fmt.Sprintf("Provided agreement URL [%s] does not match current agreement URL [%s]", update.Agreement, wfe.SubscriberAgreementURL) - wfe.sendError(response, logEvent.Error, nil, http.StatusBadRequest) + msg := fmt.Sprintf("Provided agreement URL [%s] does not match current agreement URL [%s]", update.Agreement, wfe.SubscriberAgreementURL) + logEvent.AddError(msg) + wfe.sendError(response, msg, nil, http.StatusBadRequest) return } @@ -1098,14 +1090,14 @@ func (wfe *WebFrontEndImpl) Registration(response http.ResponseWriter, request * // Ask the RA to update this authorization. updatedReg, err := wfe.RA.UpdateRegistration(currReg, update) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to update registration: %s", err) wfe.sendError(response, "Unable to update registration", err, statusCodeFromError(err)) return } jsonReply, err := json.Marshal(updatedReg) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to marshal updated registration: %s", err) // StatusInternalServerError because we just generated the reg, it should be OK wfe.sendError(response, "Failed to marshal registration", err, http.StatusInternalServerError) return @@ -1121,14 +1113,12 @@ func (wfe *WebFrontEndImpl) Registration(response http.ResponseWriter, request * // Authorization is used by clients to submit an update to one of their // authorizations. -func (wfe *WebFrontEndImpl) Authorization(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) - +func (wfe *WebFrontEndImpl) Authorization(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { // Requests to this handler should have a path that leads to a known authz id := parseIDFromPath(request.URL.Path) authz, err := wfe.SA.GetAuthorization(id) if err != nil { + logEvent.AddError("No such authorization at id %s", id) wfe.sendError(response, "Unable to find authorization", err, http.StatusNotFound) @@ -1144,16 +1134,16 @@ func (wfe *WebFrontEndImpl) Authorization(response http.ResponseWriter, request jsonReply, err := json.Marshal(authz) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("Failed to JSON marshal authz: %s", err) // InternalServerError because this is a failure to decode from our DB. - wfe.sendError(response, "Failed to marshal authz", err, http.StatusInternalServerError) + wfe.sendError(response, "Failed to JSON marshal authz", err, http.StatusInternalServerError) return } response.Header().Add("Link", link(wfe.NewCert, "next")) response.Header().Set("Content-Type", "application/json") response.WriteHeader(http.StatusOK) if _, err = response.Write(jsonReply); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to write authorization update response: %s", err) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } } @@ -1162,32 +1152,29 @@ var allHex = regexp.MustCompile("^[0-9a-f]+$") // Certificate is used by clients to request a copy of their current certificate, or to // request a reissuance of the certificate. -func (wfe *WebFrontEndImpl) Certificate(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) +func (wfe *WebFrontEndImpl) Certificate(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { path := request.URL.Path // Certificate paths consist of the CertBase path, plus exactly sixteen hex // digits. if !strings.HasPrefix(path, CertPath) { - logEvent.Error = "Certificate not found" - wfe.sendError(response, logEvent.Error, path, http.StatusNotFound) + logEvent.AddError("this request path should not have gotten to Certificate: %#v is not a prefix of %#v", path, CertPath) + wfe.sendError(response, "Certificate not found", path, http.StatusNotFound) addNoCacheHeader(response) return } serial := path[len(CertPath):] if !core.ValidSerial(serial) { - logEvent.Error = "Certificate not found" - wfe.sendError(response, logEvent.Error, serial, http.StatusNotFound) + logEvent.AddError("certificate serial provided was not valid: %s", serial) + wfe.sendError(response, "Certificate not found", serial, http.StatusNotFound) addNoCacheHeader(response) return } - wfe.log.Debug(fmt.Sprintf("Requested certificate ID %s", serial)) logEvent.Extra["RequestedSerial"] = serial cert, err := wfe.SA.GetCertificate(serial) if err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to get certificate by serial id %#v: %s", serial, err) if strings.HasPrefix(err.Error(), "gorp: multiple rows returned") { wfe.sendError(response, "Multiple certificates with same short serial", err, http.StatusConflict) } else { @@ -1204,7 +1191,7 @@ func (wfe *WebFrontEndImpl) Certificate(response http.ResponseWriter, request *h response.Header().Add("Link", link(IssuerPath, "up")) response.WriteHeader(http.StatusOK) if _, err = response.Write(cert.DER); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to write new certificate response: %s", err) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } return @@ -1212,39 +1199,30 @@ func (wfe *WebFrontEndImpl) Certificate(response http.ResponseWriter, request *h // Terms is used by the client to obtain the current Terms of Service / // Subscriber Agreement to which the subscriber must agree. -func (wfe *WebFrontEndImpl) Terms(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) - +func (wfe *WebFrontEndImpl) Terms(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { http.Redirect(response, request, wfe.SubscriberAgreementURL, http.StatusFound) } // Issuer obtains the issuer certificate used by this instance of Boulder. -func (wfe *WebFrontEndImpl) Issuer(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) - +func (wfe *WebFrontEndImpl) Issuer(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { addCacheHeader(response, wfe.IssuerCacheDuration.Seconds()) // TODO Content negotiation response.Header().Set("Content-Type", "application/pkix-cert") response.WriteHeader(http.StatusOK) if _, err := response.Write(wfe.IssuerCert); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to write issuer certificate response: %s", err) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } } // BuildID tells the requestor what build we're running. -func (wfe *WebFrontEndImpl) BuildID(response http.ResponseWriter, request *http.Request) { - logEvent := wfe.populateRequestEvent(request) - defer wfe.logRequestDetails(&logEvent) - +func (wfe *WebFrontEndImpl) BuildID(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { response.Header().Set("Content-Type", "text/plain") response.WriteHeader(http.StatusOK) detailsString := fmt.Sprintf("Boulder=(%s %s)", core.GetBuildID(), core.GetBuildTime()) if _, err := fmt.Fprintln(response, detailsString); err != nil { - logEvent.Error = err.Error() + logEvent.AddError("unable to print build information: %s", err) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } } @@ -1303,40 +1281,3 @@ func (wfe *WebFrontEndImpl) setCORSHeaders(response http.ResponseWriter, request response.Header().Set("Access-Control-Expose-Headers", "Link, Replay-Nonce") response.Header().Set("Access-Control-Max-Age", "86400") } - -func (wfe *WebFrontEndImpl) logRequestDetails(logEvent *requestEvent) { - logEvent.ResponseTime = time.Now() - var msg string - if logEvent.Error != "" { - msg = "Terminated request" - } else { - msg = "Successful request" - } - wfe.log.InfoObject(msg, logEvent) -} - -func (wfe *WebFrontEndImpl) populateRequestEvent(request *http.Request) (logEvent requestEvent) { - logEvent = requestEvent{ - ID: core.NewToken(), - RealIP: request.Header.Get("X-Real-IP"), - ClientAddr: getClientAddr(request), - Method: request.Method, - RequestTime: time.Now(), - Extra: make(map[string]interface{}, 0), - } - if request.URL != nil { - logEvent.Endpoint = request.URL.String() - } - return -} - -// Comma-separated list of HTTP clients involved in making this -// request, starting with the original requestor and ending with the -// remote end of our TCP connection (which is typically our own -// proxy). -func getClientAddr(r *http.Request) string { - if xff := r.Header.Get("X-Forwarded-For"); xff != "" { - return xff + "," + r.RemoteAddr - } - return r.RemoteAddr -} diff --git a/wfe/web-front-end_test.go b/wfe/web-front-end_test.go index f3f337d47..7eb7d705d 100644 --- a/wfe/web-front-end_test.go +++ b/wfe/web-front-end_test.go @@ -271,7 +271,7 @@ func TestHandleFunc(t *testing.T) { mux = http.NewServeMux() rw = httptest.NewRecorder() stubCalled = false - wfe.HandleFunc(mux, "/test", func(http.ResponseWriter, *http.Request) { + wfe.HandleFunc(mux, "/test", func(*requestEvent, http.ResponseWriter, *http.Request) { stubCalled = true }, allowed...) req.URL = mustParseURL("/test") @@ -463,7 +463,7 @@ func TestIndexPOST(t *testing.T) { wfe := setupWFE(t) responseWriter := httptest.NewRecorder() url, _ := url.Parse("/") - wfe.Index(responseWriter, &http.Request{ + wfe.Index(newRequestEvent(), responseWriter, &http.Request{ Method: "POST", URL: url, }) @@ -474,7 +474,7 @@ func TestPOST404(t *testing.T) { wfe := setupWFE(t) responseWriter := httptest.NewRecorder() url, _ := url.Parse("/foobar") - wfe.Index(responseWriter, &http.Request{ + wfe.Index(newRequestEvent(), responseWriter, &http.Request{ Method: "POST", URL: url, }) @@ -488,7 +488,7 @@ func TestIndex(t *testing.T) { responseWriter := httptest.NewRecorder() url, _ := url.Parse("/") - wfe.Index(responseWriter, &http.Request{ + wfe.Index(newRequestEvent(), responseWriter, &http.Request{ Method: "GET", URL: url, }) @@ -501,7 +501,7 @@ func TestIndex(t *testing.T) { responseWriter.Body.Reset() responseWriter.Header().Del("Cache-Control") url, _ = url.Parse("/foo") - wfe.Index(responseWriter, &http.Request{ + wfe.Index(newRequestEvent(), responseWriter, &http.Request{ URL: url, }) //test.AssertEquals(t, responseWriter.Code, http.StatusNotFound) @@ -566,7 +566,7 @@ func TestIssueCertificate(t *testing.T) { // POST, but no body. responseWriter.Body.Reset() - wfe.NewCertificate(responseWriter, &http.Request{ + wfe.NewCertificate(newRequestEvent(), responseWriter, &http.Request{ Method: "POST", Header: map[string][]string{ "Content-Length": []string{"0"}, @@ -578,14 +578,14 @@ func TestIssueCertificate(t *testing.T) { // POST, but body that isn't valid JWS responseWriter.Body.Reset() - wfe.NewCertificate(responseWriter, makePostRequest("hi")) + wfe.NewCertificate(newRequestEvent(), responseWriter, makePostRequest("hi")) test.AssertEquals(t, responseWriter.Body.String(), `{"type":"urn:acme:error:malformed","detail":"Unable to read/verify body :: Parse error reading JWS"}`) // POST, Properly JWS-signed, but payload is "foo", not base64-encoded JSON. responseWriter.Body.Reset() - wfe.NewCertificate(responseWriter, + wfe.NewCertificate(newRequestEvent(), responseWriter, makePostRequest(signRequest(t, "foo", &wfe.nonceService))) test.AssertEquals(t, responseWriter.Body.String(), @@ -593,7 +593,7 @@ func TestIssueCertificate(t *testing.T) { // Valid, signed JWS body, payload is '{}' responseWriter.Body.Reset() - wfe.NewCertificate(responseWriter, + wfe.NewCertificate(newRequestEvent(), responseWriter, makePostRequest( signRequest(t, "{}", &wfe.nonceService))) test.AssertEquals(t, @@ -602,7 +602,7 @@ func TestIssueCertificate(t *testing.T) { // Valid, signed JWS body, payload is '{"resource":"new-cert"}' responseWriter.Body.Reset() - wfe.NewCertificate(responseWriter, + wfe.NewCertificate(newRequestEvent(), responseWriter, makePostRequest(signRequest(t, `{"resource":"new-cert"}`, &wfe.nonceService))) test.AssertEquals(t, responseWriter.Body.String(), @@ -613,7 +613,8 @@ func TestIssueCertificate(t *testing.T) { // openssl req -outform der -new -nodes -key wfe/test/178.key -subj /CN=foo.com | \ // sed 's/foo.com/fob.com/' | b64url responseWriter.Body.Reset() - wfe.NewCertificate(responseWriter, + wfe.NewCertificate(newRequestEvent(), + responseWriter, makePostRequest(signRequest(t, `{ "resource":"new-cert", "csr": "MIICVzCCAT8CAQAwEjEQMA4GA1UEAwwHZm9iLmNvbTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAKzHhqcMSTVjBu61vufGVmIYM4mMbWXgndHOUWnIqSKcNtFtPQ465tcZRT5ITIZWXGjsmgDrj31qvG3t5qLwyaF5hsTvFHK72nLMAQhdgM6481Qe9yaoaulWpkGr_9LVz4jQ9pGAaLVamXGpSxV-ipTOo79Sev4aZE8ksD9atEfWtcOD9w8_zj74vpWjTAHN49Q88chlChVqakn0zSfHPfS-jF8g0UTddBuF0Ti3sZChjxzbo6LwZ4182xX7XPnOLav3AGj0Su7j5XMl3OpenOrlWulWJeZIHq5itGW321j306XiGdbrdWH4K7JygICFds6oolwQRGBY6yinAtCgkTcCAwEAAaAAMA0GCSqGSIb3DQEBCwUAA4IBAQBxPiHOtKuBxtvecMNtLkTSuTyEkusQGnjoFDaKe5oqwGYQgy0YBii2-BbaPmqS4ZaDc-vDz_RLeKH5ZiH-NliYR1V_CRtpFLQi18g_2pLQnZLVO3ENs-SM37nU_nBGn9O93t2bkssoM3fZmtgp3R2W7I_wvx7Z8oWKa4boTeBAg_q9Gmi6QskZBddK7A4S_vOR0frU6QSPK_ksPhvovp9fwb6CVKrlJWf556UwRPWgbkW39hvTxK2KHhrUEg3oawNkWde2jZtnZ9e-9zpw8-_5O0X7-YN0ucbFTfQybce_ReuLlGepiHT5bvVavBZoIvqw1XOgSMvGgZFU8tAWMBlj" @@ -626,7 +627,7 @@ func TestIssueCertificate(t *testing.T) { // openssl req -outform der -new -nodes -key wfe/test/178.key -subj /CN=meep.com | b64url mockLog.Clear() responseWriter.Body.Reset() - wfe.NewCertificate(responseWriter, + wfe.NewCertificate(newRequestEvent(), responseWriter, makePostRequest(signRequest(t, `{ "resource":"new-cert", "csr": "MIICWDCCAUACAQAwEzERMA8GA1UEAwwIbWVlcC5jb20wggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQCaqzue57mgXEoGTZZoVkkCZraebWgXI8irX2BgQB1A3iZa9onxGPMcWQMxhSuUisbEJi4UkMcVST12HX01rUwhj41UuBxJvI1w4wvdstssTAaa9c9tsQ5-UED2bFRL1MsyBdbmCF_-pu3i-ZIYqWgiKbjVBe3nlAVbo77zizwp3Y4Tp1_TBOwTAuFkHePmkNT63uPm9My_hNzsSm1o-Q519Cf7ry-JQmOVgz_jIgFVGFYJ17EV3KUIpUuDShuyCFATBQspgJSN2DoXRUlQjXXkNTj23OxxdT_cVLcLJjytyG6e5izME2R2aCkDBWIc1a4_sRJ0R396auPXG6KhJ7o_AgMBAAGgADANBgkqhkiG9w0BAQsFAAOCAQEALu046p76aKgvoAEHFINkMTgKokPXf9mZ4IZx_BKz-qs1MPMxVtPIrQDVweBH6tYT7Hfj2naLry6SpZ3vUNP_FYeTFWgW1V03LiqacX-QQgbEYtn99Dt3ScGyzb7EH833ztb3vDJ_-ha_CJplIrg-kHBBrlLFWXhh-I9K1qLRTNpbhZ18ooFde4Sbhkw9o9fKivGhx9aYr7ZbjRsNtKit_DsG1nwEXz53TMJ2vB9IQY29coJv_n5NFLkvBfzbG5faRNiFcimPYBO2jFdaA2mWzfxltLtwMF_dBwzTXDpMo3TVT9zEdV8YpsWqr63igqGDZVpKenlkqvRTeGJVayVuMA" @@ -639,7 +640,7 @@ func TestIssueCertificate(t *testing.T) { mockLog.Clear() responseWriter.Body.Reset() // openssl req -outform der -new -nodes -key wfe/test/178.key -subj /CN=not-an-example.com | b64url - wfe.NewCertificate(responseWriter, + wfe.NewCertificate(newRequestEvent(), responseWriter, makePostRequest(signRequest(t, `{ "resource":"new-cert", "csr": "MIICYjCCAUoCAQAwHTEbMBkGA1UEAwwSbm90LWFuLWV4YW1wbGUuY29tMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAmqs7nue5oFxKBk2WaFZJAma2nm1oFyPIq19gYEAdQN4mWvaJ8RjzHFkDMYUrlIrGxCYuFJDHFUk9dh19Na1MIY-NVLgcSbyNcOML3bLbLEwGmvXPbbEOflBA9mxUS9TLMgXW5ghf_qbt4vmSGKloIim41QXt55QFW6O-84s8Kd2OE6df0wTsEwLhZB3j5pDU-t7j5vTMv4Tc7EptaPkOdfQn-68viUJjlYM_4yIBVRhWCdexFdylCKVLg0obsghQEwULKYCUjdg6F0VJUI115DU49tzscXU_3FS3CyY8rchunuYszBNkdmgpAwViHNWuP7ESdEd_emrj1xuioSe6PwIDAQABoAAwDQYJKoZIhvcNAQELBQADggEBAE_T1nWU38XVYL28hNVSXU0rW5IBUKtbvr0qAkD4kda4HmQRTYkt-LNSuvxoZCC9lxijjgtJi-OJe_DCTdZZpYzewlVvcKToWSYHYQ6Wm1-fxxD_XzphvZOujpmBySchdiz7QSVWJmVZu34XD5RJbIcrmj_cjRt42J1hiTFjNMzQu9U6_HwIMmliDL-soFY2RTvvZf-dAFvOUQ-Wbxt97eM1PbbmxJNWRhbAmgEpe9PWDPTpqV5AK56VAa991cQ1P8ZVmPss5hvwGWhOtpnpTZVHN3toGNYFKqxWPboirqushQlfKiFqT9rpRgM3-mFjOHidGqsKEkTdmfSVlVEk3oo=" @@ -680,7 +681,7 @@ func TestGetChallenge(t *testing.T) { req, err := http.NewRequest(method, challengeURL, nil) test.AssertNotError(t, err, "Could not make NewRequest") - wfe.Challenge(resp, req) + wfe.Challenge(newRequestEvent(), resp, req) test.AssertEquals(t, resp.Code, http.StatusAccepted) @@ -722,7 +723,7 @@ func TestChallenge(t *testing.T) { test.AssertNotError(t, err, "Could not unmarshal testing key") challengeURL := "/acme/challenge/valid/23" - wfe.Challenge(responseWriter, + wfe.Challenge(newRequestEvent(), responseWriter, makePostRequestWithPath(challengeURL, signRequest(t, `{"resource":"challenge"}`, &wfe.nonceService))) @@ -842,7 +843,7 @@ func TestNewRegistration(t *testing.T) { nonce, err = wfe.nonceService.Nonce() test.AssertNotError(t, err, "Unable to create nonce") result, err = signer.Sign([]byte(`{"resource":"new-reg","contact":["tel:123456789"],"agreement":"`+agreementURL+`"}`), nonce) - wfe.NewRegistration(responseWriter, + wfe.NewRegistration(newRequestEvent(), responseWriter, makePostRequest(result.FullSerialize())) var reg core.Registration @@ -878,7 +879,7 @@ func TestNewRegistration(t *testing.T) { test.AssertNotError(t, err, "Unable to create nonce") result, err = signer.Sign([]byte(`{"resource":"new-reg","contact":["tel:123456789"],"agreement":"`+agreementURL+`"}`), nonce) - wfe.NewRegistration(responseWriter, + wfe.NewRegistration(newRequestEvent(), responseWriter, makePostRequest(result.FullSerialize())) test.AssertEquals(t, responseWriter.Body.String(), @@ -946,7 +947,7 @@ func TestRevokeCertificateCertKey(t *testing.T) { nonce, err := wfe.nonceService.Nonce() test.AssertNotError(t, err, "Unable to create nonce") result, _ := signer.Sign(revokeRequestJSON, nonce) - wfe.RevokeCertificate(responseWriter, + wfe.RevokeCertificate(newRequestEvent(), responseWriter, makePostRequest(result.FullSerialize())) test.AssertEquals(t, responseWriter.Code, 200) test.AssertEquals(t, responseWriter.Body.String(), "") @@ -970,7 +971,7 @@ func TestRevokeCertificateAccountKey(t *testing.T) { nonce, err := wfe.nonceService.Nonce() test.AssertNotError(t, err, "Unable to create nonce") result, _ := accountKeySigner.Sign(revokeRequestJSON, nonce) - wfe.RevokeCertificate(responseWriter, + wfe.RevokeCertificate(newRequestEvent(), responseWriter, makePostRequest(result.FullSerialize())) test.AssertEquals(t, responseWriter.Code, 200) test.AssertEquals(t, responseWriter.Body.String(), "") @@ -994,7 +995,7 @@ func TestRevokeCertificateWrongKey(t *testing.T) { test.AssertNotError(t, err, "Unable to create revoke request") result, _ := accountKeySigner2.Sign(revokeRequestJSON, nonce) - wfe.RevokeCertificate(responseWriter, + wfe.RevokeCertificate(newRequestEvent(), responseWriter, makePostRequest(result.FullSerialize())) test.AssertEquals(t, responseWriter.Code, 403) test.AssertEquals(t, responseWriter.Body.String(), @@ -1038,7 +1039,7 @@ func TestRevokeCertificateAlreadyRevoked(t *testing.T) { nonce, err := wfe.nonceService.Nonce() test.AssertNotError(t, err, "Unable to create nonce") result, _ := signer.Sign(revokeRequestJSON, nonce) - wfe.RevokeCertificate(responseWriter, + wfe.RevokeCertificate(newRequestEvent(), responseWriter, makePostRequest(result.FullSerialize())) test.AssertEquals(t, responseWriter.Code, 409) test.AssertEquals(t, responseWriter.Body.String(), @@ -1064,7 +1065,7 @@ func TestAuthorization(t *testing.T) { // POST, but no body. responseWriter.Body.Reset() - wfe.NewAuthorization(responseWriter, &http.Request{ + wfe.NewAuthorization(newRequestEvent(), responseWriter, &http.Request{ Method: "POST", Header: map[string][]string{ "Content-Length": []string{"0"}, @@ -1074,12 +1075,12 @@ func TestAuthorization(t *testing.T) { // POST, but body that isn't valid JWS responseWriter.Body.Reset() - wfe.NewAuthorization(responseWriter, makePostRequest("hi")) + wfe.NewAuthorization(newRequestEvent(), responseWriter, makePostRequest("hi")) test.AssertEquals(t, responseWriter.Body.String(), `{"type":"urn:acme:error:malformed","detail":"Unable to read/verify body :: Parse error reading JWS"}`) // POST, Properly JWS-signed, but payload is "foo", not base64-encoded JSON. responseWriter.Body.Reset() - wfe.NewAuthorization(responseWriter, + wfe.NewAuthorization(newRequestEvent(), responseWriter, makePostRequest(signRequest(t, "foo", &wfe.nonceService))) test.AssertEquals(t, responseWriter.Body.String(), @@ -1088,7 +1089,7 @@ func TestAuthorization(t *testing.T) { // Same signed body, but payload modified by one byte, breaking signature. // should fail JWS verification. responseWriter.Body.Reset() - wfe.NewAuthorization(responseWriter, makePostRequest(` + wfe.NewAuthorization(newRequestEvent(), responseWriter, makePostRequest(` { "header": { "alg": "RS256", @@ -1107,7 +1108,7 @@ func TestAuthorization(t *testing.T) { `{"type":"urn:acme:error:malformed","detail":"Unable to read/verify body :: JWS verification error"}`) responseWriter.Body.Reset() - wfe.NewAuthorization(responseWriter, + wfe.NewAuthorization(newRequestEvent(), responseWriter, makePostRequest(signRequest(t, `{"resource":"new-authz","identifier":{"type":"dns","value":"test.com"}}`, &wfe.nonceService))) test.AssertEquals( @@ -1166,7 +1167,7 @@ func TestRegistration(t *testing.T) { responseWriter.Body.Reset() // Test POST invalid JSON - wfe.Registration(responseWriter, makePostRequestWithPath("/2", "invalid")) + wfe.Registration(newRequestEvent(), responseWriter, makePostRequestWithPath("/2", "invalid")) test.AssertEquals(t, responseWriter.Body.String(), `{"type":"urn:acme:error:malformed","detail":"Unable to read/verify body :: Parse error reading JWS"}`) @@ -1184,7 +1185,7 @@ func TestRegistration(t *testing.T) { test.AssertNotError(t, err, "Unable to create nonce") result, err := signer.Sign([]byte(`{"resource":"reg","agreement":"`+agreementURL+`"}`), nonce) test.AssertNotError(t, err, "Unable to sign") - wfe.Registration(responseWriter, + wfe.Registration(newRequestEvent(), responseWriter, makePostRequestWithPath("/2", result.FullSerialize())) test.AssertEquals(t, responseWriter.Body.String(), @@ -1204,7 +1205,7 @@ func TestRegistration(t *testing.T) { result, err = signer.Sign([]byte(`{"resource":"reg","agreement":"https://letsencrypt.org/im-bad"}`), nonce) // Test POST valid JSON with registration up in the mock - wfe.Registration(responseWriter, + wfe.Registration(newRequestEvent(), responseWriter, makePostRequestWithPath("/1", result.FullSerialize())) test.AssertEquals(t, responseWriter.Body.String(), @@ -1216,7 +1217,7 @@ func TestRegistration(t *testing.T) { test.AssertNotError(t, err, "Unable to create nonce") result, err = signer.Sign([]byte(`{"resource":"reg","agreement":"`+agreementURL+`"}`), nonce) test.AssertNotError(t, err, "Couldn't sign") - wfe.Registration(responseWriter, + wfe.Registration(newRequestEvent(), responseWriter, makePostRequestWithPath("/1", result.FullSerialize())) test.AssertNotContains(t, responseWriter.Body.String(), "urn:acme:error") links := responseWriter.Header()["Link"] @@ -1237,7 +1238,7 @@ func TestTermsRedirect(t *testing.T) { responseWriter := httptest.NewRecorder() path, _ := url.Parse("/terms") - wfe.Terms(responseWriter, &http.Request{ + wfe.Terms(newRequestEvent(), responseWriter, &http.Request{ Method: "GET", URL: path, }) @@ -1254,7 +1255,7 @@ func TestIssuer(t *testing.T) { responseWriter := httptest.NewRecorder() - wfe.Issuer(responseWriter, &http.Request{ + wfe.Issuer(newRequestEvent(), responseWriter, &http.Request{ Method: "GET", }) test.AssertEquals(t, responseWriter.Code, http.StatusOK) @@ -1264,6 +1265,9 @@ func TestIssuer(t *testing.T) { func TestGetCertificate(t *testing.T) { wfe := setupWFE(t) + mux, err := wfe.Handler() + test.AssertNotError(t, err, "Problem setting up HTTP handlers") + wfe.CertCacheDuration = time.Second * 10 wfe.CertNoCacheExpirationWindow = time.Hour * 24 * 7 wfe.SA = &mocks.StorageAuthority{} @@ -1279,12 +1283,13 @@ func TestGetCertificate(t *testing.T) { // Valid serial, cached req, _ := http.NewRequest("GET", "/acme/cert/0000000000000000000000000000000000b2", nil) req.RemoteAddr = "192.168.0.1" - wfe.Certificate(responseWriter, req) + mux.ServeHTTP(responseWriter, req) test.AssertEquals(t, responseWriter.Code, 200) test.AssertEquals(t, responseWriter.Header().Get("Cache-Control"), "public, max-age=10") test.AssertEquals(t, responseWriter.Header().Get("Content-Type"), "application/pkix-cert") test.Assert(t, bytes.Compare(responseWriter.Body.Bytes(), certBlock.Bytes) == 0, "Certificates don't match") + t.Logf("UGH %#v", mockLog.GetAll()[0]) reqlogs := mockLog.GetAllMatching(`Successful request`) test.AssertEquals(t, len(reqlogs), 1) test.AssertEquals(t, reqlogs[0].Priority, syslog.LOG_INFO) @@ -1296,7 +1301,7 @@ func TestGetCertificate(t *testing.T) { req, _ = http.NewRequest("GET", "/acme/cert/0000000000000000000000000000000000ff", nil) req.RemoteAddr = "192.168.0.1" req.Header.Set("X-Forwarded-For", "192.168.99.99") - wfe.Certificate(responseWriter, req) + mux.ServeHTTP(responseWriter, req) test.AssertEquals(t, responseWriter.Code, 404) test.AssertEquals(t, responseWriter.Header().Get("Cache-Control"), "public, max-age=0, no-cache") test.AssertEquals(t, responseWriter.Body.String(), `{"type":"urn:acme:error:malformed","detail":"Certificate not found"}`) @@ -1309,7 +1314,7 @@ func TestGetCertificate(t *testing.T) { // Invalid serial, no cache responseWriter = httptest.NewRecorder() req, _ = http.NewRequest("GET", "/acme/cert/nothex", nil) - wfe.Certificate(responseWriter, req) + mux.ServeHTTP(responseWriter, req) test.AssertEquals(t, responseWriter.Code, 404) test.AssertEquals(t, responseWriter.Header().Get("Cache-Control"), "public, max-age=0, no-cache") test.AssertEquals(t, responseWriter.Body.String(), `{"type":"urn:acme:error:malformed","detail":"Certificate not found"}`) @@ -1317,7 +1322,7 @@ func TestGetCertificate(t *testing.T) { // Invalid serial, no cache responseWriter = httptest.NewRecorder() req, _ = http.NewRequest("GET", "/acme/cert/00000000000000", nil) - wfe.Certificate(responseWriter, req) + mux.ServeHTTP(responseWriter, req) test.AssertEquals(t, responseWriter.Code, 404) test.AssertEquals(t, responseWriter.Header().Get("Cache-Control"), "public, max-age=0, no-cache") test.AssertEquals(t, responseWriter.Body.String(), `{"type":"urn:acme:error:malformed","detail":"Certificate not found"}`) @@ -1359,7 +1364,7 @@ func TestLogCsrPem(t *testing.T) { func TestLengthRequired(t *testing.T) { wfe := setupWFE(t) - _, _, _, err := wfe.verifyPOST(&http.Request{ + _, _, _, err := wfe.verifyPOST(newRequestEvent(), &http.Request{ Method: "POST", URL: mustParseURL("/"), }, false, "resource") @@ -1387,7 +1392,7 @@ func TestVerifyPOSTUsesStoredKey(t *testing.T) { wfe.SA = &mockSADifferentStoredKey{mocks.StorageAuthority{}} // signRequest signs with test1Key, but our special mock returns a // registration with test2Key - _, _, _, err := wfe.verifyPOST(makePostRequest(signRequest(t, `{"resource":"foo"}`, &wfe.nonceService)), true, "foo") + _, _, _, err := wfe.verifyPOST(newRequestEvent(), makePostRequest(signRequest(t, `{"resource":"foo"}`, &wfe.nonceService)), true, "foo") test.AssertError(t, err, "No error returned when provided key differed from stored key.") } @@ -1398,7 +1403,7 @@ func TestBadKeyCSR(t *testing.T) { // CSR with a bad (512 bit RSA) key. // openssl req -outform der -new -newkey rsa:512 -nodes -keyout foo.com.key // -subj /CN=foo.com | base64 -w0 | sed -e 's,+,-,g' -e 's,/,_,g' - wfe.NewCertificate(responseWriter, + wfe.NewCertificate(newRequestEvent(), responseWriter, makePostRequest(signRequest(t, `{ "resource":"new-cert", "csr": "MIHLMHcCAQAwEjEQMA4GA1UEAwwHZm9vLmNvbTBcMA0GCSqGSIb3DQEBAQUAA0sAMEgCQQDCZftp4x4owgjBnwOKfzihIPedT-BUmV2fuQPMqaUlc8yJUp13vcO5uxUlaBm8leM7Dj_sgTDP_JgykorlYo73AgMBAAGgADANBgkqhkiG9w0BAQsFAANBAEaQ2QBhweK-kp1ejQCedUhMit_wG-uTBtKnc3M82f6_fztLkhg1vWQ782nmhbEI5orXp6QtNHgJYnBpqA9Ut00" @@ -1431,3 +1436,7 @@ func TestStatusCodeFromError(t *testing.T) { } } } + +func newRequestEvent() *requestEvent { + return &requestEvent{Extra: make(map[string]interface{})} +} From cddf1d27efe3b181a0a22d1d967210f69472a0d5 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 09:07:35 -0400 Subject: [PATCH 02/25] RealIP->clientAddr and fix nits --- wfe/context.go | 38 ++++++++++++++++---------------- wfe/web-front-end.go | 46 +++++++++++++++++++-------------------- wfe/web-front-end_test.go | 13 +++++------ 3 files changed, 48 insertions(+), 49 deletions(-) diff --git a/wfe/context.go b/wfe/context.go index 83646e08e..67bd3e994 100644 --- a/wfe/context.go +++ b/wfe/context.go @@ -3,6 +3,7 @@ package wfe import ( "fmt" "net/http" + "strings" "time" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" @@ -11,16 +12,15 @@ import ( ) type requestEvent struct { - ID string `json:",omitempty"` - RealIP string `json:",omitempty"` - ClientAddr string `json:",omitempty"` - Endpoint string `json:",omitempty"` - Method string `json:",omitempty"` - RequestTime time.Time `json:",omitempty"` - ResponseTime time.Time `json:",omitempty"` - Errors []string - Requester int64 `json:",omitempty"` - Contacts []*core.AcmeURL `json:",omitempty"` + ID string `json:",omitempty"` + ClientAddr string `json:",omitempty"` + Path string `json:",omitempty"` + Method string `json:",omitempty"` + RequestTime time.Time `json:",omitempty"` + ResponseTime time.Time `json:",omitempty"` + Errors []string + RegistrationID int64 `json:",omitempty"` + Contacts []*core.AcmeURL `json:",omitempty"` Extra map[string]interface{} `json:",omitempty"` } @@ -48,14 +48,13 @@ type wfeTopHandler struct { func (t *wfeTopHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { logEvent := &requestEvent{ ID: core.NewToken(), - RealIP: r.Header.Get("X-Real-IP"), ClientAddr: getClientAddr(r), Method: r.Method, RequestTime: time.Now(), Extra: make(map[string]interface{}, 0), } if r.URL != nil { - logEvent.Endpoint = r.URL.String() + logEvent.Path = r.URL.String() } defer t.logEvent(logEvent) @@ -73,13 +72,14 @@ func (t *wfeTopHandler) logEvent(logEvent *requestEvent) { t.log.InfoObject(msg, logEvent) } -// Comma-separated list of HTTP clients involved in making this -// request, starting with the original requestor and ending with the -// remote end of our TCP connection (which is typically our own -// proxy). +// Comma-separated list of HTTP clients involved in making this request, +// including the remote end of our TCP connection (which is typically our own +// proxy) as well as addresses from the X-Forwarded-For and X-Real-IP headers. func getClientAddr(r *http.Request) string { - if xff := r.Header.Get("X-Forwarded-For"); xff != "" { - return xff + "," + r.RemoteAddr + addrs := []string{ + r.RemoteAddr, + r.Header.Get("X-Forwarded-For"), + r.Header.Get("X-Real-IP"), } - return r.RemoteAddr + return strings.Join(addrs, ",") } diff --git a/wfe/web-front-end.go b/wfe/web-front-end.go index 6da36fa60..09ae27708 100644 --- a/wfe/web-front-end.go +++ b/wfe/web-front-end.go @@ -175,7 +175,7 @@ func (wfe *WebFrontEndImpl) HandleFunc(mux *http.ServeMux, pattern string, h wfe mux.Handle(pattern, &wfeTopHandler{ log: wfe.log, clk: clock.Default(), - h: wfeHandlerFunc(func(e *requestEvent, response http.ResponseWriter, request *http.Request) { + h: wfeHandlerFunc(func(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { // We do not propagate errors here, because (1) they should be // transient, and (2) they fail closed. nonce, err := wfe.nonceService.Nonce() @@ -196,7 +196,7 @@ func (wfe *WebFrontEndImpl) HandleFunc(mux *http.ServeMux, pattern string, h wfe if !methodsMap[request.Method] { msg := "Method not allowed" - e.AddError(msg) + logEvent.AddError(msg) response.Header().Set("Allow", methodsStr) wfe.sendError(response, msg, request.Method, http.StatusMethodNotAllowed) return @@ -205,7 +205,7 @@ func (wfe *WebFrontEndImpl) HandleFunc(mux *http.ServeMux, pattern string, h wfe wfe.setCORSHeaders(response, request, "") // Call the wrapped handler. - h(e, response, request) + h(logEvent, response, request) }), }) } @@ -301,7 +301,7 @@ func addCacheHeader(w http.ResponseWriter, age float64) { // Directory is an HTTP request handler that simply provides the directory // object stored in the WFE's DirectoryJSON member. -func (wfe *WebFrontEndImpl) Directory(e *requestEvent, response http.ResponseWriter, request *http.Request) { +func (wfe *WebFrontEndImpl) Directory(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { response.Header().Set("Content-Type", "application/json") response.Write(wfe.DirectoryJSON) } @@ -329,7 +329,7 @@ const ( // the key itself. verifyPOST also appends its errors to requestEvent.Errors so // code calling it does not need to if they imediately return a response to the // user. -func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, regCheck bool, resource core.AcmeResource) ([]byte, *jose.JsonWebKey, core.Registration, error) { +func (wfe *WebFrontEndImpl) verifyPOST(logEvent *requestEvent, request *http.Request, regCheck bool, resource core.AcmeResource) ([]byte, *jose.JsonWebKey, core.Registration, error) { var err error // TODO: We should return a pointer to a registration, which can be nil, // rather the a registration value with a sentinel value. @@ -339,7 +339,7 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r if _, ok := request.Header["Content-Length"]; !ok { err = core.LengthRequiredError("Content-Length header is required for POST.") wfe.stats.Inc("WFE.HTTP.ClientErrors.LengthRequiredError", 1, 1.0) - e.AddError("missing Content-Length header on POST") + logEvent.AddError("missing Content-Length header on POST") return nil, nil, reg, err } @@ -347,7 +347,7 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r if request.Body == nil { err = core.MalformedRequestError("No body on POST") wfe.stats.Inc("WFE.Errors.NoPOSTBody", 1, 1.0) - e.AddError("no body on POST") + logEvent.AddError("no body on POST") return nil, nil, reg, err } @@ -355,7 +355,7 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r if err != nil { err = core.InternalServerError("unable to read request body") wfe.stats.Inc("WFE.Errors.UnableToReadRequestBody", 1, 1.0) - e.AddError("unable to read request body") + logEvent.AddError("unable to read request body") return nil, nil, reg, err } @@ -365,7 +365,7 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r if err != nil { puberr := core.SignatureValidationError("Parse error reading JWS") wfe.stats.Inc("WFE.Errors.UnableToParseJWS", 1, 1.0) - e.AddError("could not JSON parse body into JWS: %s", err) + logEvent.AddError("could not JSON parse body into JWS: %s", err) return nil, nil, reg, puberr } @@ -378,20 +378,20 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r if len(parsedJws.Signatures) > 1 { err = core.SignatureValidationError("Too many signatures in POST body") wfe.stats.Inc("WFE.Errors.TooManyJWSSignaturesInPOST", 1, 1.0) - e.AddError("too many signatures in POST body: %d", len(parsedJws.Signatures)) + logEvent.AddError("too many signatures in POST body: %d", len(parsedJws.Signatures)) return nil, nil, reg, err } if len(parsedJws.Signatures) == 0 { err = core.SignatureValidationError("POST JWS not signed") wfe.stats.Inc("WFE.Errors.JWSNotSignedInPOST", 1, 1.0) - e.AddError("no signatures in POST body") + logEvent.AddError("no signatures in POST body") return nil, nil, reg, err } submittedKey := parsedJws.Signatures[0].Header.JsonWebKey if submittedKey == nil { err = core.SignatureValidationError("No JWK in JWS header") wfe.stats.Inc("WFE.Errors.NoJWKInJWSSignatureHeader", 1, 1.0) - e.AddError("no JWK in JWS signature header in POST body") + logEvent.AddError("no JWK in JWS signature header in POST body") return nil, nil, reg, err } @@ -406,20 +406,20 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r // to check its quality before doing the verify. if err = core.GoodKey(submittedKey.Key); err != nil { wfe.stats.Inc("WFE.Errors.JWKRejectedByGoodKey", 1, 1.0) - e.AddError("JWK in request was rejected by GoodKey: %s", err) + logEvent.AddError("JWK in request was rejected by GoodKey: %s", err) return nil, nil, reg, err } key = submittedKey } else if err != nil { // For all other errors, or if regCheck is true, return error immediately. wfe.stats.Inc("WFE.Errors.UnableToGetRegistrationByKey", 1, 1.0) - e.AddError("unable to fetch registration by the given JWK: %s", err) + logEvent.AddError("unable to fetch registration by the given JWK: %s", err) return nil, nil, reg, err } else { // If the lookup was successful, use that key. key = ®.Key - e.Requester = reg.ID - e.Contacts = reg.Contact + logEvent.RegistrationID = reg.ID + logEvent.Contacts = reg.Contact } payload, header, err := parsedJws.Verify(key) @@ -430,7 +430,7 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r if n > 100 { n = 100 } - e.AddError("verification of JWS with the JWK failed: %v; body: %s", err, body[:n]) + logEvent.AddError("verification of JWS with the JWK failed: %v; body: %s", err, body[:n]) return nil, nil, reg, puberr } @@ -438,12 +438,12 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r // i.e., Nonce is in protected header and if err != nil || len(header.Nonce) == 0 { wfe.stats.Inc("WFE.Errors.JWSMissingNonce", 1, 1.0) - e.AddError("JWS is missing an anti-replay nonce") + logEvent.AddError("JWS is missing an anti-replay nonce") err = core.SignatureValidationError("JWS has no anti-replay nonce") return nil, nil, reg, err } else if !wfe.nonceService.Valid(header.Nonce) { wfe.stats.Inc("WFE.Errors.JWSInvalidNonce", 1, 1.0) - e.AddError("JWS has an invalid anti-replay nonce") + logEvent.AddError("JWS has an invalid anti-replay nonce") err = core.SignatureValidationError(fmt.Sprintf("JWS has invalid anti-replay nonce")) return nil, nil, reg, err } @@ -455,18 +455,18 @@ func (wfe *WebFrontEndImpl) verifyPOST(e *requestEvent, request *http.Request, r err = json.Unmarshal([]byte(payload), &parsedRequest) if err != nil { wfe.stats.Inc("WFE.Errors.UnparsableJWSPayload", 1, 1.0) - e.AddError("unable to JSON parse resource from JWS payload: %s", err) + logEvent.AddError("unable to JSON parse resource from JWS payload: %s", err) puberr := core.SignatureValidationError("Request payload did not parse as JSON") return nil, nil, reg, puberr } if parsedRequest.Resource == "" { wfe.stats.Inc("WFE.Errors.NoResourceInJWSPayload", 1, 1.0) - e.AddError("JWS request payload does not specifiy a resource") + logEvent.AddError("JWS request payload does not specifiy a resource") err = core.MalformedRequestError("Request payload does not specify a resource") return nil, nil, reg, err } else if resource != core.AcmeResource(parsedRequest.Resource) { wfe.stats.Inc("WFE.Errors.MismatchedResourceInJWSPayload", 1, 1.0) - e.AddError("JWS request payload does not match resource") + logEvent.AddError("JWS request payload does not match resource") err = core.MalformedRequestError(fmt.Sprintf("JWS resource payload does not match the HTTP resource: %s != %s", parsedRequest.Resource, resource)) return nil, nil, reg, err } @@ -581,7 +581,7 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt wfe.sendError(response, "Error creating new registration", err, statusCodeFromError(err)) return } - logEvent.Requester = reg.ID + logEvent.RegistrationID = reg.ID logEvent.Contacts = reg.Contact // Use an explicitly typed variable. Otherwise `go vet' incorrectly complains diff --git a/wfe/web-front-end_test.go b/wfe/web-front-end_test.go index f1822ba0f..fb694baf1 100644 --- a/wfe/web-front-end_test.go +++ b/wfe/web-front-end_test.go @@ -179,6 +179,10 @@ func (pa *MockPA) WillingToIssue(id core.AcmeIdentifier, regID int64) error { return nil } +func newRequestEvent() *requestEvent { + return &requestEvent{Extra: make(map[string]interface{})} +} + func makeBody(s string) io.ReadCloser { return ioutil.NopCloser(strings.NewReader(s)) } @@ -1280,11 +1284,10 @@ func TestGetCertificate(t *testing.T) { test.AssertEquals(t, responseWriter.Header().Get("Content-Type"), "application/pkix-cert") test.Assert(t, bytes.Compare(responseWriter.Body.Bytes(), certBlock.Bytes) == 0, "Certificates don't match") - t.Logf("UGH %#v", mockLog.GetAll()[0]) reqlogs := mockLog.GetAllMatching(`Successful request`) test.AssertEquals(t, len(reqlogs), 1) test.AssertEquals(t, reqlogs[0].Priority, syslog.LOG_INFO) - test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.0.1"`) + test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.0.1,,"`) // Unused serial, no cache mockLog.Clear() @@ -1300,7 +1303,7 @@ func TestGetCertificate(t *testing.T) { reqlogs = mockLog.GetAllMatching(`Terminated request`) test.AssertEquals(t, len(reqlogs), 1) test.AssertEquals(t, reqlogs[0].Priority, syslog.LOG_INFO) - test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.99.99,192.168.0.1"`) + test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.0.1,192.168.99.99,"`) // Invalid serial, no cache responseWriter = httptest.NewRecorder() @@ -1427,7 +1430,3 @@ func TestStatusCodeFromError(t *testing.T) { } } } - -func newRequestEvent() *requestEvent { - return &requestEvent{Extra: make(map[string]interface{})} -} From dc58017032925a756bb93c7063e7500b262f48dc Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 09:23:17 -0400 Subject: [PATCH 03/25] Remove repetition by passing logEvent to sendError --- wfe/context.go | 1 + wfe/web-front-end.go | 157 ++++++++++++++++--------------------------- 2 files changed, 58 insertions(+), 100 deletions(-) diff --git a/wfe/context.go b/wfe/context.go index 67bd3e994..691b6a73d 100644 --- a/wfe/context.go +++ b/wfe/context.go @@ -16,6 +16,7 @@ type requestEvent struct { ClientAddr string `json:",omitempty"` Path string `json:",omitempty"` Method string `json:",omitempty"` + Status int `json:",omitEmpty"` RequestTime time.Time `json:",omitempty"` ResponseTime time.Time `json:",omitempty"` Errors []string diff --git a/wfe/web-front-end.go b/wfe/web-front-end.go index 09ae27708..e60e62380 100644 --- a/wfe/web-front-end.go +++ b/wfe/web-front-end.go @@ -196,9 +196,8 @@ func (wfe *WebFrontEndImpl) HandleFunc(mux *http.ServeMux, pattern string, h wfe if !methodsMap[request.Method] { msg := "Method not allowed" - logEvent.AddError(msg) response.Header().Set("Allow", methodsStr) - wfe.sendError(response, msg, request.Method, http.StatusMethodNotAllowed) + wfe.sendError(response, logEvent, msg, request.Method, http.StatusMethodNotAllowed) return } @@ -475,7 +474,7 @@ func (wfe *WebFrontEndImpl) verifyPOST(logEvent *requestEvent, request *http.Req } // Notify the client of an error condition and log it for audit purposes. -func (wfe *WebFrontEndImpl) sendError(response http.ResponseWriter, msg string, detail interface{}, code int) { +func (wfe *WebFrontEndImpl) sendError(response http.ResponseWriter, logEvent *requestEvent, msg string, detail interface{}, code int) { problem := core.ProblemDetails{Detail: msg} switch code { case http.StatusPreconditionFailed: @@ -498,6 +497,10 @@ func (wfe *WebFrontEndImpl) sendError(response http.ResponseWriter, msg string, problem.Type = core.ServerInternalProblem } + // Record details to the log event + logEvent.Status = code + logEvent.AddError(msg) + // Only audit log internal errors so users cannot purposefully cause // auditable events. if problem.Type == core.ServerInternalProblem { @@ -538,28 +541,25 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt body, key, _, err := wfe.verifyPOST(logEvent, request, false, core.ResourceNewReg) if err != nil { // verifyPOST handles its own setting of logEvent.Errors - wfe.sendError(response, malformedJWS, err, statusCodeFromError(err)) + wfe.sendError(response, logEvent, malformedJWS, err, statusCodeFromError(err)) return } if existingReg, err := wfe.SA.GetRegistrationByKey(*key); err == nil { - logEvent.AddError("Registration key is already in use") response.Header().Set("Location", fmt.Sprintf("%s%d", wfe.RegBase, existingReg.ID)) - wfe.sendError(response, "Registration key is already in use", nil, http.StatusConflict) + wfe.sendError(response, logEvent, "Registration key is already in use", nil, http.StatusConflict) return } var init core.Registration err = json.Unmarshal(body, &init) if err != nil { - logEvent.AddError("unable to unmarshal Registration: %s", err) - wfe.sendError(response, "Error unmarshaling JSON", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Error unmarshaling JSON", err, http.StatusBadRequest) return } if len(init.Agreement) > 0 && init.Agreement != wfe.SubscriberAgreementURL { msg := fmt.Sprintf("Provided agreement URL [%s] does not match current agreement URL [%s]", init.Agreement, wfe.SubscriberAgreementURL) - logEvent.AddError(msg) - wfe.sendError(response, msg, nil, http.StatusBadRequest) + wfe.sendError(response, logEvent, msg, nil, http.StatusBadRequest) return } init.Key = *key @@ -569,16 +569,14 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt if err == nil { init.InitialIP = net.ParseIP(host) } else { - logEvent.AddError("Couldn't parse RemoteAddr: %s", request.RemoteAddr) - wfe.sendError(response, "couldn't parse the remote (that is, the client's) address", nil, http.StatusInternalServerError) + wfe.sendError(response, logEvent, "couldn't parse the remote (that is, the client's) address", nil, http.StatusInternalServerError) return } } reg, err := wfe.RA.NewRegistration(init) if err != nil { - logEvent.AddError("unable to create new registration: %s", err) - wfe.sendError(response, "Error creating new registration", err, statusCodeFromError(err)) + wfe.sendError(response, logEvent, "Error creating new registration", err, statusCodeFromError(err)) return } logEvent.RegistrationID = reg.ID @@ -589,9 +587,8 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt regURL := fmt.Sprintf("%s%d", wfe.RegBase, reg.ID) responseBody, err := json.Marshal(reg) if err != nil { - logEvent.AddError("unable to marsh registration: %s", err) // StatusInternalServerError because we just created this registration, it should be OK. - wfe.sendError(response, "Error marshaling registration", err, http.StatusInternalServerError) + wfe.sendError(response, logEvent, "Error marshaling registration", err, http.StatusInternalServerError) return } @@ -617,22 +614,20 @@ func (wfe *WebFrontEndImpl) NewAuthorization(logEvent *requestEvent, response ht respMsg = unknownKey respCode = http.StatusForbidden } - wfe.sendError(response, respMsg, err, respCode) + wfe.sendError(response, logEvent, respMsg, err, respCode) return } // Any version of the agreement is acceptable here. Version match is enforced in // wfe.Registration when agreeing the first time. Agreement updates happen // by mailing subscribers and don't require a registration update. if currReg.Agreement == "" { - logEvent.AddError("Must agree to subscriber agreement before any further actions") - wfe.sendError(response, "Must agree to subscriber agreement before any further actions", nil, http.StatusForbidden) + wfe.sendError(response, logEvent, "Must agree to subscriber agreement before any further actions", nil, http.StatusForbidden) return } var init core.Authorization if err = json.Unmarshal(body, &init); err != nil { - logEvent.AddError("unable to JSON unmarshal Authorization: %s", err) - wfe.sendError(response, "Error unmarshaling JSON", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Error unmarshaling JSON", err, http.StatusBadRequest) return } logEvent.Extra["Identifier"] = init.Identifier @@ -640,8 +635,7 @@ func (wfe *WebFrontEndImpl) NewAuthorization(logEvent *requestEvent, response ht // Create new authz and return authz, err := wfe.RA.NewAuthorization(init, currReg.ID) if err != nil { - logEvent.AddError("unable to create new authz: %s", err) - wfe.sendError(response, "Error creating new authz", err, statusCodeFromError(err)) + wfe.sendError(response, logEvent, "Error creating new authz", err, statusCodeFromError(err)) return } logEvent.Extra["AuthzID"] = authz.ID @@ -651,9 +645,8 @@ func (wfe *WebFrontEndImpl) NewAuthorization(logEvent *requestEvent, response ht wfe.prepAuthorizationForDisplay(&authz) responseBody, err := json.Marshal(authz) if err != nil { - logEvent.AddError("unable to marshal authz: %s", err) // StatusInternalServerError because we generated the authz, it should be OK - wfe.sendError(response, "Error marshaling authz", err, http.StatusInternalServerError) + wfe.sendError(response, logEvent, "Error marshaling authz", err, http.StatusInternalServerError) return } @@ -675,7 +668,7 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response h body, requestKey, registration, err := wfe.verifyPOST(logEvent, request, false, core.ResourceRevokeCert) if err != nil { // verifyPOST handles its own setting of logEvent.Errors - wfe.sendError(response, malformedJWS, err, statusCodeFromError(err)) + wfe.sendError(response, logEvent, malformedJWS, err, statusCodeFromError(err)) return } @@ -684,16 +677,14 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response h } var revokeRequest RevokeRequest if err = json.Unmarshal(body, &revokeRequest); err != nil { - logEvent.AddError("unable to JSON unmarshal RevokeRequest: %s", err) wfe.log.Debug(fmt.Sprintf("Couldn't unmarshal in revoke request %s", string(body))) - wfe.sendError(response, "Unable to read/verify body", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Unable to read/verify body", err, http.StatusBadRequest) return } providedCert, err := x509.ParseCertificate(revokeRequest.CertificateDER) if err != nil { - logEvent.AddError("unable to parse revoke certificate DER: %s", err) wfe.log.Debug("Couldn't parse cert in revoke request.") - wfe.sendError(response, "Unable to read/verify body", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Unable to read/verify body", err, http.StatusBadRequest) return } @@ -701,14 +692,13 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response h logEvent.Extra["ProvidedCertificateSerial"] = serial cert, err := wfe.SA.GetCertificate(serial) if err != nil || !bytes.Equal(cert.DER, revokeRequest.CertificateDER) { - wfe.sendError(response, "No such certificate", err, http.StatusNotFound) + wfe.sendError(response, logEvent, "No such certificate", err, http.StatusNotFound) return } parsedCertificate, err := x509.ParseCertificate(cert.DER) if err != nil { - logEvent.AddError("unable to parse certificate DER: %s", err) // InternalServerError because this is a failure to decode from our DB. - wfe.sendError(response, "Invalid certificate", err, http.StatusInternalServerError) + wfe.sendError(response, logEvent, "Invalid certificate", err, http.StatusInternalServerError) return } logEvent.Extra["RetrievedCertificateSerial"] = core.SerialToString(parsedCertificate.SerialNumber) @@ -718,23 +708,20 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response h certStatus, err := wfe.SA.GetCertificateStatus(serial) if err != nil { - logEvent.AddError("unable to get certificate status: %s", err) - wfe.sendError(response, "Certificate status not yet available", err, http.StatusNotFound) + wfe.sendError(response, logEvent, "Certificate status not yet available", err, http.StatusNotFound) return } logEvent.Extra["CertificateStatus"] = certStatus.Status if certStatus.Status == core.OCSPStatusRevoked { - logEvent.AddError("Certificate already revoked: %#v", serial) - wfe.sendError(response, "Certificate already revoked", "", http.StatusConflict) + wfe.sendError(response, logEvent, "Certificate already revoked", "", http.StatusConflict) return } // TODO: Implement method of revocation by authorizations on account. if !(core.KeyDigestEquals(requestKey, parsedCertificate.PublicKey) || registration.ID == cert.RegistrationID) { - logEvent.AddError("Revocation request must be signed by private key of cert to be revoked, or by the account key of the account that issued it.") - wfe.sendError(response, + wfe.sendError(response, logEvent, "Revocation request must be signed by private key of cert to be revoked, or by the account key of the account that issued it.", requestKey, http.StatusForbidden) @@ -744,8 +731,7 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response h // Use revocation code 0, meaning "unspecified" err = wfe.RA.RevokeCertificateWithReg(*parsedCertificate, 0, registration.ID) if err != nil { - logEvent.AddError("failed to revoke certificate: %s", err) - wfe.sendError(response, "Failed to revoke certificate", err, statusCodeFromError(err)) + wfe.sendError(response, logEvent, "Failed to revoke certificate", err, statusCodeFromError(err)) } else { wfe.log.Debug(fmt.Sprintf("Revoked %v", serial)) response.WriteHeader(http.StatusOK) @@ -777,22 +763,20 @@ func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http respMsg = unknownKey respCode = http.StatusForbidden } - wfe.sendError(response, respMsg, err, respCode) + wfe.sendError(response, logEvent, respMsg, err, respCode) return } // Any version of the agreement is acceptable here. Version match is enforced in // wfe.Registration when agreeing the first time. Agreement updates happen // by mailing subscribers and don't require a registration update. if reg.Agreement == "" { - logEvent.AddError("Must agree to subscriber agreement before any further actions") - wfe.sendError(response, "Must agree to subscriber agreement before any further actions", nil, http.StatusForbidden) + wfe.sendError(response, logEvent, "Must agree to subscriber agreement before any further actions", nil, http.StatusForbidden) return } var certificateRequest core.CertificateRequest if err = json.Unmarshal(body, &certificateRequest); err != nil { - logEvent.AddError("unable to JSON unmarshal CertificateRequest: %s", err) - wfe.sendError(response, "Error unmarshaling certificate request", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Error unmarshaling certificate request", err, http.StatusBadRequest) return } wfe.logCsr(request, certificateRequest, reg) @@ -803,8 +787,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http // a bad key from the client is just a malformed request and doesn't need to // be audited. if err = core.GoodKey(certificateRequest.CSR.PublicKey); err != nil { - logEvent.AddError("CSR public key failed GoodKey: %s", err) - wfe.sendError(response, "Invalid key in certificate request", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Invalid key in certificate request", err, http.StatusBadRequest) return } logEvent.Extra["CSRDNSNames"] = certificateRequest.CSR.DNSNames @@ -819,8 +802,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http // RA for secondary validation. cert, err := wfe.RA.NewCertificate(certificateRequest, reg.ID) if err != nil { - logEvent.AddError("unable to create new cert: %s", err) - wfe.sendError(response, "Error creating new cert", err, statusCodeFromError(err)) + wfe.sendError(response, logEvent, "Error creating new cert", err, statusCodeFromError(err)) return } @@ -830,10 +812,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http // enumerate and mirror our certificates. parsedCertificate, err := x509.ParseCertificate([]byte(cert.DER)) if err != nil { - logEvent.AddError("unable to parse certificate: %s", err) - wfe.sendError(response, - "Error creating new cert", err, - http.StatusBadRequest) + wfe.sendError(response, logEvent, "Error creating new cert", err, http.StatusBadRequest) return } serial := parsedCertificate.SerialNumber @@ -858,7 +837,7 @@ func (wfe *WebFrontEndImpl) Challenge( request *http.Request) { notFound := func() { - wfe.sendError(response, "No such registration", request.URL.Path, http.StatusNotFound) + wfe.sendError(response, logEvent, "No such registration", request.URL.Path, http.StatusNotFound) } // Challenge URIs are of the form /acme/challenge//. @@ -887,8 +866,7 @@ func (wfe *WebFrontEndImpl) Challenge( // After expiring, challenges are inaccessible if authz.Expires == nil || authz.Expires.Before(wfe.clk.Now()) { msg := fmt.Sprintf("Authorization %v expired in the past (%v)", authz.ID, *authz.Expires) - logEvent.AddError(msg) - wfe.sendError(response, "Expired authorization", msg, http.StatusNotFound) + wfe.sendError(response, logEvent, "Expired authorization", msg, http.StatusNotFound) return } @@ -949,10 +927,9 @@ func (wfe *WebFrontEndImpl) getChallenge( jsonReply, err := json.Marshal(challenge) if err != nil { - logEvent.AddError("unable to marshal challenge: %s", err) // InternalServerError because this is a failure to decode data passed in // by the caller, which got it from the DB. - wfe.sendError(response, "Failed to marshal challenge", err, http.StatusInternalServerError) + wfe.sendError(response, logEvent, "Failed to marshal challenge", err, http.StatusInternalServerError) return } @@ -983,23 +960,21 @@ func (wfe *WebFrontEndImpl) postChallenge( respMsg = unknownKey respCode = http.StatusForbidden } - wfe.sendError(response, respMsg, err, respCode) + wfe.sendError(response, logEvent, respMsg, err, respCode) return } // Any version of the agreement is acceptable here. Version match is enforced in // wfe.Registration when agreeing the first time. Agreement updates happen // by mailing subscribers and don't require a registration update. if currReg.Agreement == "" { - logEvent.AddError("Registration didn't agree to subscriber agreement before any further actions") - wfe.sendError(response, "Registration didn't agree to subscriber agreement before any further actions", nil, http.StatusForbidden) + wfe.sendError(response, logEvent, "Registration didn't agree to subscriber agreement before any further actions", nil, http.StatusForbidden) return } // Check that the registration ID matching the key used matches // the registration ID on the authz object if currReg.ID != authz.RegistrationID { - logEvent.AddError("User registration id: %d != Authorization registration id: %v", currReg.ID, authz.RegistrationID) - wfe.sendError(response, "User registration ID doesn't match registration ID in authorization", + wfe.sendError(response, logEvent, "User registration ID doesn't match registration ID in authorization", "", http.StatusForbidden) return @@ -1007,16 +982,14 @@ func (wfe *WebFrontEndImpl) postChallenge( var challengeUpdate core.Challenge if err = json.Unmarshal(body, &challengeUpdate); err != nil { - logEvent.AddError("error JSON unmarshalling challenge response: %s", err) - wfe.sendError(response, "Error unmarshaling challenge response", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Error unmarshaling challenge response", err, http.StatusBadRequest) return } // Ask the RA to update this authorization updatedAuthorization, err := wfe.RA.UpdateAuthorization(authz, challengeIndex, challengeUpdate) if err != nil { - logEvent.AddError("unable to update challenge: %s", err) - wfe.sendError(response, "Unable to update challenge", err, statusCodeFromError(err)) + wfe.sendError(response, logEvent, "Unable to update challenge", err, statusCodeFromError(err)) return } @@ -1025,9 +998,8 @@ func (wfe *WebFrontEndImpl) postChallenge( wfe.prepChallengeForDisplay(authz, &challenge) jsonReply, err := json.Marshal(challenge) if err != nil { - logEvent.AddError("failed to marshal challenge: %s", err) // StatusInternalServerError because we made the challenges, they should be OK - wfe.sendError(response, "Failed to marshal challenge", err, http.StatusInternalServerError) + wfe.sendError(response, logEvent, "Failed to marshal challenge", err, http.StatusInternalServerError) return } @@ -1055,7 +1027,7 @@ func (wfe *WebFrontEndImpl) Registration(logEvent *requestEvent, response http.R respMsg = unknownKey respCode = http.StatusForbidden } - wfe.sendError(response, respMsg, err, respCode) + wfe.sendError(response, logEvent, respMsg, err, respCode) return } @@ -1064,31 +1036,27 @@ func (wfe *WebFrontEndImpl) Registration(logEvent *requestEvent, response http.R idStr := parseIDFromPath(request.URL.Path) id, err := strconv.ParseInt(idStr, 10, 64) if err != nil { - logEvent.AddError("registration ID must be an integer, was %#v", idStr) - wfe.sendError(response, "Registration ID must be an integer", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Registration ID must be an integer", err, http.StatusBadRequest) return } else if id <= 0 { - logEvent.AddError("Registration ID must be a positive non-zero integer, was %d", id) - wfe.sendError(response, "Registration ID must be a positive non-zero integer", id, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Registration ID must be a positive non-zero integer", id, http.StatusBadRequest) return } else if id != currReg.ID { - logEvent.AddError("Request signing key did not match registration key: %d != %d", id, currReg.ID) - wfe.sendError(response, "Request signing key did not match registration key", "", http.StatusForbidden) + wfe.sendError(response, logEvent, "Request signing key did not match registration key", "", http.StatusForbidden) return } var update core.Registration err = json.Unmarshal(body, &update) if err != nil { - logEvent.AddError("unable to JSON parse registration: %s", err) - wfe.sendError(response, "Error unmarshaling registration", err, http.StatusBadRequest) + wfe.sendError(response, logEvent, "Error unmarshaling registration", err, http.StatusBadRequest) return } if len(update.Agreement) > 0 && update.Agreement != wfe.SubscriberAgreementURL { msg := fmt.Sprintf("Provided agreement URL [%s] does not match current agreement URL [%s]", update.Agreement, wfe.SubscriberAgreementURL) logEvent.AddError(msg) - wfe.sendError(response, msg, nil, http.StatusBadRequest) + wfe.sendError(response, logEvent, msg, nil, http.StatusBadRequest) return } @@ -1101,16 +1069,14 @@ func (wfe *WebFrontEndImpl) Registration(logEvent *requestEvent, response http.R // Ask the RA to update this authorization. updatedReg, err := wfe.RA.UpdateRegistration(currReg, update) if err != nil { - logEvent.AddError("unable to update registration: %s", err) - wfe.sendError(response, "Unable to update registration", err, statusCodeFromError(err)) + wfe.sendError(response, logEvent, "Unable to update registration", err, statusCodeFromError(err)) return } jsonReply, err := json.Marshal(updatedReg) if err != nil { - logEvent.AddError("unable to marshal updated registration: %s", err) // StatusInternalServerError because we just generated the reg, it should be OK - wfe.sendError(response, "Failed to marshal registration", err, http.StatusInternalServerError) + wfe.sendError(response, logEvent, "Failed to marshal registration", err, http.StatusInternalServerError) return } response.Header().Set("Content-Type", "application/json") @@ -1129,10 +1095,7 @@ func (wfe *WebFrontEndImpl) Authorization(logEvent *requestEvent, response http. id := parseIDFromPath(request.URL.Path) authz, err := wfe.SA.GetAuthorization(id) if err != nil { - logEvent.AddError("No such authorization at id %s", id) - wfe.sendError(response, - "Unable to find authorization", err, - http.StatusNotFound) + wfe.sendError(response, logEvent, "Unable to find authorization", err, http.StatusNotFound) return } logEvent.Extra["AuthorizationID"] = authz.ID @@ -1144,8 +1107,7 @@ func (wfe *WebFrontEndImpl) Authorization(logEvent *requestEvent, response http. // After expiring, authorizations are inaccessible if authz.Expires == nil || authz.Expires.Before(wfe.clk.Now()) { msg := fmt.Sprintf("Authorization %v expired in the past (%v)", authz.ID, *authz.Expires) - logEvent.AddError(msg) - wfe.sendError(response, "Expired authorization", msg, http.StatusNotFound) + wfe.sendError(response, logEvent, "Expired authorization", msg, http.StatusNotFound) return } @@ -1153,9 +1115,8 @@ func (wfe *WebFrontEndImpl) Authorization(logEvent *requestEvent, response http. jsonReply, err := json.Marshal(authz) if err != nil { - logEvent.AddError("Failed to JSON marshal authz: %s", err) // InternalServerError because this is a failure to decode from our DB. - wfe.sendError(response, "Failed to JSON marshal authz", err, http.StatusInternalServerError) + wfe.sendError(response, logEvent, "Failed to JSON marshal authz", err, http.StatusInternalServerError) return } response.Header().Add("Link", link(wfe.NewCert, "next")) @@ -1177,15 +1138,13 @@ func (wfe *WebFrontEndImpl) Certificate(logEvent *requestEvent, response http.Re // Certificate paths consist of the CertBase path, plus exactly sixteen hex // digits. if !strings.HasPrefix(path, CertPath) { - logEvent.AddError("this request path should not have gotten to Certificate: %#v is not a prefix of %#v", path, CertPath) - wfe.sendError(response, "Certificate not found", path, http.StatusNotFound) + wfe.sendError(response, logEvent, "Certificate not found", path, http.StatusNotFound) addNoCacheHeader(response) return } serial := path[len(CertPath):] if !core.ValidSerial(serial) { - logEvent.AddError("certificate serial provided was not valid: %s", serial) - wfe.sendError(response, "Certificate not found", serial, http.StatusNotFound) + wfe.sendError(response, logEvent, "Certificate not found", serial, http.StatusNotFound) addNoCacheHeader(response) return } @@ -1193,12 +1152,11 @@ func (wfe *WebFrontEndImpl) Certificate(logEvent *requestEvent, response http.Re cert, err := wfe.SA.GetCertificate(serial) if err != nil { - logEvent.AddError("unable to get certificate by serial id %#v: %s", serial, err) if strings.HasPrefix(err.Error(), "gorp: multiple rows returned") { - wfe.sendError(response, "Multiple certificates with same short serial", err, http.StatusConflict) + wfe.sendError(response, logEvent, "Multiple certificates with same short serial", err, http.StatusConflict) } else { addNoCacheHeader(response) - wfe.sendError(response, "Certificate not found", err, http.StatusNotFound) + wfe.sendError(response, logEvent, "Certificate not found", err, http.StatusNotFound) } return } @@ -1210,7 +1168,6 @@ func (wfe *WebFrontEndImpl) Certificate(logEvent *requestEvent, response http.Re response.Header().Add("Link", link(IssuerPath, "up")) response.WriteHeader(http.StatusOK) if _, err = response.Write(cert.DER); err != nil { - logEvent.AddError("unable to write new certificate response: %s", err) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } return From d61d09bb616486a1a945c7e0b954873a167ff8bd Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 09:25:27 -0400 Subject: [PATCH 04/25] Minor beautification --- wfe/context.go | 16 ++++++++-------- wfe/web-front-end.go | 8 ++++---- 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/wfe/context.go b/wfe/context.go index 691b6a73d..9a0736382 100644 --- a/wfe/context.go +++ b/wfe/context.go @@ -40,13 +40,13 @@ type wfeHandler interface { ServeHTTP(e *requestEvent, w http.ResponseWriter, r *http.Request) } -type wfeTopHandler struct { - h wfeHandler +type topHandler struct { + wfe wfeHandler log *blog.AuditLogger clk clock.Clock } -func (t *wfeTopHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { +func (th *topHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { logEvent := &requestEvent{ ID: core.NewToken(), ClientAddr: getClientAddr(r), @@ -57,20 +57,20 @@ func (t *wfeTopHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { if r.URL != nil { logEvent.Path = r.URL.String() } - defer t.logEvent(logEvent) + defer th.logEvent(logEvent) - t.h.ServeHTTP(logEvent, w, r) + th.wfe.ServeHTTP(logEvent, w, r) } -func (t *wfeTopHandler) logEvent(logEvent *requestEvent) { - logEvent.ResponseTime = t.clk.Now() +func (th *topHandler) logEvent(logEvent *requestEvent) { + logEvent.ResponseTime = th.clk.Now() var msg string if len(logEvent.Errors) != 0 { msg = "Terminated request" } else { msg = "Successful request" } - t.log.InfoObject(msg, logEvent) + th.log.InfoObject(msg, logEvent) } // Comma-separated list of HTTP clients involved in making this request, diff --git a/wfe/web-front-end.go b/wfe/web-front-end.go index e60e62380..e0333a363 100644 --- a/wfe/web-front-end.go +++ b/wfe/web-front-end.go @@ -172,10 +172,10 @@ func (wfe *WebFrontEndImpl) HandleFunc(mux *http.ServeMux, pattern string, h wfe methodsMap["HEAD"] = true } methodsStr := strings.Join(methods, ", ") - mux.Handle(pattern, &wfeTopHandler{ + mux.Handle(pattern, &topHandler{ log: wfe.log, clk: clock.Default(), - h: wfeHandlerFunc(func(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { + wfe: wfeHandlerFunc(func(logEvent *requestEvent, response http.ResponseWriter, request *http.Request) { // We do not propagate errors here, because (1) they should be // transient, and (2) they fail closed. nonce, err := wfe.nonceService.Nonce() @@ -249,10 +249,10 @@ func (wfe *WebFrontEndImpl) Handler() (http.Handler, error) { // We don't use our special HandleFunc for "/" because it matches everything, // meaning we can wind up returning 405 when we mean to return 404. See // https://github.com/letsencrypt/boulder/issues/717 - m.Handle("/", &wfeTopHandler{ + m.Handle("/", &topHandler{ log: wfe.log, clk: clock.Default(), - h: wfeHandlerFunc(wfe.Index), + wfe: wfeHandlerFunc(wfe.Index), }) return m, nil } From d1d1690f2a0f37083d1f5949d3eff8f08f591793 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 10:46:22 -0400 Subject: [PATCH 05/25] Have the CA recognize and persist HSM faults --- ca/certificate-authority.go | 84 ++++++++++++++++++++++++++++++++ ca/certificate-authority_test.go | 49 +++++++++++++++++++ mocks/mocks.go | 33 +++++++++++++ 3 files changed, 166 insertions(+) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index 03b06183b..c1b3ec4e1 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -17,6 +17,7 @@ import ( "io/ioutil" "math/big" "strings" + "sync" "time" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" @@ -48,6 +49,12 @@ var badSignatureAlgorithms = map[x509.SignatureAlgorithm]bool{ x509.ECDSAWithSHA1: true, } +// HSM faults tend to be persistent. If we observe one, we will set a flag and +// throttle requests according to an exponential back-off, bounded by these min +// and max delay values. +const hsmFaultMinTimeout = time.Second +const hsmFaultMaxTimeout = 128 * time.Second + // CertificateAuthorityImpl represents a CA that signs certificates, CRLs, and // OCSP responses. type CertificateAuthorityImpl struct { @@ -63,6 +70,28 @@ type CertificateAuthorityImpl struct { ValidityPeriod time.Duration NotAfter time.Time MaxNames int + + hsmFault bool + hsmFaultLock sync.Mutex + hsmFaultLastObserved time.Time + hsmFaultTimeout time.Duration +} + +// checkHSMFault checks whether there has been an HSM fault observed within the +// timeout window. CA methods that use the HSM should call this method right +// away, to minimize the performance impact of HSM outages. +func (ca *CertificateAuthorityImpl) checkHSMFault() bool { + ca.hsmFaultLock.Lock() + defer ca.hsmFaultLock.Unlock() + + now := ca.Clk.Now() + timeout := ca.hsmFaultLastObserved.Add(ca.hsmFaultTimeout) + if timeout.Before(now) { + // Go ahead and try again + return false + } + + return ca.hsmFault } // NewCertificateAuthorityImpl creates a CA that talks to a remote CFSSL @@ -172,8 +201,52 @@ func loadKey(keyConfig cmd.KeyConfig) (priv crypto.Signer, err error) { return } +// noteHSMFault updates the CA's state with regard to HSM faults. CA methods +// that use an HSM should pass errors that might be HSM errors to this method. +// We distinguish HSM errors from other errors by looking for a string that the +// PKCS#11 library appends to its errors. +// +// XXX(rlb): It would be better to directly check that the error is of the +// PKCS#11 library's local Error type. But that would be messier, since we +// would have to import that library, which we don't now. +func (ca *CertificateAuthorityImpl) noteHSMFault(err error) { + ca.hsmFaultLock.Lock() + defer ca.hsmFaultLock.Unlock() + + // If err == nil, the HSM is working, reset the timeout + // Note that we don't check if the HSM is the source of this error, + // since it doesn't matter. If everything worked, then in particular, + // the HSM worked. + if err == nil { + ca.hsmFault = false + ca.hsmFaultTimeout = hsmFaultMinTimeout + return + } + + if !strings.HasPrefix(err.Error(), "pkcs11:") { + // Not an HSM error; nothing to do + return + } + + // Otherwise, things are broken, and we should back off + ca.hsmFault = true + ca.hsmFaultLastObserved = ca.Clk.Now() + if ca.hsmFaultTimeout < hsmFaultMaxTimeout { + ca.hsmFaultTimeout *= 2 + } + + return +} + // GenerateOCSP produces a new OCSP response and returns it func (ca *CertificateAuthorityImpl) GenerateOCSP(xferObj core.OCSPSigningRequest) ([]byte, error) { + hsmFault := ca.checkHSMFault() + if hsmFault { + err := fmt.Errorf("GenerateOCSP call rejected; HSM is unavailable") + ca.log.WarningErr(err) + return nil, err + } + cert, err := x509.ParseCertificate(xferObj.CertDER) if err != nil { // AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3 @@ -204,6 +277,13 @@ func (ca *CertificateAuthorityImpl) RevokeCertificate(serial string, reasonCode func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest, regID int64) (core.Certificate, error) { emptyCert := core.Certificate{} var err error + + if ca.checkHSMFault() { + err := fmt.Errorf("IssueCertificate call rejected; HSM is unavailable") + ca.log.WarningErr(err) + return emptyCert, err + } + key, ok := csr.PublicKey.(crypto.PublicKey) if !ok { err = core.MalformedRequestError("Invalid public key in CSR.") @@ -310,6 +390,10 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest certPEM, err := ca.Signer.Sign(req) if err != nil { + // Since we just used the HSM (if we're using one), note whether it worked + // or not. + ca.noteHSMFault(err) + err = core.InternalServerError(err.Error()) // AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3 ca.log.Audit(fmt.Sprintf("Signer failed, rolling back: serial=[%s] err=[%v]", serialHex, err)) diff --git a/ca/certificate-authority_test.go b/ca/certificate-authority_test.go index 0fc0403d3..01277656f 100644 --- a/ca/certificate-authority_test.go +++ b/ca/certificate-authority_test.go @@ -409,3 +409,52 @@ func TestCapitalizedLetters(t *testing.T) { expected := []string{"capitalizedletters.com", "evenmorecaps.com", "morecaps.com"} test.AssertDeepEquals(t, expected, parsedCert.DNSNames) } + +func TestHSMFaultTimeout(t *testing.T) { + ctx := setup(t) + defer ctx.cleanUp() + + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca.Publisher = &mocks.Publisher{} + ca.PA = ctx.pa + ca.SA = ctx.sa + + // Issue a certificate so that we can use it later + csr, _ := x509.ParseCertificateRequest(CNandSANCSR) + cert, err := ca.IssueCertificate(*csr, ctx.reg.ID) + ocspRequest := core.OCSPSigningRequest{ + CertDER: cert.DER, + Status: "good", + } + + // Swap in a bad signer + goodSigner := ca.Signer + badHSMErrorMessage := "This is really serious. You should wait" + ca.Signer = mocks.BadHSMSigner(badHSMErrorMessage) + + // Cause the CA to enter the HSM fault condition + _, err = ca.IssueCertificate(*csr, ctx.reg.ID) + test.AssertError(t, err, "CA failed to return HSM error") + test.AssertEquals(t, err.Error(), "pkcs11: "+badHSMErrorMessage) + + // Check that the CA rejects the next call as the HSM being down + _, err = ca.IssueCertificate(*csr, ctx.reg.ID) + test.AssertError(t, err, "CA failed to persist HSM fault") + test.AssertEquals(t, err.Error(), "IssueCertificate call rejected; HSM is unavailable") + + _, err = ca.GenerateOCSP(ocspRequest) + test.AssertError(t, err, "CA failed to persist HSM fault") + test.AssertEquals(t, err.Error(), "GenerateOCSP call rejected; HSM is unavailable") + + // Swap in a good signer and move the clock forward to clear the fault + ca.Signer = goodSigner + ctx.fc.Add(ca.hsmFaultTimeout) + ctx.fc.Add(10 * time.Second) + + // Check that the CA has recovered + _, err = ca.IssueCertificate(*csr, ctx.reg.ID) + test.AssertNotError(t, err, "CA failed to recover from HSM fault") + + _, err = ca.GenerateOCSP(ocspRequest) + test.AssertNotError(t, err, "CA failed to recover from HSM fault") +} diff --git a/mocks/mocks.go b/mocks/mocks.go index a100cb33d..6ac0e5fe1 100644 --- a/mocks/mocks.go +++ b/mocks/mocks.go @@ -6,6 +6,7 @@ package mocks import ( + "crypto/x509" "encoding/pem" "errors" "fmt" @@ -14,6 +15,9 @@ import ( "strings" "time" + "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/config" + "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/info" + "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/signer" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/letsencrypt/go-jose" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/miekg/dns" @@ -370,3 +374,32 @@ type Publisher struct { func (*Publisher) SubmitToCT([]byte) error { return nil } + +// BadHSMSigner represents a CFSSL signer that always returns a PKCS#11 error. +type BadHSMSigner string + +// Info is a mock +func (bhs BadHSMSigner) Info(info.Req) (*info.Resp, error) { + return nil, nil +} + +// Policy is a mock +func (bhs BadHSMSigner) Policy() *config.Signing { + return nil +} + +// SetPolicy is a mock +func (bhs BadHSMSigner) SetPolicy(*config.Signing) { + return +} + +// SigAlgo is a mock +func (bhs BadHSMSigner) SigAlgo() x509.SignatureAlgorithm { + return x509.UnknownSignatureAlgorithm +} + +// Sign always returns a PKCS#11 error, in the format used by +// github.com/miekg/pkcs11 +func (bhs BadHSMSigner) Sign(req signer.SignRequest) (cert []byte, err error) { + return nil, fmt.Errorf("pkcs11: " + string(bhs)) +} From d0e12c357a6e5b5bee0c54a974f52690e43a17f3 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 10:48:30 -0400 Subject: [PATCH 06/25] Move checkHSMFault together with noteHSMFault --- ca/certificate-authority.go | 34 +++++++++++++++++----------------- 1 file changed, 17 insertions(+), 17 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index c1b3ec4e1..094b1447d 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -77,23 +77,6 @@ type CertificateAuthorityImpl struct { hsmFaultTimeout time.Duration } -// checkHSMFault checks whether there has been an HSM fault observed within the -// timeout window. CA methods that use the HSM should call this method right -// away, to minimize the performance impact of HSM outages. -func (ca *CertificateAuthorityImpl) checkHSMFault() bool { - ca.hsmFaultLock.Lock() - defer ca.hsmFaultLock.Unlock() - - now := ca.Clk.Now() - timeout := ca.hsmFaultLastObserved.Add(ca.hsmFaultTimeout) - if timeout.Before(now) { - // Go ahead and try again - return false - } - - return ca.hsmFault -} - // NewCertificateAuthorityImpl creates a CA that talks to a remote CFSSL // instance. (To use a local signer, simply instantiate CertificateAuthorityImpl // directly.) Communications with the CA are authenticated with MACs, @@ -201,6 +184,23 @@ func loadKey(keyConfig cmd.KeyConfig) (priv crypto.Signer, err error) { return } +// checkHSMFault checks whether there has been an HSM fault observed within the +// timeout window. CA methods that use the HSM should call this method right +// away, to minimize the performance impact of HSM outages. +func (ca *CertificateAuthorityImpl) checkHSMFault() bool { + ca.hsmFaultLock.Lock() + defer ca.hsmFaultLock.Unlock() + + now := ca.Clk.Now() + timeout := ca.hsmFaultLastObserved.Add(ca.hsmFaultTimeout) + if timeout.Before(now) { + // Go ahead and try again + return false + } + + return ca.hsmFault +} + // noteHSMFault updates the CA's state with regard to HSM faults. CA methods // that use an HSM should pass errors that might be HSM errors to this method. // We distinguish HSM errors from other errors by looking for a string that the From 305b44bd168b2e9d8d1099ae8fde3593684498b0 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 10:49:30 -0400 Subject: [PATCH 07/25] Consistent HSM fault checking --- ca/certificate-authority.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index 094b1447d..538b3dea9 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -240,8 +240,7 @@ func (ca *CertificateAuthorityImpl) noteHSMFault(err error) { // GenerateOCSP produces a new OCSP response and returns it func (ca *CertificateAuthorityImpl) GenerateOCSP(xferObj core.OCSPSigningRequest) ([]byte, error) { - hsmFault := ca.checkHSMFault() - if hsmFault { + if ca.checkHSMFault() { err := fmt.Errorf("GenerateOCSP call rejected; HSM is unavailable") ca.log.WarningErr(err) return nil, err From be7c7aebbb59f06cc11c0d006af61755028c1f6f Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 12:29:42 -0400 Subject: [PATCH 08/25] Address @jcjones comments --- ca/certificate-authority.go | 3 ++- ca/certificate-authority_test.go | 2 ++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index 538b3dea9..882019ba7 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -261,6 +261,7 @@ func (ca *CertificateAuthorityImpl) GenerateOCSP(xferObj core.OCSPSigningRequest } ocspResponse, err := ca.OCSPSigner.Sign(signRequest) + ca.noteHSMFault(err) return ocspResponse, err } @@ -388,10 +389,10 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest } certPEM, err := ca.Signer.Sign(req) + ca.noteHSMFault(err) if err != nil { // Since we just used the HSM (if we're using one), note whether it worked // or not. - ca.noteHSMFault(err) err = core.InternalServerError(err.Error()) // AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3 diff --git a/ca/certificate-authority_test.go b/ca/certificate-authority_test.go index 01277656f..b807e6eca 100644 --- a/ca/certificate-authority_test.go +++ b/ca/certificate-authority_test.go @@ -457,4 +457,6 @@ func TestHSMFaultTimeout(t *testing.T) { _, err = ca.GenerateOCSP(ocspRequest) test.AssertNotError(t, err, "CA failed to recover from HSM fault") + + test.AssertEquals(t, ca.hsmFaultTimeout, hsmFaultMinTimeout) } From 28be8023cfd26d3ed19a23c328d2db27a8e3b273 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 13:34:43 -0400 Subject: [PATCH 09/25] Add a mock OCSP signer and better OCSP HSM fault tests --- ca/certificate-authority_test.go | 20 +++++++++++++++++--- mocks/mocks.go | 9 +++++++++ 2 files changed, 26 insertions(+), 3 deletions(-) diff --git a/ca/certificate-authority_test.go b/ca/certificate-authority_test.go index b807e6eca..6d855a55b 100644 --- a/ca/certificate-authority_test.go +++ b/ca/certificate-authority_test.go @@ -430,9 +430,11 @@ func TestHSMFaultTimeout(t *testing.T) { // Swap in a bad signer goodSigner := ca.Signer badHSMErrorMessage := "This is really serious. You should wait" - ca.Signer = mocks.BadHSMSigner(badHSMErrorMessage) + badSigner := mocks.BadHSMSigner(badHSMErrorMessage) + badOCSPSigner := mocks.BadHSMOCSPSigner(badHSMErrorMessage) // Cause the CA to enter the HSM fault condition + ca.Signer = badSigner _, err = ca.IssueCertificate(*csr, ctx.reg.ID) test.AssertError(t, err, "CA failed to return HSM error") test.AssertEquals(t, err.Error(), "pkcs11: "+badHSMErrorMessage) @@ -454,9 +456,21 @@ func TestHSMFaultTimeout(t *testing.T) { // Check that the CA has recovered _, err = ca.IssueCertificate(*csr, ctx.reg.ID) test.AssertNotError(t, err, "CA failed to recover from HSM fault") - _, err = ca.GenerateOCSP(ocspRequest) test.AssertNotError(t, err, "CA failed to recover from HSM fault") - test.AssertEquals(t, ca.hsmFaultTimeout, hsmFaultMinTimeout) + + // Check that GenerateOCSP can also trigger an HSM failure, in the same way + ca.OCSPSigner = badOCSPSigner + _, err = ca.GenerateOCSP(ocspRequest) + test.AssertError(t, err, "CA failed to return HSM error") + test.AssertEquals(t, err.Error(), "pkcs11: "+badHSMErrorMessage) + + _, err = ca.IssueCertificate(*csr, ctx.reg.ID) + test.AssertError(t, err, "CA failed to persist HSM fault") + test.AssertEquals(t, err.Error(), "IssueCertificate call rejected; HSM is unavailable") + + _, err = ca.GenerateOCSP(ocspRequest) + test.AssertError(t, err, "CA failed to persist HSM fault") + test.AssertEquals(t, err.Error(), "GenerateOCSP call rejected; HSM is unavailable") } diff --git a/mocks/mocks.go b/mocks/mocks.go index 6ac0e5fe1..7e391695a 100644 --- a/mocks/mocks.go +++ b/mocks/mocks.go @@ -17,6 +17,7 @@ import ( "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/config" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/info" + "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/ocsp" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/signer" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/letsencrypt/go-jose" @@ -403,3 +404,11 @@ func (bhs BadHSMSigner) SigAlgo() x509.SignatureAlgorithm { func (bhs BadHSMSigner) Sign(req signer.SignRequest) (cert []byte, err error) { return nil, fmt.Errorf("pkcs11: " + string(bhs)) } + +// BadHSMOCSPSigner represents a CFSSL OCSP signer that always returns a +// PKCS#11 error +type BadHSMOCSPSigner string + +func (bhos BadHSMOCSPSigner) Sign(ocsp.SignRequest) ([]byte, error) { + return nil, fmt.Errorf("pkcs11: " + string(bhos)) +} From db29b9456de9c2479b5ecd6c26805b9df32794cd Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 14:57:04 -0400 Subject: [PATCH 10/25] Lint failure --- mocks/mocks.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/mocks/mocks.go b/mocks/mocks.go index 7e391695a..4daf094ea 100644 --- a/mocks/mocks.go +++ b/mocks/mocks.go @@ -409,6 +409,8 @@ func (bhs BadHSMSigner) Sign(req signer.SignRequest) (cert []byte, err error) { // PKCS#11 error type BadHSMOCSPSigner string +// Sign always returns a PKCS#11 error, in the format used by +// github.com/miekg/pkcs11 func (bhos BadHSMOCSPSigner) Sign(ocsp.SignRequest) ([]byte, error) { return nil, fmt.Errorf("pkcs11: " + string(bhos)) } From 06a743882c4adc3b5d0602f4c54e07b0113ced69 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 15:24:45 -0400 Subject: [PATCH 11/25] Treat all signer errors as HSM errors --- ca/certificate-authority.go | 5 ----- mocks/mocks.go | 4 ++-- 2 files changed, 2 insertions(+), 7 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index 882019ba7..1ae094aee 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -223,11 +223,6 @@ func (ca *CertificateAuthorityImpl) noteHSMFault(err error) { return } - if !strings.HasPrefix(err.Error(), "pkcs11:") { - // Not an HSM error; nothing to do - return - } - // Otherwise, things are broken, and we should back off ca.hsmFault = true ca.hsmFaultLastObserved = ca.Clk.Now() diff --git a/mocks/mocks.go b/mocks/mocks.go index 4daf094ea..e2c7aac63 100644 --- a/mocks/mocks.go +++ b/mocks/mocks.go @@ -402,7 +402,7 @@ func (bhs BadHSMSigner) SigAlgo() x509.SignatureAlgorithm { // Sign always returns a PKCS#11 error, in the format used by // github.com/miekg/pkcs11 func (bhs BadHSMSigner) Sign(req signer.SignRequest) (cert []byte, err error) { - return nil, fmt.Errorf("pkcs11: " + string(bhs)) + return nil, fmt.Errorf(string(bhs)) } // BadHSMOCSPSigner represents a CFSSL OCSP signer that always returns a @@ -412,5 +412,5 @@ type BadHSMOCSPSigner string // Sign always returns a PKCS#11 error, in the format used by // github.com/miekg/pkcs11 func (bhos BadHSMOCSPSigner) Sign(ocsp.SignRequest) ([]byte, error) { - return nil, fmt.Errorf("pkcs11: " + string(bhos)) + return nil, fmt.Errorf(string(bhos)) } From 55b4fb116e0396e74d8f5a2bd093236501e4e3ac Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 16:04:36 -0400 Subject: [PATCH 12/25] Remove adaptation from rate limit --- ca/certificate-authority.go | 43 ++++++-------------------------- ca/certificate-authority_test.go | 8 +++--- 2 files changed, 10 insertions(+), 41 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index 1ae094aee..5dca16acb 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -49,11 +49,9 @@ var badSignatureAlgorithms = map[x509.SignatureAlgorithm]bool{ x509.ECDSAWithSHA1: true, } -// HSM faults tend to be persistent. If we observe one, we will set a flag and -// throttle requests according to an exponential back-off, bounded by these min -// and max delay values. -const hsmFaultMinTimeout = time.Second -const hsmFaultMaxTimeout = 128 * time.Second +// HSM faults tend to be persistent. If we observe one, we will refuse any +// further requests for signing (certificates or OCSP) for this period. +const hsmFaultTimeout = 5 * 60 * time.Second // CertificateAuthorityImpl represents a CA that signs certificates, CRLs, and // OCSP responses. @@ -71,10 +69,8 @@ type CertificateAuthorityImpl struct { NotAfter time.Time MaxNames int - hsmFault bool hsmFaultLock sync.Mutex hsmFaultLastObserved time.Time - hsmFaultTimeout time.Duration } // NewCertificateAuthorityImpl creates a CA that talks to a remote CFSSL @@ -192,44 +188,19 @@ func (ca *CertificateAuthorityImpl) checkHSMFault() bool { defer ca.hsmFaultLock.Unlock() now := ca.Clk.Now() - timeout := ca.hsmFaultLastObserved.Add(ca.hsmFaultTimeout) - if timeout.Before(now) { - // Go ahead and try again - return false - } - - return ca.hsmFault + timeout := ca.hsmFaultLastObserved.Add(hsmFaultTimeout) + return now.Before(timeout) } // noteHSMFault updates the CA's state with regard to HSM faults. CA methods // that use an HSM should pass errors that might be HSM errors to this method. -// We distinguish HSM errors from other errors by looking for a string that the -// PKCS#11 library appends to its errors. -// -// XXX(rlb): It would be better to directly check that the error is of the -// PKCS#11 library's local Error type. But that would be messier, since we -// would have to import that library, which we don't now. func (ca *CertificateAuthorityImpl) noteHSMFault(err error) { ca.hsmFaultLock.Lock() defer ca.hsmFaultLock.Unlock() - // If err == nil, the HSM is working, reset the timeout - // Note that we don't check if the HSM is the source of this error, - // since it doesn't matter. If everything worked, then in particular, - // the HSM worked. - if err == nil { - ca.hsmFault = false - ca.hsmFaultTimeout = hsmFaultMinTimeout - return + if err != nil { + ca.hsmFaultLastObserved = ca.Clk.Now() } - - // Otherwise, things are broken, and we should back off - ca.hsmFault = true - ca.hsmFaultLastObserved = ca.Clk.Now() - if ca.hsmFaultTimeout < hsmFaultMaxTimeout { - ca.hsmFaultTimeout *= 2 - } - return } diff --git a/ca/certificate-authority_test.go b/ca/certificate-authority_test.go index 6d855a55b..2c1950ee7 100644 --- a/ca/certificate-authority_test.go +++ b/ca/certificate-authority_test.go @@ -437,7 +437,7 @@ func TestHSMFaultTimeout(t *testing.T) { ca.Signer = badSigner _, err = ca.IssueCertificate(*csr, ctx.reg.ID) test.AssertError(t, err, "CA failed to return HSM error") - test.AssertEquals(t, err.Error(), "pkcs11: "+badHSMErrorMessage) + test.AssertEquals(t, err.Error(), badHSMErrorMessage) // Check that the CA rejects the next call as the HSM being down _, err = ca.IssueCertificate(*csr, ctx.reg.ID) @@ -450,21 +450,19 @@ func TestHSMFaultTimeout(t *testing.T) { // Swap in a good signer and move the clock forward to clear the fault ca.Signer = goodSigner - ctx.fc.Add(ca.hsmFaultTimeout) + ctx.fc.Add(hsmFaultTimeout) ctx.fc.Add(10 * time.Second) // Check that the CA has recovered _, err = ca.IssueCertificate(*csr, ctx.reg.ID) test.AssertNotError(t, err, "CA failed to recover from HSM fault") _, err = ca.GenerateOCSP(ocspRequest) - test.AssertNotError(t, err, "CA failed to recover from HSM fault") - test.AssertEquals(t, ca.hsmFaultTimeout, hsmFaultMinTimeout) // Check that GenerateOCSP can also trigger an HSM failure, in the same way ca.OCSPSigner = badOCSPSigner _, err = ca.GenerateOCSP(ocspRequest) test.AssertError(t, err, "CA failed to return HSM error") - test.AssertEquals(t, err.Error(), "pkcs11: "+badHSMErrorMessage) + test.AssertEquals(t, err.Error(), badHSMErrorMessage) _, err = ca.IssueCertificate(*csr, ctx.reg.ID) test.AssertError(t, err, "CA failed to persist HSM fault") From 3637dfb0c1a17765dbced00c0337e9eeacc0213e Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 16:25:43 -0400 Subject: [PATCH 13/25] ServiceUnavailableError --- ca/certificate-authority.go | 4 ++-- core/util.go | 5 +++++ rpc/amqp-rpc.go | 4 ++++ 3 files changed, 11 insertions(+), 2 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index 5dca16acb..ed185f217 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -207,7 +207,7 @@ func (ca *CertificateAuthorityImpl) noteHSMFault(err error) { // GenerateOCSP produces a new OCSP response and returns it func (ca *CertificateAuthorityImpl) GenerateOCSP(xferObj core.OCSPSigningRequest) ([]byte, error) { if ca.checkHSMFault() { - err := fmt.Errorf("GenerateOCSP call rejected; HSM is unavailable") + err := core.ServiceUnavailableError("GenerateOCSP call rejected; HSM is unavailable") ca.log.WarningErr(err) return nil, err } @@ -245,7 +245,7 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest var err error if ca.checkHSMFault() { - err := fmt.Errorf("IssueCertificate call rejected; HSM is unavailable") + err := core.ServiceUnavailableError("IssueCertificate call rejected; HSM is unavailable") ca.log.WarningErr(err) return emptyCert, err } diff --git a/core/util.go b/core/util.go index cc3027283..3e25aaeb9 100644 --- a/core/util.go +++ b/core/util.go @@ -93,6 +93,10 @@ type RateLimitedError string // limit type TooManyRPCRequestsError string +// ServiceUnavailableError indicates that a component is not available to +// satisfy a request +type ServiceUnavailableError string + func (e InternalServerError) Error() string { return string(e) } func (e NotSupportedError) Error() string { return string(e) } func (e MalformedRequestError) Error() string { return string(e) } @@ -105,6 +109,7 @@ func (e CertificateIssuanceError) Error() string { return string(e) } func (e NoSuchRegistrationError) Error() string { return string(e) } func (e RateLimitedError) Error() string { return string(e) } func (e TooManyRPCRequestsError) Error() string { return string(e) } +func (e ServiceUnavailableError) Error() string { return string(e) } // Base64 functions diff --git a/rpc/amqp-rpc.go b/rpc/amqp-rpc.go index 3cb045b82..28812951a 100644 --- a/rpc/amqp-rpc.go +++ b/rpc/amqp-rpc.go @@ -235,6 +235,8 @@ func wrapError(err error) (rpcError rpcError) { rpcError.Type = "TooManyRPCRequestsError" case core.RateLimitedError: rpcError.Type = "RateLimitedError" + case core.ServiceUnavailableError: + rpcError.Type = "ServiceUnavailableError" } } return @@ -266,6 +268,8 @@ func unwrapError(rpcError rpcError) (err error) { err = core.TooManyRPCRequestsError(rpcError.Value) case "RateLimitedError": err = core.RateLimitedError(rpcError.Value) + case "ServiceUnavailableError": + err = core.ServiceUnavailableError(rpcError.Value) default: err = errors.New(rpcError.Value) } From 128b7848052ce416316bc4a51c2ae13edec1ffaa Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 17:00:06 -0400 Subject: [PATCH 14/25] Add stats to CA --- ca/certificate-authority.go | 17 ++++++++++++++++- ca/certificate-authority_test.go | 30 +++++++++++++++++++----------- cmd/boulder-ca/main.go | 2 +- mocks/mocks.go | 20 ++++++++++++++++++++ 4 files changed, 56 insertions(+), 13 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index ed185f217..f6510484a 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -20,6 +20,7 @@ import ( "sync" "time" + "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cactus/go-statsd-client/statsd" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" "github.com/letsencrypt/boulder/cmd" "github.com/letsencrypt/boulder/core" @@ -49,6 +50,15 @@ var badSignatureAlgorithms = map[x509.SignatureAlgorithm]bool{ x509.ECDSAWithSHA1: true, } +// Metrics for CA statistics +const ( + // Increments when CA observes an HSM fault + metricHSMFaultObserved = "CA.OCSP.HSMFault.Observed" + + // Increments when CA rejects a request due to an HSM fault + metricHSMFaultRejected = "CA.OCSP.HSMFault.Rejected" +) + // HSM faults tend to be persistent. If we observe one, we will refuse any // further requests for signing (certificates or OCSP) for this period. const hsmFaultTimeout = 5 * 60 * time.Second @@ -64,6 +74,7 @@ type CertificateAuthorityImpl struct { Publisher core.Publisher Clk clock.Clock // TODO(jmhodges): should be private, like log log *blog.AuditLogger + stats statsd.Statter Prefix int // Prepended to the serial number ValidityPeriod time.Duration NotAfter time.Time @@ -79,7 +90,7 @@ type CertificateAuthorityImpl struct { // using CFSSL's authenticated signature scheme. A CA created in this way // issues for a single profile on the remote signer, which is indicated // by name in this constructor. -func NewCertificateAuthorityImpl(config cmd.CAConfig, clk clock.Clock, issuerCert string) (*CertificateAuthorityImpl, error) { +func NewCertificateAuthorityImpl(config cmd.CAConfig, clk clock.Clock, stats statsd.Statter, issuerCert string) (*CertificateAuthorityImpl, error) { var ca *CertificateAuthorityImpl var err error logger := blog.GetAuditLogger() @@ -139,6 +150,7 @@ func NewCertificateAuthorityImpl(config cmd.CAConfig, clk clock.Clock, issuerCer Prefix: config.SerialPrefix, Clk: clk, log: logger, + stats: stats, NotAfter: issuer.NotAfter, } @@ -199,6 +211,7 @@ func (ca *CertificateAuthorityImpl) noteHSMFault(err error) { defer ca.hsmFaultLock.Unlock() if err != nil { + ca.stats.Inc(metricHSMFaultObserved, 1, 1.0) ca.hsmFaultLastObserved = ca.Clk.Now() } return @@ -209,6 +222,7 @@ func (ca *CertificateAuthorityImpl) GenerateOCSP(xferObj core.OCSPSigningRequest if ca.checkHSMFault() { err := core.ServiceUnavailableError("GenerateOCSP call rejected; HSM is unavailable") ca.log.WarningErr(err) + ca.stats.Inc(metricHSMFaultRejected, 1, 1.0) return nil, err } @@ -247,6 +261,7 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest if ca.checkHSMFault() { err := core.ServiceUnavailableError("IssueCertificate call rejected; HSM is unavailable") ca.log.WarningErr(err) + ca.stats.Inc(metricHSMFaultRejected, 1, 1.0) return emptyCert, err } diff --git a/ca/certificate-authority_test.go b/ca/certificate-authority_test.go index 2c1950ee7..8099180b9 100644 --- a/ca/certificate-authority_test.go +++ b/ca/certificate-authority_test.go @@ -116,6 +116,7 @@ type testCtx struct { reg core.Registration pa core.PolicyAuthority fc clock.FakeClock + stats *mocks.Statter cleanUp func() } @@ -192,7 +193,10 @@ func setup(t *testing.T) *testCtx { }, }, } - return &testCtx{ssa, caConfig, reg, pa, fc, cleanUp} + + stats := mocks.NewStatter() + + return &testCtx{ssa, caConfig, reg, pa, fc, &stats, cleanUp} } func TestFailNoSerial(t *testing.T) { @@ -200,14 +204,14 @@ func TestFailNoSerial(t *testing.T) { defer ctx.cleanUp() ctx.caConfig.SerialPrefix = 0 - _, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + _, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) test.AssertError(t, err, "CA should have failed with no SerialPrefix") } func TestIssueCertificate(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) test.AssertNotError(t, err, "Failed to create CA") ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa @@ -284,7 +288,7 @@ func TestIssueCertificate(t *testing.T) { func TestRejectNoName(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) test.AssertNotError(t, err, "Failed to create CA") ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa @@ -301,7 +305,7 @@ func TestRejectNoName(t *testing.T) { func TestRejectTooManyNames(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) test.AssertNotError(t, err, "Failed to create CA") ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa @@ -318,7 +322,7 @@ func TestRejectTooManyNames(t *testing.T) { func TestDeduplication(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) test.AssertNotError(t, err, "Failed to create CA") ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa @@ -342,7 +346,7 @@ func TestDeduplication(t *testing.T) { func TestRejectValidityTooLong(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) test.AssertNotError(t, err, "Failed to create CA") ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa @@ -360,7 +364,7 @@ func TestRejectValidityTooLong(t *testing.T) { func TestShortKey(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa ca.SA = ctx.sa @@ -376,7 +380,7 @@ func TestShortKey(t *testing.T) { func TestRejectBadAlgorithm(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa ca.SA = ctx.sa @@ -393,7 +397,7 @@ func TestCapitalizedLetters(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() ctx.caConfig.MaxNames = 3 - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa ca.SA = ctx.sa @@ -414,7 +418,7 @@ func TestHSMFaultTimeout(t *testing.T) { ctx := setup(t) defer ctx.cleanUp() - ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, caCertFile) + ca, err := NewCertificateAuthorityImpl(ctx.caConfig, ctx.fc, ctx.stats, caCertFile) ca.Publisher = &mocks.Publisher{} ca.PA = ctx.pa ca.SA = ctx.sa @@ -471,4 +475,8 @@ func TestHSMFaultTimeout(t *testing.T) { _, err = ca.GenerateOCSP(ocspRequest) test.AssertError(t, err, "CA failed to persist HSM fault") test.AssertEquals(t, err.Error(), "GenerateOCSP call rejected; HSM is unavailable") + + // Verify that the appropriate stats got recorded for all this + test.AssertEquals(t, ctx.stats.Counters[metricHSMFaultObserved], int64(2)) + test.AssertEquals(t, ctx.stats.Counters[metricHSMFaultRejected], int64(4)) } diff --git a/cmd/boulder-ca/main.go b/cmd/boulder-ca/main.go index 585be6736..7217fdf4a 100644 --- a/cmd/boulder-ca/main.go +++ b/cmd/boulder-ca/main.go @@ -39,7 +39,7 @@ func main() { pa, err := policy.NewPolicyAuthorityImpl(paDbMap, c.PA.EnforcePolicyWhitelist) cmd.FailOnError(err, "Couldn't create PA") - cai, err := ca.NewCertificateAuthorityImpl(c.CA, clock.Default(), c.Common.IssuerCert) + cai, err := ca.NewCertificateAuthorityImpl(c.CA, clock.Default(), stats, c.Common.IssuerCert) cmd.FailOnError(err, "Failed to create CA impl") cai.PA = pa diff --git a/mocks/mocks.go b/mocks/mocks.go index e2c7aac63..a63341d74 100644 --- a/mocks/mocks.go +++ b/mocks/mocks.go @@ -15,6 +15,7 @@ import ( "strings" "time" + "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cactus/go-statsd-client/statsd" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/config" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/info" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/ocsp" @@ -414,3 +415,22 @@ type BadHSMOCSPSigner string func (bhos BadHSMOCSPSigner) Sign(ocsp.SignRequest) ([]byte, error) { return nil, fmt.Errorf(string(bhos)) } + +// Statter is a stat counter that is a no-op except for locally handling Inc +// calls (which are most of what we use). +type Statter struct { + statsd.NoopClient + Counters map[string]int64 +} + +// Inc increments the indicated metric by the indicated value, in the Counters +// map maintained by the statter +func (s *Statter) Inc(metric string, value int64, rate float32) error { + s.Counters[metric] += value + return nil +} + +// NewStatter returns an empty statter with all counters zero +func NewStatter() Statter { + return Statter{statsd.NoopClient{}, map[string]int64{}} +} From 288945217ea74b213a8cdb2b429a94ccb218df96 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 17:33:19 -0400 Subject: [PATCH 15/25] Allow configuration of the HSM timeout --- ca/certificate-authority.go | 34 +++++++++++++++++++++----------- ca/certificate-authority_test.go | 2 +- cmd/shell.go | 2 ++ test/boulder-config.json | 3 ++- 4 files changed, 27 insertions(+), 14 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index f6510484a..0c17ba543 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -59,9 +59,7 @@ const ( metricHSMFaultRejected = "CA.OCSP.HSMFault.Rejected" ) -// HSM faults tend to be persistent. If we observe one, we will refuse any -// further requests for signing (certificates or OCSP) for this period. -const hsmFaultTimeout = 5 * 60 * time.Second +const defaultHSMFaultTimeout = 5 * 60 * time.Second // CertificateAuthorityImpl represents a CA that signs certificates, CRLs, and // OCSP responses. @@ -82,6 +80,7 @@ type CertificateAuthorityImpl struct { hsmFaultLock sync.Mutex hsmFaultLastObserved time.Time + hsmFaultTimeout time.Duration } // NewCertificateAuthorityImpl creates a CA that talks to a remote CFSSL @@ -136,6 +135,16 @@ func NewCertificateAuthorityImpl(config cmd.CAConfig, clk clock.Clock, stats sta return nil, err } + var hsmFaultTimeout time.Duration + if config.HSMFaultTimeout == "" { + hsmFaultTimeout = defaultHSMFaultTimeout + } else { + hsmFaultTimeout, err = time.ParseDuration(config.HSMFaultTimeout) + if err != nil { + return nil, err + } + } + // Set up our OCSP signer. Note this calls for both the issuer cert and the // OCSP signing cert, which are the same in our case. ocspSigner, err := ocsp.NewSigner(issuer, issuer, priv, lifespanOCSP) @@ -144,14 +153,15 @@ func NewCertificateAuthorityImpl(config cmd.CAConfig, clk clock.Clock, stats sta } ca = &CertificateAuthorityImpl{ - Signer: signer, - OCSPSigner: ocspSigner, - profile: config.Profile, - Prefix: config.SerialPrefix, - Clk: clk, - log: logger, - stats: stats, - NotAfter: issuer.NotAfter, + Signer: signer, + OCSPSigner: ocspSigner, + profile: config.Profile, + Prefix: config.SerialPrefix, + Clk: clk, + log: logger, + stats: stats, + NotAfter: issuer.NotAfter, + hsmFaultTimeout: hsmFaultTimeout, } if config.Expiry == "" { @@ -200,7 +210,7 @@ func (ca *CertificateAuthorityImpl) checkHSMFault() bool { defer ca.hsmFaultLock.Unlock() now := ca.Clk.Now() - timeout := ca.hsmFaultLastObserved.Add(hsmFaultTimeout) + timeout := ca.hsmFaultLastObserved.Add(ca.hsmFaultTimeout) return now.Before(timeout) } diff --git a/ca/certificate-authority_test.go b/ca/certificate-authority_test.go index 8099180b9..04a885565 100644 --- a/ca/certificate-authority_test.go +++ b/ca/certificate-authority_test.go @@ -454,7 +454,7 @@ func TestHSMFaultTimeout(t *testing.T) { // Swap in a good signer and move the clock forward to clear the fault ca.Signer = goodSigner - ctx.fc.Add(hsmFaultTimeout) + ctx.fc.Add(ca.hsmFaultTimeout) ctx.fc.Add(10 * time.Second) // Check that the CA has recovered diff --git a/cmd/shell.go b/cmd/shell.go index 5d7c16ac9..b2d227c96 100644 --- a/cmd/shell.go +++ b/cmd/shell.go @@ -240,6 +240,8 @@ type CAConfig struct { MaxConcurrentRPCServerRequests int64 + HSMFaultTimeout string + // DebugAddr is the address to run the /debug handlers on. DebugAddr string } diff --git a/test/boulder-config.json b/test/boulder-config.json index 32f307d5a..d5276f11c 100644 --- a/test/boulder-config.json +++ b/test/boulder-config.json @@ -111,7 +111,8 @@ } } }, - "maxConcurrentRPCServerRequests": 16 + "maxConcurrentRPCServerRequests": 16, + "hsmFaultTimeout": "300s", }, "pa": { From fcee10950260085291023803b2ee6a037739dd21 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 17:39:14 -0400 Subject: [PATCH 16/25] Remove stray comma --- test/boulder-config.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/boulder-config.json b/test/boulder-config.json index d359345a8..0bf0c68e0 100644 --- a/test/boulder-config.json +++ b/test/boulder-config.json @@ -112,7 +112,7 @@ } }, "maxConcurrentRPCServerRequests": 16, - "hsmFaultTimeout": "300s", + "hsmFaultTimeout": "300s" }, "pa": { From ba56e7c5871d707d716865e1cb99331ac477bea7 Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Wed, 21 Oct 2015 15:02:15 -0700 Subject: [PATCH 17/25] Make MatchesCSR downcase CommonName before checking equality --- ra/registration-authority.go | 6 ++++-- ra/registration-authority_test.go | 2 ++ 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/ra/registration-authority.go b/ra/registration-authority.go index d3469fed2..0ef9a03ce 100644 --- a/ra/registration-authority.go +++ b/ra/registration-authority.go @@ -327,7 +327,8 @@ func (ra *RegistrationAuthorityImpl) NewAuthorization(request core.Authorization // * Subject only contains CommonName & Names func (ra *RegistrationAuthorityImpl) MatchesCSR( cert core.Certificate, - csr *x509.CertificateRequest) (err error) { + csr *x509.CertificateRequest, +) (err error) { parsedCertificate, err := x509.ParseCertificate([]byte(cert.DER)) if err != nil { return @@ -345,7 +346,8 @@ func (ra *RegistrationAuthorityImpl) MatchesCSR( err = core.InternalServerError("Generated certificate public key doesn't match CSR public key") return } - if len(csr.Subject.CommonName) > 0 && parsedCertificate.Subject.CommonName != csr.Subject.CommonName { + if len(csr.Subject.CommonName) > 0 && + parsedCertificate.Subject.CommonName != strings.ToLower(csr.Subject.CommonName) { err = core.InternalServerError("Generated certificate CommonName doesn't match CSR CommonName") return } diff --git a/ra/registration-authority_test.go b/ra/registration-authority_test.go index f2731e949..f543d6ba8 100644 --- a/ra/registration-authority_test.go +++ b/ra/registration-authority_test.go @@ -606,6 +606,8 @@ func TestNewCertificate(t *testing.T) { authzFinalWWW, _ = sa.NewPendingAuthorization(authzFinalWWW) sa.FinalizeAuthorization(authzFinalWWW) + // Check that we don't fail on case mismatches + ExampleCSR.Subject.CommonName = "www.NOT-example.com" certRequest := core.CertificateRequest{ CSR: ExampleCSR, } From aff276fc7d2cbb2af8066980604e089767e31cb6 Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Wed, 21 Oct 2015 15:18:13 -0700 Subject: [PATCH 18/25] Change node test to request a domain using mixed-case --- test/amqp-integration-test.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/amqp-integration-test.py b/test/amqp-integration-test.py index 0814f6b0d..e97c999a5 100644 --- a/test/amqp-integration-test.py +++ b/test/amqp-integration-test.py @@ -145,7 +145,7 @@ def run_node_test(): domain = subprocess.check_output("openssl rand -hex 6", shell=True).strip() if subprocess.Popen(''' node test.js --email foo@letsencrypt.org --agree true \ - --domains www.%s.com --new-reg http://localhost:4000/acme/new-reg \ + --domains www.%s-TEST.com --new-reg http://localhost:4000/acme/new-reg \ --certKey %s --cert %s ''' % (domain, keyFile, certFile), shell=True).wait() != 0: print("\nIssuing failed") From f820d9f29c06dd3d1b6c549ce8f159137e10aad9 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 21:18:29 -0400 Subject: [PATCH 19/25] Address @jsha comments --- ca/certificate-authority.go | 35 ++++++++++++-------------------- ca/certificate-authority_test.go | 15 +++++++------- cmd/shell.go | 2 +- 3 files changed, 22 insertions(+), 30 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index 0c17ba543..8364ab36c 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -59,8 +59,6 @@ const ( metricHSMFaultRejected = "CA.OCSP.HSMFault.Rejected" ) -const defaultHSMFaultTimeout = 5 * 60 * time.Second - // CertificateAuthorityImpl represents a CA that signs certificates, CRLs, and // OCSP responses. type CertificateAuthorityImpl struct { @@ -135,16 +133,6 @@ func NewCertificateAuthorityImpl(config cmd.CAConfig, clk clock.Clock, stats sta return nil, err } - var hsmFaultTimeout time.Duration - if config.HSMFaultTimeout == "" { - hsmFaultTimeout = defaultHSMFaultTimeout - } else { - hsmFaultTimeout, err = time.ParseDuration(config.HSMFaultTimeout) - if err != nil { - return nil, err - } - } - // Set up our OCSP signer. Note this calls for both the issuer cert and the // OCSP signing cert, which are the same in our case. ocspSigner, err := ocsp.NewSigner(issuer, issuer, priv, lifespanOCSP) @@ -161,7 +149,7 @@ func NewCertificateAuthorityImpl(config cmd.CAConfig, clk clock.Clock, stats sta log: logger, stats: stats, NotAfter: issuer.NotAfter, - hsmFaultTimeout: hsmFaultTimeout, + hsmFaultTimeout: config.HSMFaultTimeout.Duration, } if config.Expiry == "" { @@ -205,13 +193,21 @@ func loadKey(keyConfig cmd.KeyConfig) (priv crypto.Signer, err error) { // checkHSMFault checks whether there has been an HSM fault observed within the // timeout window. CA methods that use the HSM should call this method right // away, to minimize the performance impact of HSM outages. -func (ca *CertificateAuthorityImpl) checkHSMFault() bool { +func (ca *CertificateAuthorityImpl) checkHSMFault() error { ca.hsmFaultLock.Lock() defer ca.hsmFaultLock.Unlock() + // If no timeout is set, never gate on a fault + if ca.hsmFaultTimeout == 0 { + return nil + } + now := ca.Clk.Now() timeout := ca.hsmFaultLastObserved.Add(ca.hsmFaultTimeout) - return now.Before(timeout) + if now.Before(timeout) { + return core.ServiceUnavailableError("HSM is unavailable") + } + return nil } // noteHSMFault updates the CA's state with regard to HSM faults. CA methods @@ -229,8 +225,7 @@ func (ca *CertificateAuthorityImpl) noteHSMFault(err error) { // GenerateOCSP produces a new OCSP response and returns it func (ca *CertificateAuthorityImpl) GenerateOCSP(xferObj core.OCSPSigningRequest) ([]byte, error) { - if ca.checkHSMFault() { - err := core.ServiceUnavailableError("GenerateOCSP call rejected; HSM is unavailable") + if err := ca.checkHSMFault(); err != nil { ca.log.WarningErr(err) ca.stats.Inc(metricHSMFaultRejected, 1, 1.0) return nil, err @@ -268,8 +263,7 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest emptyCert := core.Certificate{} var err error - if ca.checkHSMFault() { - err := core.ServiceUnavailableError("IssueCertificate call rejected; HSM is unavailable") + if err := ca.checkHSMFault(); err != nil { ca.log.WarningErr(err) ca.stats.Inc(metricHSMFaultRejected, 1, 1.0) return emptyCert, err @@ -382,9 +376,6 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest certPEM, err := ca.Signer.Sign(req) ca.noteHSMFault(err) if err != nil { - // Since we just used the HSM (if we're using one), note whether it worked - // or not. - err = core.InternalServerError(err.Error()) // AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3 ca.log.Audit(fmt.Sprintf("Signer failed, rolling back: serial=[%s] err=[%v]", serialHex, err)) diff --git a/ca/certificate-authority_test.go b/ca/certificate-authority_test.go index d42c0659c..9b1259ea6 100644 --- a/ca/certificate-authority_test.go +++ b/ca/certificate-authority_test.go @@ -151,9 +151,10 @@ func setup(t *testing.T) *testCtx { Key: cmd.KeyConfig{ File: caKeyFile, }, - Expiry: "8760h", - LifespanOCSP: "45m", - MaxNames: 2, + Expiry: "8760h", + LifespanOCSP: "45m", + MaxNames: 2, + HSMFaultTimeout: cmd.ConfigDuration{60 * time.Second}, CFSSL: cfsslConfig.Config{ Signing: &cfsslConfig.Signing{ Profiles: map[string]*cfsslConfig.SigningProfile{ @@ -442,11 +443,11 @@ func TestHSMFaultTimeout(t *testing.T) { // Check that the CA rejects the next call as the HSM being down _, err = ca.IssueCertificate(*csr, ctx.reg.ID) test.AssertError(t, err, "CA failed to persist HSM fault") - test.AssertEquals(t, err.Error(), "IssueCertificate call rejected; HSM is unavailable") + test.AssertEquals(t, err.Error(), "HSM is unavailable") _, err = ca.GenerateOCSP(ocspRequest) test.AssertError(t, err, "CA failed to persist HSM fault") - test.AssertEquals(t, err.Error(), "GenerateOCSP call rejected; HSM is unavailable") + test.AssertEquals(t, err.Error(), "HSM is unavailable") // Swap in a good signer and move the clock forward to clear the fault ca.Signer = goodSigner @@ -466,11 +467,11 @@ func TestHSMFaultTimeout(t *testing.T) { _, err = ca.IssueCertificate(*csr, ctx.reg.ID) test.AssertError(t, err, "CA failed to persist HSM fault") - test.AssertEquals(t, err.Error(), "IssueCertificate call rejected; HSM is unavailable") + test.AssertEquals(t, err.Error(), "HSM is unavailable") _, err = ca.GenerateOCSP(ocspRequest) test.AssertError(t, err, "CA failed to persist HSM fault") - test.AssertEquals(t, err.Error(), "GenerateOCSP call rejected; HSM is unavailable") + test.AssertEquals(t, err.Error(), "HSM is unavailable") // Verify that the appropriate stats got recorded for all this test.AssertEquals(t, ctx.stats.Counters[metricHSMFaultObserved], int64(2)) diff --git a/cmd/shell.go b/cmd/shell.go index b2d227c96..3ccc8d368 100644 --- a/cmd/shell.go +++ b/cmd/shell.go @@ -240,7 +240,7 @@ type CAConfig struct { MaxConcurrentRPCServerRequests int64 - HSMFaultTimeout string + HSMFaultTimeout ConfigDuration // DebugAddr is the address to run the /debug handlers on. DebugAddr string From 8cf950e515d3c1253ccc28dbc70ac688f143068b Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 21:36:07 -0400 Subject: [PATCH 20/25] Fix go vet error --- ca/certificate-authority_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ca/certificate-authority_test.go b/ca/certificate-authority_test.go index 9b1259ea6..d592669f0 100644 --- a/ca/certificate-authority_test.go +++ b/ca/certificate-authority_test.go @@ -154,7 +154,7 @@ func setup(t *testing.T) *testCtx { Expiry: "8760h", LifespanOCSP: "45m", MaxNames: 2, - HSMFaultTimeout: cmd.ConfigDuration{60 * time.Second}, + HSMFaultTimeout: cmd.ConfigDuration{Duration: 60 * time.Second}, CFSSL: cfsslConfig.Config{ Signing: &cfsslConfig.Signing{ Profiles: map[string]*cfsslConfig.SigningProfile{ From ded5fa6f207b41ae02fb27bb7193802ed32bea58 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 21:55:45 -0400 Subject: [PATCH 21/25] Back out field name changes --- wfe/context.go | 39 +++++++++++++++++++-------------------- wfe/web-front-end.go | 5 ++--- wfe/web-front-end_test.go | 13 +++++++------ 3 files changed, 28 insertions(+), 29 deletions(-) diff --git a/wfe/context.go b/wfe/context.go index 9a0736382..c4e65a23a 100644 --- a/wfe/context.go +++ b/wfe/context.go @@ -3,7 +3,6 @@ package wfe import ( "fmt" "net/http" - "strings" "time" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" @@ -12,16 +11,16 @@ import ( ) type requestEvent struct { - ID string `json:",omitempty"` - ClientAddr string `json:",omitempty"` - Path string `json:",omitempty"` - Method string `json:",omitempty"` - Status int `json:",omitEmpty"` - RequestTime time.Time `json:",omitempty"` - ResponseTime time.Time `json:",omitempty"` - Errors []string - RegistrationID int64 `json:",omitempty"` - Contacts []*core.AcmeURL `json:",omitempty"` + ID string `json:",omitempty"` + RealIP string `json:",omitempty"` + ClientAddr string `json:",omitempty"` + Endpoint string `json:",omitempty"` + Method string `json:",omitempty"` + RequestTime time.Time `json:",omitempty"` + ResponseTime time.Time `json:",omitempty"` + Errors []string + Requester int64 `json:",omitempty"` + Contacts []*core.AcmeURL `json:",omitempty"` Extra map[string]interface{} `json:",omitempty"` } @@ -49,13 +48,14 @@ type topHandler struct { func (th *topHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { logEvent := &requestEvent{ ID: core.NewToken(), + RealIP: r.Header.Get("X-Real-IP"), ClientAddr: getClientAddr(r), Method: r.Method, RequestTime: time.Now(), Extra: make(map[string]interface{}, 0), } if r.URL != nil { - logEvent.Path = r.URL.String() + logEvent.Endpoint = r.URL.String() } defer th.logEvent(logEvent) @@ -73,14 +73,13 @@ func (th *topHandler) logEvent(logEvent *requestEvent) { th.log.InfoObject(msg, logEvent) } -// Comma-separated list of HTTP clients involved in making this request, -// including the remote end of our TCP connection (which is typically our own -// proxy) as well as addresses from the X-Forwarded-For and X-Real-IP headers. +// Comma-separated list of HTTP clients involved in making this +// request, starting with the original requestor and ending with the +// remote end of our TCP connection (which is typically our own +// proxy). func getClientAddr(r *http.Request) string { - addrs := []string{ - r.RemoteAddr, - r.Header.Get("X-Forwarded-For"), - r.Header.Get("X-Real-IP"), + if xff := r.Header.Get("X-Forwarded-For"); xff != "" { + return xff + "," + r.RemoteAddr } - return strings.Join(addrs, ",") + return r.RemoteAddr } diff --git a/wfe/web-front-end.go b/wfe/web-front-end.go index e0333a363..75e1c23c4 100644 --- a/wfe/web-front-end.go +++ b/wfe/web-front-end.go @@ -417,7 +417,7 @@ func (wfe *WebFrontEndImpl) verifyPOST(logEvent *requestEvent, request *http.Req } else { // If the lookup was successful, use that key. key = ®.Key - logEvent.RegistrationID = reg.ID + logEvent.Requester = reg.ID logEvent.Contacts = reg.Contact } @@ -498,7 +498,6 @@ func (wfe *WebFrontEndImpl) sendError(response http.ResponseWriter, logEvent *re } // Record details to the log event - logEvent.Status = code logEvent.AddError(msg) // Only audit log internal errors so users cannot purposefully cause @@ -579,7 +578,7 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt wfe.sendError(response, logEvent, "Error creating new registration", err, statusCodeFromError(err)) return } - logEvent.RegistrationID = reg.ID + logEvent.Requester = reg.ID logEvent.Contacts = reg.Contact // Use an explicitly typed variable. Otherwise `go vet' incorrectly complains diff --git a/wfe/web-front-end_test.go b/wfe/web-front-end_test.go index fb694baf1..f1822ba0f 100644 --- a/wfe/web-front-end_test.go +++ b/wfe/web-front-end_test.go @@ -179,10 +179,6 @@ func (pa *MockPA) WillingToIssue(id core.AcmeIdentifier, regID int64) error { return nil } -func newRequestEvent() *requestEvent { - return &requestEvent{Extra: make(map[string]interface{})} -} - func makeBody(s string) io.ReadCloser { return ioutil.NopCloser(strings.NewReader(s)) } @@ -1284,10 +1280,11 @@ func TestGetCertificate(t *testing.T) { test.AssertEquals(t, responseWriter.Header().Get("Content-Type"), "application/pkix-cert") test.Assert(t, bytes.Compare(responseWriter.Body.Bytes(), certBlock.Bytes) == 0, "Certificates don't match") + t.Logf("UGH %#v", mockLog.GetAll()[0]) reqlogs := mockLog.GetAllMatching(`Successful request`) test.AssertEquals(t, len(reqlogs), 1) test.AssertEquals(t, reqlogs[0].Priority, syslog.LOG_INFO) - test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.0.1,,"`) + test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.0.1"`) // Unused serial, no cache mockLog.Clear() @@ -1303,7 +1300,7 @@ func TestGetCertificate(t *testing.T) { reqlogs = mockLog.GetAllMatching(`Terminated request`) test.AssertEquals(t, len(reqlogs), 1) test.AssertEquals(t, reqlogs[0].Priority, syslog.LOG_INFO) - test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.0.1,192.168.99.99,"`) + test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.99.99,192.168.0.1"`) // Invalid serial, no cache responseWriter = httptest.NewRecorder() @@ -1430,3 +1427,7 @@ func TestStatusCodeFromError(t *testing.T) { } } } + +func newRequestEvent() *requestEvent { + return &requestEvent{Extra: make(map[string]interface{})} +} From a79020c1d09204e25f3d26313bb87d1e7e66b4ce Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 22:09:44 -0400 Subject: [PATCH 22/25] Further consolidation --- ca/certificate-authority.go | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/ca/certificate-authority.go b/ca/certificate-authority.go index 8364ab36c..7d43148af 100644 --- a/ca/certificate-authority.go +++ b/ca/certificate-authority.go @@ -205,7 +205,10 @@ func (ca *CertificateAuthorityImpl) checkHSMFault() error { now := ca.Clk.Now() timeout := ca.hsmFaultLastObserved.Add(ca.hsmFaultTimeout) if now.Before(timeout) { - return core.ServiceUnavailableError("HSM is unavailable") + err := core.ServiceUnavailableError("HSM is unavailable") + ca.log.WarningErr(err) + ca.stats.Inc(metricHSMFaultRejected, 1, 1.0) + return err } return nil } @@ -226,8 +229,6 @@ func (ca *CertificateAuthorityImpl) noteHSMFault(err error) { // GenerateOCSP produces a new OCSP response and returns it func (ca *CertificateAuthorityImpl) GenerateOCSP(xferObj core.OCSPSigningRequest) ([]byte, error) { if err := ca.checkHSMFault(); err != nil { - ca.log.WarningErr(err) - ca.stats.Inc(metricHSMFaultRejected, 1, 1.0) return nil, err } @@ -264,8 +265,6 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest var err error if err := ca.checkHSMFault(); err != nil { - ca.log.WarningErr(err) - ca.stats.Inc(metricHSMFaultRejected, 1, 1.0) return emptyCert, err } From 2ebba2a4664301719d76e8a6b9c5160fcbf1d7b5 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Wed, 21 Oct 2015 22:45:54 -0400 Subject: [PATCH 23/25] Re-add descriptive errors --- wfe/web-front-end.go | 35 ++++++++++++++++++++++++++++++++--- 1 file changed, 32 insertions(+), 3 deletions(-) diff --git a/wfe/web-front-end.go b/wfe/web-front-end.go index 75e1c23c4..7b27492a6 100644 --- a/wfe/web-front-end.go +++ b/wfe/web-front-end.go @@ -568,6 +568,7 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt if err == nil { init.InitialIP = net.ParseIP(host) } else { + logEvent.AddError("Couldn't parse RemoteAddr: %s", request.RemoteAddr) wfe.sendError(response, logEvent, "couldn't parse the remote (that is, the client's) address", nil, http.StatusInternalServerError) return } @@ -575,6 +576,7 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt reg, err := wfe.RA.NewRegistration(init) if err != nil { + logEvent.AddError("unable to create new registration: %s", err) wfe.sendError(response, logEvent, "Error creating new registration", err, statusCodeFromError(err)) return } @@ -587,6 +589,7 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt responseBody, err := json.Marshal(reg) if err != nil { // StatusInternalServerError because we just created this registration, it should be OK. + logEvent.AddError("unable to marsh registration: %s", err) wfe.sendError(response, logEvent, "Error marshaling registration", err, http.StatusInternalServerError) return } @@ -626,6 +629,7 @@ func (wfe *WebFrontEndImpl) NewAuthorization(logEvent *requestEvent, response ht var init core.Authorization if err = json.Unmarshal(body, &init); err != nil { + logEvent.AddError("unable to JSON unmarshal Authorization: %s", err) wfe.sendError(response, logEvent, "Error unmarshaling JSON", err, http.StatusBadRequest) return } @@ -634,6 +638,7 @@ func (wfe *WebFrontEndImpl) NewAuthorization(logEvent *requestEvent, response ht // Create new authz and return authz, err := wfe.RA.NewAuthorization(init, currReg.ID) if err != nil { + logEvent.AddError("unable to create new authz: %s", err) wfe.sendError(response, logEvent, "Error creating new authz", err, statusCodeFromError(err)) return } @@ -676,13 +681,13 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response h } var revokeRequest RevokeRequest if err = json.Unmarshal(body, &revokeRequest); err != nil { - wfe.log.Debug(fmt.Sprintf("Couldn't unmarshal in revoke request %s", string(body))) + logEvent.AddError(fmt.Sprintf("Couldn't unmarshal in revoke request %s", string(body))) wfe.sendError(response, logEvent, "Unable to read/verify body", err, http.StatusBadRequest) return } providedCert, err := x509.ParseCertificate(revokeRequest.CertificateDER) if err != nil { - wfe.log.Debug("Couldn't parse cert in revoke request.") + logEvent.AddError("unable to parse revoke certificate DER: %s", err) wfe.sendError(response, logEvent, "Unable to read/verify body", err, http.StatusBadRequest) return } @@ -707,12 +712,14 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response h certStatus, err := wfe.SA.GetCertificateStatus(serial) if err != nil { + logEvent.AddError("unable to get certificate status: %s", err) wfe.sendError(response, logEvent, "Certificate status not yet available", err, http.StatusNotFound) return } logEvent.Extra["CertificateStatus"] = certStatus.Status if certStatus.Status == core.OCSPStatusRevoked { + logEvent.AddError("Certificate already revoked: %#v", serial) wfe.sendError(response, logEvent, "Certificate already revoked", "", http.StatusConflict) return } @@ -730,6 +737,7 @@ func (wfe *WebFrontEndImpl) RevokeCertificate(logEvent *requestEvent, response h // Use revocation code 0, meaning "unspecified" err = wfe.RA.RevokeCertificateWithReg(*parsedCertificate, 0, registration.ID) if err != nil { + logEvent.AddError("failed to revoke certificate: %s", err) wfe.sendError(response, logEvent, "Failed to revoke certificate", err, statusCodeFromError(err)) } else { wfe.log.Debug(fmt.Sprintf("Revoked %v", serial)) @@ -775,6 +783,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http var certificateRequest core.CertificateRequest if err = json.Unmarshal(body, &certificateRequest); err != nil { + logEvent.AddError("unable to JSON unmarshal CertificateRequest: %s", err) wfe.sendError(response, logEvent, "Error unmarshaling certificate request", err, http.StatusBadRequest) return } @@ -786,6 +795,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http // a bad key from the client is just a malformed request and doesn't need to // be audited. if err = core.GoodKey(certificateRequest.CSR.PublicKey); err != nil { + logEvent.AddError("CSR public key failed GoodKey: %s", err) wfe.sendError(response, logEvent, "Invalid key in certificate request", err, http.StatusBadRequest) return } @@ -801,6 +811,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http // RA for secondary validation. cert, err := wfe.RA.NewCertificate(certificateRequest, reg.ID) if err != nil { + logEvent.AddError("unable to create new cert: %s", err) wfe.sendError(response, logEvent, "Error creating new cert", err, statusCodeFromError(err)) return } @@ -811,6 +822,7 @@ func (wfe *WebFrontEndImpl) NewCertificate(logEvent *requestEvent, response http // enumerate and mirror our certificates. parsedCertificate, err := x509.ParseCertificate([]byte(cert.DER)) if err != nil { + logEvent.AddError("unable to parse certificate: %s", err) wfe.sendError(response, logEvent, "Error creating new cert", err, http.StatusBadRequest) return } @@ -928,6 +940,7 @@ func (wfe *WebFrontEndImpl) getChallenge( if err != nil { // InternalServerError because this is a failure to decode data passed in // by the caller, which got it from the DB. + logEvent.AddError("unable to marshal challenge: %s", err) wfe.sendError(response, logEvent, "Failed to marshal challenge", err, http.StatusInternalServerError) return } @@ -973,6 +986,7 @@ func (wfe *WebFrontEndImpl) postChallenge( // Check that the registration ID matching the key used matches // the registration ID on the authz object if currReg.ID != authz.RegistrationID { + logEvent.AddError("User registration id: %d != Authorization registration id: %v", currReg.ID, authz.RegistrationID) wfe.sendError(response, logEvent, "User registration ID doesn't match registration ID in authorization", "", http.StatusForbidden) @@ -981,6 +995,7 @@ func (wfe *WebFrontEndImpl) postChallenge( var challengeUpdate core.Challenge if err = json.Unmarshal(body, &challengeUpdate); err != nil { + logEvent.AddError("error JSON unmarshalling challenge response: %s", err) wfe.sendError(response, logEvent, "Error unmarshaling challenge response", err, http.StatusBadRequest) return } @@ -988,6 +1003,7 @@ func (wfe *WebFrontEndImpl) postChallenge( // Ask the RA to update this authorization updatedAuthorization, err := wfe.RA.UpdateAuthorization(authz, challengeIndex, challengeUpdate) if err != nil { + logEvent.AddError("unable to update challenge: %s", err) wfe.sendError(response, logEvent, "Unable to update challenge", err, statusCodeFromError(err)) return } @@ -998,6 +1014,7 @@ func (wfe *WebFrontEndImpl) postChallenge( jsonReply, err := json.Marshal(challenge) if err != nil { // StatusInternalServerError because we made the challenges, they should be OK + logEvent.AddError("failed to marshal challenge: %s", err) wfe.sendError(response, logEvent, "Failed to marshal challenge", err, http.StatusInternalServerError) return } @@ -1035,12 +1052,15 @@ func (wfe *WebFrontEndImpl) Registration(logEvent *requestEvent, response http.R idStr := parseIDFromPath(request.URL.Path) id, err := strconv.ParseInt(idStr, 10, 64) if err != nil { + logEvent.AddError("registration ID must be an integer, was %#v", idStr) wfe.sendError(response, logEvent, "Registration ID must be an integer", err, http.StatusBadRequest) return } else if id <= 0 { + logEvent.AddError("Registration ID must be a positive non-zero integer, was %d", id) wfe.sendError(response, logEvent, "Registration ID must be a positive non-zero integer", id, http.StatusBadRequest) return } else if id != currReg.ID { + logEvent.AddError("Request signing key did not match registration key: %d != %d", id, currReg.ID) wfe.sendError(response, logEvent, "Request signing key did not match registration key", "", http.StatusForbidden) return } @@ -1048,6 +1068,7 @@ func (wfe *WebFrontEndImpl) Registration(logEvent *requestEvent, response http.R var update core.Registration err = json.Unmarshal(body, &update) if err != nil { + logEvent.AddError("unable to JSON parse registration: %s", err) wfe.sendError(response, logEvent, "Error unmarshaling registration", err, http.StatusBadRequest) return } @@ -1068,6 +1089,7 @@ func (wfe *WebFrontEndImpl) Registration(logEvent *requestEvent, response http.R // Ask the RA to update this authorization. updatedReg, err := wfe.RA.UpdateRegistration(currReg, update) if err != nil { + logEvent.AddError("unable to update registration: %s", err) wfe.sendError(response, logEvent, "Unable to update registration", err, statusCodeFromError(err)) return } @@ -1075,6 +1097,7 @@ func (wfe *WebFrontEndImpl) Registration(logEvent *requestEvent, response http.R jsonReply, err := json.Marshal(updatedReg) if err != nil { // StatusInternalServerError because we just generated the reg, it should be OK + logEvent.AddError("unable to marshal updated registration: %s", err) wfe.sendError(response, logEvent, "Failed to marshal registration", err, http.StatusInternalServerError) return } @@ -1094,6 +1117,7 @@ func (wfe *WebFrontEndImpl) Authorization(logEvent *requestEvent, response http. id := parseIDFromPath(request.URL.Path) authz, err := wfe.SA.GetAuthorization(id) if err != nil { + logEvent.AddError("No such authorization at id %s", id) wfe.sendError(response, logEvent, "Unable to find authorization", err, http.StatusNotFound) return } @@ -1115,6 +1139,7 @@ func (wfe *WebFrontEndImpl) Authorization(logEvent *requestEvent, response http. jsonReply, err := json.Marshal(authz) if err != nil { // InternalServerError because this is a failure to decode from our DB. + logEvent.AddError("Failed to JSON marshal authz: %s", err) wfe.sendError(response, logEvent, "Failed to JSON marshal authz", err, http.StatusInternalServerError) return } @@ -1122,7 +1147,7 @@ func (wfe *WebFrontEndImpl) Authorization(logEvent *requestEvent, response http. response.Header().Set("Content-Type", "application/json") response.WriteHeader(http.StatusOK) if _, err = response.Write(jsonReply); err != nil { - logEvent.AddError("unable to write authorization update response: %s", err) + logEvent.AddError(err.Error()) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } } @@ -1137,12 +1162,14 @@ func (wfe *WebFrontEndImpl) Certificate(logEvent *requestEvent, response http.Re // Certificate paths consist of the CertBase path, plus exactly sixteen hex // digits. if !strings.HasPrefix(path, CertPath) { + logEvent.AddError("this request path should not have gotten to Certificate: %#v is not a prefix of %#v", path, CertPath) wfe.sendError(response, logEvent, "Certificate not found", path, http.StatusNotFound) addNoCacheHeader(response) return } serial := path[len(CertPath):] if !core.ValidSerial(serial) { + logEvent.AddError("certificate serial provided was not valid: %s", serial) wfe.sendError(response, logEvent, "Certificate not found", serial, http.StatusNotFound) addNoCacheHeader(response) return @@ -1151,6 +1178,7 @@ func (wfe *WebFrontEndImpl) Certificate(logEvent *requestEvent, response http.Re cert, err := wfe.SA.GetCertificate(serial) if err != nil { + logEvent.AddError("unable to get certificate by serial id %#v: %s", serial, err) if strings.HasPrefix(err.Error(), "gorp: multiple rows returned") { wfe.sendError(response, logEvent, "Multiple certificates with same short serial", err, http.StatusConflict) } else { @@ -1167,6 +1195,7 @@ func (wfe *WebFrontEndImpl) Certificate(logEvent *requestEvent, response http.Re response.Header().Add("Link", link(IssuerPath, "up")) response.WriteHeader(http.StatusOK) if _, err = response.Write(cert.DER); err != nil { + logEvent.AddError(err.Error()) wfe.log.Warning(fmt.Sprintf("Could not write response: %s", err)) } return From c073da7b1bf795e1c11ff3a8d79d49fe96b4580c Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Thu, 22 Oct 2015 10:21:29 -0700 Subject: [PATCH 24/25] Flatten method sig --- ra/registration-authority.go | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/ra/registration-authority.go b/ra/registration-authority.go index 0ef9a03ce..49dd2149c 100644 --- a/ra/registration-authority.go +++ b/ra/registration-authority.go @@ -325,10 +325,7 @@ func (ra *RegistrationAuthorityImpl) NewAuthorization(request core.Authorization // * IsCA is false // * ExtKeyUsage only contains ExtKeyUsageServerAuth & ExtKeyUsageClientAuth // * Subject only contains CommonName & Names -func (ra *RegistrationAuthorityImpl) MatchesCSR( - cert core.Certificate, - csr *x509.CertificateRequest, -) (err error) { +func (ra *RegistrationAuthorityImpl) MatchesCSR(cert core.Certificate, csr *x509.CertificateRequest) (err error) { parsedCertificate, err := x509.ParseCertificate([]byte(cert.DER)) if err != nil { return From c62d4a08285e5788398360405ae57b612948db54 Mon Sep 17 00:00:00 2001 From: Richard Barnes Date: Thu, 22 Oct 2015 13:59:18 -0400 Subject: [PATCH 25/25] Spelling fix --- wfe/web-front-end.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/wfe/web-front-end.go b/wfe/web-front-end.go index 7b27492a6..c63ba59b8 100644 --- a/wfe/web-front-end.go +++ b/wfe/web-front-end.go @@ -589,7 +589,7 @@ func (wfe *WebFrontEndImpl) NewRegistration(logEvent *requestEvent, response htt responseBody, err := json.Marshal(reg) if err != nil { // StatusInternalServerError because we just created this registration, it should be OK. - logEvent.AddError("unable to marsh registration: %s", err) + logEvent.AddError("unable to marshal registration: %s", err) wfe.sendError(response, logEvent, "Error marshaling registration", err, http.StatusInternalServerError) return }