RFC: Include timeout duration in exception message

Summary: For debugging purposes, it's often extremely useful to have the duration of the expired timeout in the exception message (in case the timeout was excessively low, or to understand exactly how long the operation ran before failing due to timeout). Here we make a best effort to include the timeout when possible.

Reviewed By: yfeldblum

Differential Revision: D4476038

fbshipit-source-id: f2d0aa5e1f6367a3cfe20579c27577ab91fd8d9c

diff --git a/folly/io/async/AsyncSSLSocket.cpp b/folly/io/async/AsyncSSLSocket.cpp
index 1f66ddd640dc1d6821d8c8568cde4c45d7cca454..80660352096376a4e4b3673b5a1322804123400d 100644 (file)
--- a/folly/io/async/AsyncSSLSocket.cpp
+++ b/folly/io/async/AsyncSSLSocket.cpp
@@ -106,8 +106,9 @@ class AsyncSSLSocketConnector: public AsyncSocket::ConnectCallback,
 
       timeoutLeft = timeout_ - (curTime - startTime_);
       if (timeoutLeft <= 0) {
-        AsyncSocketException ex(AsyncSocketException::TIMED_OUT,
-                                "SSL connect timed out");
+        AsyncSocketException ex(
+            AsyncSocketException::TIMED_OUT,
+            folly::sformat("SSL connect timed out after {}ms", timeout_));
         fail(ex);
         delete this;
         return;
@@ -561,10 +562,10 @@ void AsyncSSLSocket::setServerName(std::string serverName) noexcept {
 
 #endif // FOLLY_OPENSSL_HAS_SNI
 
-void AsyncSSLSocket::timeoutExpired() noexcept {
+void AsyncSSLSocket::timeoutExpired(
+    std::chrono::milliseconds timeout) noexcept {
   if (state_ == StateEnum::ESTABLISHED &&
-      (sslState_ == STATE_CACHE_LOOKUP ||
-       sslState_ == STATE_ASYNC_PENDING)) {
+      (sslState_ == STATE_CACHE_LOOKUP || sslState_ == STATE_ASYNC_PENDING)) {
     sslState_ = STATE_ERROR;
     // We are expecting a callback in restartSSLAccept.  The cache lookup
     // and rsa-call necessarily have pointers to this ssl socket, so delay
@@ -579,9 +580,12 @@ void AsyncSSLSocket::timeoutExpired() noexcept {
     assert(state_ == StateEnum::ESTABLISHED &&
            (sslState_ == STATE_CONNECTING || sslState_ == STATE_ACCEPTING));
     DestructorGuard dg(this);
-    AsyncSocketException ex(AsyncSocketException::TIMED_OUT,
-                           (sslState_ == STATE_CONNECTING) ?
-                           "SSL connect timed out" : "SSL accept timed out");
+    AsyncSocketException ex(
+        AsyncSocketException::TIMED_OUT,
+        folly::sformat(
+            "SSL {} timed out after {}ms",
+            (sslState_ == STATE_CONNECTING) ? "connect" : "accept",
+            timeout.count()));
     failHandshake(__func__, ex);
   }
 }
@@ -990,8 +994,8 @@ AsyncSSLSocket::restartSSLAccept()
   }
   if (sslState_ == STATE_ERROR) {
     // go straight to fail if timeout expired during lookup
-    AsyncSocketException ex(AsyncSocketException::TIMED_OUT,
-                           "SSL accept timed out");
+    AsyncSocketException ex(
+        AsyncSocketException::TIMED_OUT, "SSL accept timed out");
     failHandshake(__func__, ex);
     return;
   }

diff --git a/folly/io/async/AsyncSSLSocket.h b/folly/io/async/AsyncSSLSocket.h
index 7d90fbb1e1e9dcd3de7160dbe1c4b1412e4890f8..fe8cbdd3632f9e19477dadb22773dab988a93c70 100644 (file)
--- a/folly/io/async/AsyncSSLSocket.h
+++ b/folly/io/async/AsyncSSLSocket.h
@@ -123,32 +123,31 @@ class AsyncSSLSocket : public virtual AsyncSocket {
       noexcept = 0;
   };
 
-  class HandshakeTimeout : public AsyncTimeout {
+  class Timeout : public AsyncTimeout {
    public:
-    HandshakeTimeout(AsyncSSLSocket* sslSocket, EventBase* eventBase)
-      : AsyncTimeout(eventBase)
-      , sslSocket_(sslSocket) {}
+    Timeout(AsyncSSLSocket* sslSocket, EventBase* eventBase)
+        : AsyncTimeout(eventBase), sslSocket_(sslSocket) {}
 
-    virtual void timeoutExpired() noexcept {
-      sslSocket_->timeoutExpired();
+    bool scheduleTimeout(TimeoutManager::timeout_type timeout) {
+      timeout_ = timeout;
+      return AsyncTimeout::scheduleTimeout(timeout);
     }
 
-   private:
-    AsyncSSLSocket* sslSocket_;
-  };
+    bool scheduleTimeout(uint32_t timeoutMs) {
+      return scheduleTimeout(std::chrono::milliseconds{timeoutMs});
+    }
 
-  // Timer for if we fallback from SSL connects to TCP connects
-  class ConnectionTimeout : public AsyncTimeout {
-   public:
-    ConnectionTimeout(AsyncSSLSocket* sslSocket, EventBase* eventBase)
-        : AsyncTimeout(eventBase), sslSocket_(sslSocket) {}
+    TimeoutManager::timeout_type getTimeout() {
+      return timeout_;
+    }
 
     virtual void timeoutExpired() noexcept override {
-      sslSocket_->timeoutExpired();
+      sslSocket_->timeoutExpired(timeout_);
     }
 
    private:
     AsyncSSLSocket* sslSocket_;
+    TimeoutManager::timeout_type timeout_;
   };
 
   /**
@@ -545,7 +544,7 @@ class AsyncSSLSocket : public virtual AsyncSocket {
   void setServerName(std::string serverName) noexcept;
 #endif // FOLLY_OPENSSL_HAS_SNI
 
-  void timeoutExpired() noexcept;
+  void timeoutExpired(std::chrono::milliseconds timeout) noexcept;
 
   /**
    * Get the list of supported ciphers sent by the client in the client's
@@ -781,8 +780,8 @@ class AsyncSSLSocket : public virtual AsyncSocket {
   HandshakeCB* handshakeCallback_{nullptr};
   SSL* ssl_{nullptr};
   SSL_SESSION *sslSession_{nullptr};
-  HandshakeTimeout handshakeTimeout_;
-  ConnectionTimeout connectionTimeout_;
+  Timeout handshakeTimeout_;
+  Timeout connectionTimeout_;
   // whether the SSL session was resumed using session ID or not
   bool sessionIDResumed_{false};
 

diff --git a/folly/io/async/AsyncSocket.cpp b/folly/io/async/AsyncSocket.cpp
index bbdbc46cec4ff2de7b7918bc46ea0f0cae453f93..8a9a37e72a80fc03ecae6cf66bc3074bbb2dd38a 100644 (file)
--- a/folly/io/async/AsyncSocket.cpp
+++ b/folly/io/async/AsyncSocket.cpp
@@ -1771,7 +1771,9 @@ void AsyncSocket::timeoutExpired() noexcept {
     // Unregister for I/O events.
     if (connectCallback_) {
       AsyncSocketException ex(
-          AsyncSocketException::TIMED_OUT, "connect timed out");
+          AsyncSocketException::TIMED_OUT,
+          folly::sformat(
+              "connect timed out after {}ms", connectTimeout_.count()));
       failConnect(__func__, ex);
     } else {
       // we faced a connect error without a connect callback, which could
@@ -1782,7 +1784,9 @@ void AsyncSocket::timeoutExpired() noexcept {
     }
   } else {
     // a normal write operation timed out
-    AsyncSocketException ex(AsyncSocketException::TIMED_OUT, "write timed out");
+    AsyncSocketException ex(
+        AsyncSocketException::TIMED_OUT,
+        folly::sformat("write timed out after {}ms", sendTimeout_));
     failWrite(__func__, ex);
   }
 }