diff --git a/include/boost/redis/impl/reader_fsm.ipp b/include/boost/redis/impl/reader_fsm.ipp index 5c1539eb..f04dff4d 100644 --- a/include/boost/redis/impl/reader_fsm.ipp +++ b/include/boost/redis/impl/reader_fsm.ipp @@ -29,7 +29,7 @@ reader_fsm::action reader_fsm::resume( // Prepare the buffer for the read operation ec = st.mpx.prepare_read(); if (ec) { - log_debug(st.logger, "Reader task: error in prepare_read: ", ec); + log_err(st.logger, "Error preparing the read buffer: ", ec); return {ec}; } @@ -53,10 +53,9 @@ reader_fsm::action reader_fsm::resume( } // Log what we read + log_debug(st.logger, "Reader task: ", bytes_read, " bytes read"); if (ec) { - log_debug(st.logger, "Reader task: ", bytes_read, " bytes read, error: ", ec); - } else { - log_debug(st.logger, "Reader task: ", bytes_read, " bytes read"); + log_err(st.logger, "Error reading data from the server: ", ec); } // Process the bytes read, even if there was an error @@ -77,7 +76,12 @@ reader_fsm::action reader_fsm::resume( if (ec) { // TODO: Perhaps log what has not been consumed to aid // debugging. - log_debug(st.logger, "Reader task: error processing message: ", ec); + if (ec == error::resp3_hello) { + // This is already logged in the setup adapter + log_debug(st.logger, "Error processing message: setup request error"); + } else { + log_err(st.logger, "Error processing message: ", ec); + } return ec; } @@ -94,9 +98,10 @@ reader_fsm::action reader_fsm::resume( return system::error_code(asio::error::operation_aborted); } - // Check for other errors + // Check for other errors. + // We should't get any in the real world, but just in case. if (ec) { - log_debug(st.logger, "Reader task: error notifying push receiver: ", ec); + log_err(st.logger, "Error notifying push receiver: ", ec); return ec; } } else { diff --git a/include/boost/redis/impl/run_fsm.ipp b/include/boost/redis/impl/run_fsm.ipp index d477d549..8315665e 100644 --- a/include/boost/redis/impl/run_fsm.ipp +++ b/include/boost/redis/impl/run_fsm.ipp @@ -50,10 +50,12 @@ inline void on_setup_done(const multiplexer::elem& elm, connection_state& st) { const auto ec = elm.get_error(); if (ec) { - if (st.diagnostic.empty()) { - log_info(st.logger, "Setup request execution: ", ec); + if (ec == error::resp3_hello) { + // This is the most common case, and the only one that generates a string diagnostic + log_err(st.logger, "Setup request execution failed: ", st.diagnostic); } else { - log_info(st.logger, "Setup request execution: ", ec, " (", st.diagnostic, ")"); + // Something else went wrong (e.g. network error while running the request). + log_err(st.logger, "Setup request execution failed: ", ec); } } else { log_info(st.logger, "Setup request execution: success"); @@ -144,7 +146,7 @@ run_action run_fsm::resume( if (ec) { // There was an error. Skip to the reconnection loop - log_info( + log_err( st.logger, "Failed to connect to Redis server at ", get_server_address(st), diff --git a/include/boost/redis/impl/writer_fsm.ipp b/include/boost/redis/impl/writer_fsm.ipp index f4d3f779..460f21c6 100644 --- a/include/boost/redis/impl/writer_fsm.ipp +++ b/include/boost/redis/impl/writer_fsm.ipp @@ -14,6 +14,7 @@ #include #include #include +#include #include #include #include @@ -39,7 +40,7 @@ inline void process_ping_node( } if (ec) { - log_info(lgr, "Health checker: server answered ping with an error: ", nd.value); + log_err(lgr, "Health checker: server answered ping with an error: ", nd.value); } } @@ -89,7 +90,7 @@ writer_action writer_fsm::resume( if (ec == asio::error::operation_aborted) { log_debug(st.logger, "Writer task: cancelled (1)."); } else { - log_debug(st.logger, "Writer task error: ", ec); + log_err(st.logger, "Error writing data to the server: ", ec); } return ec; } diff --git a/test/test_reader_fsm.cpp b/test/test_reader_fsm.cpp index 75664aee..b5cc60c0 100644 --- a/test/test_reader_fsm.cpp +++ b/test/test_reader_fsm.cpp @@ -7,9 +7,12 @@ #include #include +#include #include #include #include +#include +#include #include #include @@ -19,20 +22,17 @@ #include "sansio_utils.hpp" #include +#include #include +using namespace boost::redis; namespace net = boost::asio; -namespace redis = boost::redis; using boost::system::error_code; using net::cancellation_type_t; -using redis::detail::reader_fsm; -using redis::detail::multiplexer; -using redis::generic_response; -using redis::any_adapter; -using redis::config; -using redis::detail::connection_state; -using action = redis::detail::reader_fsm::action; -using redis::logger; +using detail::reader_fsm; +using detail::multiplexer; +using detail::connection_state; +using action = detail::reader_fsm::action; using namespace std::chrono_literals; // Operators @@ -95,7 +95,7 @@ void copy_to(multiplexer& mpx, std::string_view data) std::copy(data.cbegin(), data.cend(), buffer.begin()); } -struct fixture : redis::detail::log_fixture { +struct fixture : detail::log_fixture { connection_state st{{make_logger()}}; generic_response resp; @@ -246,14 +246,15 @@ void test_read_error() copy_to(fix.st.mpx, payload); // Deliver the data - act = fsm.resume(fix.st, payload.size(), {redis::error::empty_field}, cancellation_type_t::none); - BOOST_TEST_EQ(act, error_code{redis::error::empty_field}); + act = fsm.resume(fix.st, payload.size(), {error::empty_field}, cancellation_type_t::none); + BOOST_TEST_EQ(act, error_code{error::empty_field}); // Check logging fix.check_log({ // clang-format off - {logger::level::debug, "Reader task: issuing read" }, - {logger::level::debug, "Reader task: 11 bytes read, error: Expected field value is empty. [boost.redis:5]"}, + {logger::level::debug, "Reader task: issuing read" }, + {logger::level::debug, "Reader task: 11 bytes read" }, + {logger::level::err, "Error reading data from the server: Expected field value is empty. [boost.redis:5]"}, // clang-format on }); } @@ -270,13 +271,14 @@ void test_read_timeout() // Timeout act = fsm.resume(fix.st, 0, {net::error::operation_aborted}, cancellation_type_t::none); - BOOST_TEST_EQ(act, error_code{redis::error::pong_timeout}); + BOOST_TEST_EQ(act, error_code{error::pong_timeout}); // Check logging fix.check_log({ // clang-format off - {logger::level::debug, "Reader task: issuing read" }, - {logger::level::debug, "Reader task: 0 bytes read, error: Pong timeout. [boost.redis:19]"}, + {logger::level::debug, "Reader task: issuing read" }, + {logger::level::debug, "Reader task: 0 bytes read" }, + {logger::level::err, "Error reading data from the server: Pong timeout. [boost.redis:19]"}, // clang-format on }); } @@ -296,18 +298,60 @@ void test_parse_error() // Deliver the data act = fsm.resume(fix.st, payload.size(), {}, cancellation_type_t::none); - BOOST_TEST_EQ(act, error_code{redis::error::not_a_number}); + BOOST_TEST_EQ(act, error_code{error::not_a_number}); // Check logging fix.check_log({ {logger::level::debug, "Reader task: issuing read"}, {logger::level::debug, "Reader task: 4 bytes read"}, - {logger::level::debug, - "Reader task: error processing message: Can't convert string to number (maybe forgot to " + {logger::level::err, + "Error processing message: Can't convert string to number (maybe forgot to " "upgrade to RESP3?). [boost.redis:2]" }, }); } +// A setup request error is similar to a parse error. +// The adapter would return error::resp3_hello. +// We log this somewhere else, so it shouldn't be logged here by default. +void test_setup_request_error() +{ + // Setup + fixture fix; + reader_fsm fsm; + request req; + req.push("PING"); // should have 1 command + auto elem = std::make_shared( + req, + any_adapter{[](any_adapter::parse_event, const resp3::node_view&, error_code& ec) { + ec = error::resp3_hello; + }}); + elem->set_done_callback([] { }); + + // Add the request to the multiplexer and simulate a successful write + fix.st.mpx.add(elem); + BOOST_TEST_EQ(fix.st.mpx.prepare_write(), 1u); + BOOST_TEST(fix.st.mpx.commit_write(fix.st.mpx.get_write_buffer().size())); + + // Initiate + auto act = fsm.resume(fix.st, 0, error_code(), cancellation_type_t::none); + BOOST_TEST_EQ(act, action::read_some(6s)); + + // The fsm is asking for data. + std::string const payload = "-ERR: bad\r\n"; + copy_to(fix.st.mpx, payload); + + // Deliver the data + act = fsm.resume(fix.st, payload.size(), {}, cancellation_type_t::none); + BOOST_TEST_EQ(act, error_code{error::resp3_hello}); + + // Check logging + fix.check_log({ + {logger::level::debug, "Reader task: issuing read" }, + {logger::level::debug, "Reader task: 11 bytes read" }, + {logger::level::debug, "Error processing message: setup request error"}, + }); +} + void test_push_deliver_error() { fixture fix; @@ -326,15 +370,15 @@ void test_push_deliver_error() BOOST_TEST_EQ(act, action::notify_push_receiver(11u)); // Resumes from notifying a push with an error. - act = fsm.resume(fix.st, 0, redis::error::empty_field, cancellation_type_t::none); - BOOST_TEST_EQ(act, error_code{redis::error::empty_field}); + act = fsm.resume(fix.st, 0, error::empty_field, cancellation_type_t::none); + BOOST_TEST_EQ(act, error_code{error::empty_field}); // Check logging fix.check_log({ // clang-format off {logger::level::debug, "Reader task: issuing read" }, {logger::level::debug, "Reader task: 11 bytes read" }, - {logger::level::debug, "Reader task: error notifying push receiver: Expected field value is empty. [boost.redis:5]"}, + {logger::level::err, "Error notifying push receiver: Expected field value is empty. [boost.redis:5]"}, // clang-format on }); } @@ -355,15 +399,15 @@ void test_max_read_buffer_size() std::string const part1 = ">3\r\n"; copy_to(fix.st.mpx, part1); act = fsm.resume(fix.st, part1.size(), error_code(), cancellation_type_t::none); - BOOST_TEST_EQ(act, error_code(redis::error::exceeds_maximum_read_buffer_size)); + BOOST_TEST_EQ(act, error_code(error::exceeds_maximum_read_buffer_size)); // Check logging fix.check_log({ {logger::level::debug, "Reader task: issuing read" }, {logger::level::debug, "Reader task: 4 bytes read" }, {logger::level::debug, "Reader task: incomplete message received"}, - {logger::level::debug, - "Reader task: error in prepare_read: Reading data from the socket would exceed the maximum " + {logger::level::err, + "Error preparing the read buffer: Reading data from the socket would exceed the maximum " "size allowed of the read buffer. [boost.redis:26]" }, }); } @@ -494,6 +538,7 @@ int main() test_read_error(); test_read_timeout(); test_parse_error(); + test_setup_request_error(); test_push_deliver_error(); test_max_read_buffer_size(); diff --git a/test/test_run_fsm.cpp b/test/test_run_fsm.cpp index 53f413f6..25558fd5 100644 --- a/test/test_run_fsm.cpp +++ b/test/test_run_fsm.cpp @@ -191,7 +191,7 @@ void test_connect_error() fix.check_log({ // clang-format off {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)" }, - {logger::level::info, "Failed to connect to Redis server at 127.0.0.1:6379 (TLS disabled): Connect timeout. [boost.redis:18]"}, + {logger::level::err, "Failed to connect to Redis server at 127.0.0.1:6379 (TLS disabled): Connect timeout. [boost.redis:18]"}, {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)" }, {logger::level::info, "Connected to Redis server at 127.0.0.1:6379 (TLS disabled)" }, // clang-format on @@ -224,7 +224,7 @@ void test_connect_error_ssl() fix.check_log({ // clang-format off {logger::level::info, "Trying to connect to Redis server at my_hostname:10000 (TLS enabled)" }, - {logger::level::info, "Failed to connect to Redis server at my_hostname:10000 (TLS enabled): Connect timeout. [boost.redis:18]"}, + {logger::level::err, "Failed to connect to Redis server at my_hostname:10000 (TLS enabled): Connect timeout. [boost.redis:18]"}, {logger::level::info, "Trying to connect to Redis server at my_hostname:10000 (TLS enabled)" }, {logger::level::info, "Connected to Redis server at my_hostname:10000 (TLS enabled)" }, // clang-format on @@ -256,7 +256,7 @@ void test_connect_error_unix() fix.check_log({ // clang-format off {logger::level::info, "Trying to connect to Redis server at '/tmp/sock'" }, - {logger::level::info, "Failed to connect to Redis server at '/tmp/sock': Connect timeout. [boost.redis:18]"}, + {logger::level::err, "Failed to connect to Redis server at '/tmp/sock': Connect timeout. [boost.redis:18]"}, {logger::level::info, "Trying to connect to Redis server at '/tmp/sock'" }, {logger::level::info, "Connected to Redis server at '/tmp/sock'" }, // clang-format on @@ -282,7 +282,7 @@ void test_connect_error_no_reconnect() fix.check_log({ // clang-format off {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)" }, - {logger::level::info, "Failed to connect to Redis server at 127.0.0.1:6379 (TLS disabled): Connect timeout. [boost.redis:18]"}, + {logger::level::err, "Failed to connect to Redis server at 127.0.0.1:6379 (TLS disabled): Connect timeout. [boost.redis:18]"}, // clang-format on }); } @@ -533,10 +533,10 @@ void test_several_reconnections() // Log fix.check_log({ // clang-format off - {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)" }, - {logger::level::info, "Failed to connect to Redis server at 127.0.0.1:6379 (TLS disabled): Connect timeout. [boost.redis:18]"}, - {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)" }, - {logger::level::info, "Connected to Redis server at 127.0.0.1:6379 (TLS disabled)" }, + {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)" }, + {logger::level::err, "Failed to connect to Redis server at 127.0.0.1:6379 (TLS disabled): Connect timeout. [boost.redis:18]"}, + {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)" }, + {logger::level::info, "Connected to Redis server at 127.0.0.1:6379 (TLS disabled)" }, {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)"}, {logger::level::info, "Connected to Redis server at 127.0.0.1:6379 (TLS disabled)" }, {logger::level::debug, "Run: cancelled (2)" } // clang-format on @@ -672,9 +672,51 @@ void test_setup_request_server_error() fix.check_log({ {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)"}, {logger::level::info, "Connected to Redis server at 127.0.0.1:6379 (TLS disabled)" }, - {logger::level::info, - "Setup request execution: The server response to the setup request sent during connection " - "establishment contains an error. [boost.redis:23] (ERR: wrong command)" } + {logger::level::err, "Setup request execution failed: ERR: wrong command" } + }); +} + +// If the setup request finishes with another error (e.g. network error), we log it +void test_setup_request_other_error() +{ + // Setup + fixture fix; + fix.st.diagnostic = "leftover"; // simulate a leftover from previous runs + fix.st.cfg.setup.clear(); + fix.st.cfg.setup.push("HELLO", 3); + fix.st.cfg.reconnect_wait_interval = 0s; + + // Run the operation. We connect and launch the tasks + auto act = fix.fsm.resume(fix.st, error_code(), cancellation_type_t::none); + BOOST_TEST_EQ(act, run_action_type::connect); + act = fix.fsm.resume(fix.st, error_code(), cancellation_type_t::none); + BOOST_TEST_EQ(act, run_action_type::parallel_group); + + // At this point, the setup request should be already queued. + // Simulate the writer + BOOST_TEST_EQ(fix.st.mpx.prepare_write(), 1u); + BOOST_TEST(fix.st.mpx.commit_write(fix.st.mpx.get_write_buffer().size())); + + // Simulate a read error + read(fix.st.mpx, "*malformed\r\n"); + error_code ec; + auto res = fix.st.mpx.consume(ec); + BOOST_TEST_EQ(ec, error::not_a_number); + BOOST_TEST(res.first == detail::consume_result::got_response); + + // This will cause the writer to exit + act = fix.fsm.resume(fix.st, error::not_a_number, cancellation_type_t::none); + BOOST_TEST_EQ(act, run_action_type::cancel_receive); + act = fix.fsm.resume(fix.st, error_code(), cancellation_type_t::none); + BOOST_TEST_EQ(act, error_code(error::not_a_number)); + + // Check log + fix.check_log({ + // clang-format off + {logger::level::info, "Trying to connect to Redis server at 127.0.0.1:6379 (TLS disabled)"}, + {logger::level::info, "Connected to Redis server at 127.0.0.1:6379 (TLS disabled)" }, + {logger::level::err, "Setup request execution failed: Can't convert string to number (maybe forgot to upgrade to RESP3?). [boost.redis:2]" }, + // clang-format on }); } @@ -733,7 +775,7 @@ void test_sentinel_reconnection() fix.check_log({ // clang-format off {logger::level::info, "Trying to connect to Redis server at host1:1000 (TLS disabled)"}, - {logger::level::info, "Failed to connect to Redis server at host1:1000 (TLS disabled): Connect timeout. [boost.redis:18]"}, + {logger::level::err, "Failed to connect to Redis server at host1:1000 (TLS disabled): Connect timeout. [boost.redis:18]"}, {logger::level::info, "Trying to connect to Redis server at host2:2000 (TLS disabled)"}, {logger::level::info, "Connected to Redis server at host2:2000 (TLS disabled)"}, {logger::level::info, "Setup request execution: success"}, @@ -847,6 +889,7 @@ int main() test_setup_request_success(); test_setup_request_empty(); test_setup_request_server_error(); + test_setup_request_other_error(); test_sentinel_reconnection(); test_sentinel_resolve_error(); diff --git a/test/test_writer_fsm.cpp b/test/test_writer_fsm.cpp index da7f185d..0c151a3f 100644 --- a/test/test_writer_fsm.cpp +++ b/test/test_writer_fsm.cpp @@ -366,7 +366,7 @@ void test_ping_error() // Logs fix.check_log({ {logger::level::debug, "Writer task: 28 bytes written." }, - {logger::level::info, "Health checker: server answered ping with an error: ERR: bad command"}, + {logger::level::err, "Health checker: server answered ping with an error: ERR: bad command"}, }); } @@ -394,8 +394,9 @@ void test_write_error() // Logs fix.check_log({ - {logger::level::debug, "Writer task: 2 bytes written." }, - {logger::level::debug, "Writer task error: Expected field value is empty. [boost.redis:5]"}, + {logger::level::debug, "Writer task: 2 bytes written." }, + {logger::level::err, + "Error writing data to the server: Expected field value is empty. [boost.redis:5]"}, }); } @@ -420,9 +421,10 @@ void test_write_timeout() // Logs fix.check_log({ - {logger::level::debug, "Writer task: 0 bytes written." }, - {logger::level::debug, - "Writer task error: Timeout while writing data to the server. [boost.redis:27]"}, + // clang-format off + {logger::level::debug, "Writer task: 0 bytes written."}, + {logger::level::err, "Error writing data to the server: Timeout while writing data to the server. [boost.redis:27]" }, + // clang-format on }); }