Merge 24558c2cf18210f46d6e2fadf0c5c5912f4b8e10 into cd8089c20baaaee329cbf7951195953a9f86d7cf

Could aid debugging when an HTTP request gets stuck at shutdown.

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
@@ -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<HTTPRequest>(req, *static_cast<const util::SignalInterrupt*>(arg))};
+    const uint32_t request_id = g_request_id++;
+    auto hreq{std::make_unique<HTTPRequest>(req, *static_cast<const util::SignalInterrupt*>(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();
@@ -529,32 +532,50 @@ 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);
     }
     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, so
-        // that evhttp_free does not need to be called again after the handling
-        // of unfinished request connections that follows.
-        event_base_once(eventBase, -1, EV_TIMEOUT, [](evutil_socket_t, short, void*) {
+        // 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.
+        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");
@@ -591,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)
 {
 }
 
@@ -653,6 +674,7 @@ void HTTPRequest::WriteReply(int nStatus, std::span<const std::byte> reply)
 {
     assert(!replySent && req);
     if (m_interrupt) {
+        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
@@ -660,8 +682,9 @@ void HTTPRequest::WriteReply(int nStatus, std::span<const std::byte> 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) {

src/httpserver.h

@@ -5,6 +5,7 @@
 #ifndef BITCOIN_HTTPSERVER_H
 #define BITCOIN_HTTPSERVER_H
 
+#include <cstdint>
 #include <functional>
 #include <optional>
 #include <span>
@@ -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 {

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