[release/6.x] Cherry-pick: Curl snags (#7308)

CHANGELOG.md

@@ -5,6 +5,14 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/)
 and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html).
 
+## [6.0.14]
+
+[6.0.14]: https://github.com/microsoft/CCF/releases/tag/ccf-6.0.14
+
+### Added
+
+- Improved handling of socket errors in curlm callbacks (#7308)
+
 ## [6.0.13]
 
 [6.0.13]: https://github.com/microsoft/CCF/releases/tag/ccf-6.0.13

python/pyproject.toml

@@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta"
 
 [project]
 name = "ccf"
-version = "6.0.13"
+version = "6.0.14"
 authors = [
   { name="CCF Team", email="CCF-Sec@microsoft.com" },
 ]

src/http/curl.h

@@ -337,7 +337,7 @@ namespace ccf::curl
           }
           else
           {
-            LOG_INFO_FMT("Ignoring invalid-looking HTTP Header '{}'", header);
+            LOG_DEBUG_FMT("Ignoring invalid-looking HTTP Header '{}'", header);
           }
         }
       }
@@ -458,7 +458,7 @@ namespace ccf::curl
     static void handle_response(
       std::unique_ptr<CurlRequest>&& request, CURLcode curl_response_code)
     {
-      LOG_TRACE_FMT("Handling response for {}", request->url);
+      LOG_DEBUG_FMT("Handling response for {}", request->url);
       if (request->response_callback.has_value())
       {
         long status_code = 0;
@@ -533,7 +533,7 @@ namespace ccf::curl
       {
         throw std::logic_error("Cannot attach a null CurlRequest");
       }
-      LOG_TRACE_FMT("Attaching CurlRequest to {} to Curlm", request->get_url());
+      LOG_DEBUG_FMT("Attaching CurlRequest to {} to Curlm", request->get_url());
       CURL* curl_handle = request->get_easy_handle();
       CHECK_CURL_EASY_SETOPT(curl_handle, CURLOPT_PRIVATE, request.release());
       CHECK_CURL_MULTI(curl_multi_add_handle, p.get(), curl_handle);
@@ -642,7 +642,7 @@ namespace ccf::curl
         return;
       }
 
-      LOG_TRACE_FMT("Libuv: processing pending curl requests");
+      LOG_DEBUG_FMT("Libuv: processing pending curl requests");
 
       std::deque<std::unique_ptr<CurlRequest>> requests_to_add;
       {
@@ -672,7 +672,7 @@ namespace ccf::curl
         return;
       }
 
-      LOG_TRACE_FMT("Libuv timeout");
+      LOG_DEBUG_FMT("Libuv timeout");
 
       int running_handles = 0;
       CHECK_CURL_MULTI(
@@ -700,7 +700,7 @@ namespace ccf::curl
         return 0;
       }
 
-      LOG_TRACE_FMT("Curl timeout {}ms", timeout_ms);
+      LOG_DEBUG_FMT("Curl timeout {}ms", timeout_ms);
 
       if (timeout_ms < 0)
       {
@@ -721,12 +721,6 @@ namespace ccf::curl
     static void libuv_socket_poll_callback(
       uv_poll_t* req, int status, int events)
     {
-      if (status < 0)
-      {
-        LOG_FAIL_FMT("Socket poll error: {}", uv_strerror(status));
-        return;
-      }
-
       auto* socket_context = static_cast<SocketContextImpl*>(req->data);
       if (socket_context == nullptr)
       {
@@ -743,11 +737,45 @@ namespace ccf::curl
 
       if (self->is_stopping)
       {
-        LOG_FAIL_FMT("libuv_socket_poll_callback called while stopping");
+        LOG_FAIL_FMT(
+          "libuv_socket_poll_callback called on {} while stopped",
+          socket_context->socket);
+        return;
+      }
+
+      if (status < 0)
+      {
+        if (status == UV_EBADF)
+        {
+          // Thrown when POLLERR is thrown by the epoll socket, such as when a
+          // TCP socket received a reset at a bad time
+          // https://docs.libuv.org/en/v1.x/poll.html#c.uv_poll_start
+          // https://github.com/libuv/libuv/issues/3796
+          LOG_INFO_FMT(
+            "Socket poll error on {}: {}",
+            socket_context->socket,
+            uv_strerror(status));
+        }
+        else
+        {
+          LOG_FAIL_FMT(
+            "Socket poll error on {}: {}",
+            socket_context->socket,
+            uv_strerror(status));
+        }
+
+        // Notify curl of the error
+        CHECK_CURL_MULTI(
+          curl_multi_socket_action,
+          self->curl_request_curlm,
+          socket_context->socket,
+          CURL_CSELECT_ERR,
+          nullptr);
+        self->curl_request_curlm.perform();
         return;
       }
 
-      LOG_TRACE_FMT(
+      LOG_DEBUG_FMT(
         "Libuv socket poll callback on {}: {}",
         static_cast<int>(socket_context->socket),
         static_cast<int>(events));
@@ -786,15 +814,17 @@ namespace ccf::curl
         case CURL_POLL_OUT:
         case CURL_POLL_INOUT:
         {
-          // Possibly called during shutdown
+          LOG_DEBUG_FMT(
+            "Curl socket callback: listen on socket {}, {}",
+            static_cast<int>(s),
+            static_cast<int>(action));
+
+          // During shutdown ignore requests to add new sockets
           if (self->is_stopping)
           {
-            LOG_FAIL_FMT("curl_socket_callback called while stopping");
             return 0;
           }
 
-          LOG_INFO_FMT(
-            "Curl socket callback: listen on socket {}", static_cast<int>(s));
           if (socket_context == nullptr)
           {
             auto socket_context_ptr = std::make_unique<SocketContextImpl>();
@@ -820,7 +850,7 @@ namespace ccf::curl
         case CURL_POLL_REMOVE:
           if (socket_context != nullptr)
           {
-            LOG_INFO_FMT(
+            LOG_DEBUG_FMT(
               "CurlmLibuv: curl socket callback: remove socket {}",
               static_cast<int>(s));
             SocketContext socket_context_ptr(socket_context);
@@ -872,7 +902,7 @@ namespace ccf::curl
         LOG_FAIL_FMT("CurlmLibuvContext already closed, cannot attach request");
         return;
       }
-      LOG_INFO_FMT("Adding request to {} to queue", request->get_url());
+      LOG_DEBUG_FMT("Adding request to {} to queue", request->get_url());
       std::lock_guard<std::mutex> requests_lock(requests_mutex);
       pending_requests.push_back(std::move(request));
       uv_async_send(&async_requests_handle);