diff --git a/src/web/connections/base.cpp b/src/web/connections/base.cpp index e647aa2..8f70ae7 100644 --- a/src/web/connections/base.cpp +++ b/src/web/connections/base.cpp @@ -12,8 +12,10 @@ Connection::Connection(const std::string& url, CURL* curl_handle) : curl_error_buffer_(CURL_ERROR_SIZE, '\0'), url_(utils::normalize_url(url)) { + // Populate backtrace log_bt(web, "Initialize conn object and curl handle for {}", url_); + // Check that curl handle is valid if (!curl_handle_) [[unlikely]] { throw std::runtime_error( "Could not create cURL handle, or null handle provided." @@ -89,6 +91,7 @@ Connection::debug_log_callback_( } if (logging::get_libcurl_logger()->should_log()) + [[unlikely]] log_t3(libcurl, "Hexdump\n{}", utils::hexdump(raw_data, size)); return 0; diff --git a/src/web/connections/ws.cpp b/src/web/connections/ws.cpp index 9ed77d7..5b041c4 100644 --- a/src/web/connections/ws.cpp +++ b/src/web/connections/ws.cpp @@ -26,32 +26,41 @@ WebSocketConnection::write_callback_( // Get our frame const auto* frame = curl_ws_meta(conn->curl_handle()); - assert(frame); - // Log information - log_t1( + if (!frame) [[unlikely]] { + log_c( + web, + "In WebSocket write callback for {} but got NULL frame, aborting!", + conn->url() + ); + abort(); + } + + // Populate backtrace + log_bt( web, - "WebSocket data callback ran for {} ({} bytes, {} left)", + "WS write callback for url {} with buf of len {} ({}x{}), {} bytes left", conn->url(), size, + elem_size, + length, frame->bytesleft ); - if (logging::get_web_logger()->should_log()) - log_t3(web, "Data hexdump\n{}", utils::hexdump(buf, length)); - - log_bt( + // Log information + log_t1( web, - "WS write callback for url {} with buf of len {} ({}x{}), {} bytes left", + "WebSocket data callback ran for {} ({} bytes, {} left)", conn->url(), size, - elem_size, - length, frame->bytesleft ); + if (logging::get_web_logger()->should_log()) [[unlikely]] + log_t3(web, "Data hexdump\n{}", utils::hexdump(buf, length)); + // Make sure this connection isn't closed - if (!conn->open()) { + if (!conn->open()) [[unlikely]] { log_w(web, "Write callback for {} called after close().", conn->url()); return size; // piped bytes to /dev/null @@ -61,7 +70,7 @@ WebSocketConnection::write_callback_( // NOLINTNEXTLINE(*-pointer-arithmetic) conn->write_buf_.insert(conn->write_buf_.end(), buf, buf + size); - if (frame->bytesleft == 0) { // got all data in frame + if (frame->bytesleft == 0) [[likely]] { // got all data in frame; most are short // log some data log_bt(web, "Entering user data callback for {}", conn->url()); log_d( @@ -94,7 +103,8 @@ WebSocketConnection::start_() assert(ready()); assert(!open()); - log_d(web, "Starting web socket connection to {}", url()); + // Populate backtrace + log_bt(web, "Setting up WS connection to {}", url()); // Clear error buffer clear_error_buffer_(); @@ -107,8 +117,8 @@ WebSocketConnection::start_() curl_easy_setopt(curl_handle(), CURLOPT_WRITEDATA, this); // Mark the websocket as open - log_bt(web, "Set up WS connection to {}", url()); open() = true; + log_d(web, "Set up web socket connection to {}", url()); } size_t @@ -116,9 +126,7 @@ WebSocketConnection::close(WebSocketCloseStatus status, std::vector dat { assert(ready()); - log_i(web, "Closing WebSocket connection to {} with code {}", url(), status); - log_t2(web, "Data: {}", data); - + // Backtrace log log_bt( web, "Send WS close message to {} with status {} and data {}", @@ -127,6 +135,17 @@ WebSocketConnection::close(WebSocketCloseStatus status, std::vector dat data ); + // Log about arguments + log_i(web, "Closing WebSocket connection to {} with code {}", url(), status); + log_d(web, "{} bytes of data provided", data.size()); + + if ( // + !data.empty() + && logging::get_web_logger()->should_log() + ) [[unlikely]] { + log_t2(web, "Data hexdump\n{}", utils::hexdump(data)); + } + // Make sure we're not already closed if (!open()) { log_w( @@ -167,11 +186,7 @@ WebSocketConnection::send(std::vector data, unsigned flags) { assert(ready()); - log_t1(web, "Sending {} bytes to {} with flags {:#b}", data.size(), url(), flags); - - if (logging::get_web_logger()->should_log()) - log_t3(web, "Hexdump\n{}", utils::hexdump(data.data(), data.size())); - + // Populate backtrace log_bt( web, "Websocket send to {} with flags {:#b} and {} bytes: {}", @@ -181,6 +196,12 @@ WebSocketConnection::send(std::vector data, unsigned flags) data ); + // Log about arguments + log_t1(web, "Sending {} bytes to {} with flags {:#b}", data.size(), url(), flags); + + if (logging::get_web_logger()->should_log()) [[unlikely]] + log_t3(web, "Data hexdump\n{}", utils::hexdump(data.data(), data.size())); + // Clear error buffer clear_error_buffer_(); diff --git a/src/web/connections/ws.hpp b/src/web/connections/ws.hpp index 81a6b0c..f51adba 100644 --- a/src/web/connections/ws.hpp +++ b/src/web/connections/ws.hpp @@ -108,7 +108,7 @@ class WebSocketConnection : public Connection { /** * Create a new websocket connection. * - * Should only be called by the RequestManager. + * Should only be called by the Session. */ WebSocketConnection(const std::string& url, callback on_data) : Connection(url), on_data_(std::move(on_data)) diff --git a/src/web/session.cpp b/src/web/session.cpp index 8b9d9d4..6f73d86 100644 --- a/src/web/session.cpp +++ b/src/web/session.cpp @@ -19,6 +19,7 @@ namespace web { Session::Session(uv_loop_t* event_loop) : curl_handle_(curl_multi_init()), loop_(event_loop) { + // Populate backtrace log_bt(web, "Creating session for handle {}", fmt::ptr(curl_handle_)); // Set up callbacks @@ -113,13 +114,16 @@ Session::Session(uv_loop_t* event_loop) : void Session::process_libcurl_messages_() { + // Populate backtrace log_bt(web, "Start libcurl message processing"); + // Read messages CURLMsg* message{}; int remaining_messages{}; size_t current_message = 0; while ((message = curl_multi_info_read(curl_handle_, &remaining_messages))) { + // Print progress log_t1( web, "Processing libcurl message {}; {} remaining", @@ -162,7 +166,7 @@ Session::process_libcurl_messages_() // Log any errors auto err = message->data.result; // NOLINT(*-union-access) - if (err) { + if (err) [[unlikely]] { log_w(web, "Found errors in connection to {}", url); conn->process_curl_error_(err); } @@ -193,7 +197,7 @@ Session::process_libcurl_messages_() break; } - default: + [[unlikely]] default: log_w( web, "Received unknown message with ID {} from libcurl for {}", @@ -212,25 +216,31 @@ Session::process_libcurl_messages_() void Session::run_initializations_(uv_timer_t* handle) { - log_bt(web, "Running connection initializations"); + // Get session + auto* session = static_cast(handle->data); - // Get manager - auto* manager = static_cast(handle->data); + // Populate backtrace + log_bt( + web, + "Running {} connection initializations", + session->connections_to_init_.size() + ); // Run through initialization queue - auto& init_queue = manager->connections_to_init_; + auto& init_queue = session->connections_to_init_; while (!init_queue.empty()) { // Get our connection auto conn = std::move(init_queue.front()); init_queue.pop(); + // Log our progress log_bt(web, "Init connection to {}", conn->url()); log_i(web, "Opening connection to {}", conn->url()); // Add the connection to the curl multi handle - auto err = curl_multi_add_handle(manager->curl_handle_, conn->curl_handle_); - if (err) { + auto err = curl_multi_add_handle(session->curl_handle_, conn->curl_handle_); + if (err) [[unlikely]] { log_e( web, "Connection to {} failed: {} (Code {})", @@ -249,13 +259,14 @@ Session::run_initializations_(uv_timer_t* handle) conn->start_(); // Save it to our connection list - manager->connections_.push_back(std::move(conn)); + session->connections_.push_back(std::move(conn)); } } std::shared_ptr Session::ws(const std::string& url, WebSocketConnection::callback on_data) { + // Populate backtrace log_bt(web, "Create WS conn to {}", url); // Create the connection @@ -282,43 +293,47 @@ Session::ws(const std::string& url, WebSocketConnection::callback on_data) namespace detail { CURLM* -get_handle(Session* manager) +get_handle(Session* session) { - return manager->curl_handle_; + return session->curl_handle_; } void -process_libcurl_messages(Session* manager, int running_handles) +process_libcurl_messages(Session* session, int running_handles) { + // Populate backtrace and log updates log_bt(web, "libcurl message processing ran ({} running handles)", running_handles); log_d(web, "{} running handles", running_handles); // Process any libcurl messages // All this currently does is free the data for any closed sockets - manager->process_libcurl_messages_(); + session->process_libcurl_messages_(); // If there are no running handles, we're done // So exit the loop - if (running_handles == 0) - uv_stop(manager->loop_); + if (running_handles == 0) [[unlikely]] { // only happens once + log_i(web, "No running handles, stopping event loop"); + uv_stop(session->loop_); + } } /** * Struct linking a curl socket to a uv socket. */ struct curl_context_t { - uv_poll_t poll_handle; - curl_socket_t sock_fd; + uv_poll_t poll_handle; // libuv socket polling handle + curl_socket_t sock_fd; // socket to poll - Session* manager; + Session* session; // web request session }; /** * Create a new curl context. */ static curl_context_t* -create_curl_context(curl_socket_t sock_fd, uv_loop_t* loop, Session* manager) +create_curl_context(curl_socket_t sock_fd, uv_loop_t* loop, Session* session) { + // Populate backtrace log_bt(web, "Create curl ctx for socket {}", sock_fd); // Create our context @@ -331,8 +346,8 @@ create_curl_context(curl_socket_t sock_fd, uv_loop_t* loop, Session* manager) uv_poll_init_socket(loop, &ctx->poll_handle, sock_fd); ctx->poll_handle.data = ctx; - // Attach the request manager - ctx->manager = manager; + // Attach the request session + ctx->session = session; return ctx; } @@ -343,6 +358,7 @@ create_curl_context(curl_socket_t sock_fd, uv_loop_t* loop, Session* manager) static void destroy_curl_context(curl_context_t* ctx) { + // Populate backtrace log_bt(web, "Destroy curl ctx for socket {}", ctx->sock_fd); uv_close( @@ -378,6 +394,7 @@ on_poll(uv_poll_t* req, int status, int uv_events) if (events & UV_WRITABLE) flags |= CURL_CSELECT_OUT; + // Log the data that we have received log_t2( web, "Received data from libuv on socket {}: {}{}", @@ -389,14 +406,14 @@ on_poll(uv_poll_t* req, int status, int uv_events) // Report to curl int running_handles{}; curl_multi_socket_action( - get_handle(curl_ctx->manager), + get_handle(curl_ctx->session), curl_ctx->sock_fd, static_cast(flags), &running_handles ); // Log status - process_libcurl_messages(curl_ctx->manager, running_handles); + process_libcurl_messages(curl_ctx->session, running_handles); } } // namespace detail @@ -411,10 +428,12 @@ Session::handle_socket_( ) { UNUSED(easy); + + // Populate backtrace log_bt(web, "libcurl action {} on socket {}", action, sock_fd); - // Get our request manager - auto* manager = static_cast(user_ptr); + // Get our request session + auto* session = static_cast(user_ptr); // Get our socket context auto* curl_ctx = static_cast(socket_ptr); @@ -428,13 +447,13 @@ Session::handle_socket_( if (!curl_ctx) { curl_ctx = detail::create_curl_context( // sock_fd, - manager->loop_, - manager + session->loop_, + session ); } // Assign the context to this socket - curl_multi_assign(manager->curl_handle_, sock_fd, curl_ctx); + curl_multi_assign(session->curl_handle_, sock_fd, curl_ctx); // Get our libuv events uint32_t events = 0; @@ -460,6 +479,7 @@ Session::handle_socket_( break; } + case CURL_POLL_REMOVE: { log_t2(web, "Stop polling socket {}", sock_fd); @@ -472,15 +492,17 @@ Session::handle_socket_( destroy_curl_context(curl_ctx); // Clear the data in libcurl - curl_multi_assign(manager->curl_handle_, sock_fd, nullptr); + curl_multi_assign(session->curl_handle_, sock_fd, nullptr); } break; } - default: + + [[unlikely]] default: // Should never be here abort(); } + // No errors return 0; } @@ -492,15 +514,17 @@ Session::start_timeout_( // NOLINT(*-naming) ) { UNUSED(multi); + + // Populate backtrace log_bt(web, "Update libcurl timeout to {}ms", timeout_ms); - // Get our request manager - auto* manager = static_cast(user_ptr); + // Get our request session + auto* session = static_cast(user_ptr); // Process timer if (timeout_ms < 0) { // curl wants to stop the timer log_t2(web, "Stopping libcurl timeout"); - uv_timer_stop(&manager->timeout_); + uv_timer_stop(&session->timeout_); } else { // curl wants to create a new timer @@ -513,26 +537,27 @@ Session::start_timeout_( // NOLINT(*-naming) log_bt(web, "libcurl socket timeout ran"); log_t2(web, "libcurl socket timeout"); - // Get manager - auto* cb_manager = static_cast(timer->data); + // Get session + auto* cb_session = static_cast(timer->data); // Process the request int running_handles{}; curl_multi_socket_action( - cb_manager->curl_handle_, CURL_SOCKET_TIMEOUT, 0, &running_handles + cb_session->curl_handle_, CURL_SOCKET_TIMEOUT, 0, &running_handles ); // Log info - detail::process_libcurl_messages(cb_manager, running_handles); + detail::process_libcurl_messages(cb_session, running_handles); }; // Start our timer log_t2(web, "Starting libcurl timeout to run in {}ms", timeout_ms); uv_timer_start( - &manager->timeout_, on_timeout, static_cast(timeout_ms), 0 + &session->timeout_, on_timeout, static_cast(timeout_ms), 0 ); } + // No errors return 0; } diff --git a/src/web/session.hpp b/src/web/session.hpp index a0e2d10..f19c101 100644 --- a/src/web/session.hpp +++ b/src/web/session.hpp @@ -19,14 +19,14 @@ class Session; namespace detail { /** - * Friend function to access the handle of the request manager. + * Friend function to access the handle of the request session. */ -CURLM* get_handle(Session* manager); +CURLM* get_handle(Session* session); /** - * Friend function to access a private method of the request manager. + * Friend function to access a private method of the request session. */ -void process_libcurl_messages(Session* manager, int running_handles); +void process_libcurl_messages(Session* session, int running_handles); } // namespace detail @@ -36,7 +36,7 @@ void process_libcurl_messages(Session* manager, int running_handles); class Session { public: /** - * Status of the request manager. + * Status of the request session. */ enum Status { STATUS_OK = 0, @@ -70,7 +70,7 @@ class Session { public: /** - * Create a new request manager. + * Create a new session. */ explicit Session(uv_loop_t* event_loop = uv_default_loop()); @@ -128,9 +128,9 @@ class Session { } /* Friends */ - friend CURLM* detail::get_handle(Session* manager); + friend CURLM* detail::get_handle(Session* session); - friend void detail::process_libcurl_messages(Session* manager, int running_handles); + friend void detail::process_libcurl_messages(Session* session, int running_handles); private: static void run_initializations_(uv_timer_t* handle); // NOLINT(*-naming)