[trafficserver] branch 9.0.x updated: Emits log when OCSP fails to connect to server (#7183)

[zw...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

zwoop pushed a commit to branch 9.0.x
in repository https://gitbox.apache.org/repos/asf/trafficserver.git


The following commit(s) were added to refs/heads/9.0.x by this push:
     new adf7331  Emits log when OCSP fails to connect to server (#7183)
adf7331 is described below

commit adf73316881e91883b247d122cf02550c72d8c1a
Author: Randall Meyer <rr...@apache.org>
AuthorDate: Mon Sep 14 10:00:08 2020 -0700

    Emits log when OCSP fails to connect to server (#7183)
    
    This also adds a pair of log messages for the initial OCSP update.
    ATS doesn't respond until this is complete and may give operators an
    understanding where it on load.
    
    Fixes issue #6801
    
    (cherry picked from commit b353df22e09ffaecac1fd561a598cf8c13437f62)
---
 iocore/net/OCSPStapling.cc    | 25 ++++++++++++++-----------
 iocore/net/SSLNetProcessor.cc |  3 +++
 2 files changed, 17 insertions(+), 11 deletions(-)

diff --git a/iocore/net/OCSPStapling.cc b/iocore/net/OCSPStapling.cc
index d39bf6b..7c39d2b 100644
--- a/iocore/net/OCSPStapling.cc
+++ b/iocore/net/OCSPStapling.cc
@@ -374,10 +374,12 @@ query_responder(BIO *b, char *host, char *path, OCSP_REQUEST *req, int req_timeo
 
   OCSP_REQ_CTX_free(ctx);
 
-  if (rv) {
+  if (rv == 1) {
     return resp;
   }
 
+  Error("failed to connect to OCSP server; host=%s path=%s", host, path);
+
   return nullptr;
 }
 
@@ -396,7 +398,7 @@ process_responder(OCSP_REQUEST *req, char *host, char *path, char *port, int req
 
   BIO_set_nbio(cbio, 1);
   if (BIO_do_connect(cbio) <= 0 && !BIO_should_retry(cbio)) {
-    Debug("ssl_ocsp", "process_responder: failed to connect to OCSP response server. host=%s port=%s path=%s", host, port, path);
+    Debug("ssl_ocsp", "process_responder: failed to connect to OCSP server; host=%s port=%s path=%s", host, port, path);
     goto end;
   }
   resp = query_responder(cbio, host, path, req, req_timeout);
@@ -415,16 +417,18 @@ stapling_refresh_response(certinfo *cinf, OCSP_RESPONSE **prsp)
   OCSP_REQUEST *req = nullptr;
   OCSP_CERTID *id   = nullptr;
   char *host = nullptr, *port = nullptr, *path = nullptr;
-  int ssl_flag    = 0;
-  int req_timeout = -1;
+  int ssl_flag        = 0;
+  int response_status = 0;
 
-  Debug("ssl_ocsp", "stapling_refresh_response: querying responder");
   *prsp = nullptr;
 
   if (!OCSP_parse_url(cinf->uri, &host, &port, &path, &ssl_flag)) {
+    Debug("ssl_ocsp", "stapling_refresh_response: OCSP_parse_url failed; uri=%s", cinf->uri);
     goto err;
   }
 
+  Debug("ssl_ocsp", "stapling_refresh_response: querying responder; host=%s port=%s path=%s", host, port, path);
+
   req = OCSP_REQUEST_new();
   if (!req) {
     goto err;
@@ -437,19 +441,18 @@ stapling_refresh_response(certinfo *cinf, OCSP_RESPONSE **prsp)
     goto err;
   }
 
-  req_timeout = SSLConfigParams::ssl_ocsp_request_timeout;
-  *prsp       = process_responder(req, host, path, port, req_timeout);
-
+  *prsp = process_responder(req, host, path, port, SSLConfigParams::ssl_ocsp_request_timeout);
   if (*prsp == nullptr) {
     goto done;
   }
 
-  if (OCSP_response_status(*prsp) == OCSP_RESPONSE_STATUS_SUCCESSFUL) {
+  response_status = OCSP_response_status(*prsp);
+  if (response_status == OCSP_RESPONSE_STATUS_SUCCESSFUL) {
     Debug("ssl_ocsp", "stapling_refresh_response: query response received");
     stapling_check_response(cinf, *prsp);
   } else {
-    // TODO: We should log the actual openssl error
-    Error("stapling_refresh_response: responder error");
+    Error("stapling_refresh_response: responder response error; host=%s port=%s path=%s response_status=%d", host, port, path,
+          response_status);
   }
 
   if (!stapling_cache_response(*prsp, cinf)) {
diff --git a/iocore/net/SSLNetProcessor.cc b/iocore/net/SSLNetProcessor.cc
index fd85508..0707cc3 100644
--- a/iocore/net/SSLNetProcessor.cc
+++ b/iocore/net/SSLNetProcessor.cc
@@ -78,7 +78,10 @@ SSLNetProcessor::start(int, size_t stacksize)
 #if TS_USE_TLS_OCSP
   if (SSLConfigParams::ssl_ocsp_enabled) {
     // Call the update initially to get things populated
+    Note("Initial OCSP refresh started");
     ocsp_update();
+    Note("Initial OCSP refresh finished");
+
     EventType ET_OCSP = eventProcessor.spawn_event_threads("ET_OCSP", 1, stacksize);
     eventProcessor.schedule_every(new OCSPContinuation(), HRTIME_SECONDS(SSLConfigParams::ssl_ocsp_update_period), ET_OCSP);
   }