SNOW-75337: Improved OCSP Monitoring script

snowflakedb · Apr 22, 2019 · ff20301 · ff20301
1 parent 8230e9b
commit ff20301
Show file tree

Hide file tree

Showing 3 changed files with 99 additions and 56 deletions.
diff --git 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
@@ -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
@@ -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,31 +1102,42 @@ 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:
  max_retry = 30 if do_retry else 1
  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)