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

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;
   }

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};
 

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);
   }
 }