diff --git a/ocsp_asn1crypto.py b/ocsp_asn1crypto.py index 5995f61ef..0dc03a711 100644 --- a/ocsp_asn1crypto.py +++ b/ocsp_asn1crypto.py @@ -194,16 +194,17 @@ def process_ocsp_response(self, issuer, cert_id, ocsp_response): if cur_time > ocsp_cert['tbs_certificate']['validity']['not_after'].native or \ cur_time < ocsp_cert['tbs_certificate']['validity']['not_before'].native: + debug_msg = "Certificate attached to OCSP response is invalid. OCSP response " \ + "current time - {0} certificate not before time - {1} certificate " \ + "not after time - {2}. Consider running curl -o ocsp.der {3}".\ + format(cur_time, + ocsp_cert['tbs_certificate']['validity']['not_before'].native, + ocsp_cert['tbs_certificate']['validity']['not_after'].native, + super(SnowflakeOCSPAsn1Crypto, self).debug_ocsp_failure_url) + raise OperationalError( - msg="Certificate attached to OCSP response is invalid. OCSP response " - "current time - {0} " - "certificate not before time - {1} " - "certificate not after time - {2}". - format(cur_time, - ocsp_cert['tbs_certificate']['validity']['not_before'].native, - ocsp_cert['tbs_certificate']['validity']['not_after'].native), - errno=ER_INVALID_OCSP_RESPONSE_CODE - ) + msg=debug_msg, + errno=ER_INVALID_OCSP_RESPONSE_CODE) self.verify_signature( ocsp_cert.hash_algo, @@ -227,19 +228,27 @@ def process_ocsp_response(self, issuer, cert_id, ocsp_response): single_response = tbs_response_data['responses'][0] cert_status = single_response['cert_status'].name - if cert_status == 'good': - self._process_good_status(single_response, cert_id, ocsp_response) - SnowflakeOCSP.OCSP_CACHE.update_cache(self, cert_id, ocsp_response) - elif cert_status == 'revoked': - self._process_revoked_status(single_response, cert_id) - elif cert_status == 'unknown': - self._process_unknown_status(cert_id) - else: - raise OperationalError( - msg="Unknown revocation status was returned. OCSP response " - "may be malformed: {0}".format(cert_status), - errno=ER_INVALID_OCSP_RESPONSE_CODE - ) + try: + if cert_status == 'good': + self._process_good_status(single_response, cert_id, ocsp_response) + SnowflakeOCSP.OCSP_CACHE.update_cache(self, cert_id, ocsp_response) + elif cert_status == 'revoked': + self._process_revoked_status(single_response, cert_id) + elif cert_status == 'unknown': + self._process_unknown_status(cert_id) + else: + debug_msg = "Unknown revocation status was returned." \ + "OCSP response may be malformed: {0}.".\ + format(cert_status) + raise OperationalError( + msg=debug_msg, + errno=ER_INVALID_OCSP_RESPONSE_CODE + ) + except OperationalError as op_er: + debug_msg = "{0} Consider running curl -o ocsp.der {1}".\ + format(op_er.msg, + self.debug_ocsp_failure_url) + raise OperationalError(msg=debug_msg, errno=op_er.errno) def verify_signature(self, signature_algorithm, signature, cert, data): pubkey = cert.public_key.unwrap().dump() diff --git a/ocsp_pyasn1.py b/ocsp_pyasn1.py index ece88cffb..35e82ebcf 100644 --- a/ocsp_pyasn1.py +++ b/ocsp_pyasn1.py @@ -422,11 +422,12 @@ def process_ocsp_response(self, issuer, cert_id, ocsp_response): cert_not_before_utc = cert_not_before.getComponentByName('utcTime').asDateTime if cur_time > cert_not_after_utc or cur_time < cert_not_before_utc: + debug_msg = "Certificate attached to OCSP Response is invalid. " \ + "OCSP response current time - {0} certificate not " \ + "before time - {1} certificate not after time - {2}. ".\ + format(cur_time, cert_not_before_utc, cert_not_after_utc) raise OperationalError( - msg="Certificate attached to OCSP Response is invalid. OCSP response " - "current time - {0} " - "certificate not before time - {1} " - "certificate not after time - {2}".format(cur_time, cert_not_before_utc, cert_not_after_utc), + msg=debug_msg, errno=ER_INVALID_OCSP_RESPONSE_CODE ) @@ -453,19 +454,31 @@ def process_ocsp_response(self, issuer, cert_id, ocsp_response): single_response = tbs_response_data.getComponentByName('responses')[0] cert_status = single_response.getComponentByName('certStatus') - if cert_status.getName() == 'good': - self._process_good_status(single_response, cert_id, ocsp_response) - SnowflakeOCSP.OCSP_CACHE.update_cache(self, cert_id, ocsp_response) - elif cert_status.getName() == 'revoked': - self._process_revoked_status(single_response, cert_id) - elif cert_status.getName() == 'unknown': - self._process_unknown_status(cert_id) - else: + try: + if cert_status.getName() == 'good': + self._process_good_status(single_response, cert_id, ocsp_response) + SnowflakeOCSP.OCSP_CACHE.update_cache(self, cert_id, ocsp_response) + elif cert_status.getName() == 'revoked': + self._process_revoked_status(single_response, cert_id) + elif cert_status.getName() == 'unknown': + self._process_unknown_status(cert_id) + else: + debug_msg = "Unknown revocation status was returned. " \ + "OCSP response may be malformed: {0}. ".format(cert_status) + raise OperationalError( + msg=debug_msg, + errno=ER_INVALID_OCSP_RESPONSE_CODE + ) + except OperationalError as op_er: + if not self.debug_ocsp_failure_url: + debug_msg = op_er.msg + else: + debug_msg = "{0} Consider running curl -o ocsp.der {1}".\ + format(op_er.msg, + self.debug_ocsp_failure_url) raise OperationalError( - msg="Unknown revocation status was returned. OCSP response " - "may be malformed: {0}".format(cert_status), - errno=ER_INVALID_OCSP_RESPONSE_CODE - ) + msg=debug_msg, + errno=op_er.errno) def verify_signature(self, signature_algorithm, signature, cert, data): """ diff --git a/ocsp_snowflake.py b/ocsp_snowflake.py index a4b06f87b..7c192daaf 100644 --- a/ocsp_snowflake.py +++ b/ocsp_snowflake.py @@ -765,6 +765,8 @@ def __init__( SnowflakeOCSP.SSD.check_ssd_support() self.OCSP_CACHE_SERVER = OCSPServer() + self.debug_ocsp_failure_url = None + if SnowflakeOCSP.SSD.ACTIVATE_SSD: SnowflakeOCSP.OCSP_CACHE.set_ssd_status(SnowflakeOCSP.SSD.ACTIVATE_SSD) SnowflakeOCSP.SSD.clear_ssd_cache() @@ -900,6 +902,8 @@ def validate_by_direct_connection(self, issuer, subject, hostname=None, do_retry logger.debug("getting OCSP response from CA's OCSP server") ocsp_response = self._fetch_ocsp_response(req, subject, cert_id, hostname) else: + ocsp_url = self.extract_ocsp_url(subject) + self.debug_ocsp_failure_url = SnowflakeOCSP.create_ocsp_debug_info(self, req, ocsp_url) logger.debug("using OCSP response cache") if not ocsp_response: @@ -1056,6 +1060,12 @@ def cache_size(): def delete_cache_file(): SnowflakeOCSP.OCSP_CACHE.delete_cache_file() + @staticmethod + def create_ocsp_debug_info(ocsp, ocsp_request, ocsp_url): + b64data = ocsp.decode_ocsp_request_b64(ocsp_request) + target_url = "{0}/{1}".format(ocsp_url, b64data) + return target_url + def _fetch_ocsp_response(self, ocsp_request, subject, cert_id, hostname=None, do_retry=True): """ Fetch OCSP response using OCSPRequest @@ -1092,6 +1102,8 @@ def _fetch_ocsp_response(self, ocsp_request, subject, cert_id, hostname=None, do 'ocsp_responder_url': ocsp_url}) headers = {'Content-Type': 'application/json'} + self.debug_ocsp_failure_url = SnowflakeOCSP.create_ocsp_debug_info(self, ocsp_request, ocsp_url) + ret = None logger.debug('url: %s', target_url) with generic_requests.Session() as session: @@ -1099,24 +1111,33 @@ def _fetch_ocsp_response(self, ocsp_request, subject, cert_id, hostname=None, do sleep_time = 1 backoff = DecorrelateJitterBackoff(sleep_time, 16) for attempt in range(max_retry): - response = session.request( - headers=headers, - method=actual_method, - url=target_url, - timeout=30, - data=payload, - ) - if response.status_code == OK: - logger.debug( - "OCSP response was successfully returned from OCSP " - "server.") - ret = response.content - break - elif max_retry > 1: - sleep_time = backoff.next_sleep(1, sleep_time) - logger.debug("OCSP server returned %s. Retrying in %s(s)", - response.status_code, sleep_time) - time.sleep(sleep_time) + try: + response = session.request( + headers=headers, + method=actual_method, + url=target_url, + timeout=30, + data=payload, + ) + if response.status_code == OK: + logger.debug( + "OCSP response was successfully returned from OCSP " + "server.") + ret = response.content + break + elif max_retry > 1: + sleep_time = backoff.next_sleep(1, sleep_time) + logger.debug("OCSP server returned %s. Retrying in %s(s)", + response.status_code, sleep_time) + time.sleep(sleep_time) + except Exception as ex: + if max_retry > 1: + sleep_time = backoff.next_sleep(1, sleep_time) + logger.debug("Could not fetch OCSP Response from server" + "Retrying in %s(s)", sleep_time) + time.sleep(sleep_time) + else: + raise ex else: logger.error( "Failed to get OCSP response after %s attempt.", max_retry)