From 1350087f9ae4bbcd967ddf692080dc687dd40b82 Mon Sep 17 00:00:00 2001 From: Hodlinator <172445034+hodlinator@users.noreply.github.com> Date: Fri, 21 Feb 2025 15:20:03 +0100 Subject: [PATCH 1/4] doc http: Improve documentation around (libevent) HTTP shutdown behavior --- src/httpserver.cpp | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index bd2dec19b97..bc65453dbda 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -529,8 +529,9 @@ void StopHTTPServer() } g_thread_http_workers.clear(); } - // Unlisten sockets, these are what make the event loop running, which means - // that after this and all connections are closed the event loop will quit. + // Unlisten sockets which would otherwise keep the event loop running. Doing + // so avoids new connections being created, while existing ones continue + // being processed in parallel with this thread until they complete. for (evhttp_bound_socket *socket : boundSockets) { evhttp_del_accept_socket(eventHTTP, socket); } @@ -542,9 +543,9 @@ void StopHTTPServer() g_requests.WaitUntilEmpty(); } if (eventHTTP) { - // Schedule a callback to call evhttp_free in the event base thread, so - // that evhttp_free does not need to be called again after the handling - // of unfinished request connections that follows. + // Schedule a callback to call evhttp_free in the event base thread, as + // otherwise eventHTTP often keeps internal events alive, meaning + // aforementioned thread would never run out of events and exit. event_base_once(eventBase, -1, EV_TIMEOUT, [](evutil_socket_t, short, void*) { evhttp_free(eventHTTP); eventHTTP = nullptr; @@ -653,6 +654,7 @@ void HTTPRequest::WriteReply(int nStatus, std::span reply) { assert(!replySent && req); if (m_interrupt) { + LogDebug(BCLog::HTTP, "Instructing client to close their TCP connection to us."); WriteHeader("Connection", "close"); } // Send event to main http thread to send reply message From 757de96db5628cfbf0f2d0dbaaa135da77440bd9 Mon Sep 17 00:00:00 2001 From: Hodlinator <172445034+hodlinator@users.noreply.github.com> Date: Fri, 21 Feb 2025 14:31:36 +0100 Subject: [PATCH 2/4] http: Ensure eventHTTP is always freed There is a race between ThreadHTTP exiting and our queuing of the freeing-event (event_base_once). Additional free was useful in 709 of 962 runs. --- src/httpserver.cpp | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index bc65453dbda..a3a6a8bea62 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -546,16 +546,25 @@ void StopHTTPServer() // Schedule a callback to call evhttp_free in the event base thread, as // otherwise eventHTTP often keeps internal events alive, meaning // aforementioned thread would never run out of events and exit. - event_base_once(eventBase, -1, EV_TIMEOUT, [](evutil_socket_t, short, void*) { + if (event_base_once(eventBase, -1, EV_TIMEOUT, [](evutil_socket_t, short, void*) { evhttp_free(eventHTTP); eventHTTP = nullptr; - }, nullptr, nullptr); + }, nullptr, nullptr) != 0) { + LogDebug(BCLog::HTTP, "event_base_once failed"); + } } if (eventBase) { LogDebug(BCLog::HTTP, "Waiting for HTTP event thread to exit\n"); if (g_thread_http.joinable()) g_thread_http.join(); + if (eventHTTP) { + LogDebug(BCLog::HTTP, "Freeing eventHTTP-event was not picked up by ThreadHTTP before it exited."); + evhttp_free(eventHTTP); + eventHTTP = nullptr; + } event_base_free(eventBase); eventBase = nullptr; + } else { + Assume(!g_thread_http.joinable()); } g_work_queue.reset(); LogDebug(BCLog::HTTP, "Stopped HTTP server\n"); From a00dfd2046a9edd8fc4063971c2a5f9a444117e7 Mon Sep 17 00:00:00 2001 From: Hodlinator <172445034+hodlinator@users.noreply.github.com> Date: Fri, 21 Feb 2025 14:58:29 +0100 Subject: [PATCH 3/4] http: Abort with clear error instead of hanging forever Could happen when connection doesn't complete for some reason. Output early warning to give clue about what's up. Prior check+log message before even starting to wait was a bit too eager to hint at something being wrong. --- src/httpserver.cpp | 20 ++++++++++++++------ 1 file changed, 14 insertions(+), 6 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index a3a6a8bea62..288d7c08fd6 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -197,10 +197,10 @@ public: return WITH_LOCK(m_mutex, return m_tracker.size()); } //! Wait until there are no more connections with active requests in the tracker - void WaitUntilEmpty() const EXCLUSIVE_LOCKS_REQUIRED(!m_mutex) + void WaitUntilEmpty(std::chrono::seconds timeout) const EXCLUSIVE_LOCKS_REQUIRED(!m_mutex) { WAIT_LOCK(m_mutex, lock); - m_cv.wait(lock, [this]() EXCLUSIVE_LOCKS_REQUIRED(m_mutex) { return m_tracker.empty(); }); + m_cv.wait_for(lock, timeout, [this]() EXCLUSIVE_LOCKS_REQUIRED(m_mutex) { return m_tracker.empty(); }); } }; //! Track active requests @@ -536,11 +536,19 @@ void StopHTTPServer() evhttp_del_accept_socket(eventHTTP, socket); } boundSockets.clear(); - { - if (const auto n_connections{g_requests.CountActiveConnections()}; n_connections != 0) { - LogDebug(BCLog::HTTP, "Waiting for %d connections to stop HTTP server\n", n_connections); + // Give clients time to close down TCP connections from their side before we + // free eventHTTP, this avoids issues like RemoteDisconnected exceptions in + // the test framework. + g_requests.WaitUntilEmpty(/*timeout=*/30s); + if (auto connections{g_requests.CountActiveConnections()}) { + LogWarning("%d remaining HTTP connection(s) after 30s timeout, waiting for longer.", connections); + g_requests.WaitUntilEmpty(/*timeout=*/10min); + if ((connections = g_requests.CountActiveConnections())) { + LogError("%d remaining HTTP connection(s) after long timeout. " + "Aborting to avoid potential use-after-frees from " + "connections still running after freeing eventHTTP.", connections); + std::abort(); } - g_requests.WaitUntilEmpty(); } if (eventHTTP) { // Schedule a callback to call evhttp_free in the event base thread, as From 24558c2cf18210f46d6e2fadf0c5c5912f4b8e10 Mon Sep 17 00:00:00 2001 From: Hodlinator <172445034+hodlinator@users.noreply.github.com> Date: Fri, 21 Feb 2025 16:01:02 +0100 Subject: [PATCH 4/4] http: Add logged request ids Could aid debugging when an HTTP request gets stuck at shutdown. --- src/httpserver.cpp | 18 +++++++++++------- src/httpserver.h | 4 +++- src/test/fuzz/http_request.cpp | 2 +- 3 files changed, 15 insertions(+), 9 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index 288d7c08fd6..52fa8463d2b 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -258,6 +258,8 @@ std::string RequestMethodString(HTTPRequest::RequestMethod m) assert(false); } +static std::atomic_uint32_t g_request_id{0}; + /** HTTP request callback */ static void http_request_cb(struct evhttp_request* req, void* arg) { @@ -284,7 +286,8 @@ static void http_request_cb(struct evhttp_request* req, void* arg) } } } - auto hreq{std::make_unique(req, *static_cast(arg))}; + const uint32_t request_id = g_request_id++; + auto hreq{std::make_unique(req, *static_cast(arg), request_id, /*replySent=*/false)}; // Early address-based allow check if (!ClientAllowed(hreq->GetPeer())) { @@ -302,8 +305,8 @@ static void http_request_cb(struct evhttp_request* req, void* arg) return; } - LogDebug(BCLog::HTTP, "Received a %s request for %s from %s\n", - RequestMethodString(hreq->GetRequestMethod()), SanitizeString(hreq->GetURI(), SAFE_CHARS_URI).substr(0, 100), hreq->GetPeer().ToStringAddrPort()); + LogDebug(BCLog::HTTP, "Received a %s request for %s from %s, id: %d\n", + RequestMethodString(hreq->GetRequestMethod()), SanitizeString(hreq->GetURI(), SAFE_CHARS_URI).substr(0, 100), hreq->GetPeer().ToStringAddrPort(), request_id); // Find registered handler for prefix std::string strURI = hreq->GetURI(); @@ -609,8 +612,8 @@ void HTTPEvent::trigger(struct timeval* tv) else evtimer_add(ev, tv); // trigger after timeval passed } -HTTPRequest::HTTPRequest(struct evhttp_request* _req, const util::SignalInterrupt& interrupt, bool _replySent) - : req(_req), m_interrupt(interrupt), replySent(_replySent) +HTTPRequest::HTTPRequest(struct evhttp_request* _req, const util::SignalInterrupt& interrupt, uint32_t id, bool _replySent) + : req(_req), m_interrupt(interrupt), m_id(id), replySent(_replySent) { } @@ -671,7 +674,7 @@ void HTTPRequest::WriteReply(int nStatus, std::span reply) { assert(!replySent && req); if (m_interrupt) { - LogDebug(BCLog::HTTP, "Instructing client to close their TCP connection to us."); + LogDebug(BCLog::HTTP, "Instructing client to close their TCP connection to us (request id %d).", m_id); WriteHeader("Connection", "close"); } // Send event to main http thread to send reply message @@ -679,8 +682,9 @@ void HTTPRequest::WriteReply(int nStatus, std::span reply) assert(evb); evbuffer_add(evb, reply.data(), reply.size()); auto req_copy = req; - HTTPEvent* ev = new HTTPEvent(eventBase, true, [req_copy, nStatus]{ + HTTPEvent* ev = new HTTPEvent(eventBase, true, [req_copy, nStatus, id = m_id](){ evhttp_send_reply(req_copy, nStatus, nullptr, nullptr); + LogDebug(BCLog::HTTP, "Replied to request: %d", id); // Re-enable reading from the socket. This is the second part of the libevent // workaround above. if (event_get_version_number() >= 0x02010600 && event_get_version_number() < 0x02010900) { diff --git a/src/httpserver.h b/src/httpserver.h index 6535dc6086c..1a185ac9f2e 100644 --- a/src/httpserver.h +++ b/src/httpserver.h @@ -5,6 +5,7 @@ #ifndef BITCOIN_HTTPSERVER_H #define BITCOIN_HTTPSERVER_H +#include #include #include #include @@ -72,10 +73,11 @@ class HTTPRequest private: struct evhttp_request* req; const util::SignalInterrupt& m_interrupt; + const uint32_t m_id; bool replySent; public: - explicit HTTPRequest(struct evhttp_request* req, const util::SignalInterrupt& interrupt, bool replySent = false); + explicit HTTPRequest(struct evhttp_request* req, const util::SignalInterrupt& interrupt, uint32_t id, bool replySent); ~HTTPRequest(); enum RequestMethod { diff --git a/src/test/fuzz/http_request.cpp b/src/test/fuzz/http_request.cpp index f13f1c72a51..e13e433f324 100644 --- a/src/test/fuzz/http_request.cpp +++ b/src/test/fuzz/http_request.cpp @@ -49,7 +49,7 @@ FUZZ_TARGET(http_request) } util::SignalInterrupt interrupt; - HTTPRequest http_request{evreq, interrupt, true}; + HTTPRequest http_request{evreq, interrupt, /*id=*/0, /*replySent=*/true}; const HTTPRequest::RequestMethod request_method = http_request.GetRequestMethod(); (void)RequestMethodString(request_method); (void)http_request.GetURI();