From d4bd548d61f5f7ab796149287400980cc77dbafe Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Mon, 10 Apr 2023 17:21:22 -0500 Subject: [PATCH] GH-678 Log all http request/response when debug log enabled --- plugins/http_plugin/http_plugin.cpp | 10 +++- .../eosio/http_plugin/beast_http_listener.hpp | 4 +- .../eosio/http_plugin/beast_http_session.hpp | 52 +++++++++++++++---- 3 files changed, 55 insertions(+), 11 deletions(-) diff --git a/plugins/http_plugin/http_plugin.cpp b/plugins/http_plugin/http_plugin.cpp index 8800ad7af8..b58a987f20 100644 --- a/plugins/http_plugin/http_plugin.cpp +++ b/plugins/http_plugin/http_plugin.cpp @@ -489,22 +489,30 @@ class http_plugin_impl : public std::enable_shared_from_this { my->plugin_state->url_handlers[url] = my->make_http_thread_url_handler(handler); } - void http_plugin::handle_exception( const char *api_name, const char *call_name, const string& body, const url_response_callback& cb) { + void http_plugin::handle_exception( const char* api_name, const char* call_name, const string& body, const url_response_callback& cb) { try { try { throw; } catch (chain::unknown_block_exception& e) { error_results results{400, "Unknown Block", error_results::error_info(e, verbose_http_errors)}; cb( 400, fc::time_point::maximum(), fc::variant( results )); + fc_dlog( logger(), "Unknown block while processing ${api}.${call}: ${e}", + ("api", api_name)("call", call_name)("e", e.to_detail_string()) ); } catch (chain::invalid_http_request& e) { error_results results{400, "Invalid Request", error_results::error_info(e, verbose_http_errors)}; cb( 400, fc::time_point::maximum(), fc::variant( results )); + fc_dlog( logger(), "Invalid http request while processing ${api}.${call}: ${e}", + ("api", api_name)("call", call_name)("e", e.to_detail_string()) ); } catch (chain::unsatisfied_authorization& e) { error_results results{401, "UnAuthorized", error_results::error_info(e, verbose_http_errors)}; cb( 401, fc::time_point::maximum(), fc::variant( results )); + fc_dlog( logger(), "Auth error while processing ${api}.${call}: ${e}", + ("api", api_name)("call", call_name)("e", e.to_detail_string()) ); } catch (chain::tx_duplicate& e) { error_results results{409, "Conflict", error_results::error_info(e, verbose_http_errors)}; cb( 409, fc::time_point::maximum(), fc::variant( results )); + fc_dlog( logger(), "Duplicate trx while processing ${api}.${call}: ${e}", + ("api", api_name)("call", call_name)("e", e.to_detail_string()) ); } catch (fc::eof_exception& e) { error_results results{422, "Unprocessable Entity", error_results::error_info(e, verbose_http_errors)}; cb( 422, fc::time_point::maximum(), fc::variant( results )); diff --git a/plugins/http_plugin/include/eosio/http_plugin/beast_http_listener.hpp b/plugins/http_plugin/include/eosio/http_plugin/beast_http_listener.hpp index 004dee7392..8a0e878954 100644 --- a/plugins/http_plugin/include/eosio/http_plugin/beast_http_listener.hpp +++ b/plugins/http_plugin/include/eosio/http_plugin/beast_http_listener.hpp @@ -110,9 +110,11 @@ class beast_http_listener : public std::enable_shared_from_thisplugin_state_->logger, "closing connection"); } else { // Create the session object and run it + std::string remote_endpoint = boost::lexical_cast(self->socket_.remote_endpoint()); std::make_shared( std::move(self->socket_), - self->plugin_state_) + self->plugin_state_, + std::move(remote_endpoint)) ->run_session(); } diff --git a/plugins/http_plugin/include/eosio/http_plugin/beast_http_session.hpp b/plugins/http_plugin/include/eosio/http_plugin/beast_http_session.hpp index 78dc2b0ffe..4dccb8f081 100644 --- a/plugins/http_plugin/include/eosio/http_plugin/beast_http_session.hpp +++ b/plugins/http_plugin/include/eosio/http_plugin/beast_http_session.hpp @@ -3,6 +3,9 @@ #include #include +#include +#include + #include #include @@ -75,6 +78,26 @@ bool allow_host(const http::request& req, T& session, return true; } +// T can be request or response or anything serializable to boost iostreams +template +std::string to_log_string(const T& req, size_t max_size = 1024) { + assert( max_size > 4 ); + std::string buffer( max_size, '\0' ); + { + boost::iostreams::array_sink sink( buffer.data(), buffer.size() ); + boost::iostreams::stream stream( sink ); + stream << req; + } + buffer.resize( std::strlen( buffer.data() ) ); + if( buffer.size() == max_size ) { + buffer[max_size - 3] = '.'; + buffer[max_size - 2] = '.'; + buffer[max_size - 1] = '.'; + } + std::replace_if( buffer.begin(), buffer.end(), []( unsigned char c ) { return c == '\r' || c == '\n'; }, ' ' ); + return buffer; +} + // Handle HTTP conneciton using boost::beast for TCP communication // Subclasses of this class (plain_session, ssl_session, etc.) // use the Curiously Recurring Template Pattern so that @@ -95,6 +118,7 @@ class beast_http_session : public detail::abstract_conn { std::optional> res_; std::shared_ptr plugin_state_; + std::string remote_endpoint_; // whether response should be sent back to client when an exception occurs bool is_send_exception_response_ = true; @@ -143,6 +167,9 @@ class beast_http_session : public detail::abstract_conn { // verfiy bytes in flight/requests in flight if(!verify_max_bytes_in_flight()) return; + fc_dlog( plugin_state_->logger, "Request: ${ep} ${r}", + ("ep", remote_endpoint_)("r", to_log_string(req)) ); + std::string resource = std::string(req.target()); // look for the URL handler to handle this resource auto handler_itr = plugin_state_->url_handlers.find(resource); @@ -211,9 +238,9 @@ class beast_http_session : public detail::abstract_conn { // shared_from_this() requires default constructor beast_http_session() = default; - beast_http_session( - std::shared_ptr plugin_state) - : plugin_state_(std::move(plugin_state)) { + beast_http_session(std::shared_ptr plugin_state, std::string remote_endpoint) + : plugin_state_(std::move(plugin_state)), + remote_endpoint_(std::move(remote_endpoint)) { plugin_state_->requests_in_flight += 1; req_parser_.emplace(); req_parser_->body_limit(plugin_state_->max_body_size); @@ -368,6 +395,9 @@ class beast_http_session : public detail::abstract_conn { // Determine if we should close the connection after bool close = !(plugin_state_->keep_alive) || res_->need_eof(); + fc_dlog( plugin_state_->logger, "Response: ${ep} ${b}", + ("ep", remote_endpoint_)("b", to_log_string(*res_)) ); + // Write the response auto self = derived().shared_from_this(); http::async_write( @@ -396,8 +426,9 @@ class plain_session // Create the session plain_session( tcp_socket_t socket, - std::shared_ptr plugin_state) - : beast_http_session(std::move(plugin_state)), socket_(std::move(socket)) {} + std::shared_ptr plugin_state, + std::string remote_endpoint) + : beast_http_session(std::move(plugin_state), std::move(remote_endpoint)), socket_(std::move(socket)) {} tcp_socket_t& stream() { return socket_; } tcp_socket_t& socket() { return socket_; } @@ -441,8 +472,10 @@ class ssl_session ssl_session( tcp_socket_t socket, - std::shared_ptr plugin_state) - : beast_http_session(std::move(plugin_state)), stream_(std::move(socket), *plugin_state_->ctx) {} + std::shared_ptr plugin_state, + std::string remote_endpoint) + : beast_http_session(std::move(plugin_state), std::move(remote_endpoint)), + stream_(std::move(socket), *plugin_state_->ctx) {} ssl::stream& stream() { return stream_; } @@ -508,8 +541,9 @@ class unix_socket_session public: unix_socket_session(stream_protocol::socket sock, - std::shared_ptr plugin_state) - : beast_http_session(std::move(plugin_state)), socket_(std::move(sock)) {} + std::shared_ptr plugin_state, + std::string remote_endpoint) + : beast_http_session(std::move(plugin_state), std::move(remote_endpoint)), socket_(std::move(sock)) {} virtual ~unix_socket_session() = default;