From 0ea1868e77693a550ddc7c0d4075797a2cb780dd Mon Sep 17 00:00:00 2001 From: Jason Rahman Date: Fri, 27 Jan 2017 22:24:55 -0800 Subject: [PATCH] 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 | 24 ++++++++++++--------- folly/io/async/AsyncSSLSocket.h | 35 +++++++++++++++---------------- folly/io/async/AsyncSocket.cpp | 8 +++++-- 3 files changed, 37 insertions(+), 30 deletions(-) diff --git a/folly/io/async/AsyncSSLSocket.cpp b/folly/io/async/AsyncSSLSocket.cpp index 1f66ddd6..80660352 100644 --- 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 7d90fbb1..fe8cbdd3 100644 --- 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 bbdbc46c..8a9a37e7 100644 --- 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); } } -- 2.34.1