Fix TLS write busy-spin on SSL_ERROR_WANT_READ
A TLS sendData() failing with SSL_ERROR_WANT_READ (mid-handshake application data, or a post-handshake session ticket exchange) has nothing to do with write-readiness, but resetSocket() kept re-arming EPOLLWRNORM anyway - an already-writable TCP socket fires that immediately, so the retry loop spun the CPU as fast as it could until the connection was eventually dropped, without ever reading the peer's first command. Confirmed via a 15GB+ debug log from one stuck connection. sendNeedsRead() lets Socket now tell the difference and wait for a real EPOLLIN instead of busy-retrying.
This commit is contained in:
1 parent
c3e8d70774
commit
2676aaf84c
6 files changed
+68
-1
No files matched your search
+15
-1
@@ -80,6 +80,12 @@ namespace core
|
|||||||
}
|
}
|
||||||
if(event.events & EPOLLIN) {
|
if(event.events & EPOLLIN) {
|
||||||
coreutils::Log(coreutils::LOG_DEBUG_2) << "EPOLLIN";
|
coreutils::Log(coreutils::LOG_DEBUG_2) << "EPOLLIN";
|
||||||
|
// A read just happened (or at least an opportunity for OpenSSL
|
||||||
|
// to make progress on whatever it needed a read for) - give any
|
||||||
|
// write that was waiting on that a fresh attempt via this same
|
||||||
|
// call's own trailing resetSocket(), rather than leaving
|
||||||
|
// EPOLLWRNORM permanently un-armed from a single earlier stall.
|
||||||
|
waitingOnReadToWrite = false;
|
||||||
coreutils::ZString zbuffer(buffer, length);
|
coreutils::ZString zbuffer(buffer, length);
|
||||||
// receiveData() calls all the way down through
|
// receiveData() calls all the way down through
|
||||||
// onDataReceived()/HTTPRequest::doParse()/application request
|
// onDataReceived()/HTTPRequest::doParse()/application request
|
||||||
@@ -241,10 +247,18 @@ namespace core
|
|||||||
int sent = sendData(fifo.front().c_str(), fifo.front().length());
|
int sent = sendData(fifo.front().c_str(), fifo.front().length());
|
||||||
if(sent > 0) {
|
if(sent > 0) {
|
||||||
consecutiveWriteStalls = 0;
|
consecutiveWriteStalls = 0;
|
||||||
|
waitingOnReadToWrite = false;
|
||||||
if((size_t)sent >= fifo.front().length())
|
if((size_t)sent >= fifo.front().length())
|
||||||
fifo.pop();
|
fifo.pop();
|
||||||
else
|
else
|
||||||
fifo.front().erase(0, sent);
|
fifo.front().erase(0, sent);
|
||||||
|
} else if(sendNeedsRead()) {
|
||||||
|
// Not a stall in the CPU-spinning sense consecutiveWriteStalls
|
||||||
|
// exists to catch - resetSocket() below simply won't re-arm
|
||||||
|
// EPOLLWRNORM while this is true, so there's nothing to busy-
|
||||||
|
// retry until a real EPOLLIN event (already always watched
|
||||||
|
// for) brings in whatever OpenSSL is actually waiting to read.
|
||||||
|
waitingOnReadToWrite = true;
|
||||||
} else if(++consecutiveWriteStalls > 50) {
|
} else if(++consecutiveWriteStalls > 50) {
|
||||||
// sendData() keeps failing for a reason that has nothing to
|
// sendData() keeps failing for a reason that has nothing to
|
||||||
// do with the socket's own write-readiness (confirmed real
|
// do with the socket's own write-readiness (confirmed real
|
||||||
@@ -307,7 +321,7 @@ namespace core
|
|||||||
struct epoll_event event;
|
struct epoll_event event;
|
||||||
event.data.ptr = this;
|
event.data.ptr = this;
|
||||||
event.events = EPOLLIN | EPOLLRDHUP | EPOLLONESHOT | EPOLLET;
|
event.events = EPOLLIN | EPOLLRDHUP | EPOLLONESHOT | EPOLLET;
|
||||||
if(fifo.size() > 0)
|
if(fifo.size() > 0 && !waitingOnReadToWrite)
|
||||||
event.events |= EPOLLWRNORM;
|
event.events |= EPOLLWRNORM;
|
||||||
// Was `if(!shutDown)` - refused to re-arm at all once shutting
|
// Was `if(!shutDown)` - refused to re-arm at all once shutting
|
||||||
// down, even with data still queued to send (e.g. a graceful
|
// down, even with data still queued to send (e.g. a graceful
|
||||||
|
|||||||
@@ -182,6 +182,17 @@ namespace core {
|
|||||||
|
|
||||||
virtual int sendData(const char *data, int length);
|
virtual int sendData(const char *data, int length);
|
||||||
|
|
||||||
|
///
|
||||||
|
/// Overridden by TCPSocket to report whether the last sendData()
|
||||||
|
/// call failed specifically because the TLS layer needs a READ to
|
||||||
|
/// make progress (SSL_ERROR_WANT_READ), as opposed to any other
|
||||||
|
/// reason - see waitingOnReadToWrite's own doc comment for why
|
||||||
|
/// writeSocket()/resetSocket() need to know this. Always false for
|
||||||
|
/// a plain (non-TLS) socket, which has no such distinction.
|
||||||
|
///
|
||||||
|
|
||||||
|
virtual bool sendNeedsRead() { return false; }
|
||||||
|
|
||||||
private:
|
private:
|
||||||
|
|
||||||
std::string text;
|
std::string text;
|
||||||
@@ -226,6 +237,19 @@ namespace core {
|
|||||||
// clearly never going to un-stick itself and gets shut down.
|
// clearly never going to un-stick itself and gets shut down.
|
||||||
int consecutiveWriteStalls = 0;
|
int consecutiveWriteStalls = 0;
|
||||||
|
|
||||||
|
// Set by writeSocket() when the last failed send specifically
|
||||||
|
// needed a read to proceed (sendNeedsRead() true) rather than
|
||||||
|
// being genuinely stalled on write-readiness. resetSocket() skips
|
||||||
|
// adding EPOLLWRNORM to the re-armed event mask while this is
|
||||||
|
// true - re-arming it anyway just spins the CPU as fast as it can
|
||||||
|
// loop, since an already-writable TCP socket keeps firing
|
||||||
|
// EPOLLWRNORM immediately while the actual blocker (more bytes
|
||||||
|
// from the peer) has nothing to do with write-readiness at all.
|
||||||
|
// Cleared on any EPOLLIN event (see eventReceived()) so the write
|
||||||
|
// gets a fresh attempt via that same event's own trailing
|
||||||
|
// resetSocket() call, once there's real reason to expect progress.
|
||||||
|
bool waitingOnReadToWrite = false;
|
||||||
|
|
||||||
void resetSocket();
|
void resetSocket();
|
||||||
|
|
||||||
std::mutex lock;
|
std::mutex lock;
|
||||||
|
|||||||
@@ -66,6 +66,10 @@ namespace core {
|
|||||||
return Socket::sendData(data, length);
|
return Socket::sendData(data, length);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
bool TCPSocket::sendNeedsRead() {
|
||||||
|
return ctx && lastSendWantedRead;
|
||||||
|
}
|
||||||
|
|
||||||
void TCPSocket::performTLSHandshake() {
|
void TCPSocket::performTLSHandshake() {
|
||||||
// registerSocket() makes this fd eligible for epoll dispatch to ANY
|
// registerSocket() makes this fd eligible for epoll dispatch to ANY
|
||||||
// worker thread immediately. ioLock MUST be acquired BEFORE that
|
// worker thread immediately. ioLock MUST be acquired BEFORE that
|
||||||
|
|||||||
@@ -123,6 +123,15 @@ namespace core {
|
|||||||
|
|
||||||
virtual int sendData(const char *data, int length) override;
|
virtual int sendData(const char *data, int length) override;
|
||||||
|
|
||||||
|
///
|
||||||
|
/// True only when this socket is actually TLS (ctx set) and the
|
||||||
|
/// last sendData() call failed specifically with
|
||||||
|
/// SSL_ERROR_WANT_READ - see TLS::lastSendWantedRead's own doc
|
||||||
|
/// comment for why Socket::writeSocket()/resetSocket() need this.
|
||||||
|
///
|
||||||
|
|
||||||
|
virtual bool sendNeedsRead() override;
|
||||||
|
|
||||||
///
|
///
|
||||||
/// Completes the TLS handshake (SSL_new/SSL_set_fd/SSL_accept) for
|
/// Completes the TLS handshake (SSL_new/SSL_set_fd/SSL_accept) for
|
||||||
/// THIS socket's own ctx/descriptor. registerSocket()/acceptSocket()
|
/// THIS socket's own ctx/descriptor. registerSocket()/acceptSocket()
|
||||||
|
|||||||
@@ -251,15 +251,18 @@ namespace core {
|
|||||||
|
|
||||||
if((len = ::SSL_write(ssl, data, length)) >= 0) {
|
if((len = ::SSL_write(ssl, data, length)) >= 0) {
|
||||||
coreutils::Log(coreutils::LOG_DEBUG_3) << "sendData TLS...len=" << len;
|
coreutils::Log(coreutils::LOG_DEBUG_3) << "sendData TLS...len=" << len;
|
||||||
|
lastSendWantedRead = false;
|
||||||
return len;
|
return len;
|
||||||
}
|
}
|
||||||
else {
|
else {
|
||||||
|
lastSendWantedRead = false;
|
||||||
switch (SSL_get_error(ssl, len)) {
|
switch (SSL_get_error(ssl, len)) {
|
||||||
case SSL_ERROR_SSL:
|
case SSL_ERROR_SSL:
|
||||||
coreutils::Log(coreutils::LOG_DEBUG_3) << "ERROR_SSL on ssl_write. error=" << errno;
|
coreutils::Log(coreutils::LOG_DEBUG_3) << "ERROR_SSL on ssl_write. error=" << errno;
|
||||||
break;
|
break;
|
||||||
case SSL_ERROR_WANT_READ:
|
case SSL_ERROR_WANT_READ:
|
||||||
coreutils::Log(coreutils::LOG_DEBUG_3) << "ERROR_WANT_READ on ssl_write.";
|
coreutils::Log(coreutils::LOG_DEBUG_3) << "ERROR_WANT_READ on ssl_write.";
|
||||||
|
lastSendWantedRead = true;
|
||||||
break;
|
break;
|
||||||
case SSL_ERROR_WANT_WRITE:
|
case SSL_ERROR_WANT_WRITE:
|
||||||
coreutils::Log(coreutils::LOG_DEBUG_3) << "ERROR_WANT_WRITE on ssl_write.";
|
coreutils::Log(coreutils::LOG_DEBUG_3) << "ERROR_WANT_WRITE on ssl_write.";
|
||||||
|
|||||||
@@ -59,6 +59,19 @@ namespace core {
|
|||||||
void registerSocket(int fd);
|
void registerSocket(int fd);
|
||||||
void acceptSocket();
|
void acceptSocket();
|
||||||
|
|
||||||
|
protected:
|
||||||
|
// Set by sendData() when the last SSL_write() failed specifically
|
||||||
|
// with SSL_ERROR_WANT_READ (needs a READ to make progress - e.g.
|
||||||
|
// mid-handshake application data, or a post-handshake session
|
||||||
|
// ticket exchange) rather than any other reason. TCPSocket::
|
||||||
|
// sendNeedsRead() reads this (protected, so a subclass can reach
|
||||||
|
// it directly) to tell Socket::writeSocket()/resetSocket() not to
|
||||||
|
// busy-spin retrying the write via EPOLLWRNORM - see their own
|
||||||
|
// doc comments for the confirmed real damage (a 15GB+ debug log,
|
||||||
|
// and every affected connection dropped before ever reading the
|
||||||
|
// client's first command) this caused when unaddressed.
|
||||||
|
bool lastSendWantedRead = false;
|
||||||
|
|
||||||
private:
|
private:
|
||||||
char *sip_cacert = (char *)"../testkeys/certs/pbxca.crt";
|
char *sip_cacert = (char *)"../testkeys/certs/pbxca.crt";
|
||||||
char *sip_cert = (char *)"../testkeys/certs/pbxserver.crt";
|
char *sip_cert = (char *)"../testkeys/certs/pbxserver.crt";
|
||||||
|
|||||||
Reference in new issue
Block a user