From 25ca4f6aaadbf01f5b51b6b6dc69daa72d351777 Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Mon, 13 May 2019 16:44:01 +0200 Subject: [PATCH 1/7] [#599,!320] Fixed Kea HTTP client crash as a result of premature timeout --- src/lib/http/client.cc | 126 +++++++++++++++++++++++++++-------------- 1 file changed, 85 insertions(+), 41 deletions(-) diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc index b1474fb4e7..c45f1fd435 100644 --- a/src/lib/http/client.cc +++ b/src/lib/http/client.cc @@ -136,6 +136,19 @@ public: /// @return true if transaction has been initiated, false otherwise. bool isTransactionOngoing() const; + /// @brief Checks and logs if premature transaction timeout is suspected. + /// + /// There are cases when the premature timeout occurs, e.g. as a result of + /// moving system clock, during the transaction. In such case, the + /// @c terminate function is called which resets the transaction state but + /// the transaction handlers may be already waiting for the execution. + /// Each such handler should call this function to check if the transaction + /// it is participating in is still alive. If it is not, it should simply + /// return. This method also logs such situation. + /// + /// @return true if the premature timeout is suspected, false otherwise. + bool checkPrematureTimeout() const; + private: /// @brief Resets the state of the object. @@ -519,62 +532,72 @@ Connection::isTransactionOngoing() const { return (static_cast(current_request_)); } +bool +Connection::checkPrematureTimeout() const { + if (!isTransactionOngoing()) { + return (true); + } + return (false); +} + void Connection::terminate(const boost::system::error_code& ec, const std::string& parsing_error) { - timer_.cancel(); - socket_.cancel(); - HttpResponsePtr response; - if (!ec && current_response_->isFinalized()) { - response = current_response_; + if (isTransactionOngoing()) { - LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC, - HTTP_SERVER_RESPONSE_RECEIVED) - .arg(url_.toText()); + timer_.cancel(); + socket_.cancel(); - LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA, - HTTP_SERVER_RESPONSE_RECEIVED_DETAILS) - .arg(url_.toText()) - .arg(parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE)); + if (!ec && current_response_->isFinalized()) { + response = current_response_; - } else { - std::string err = parsing_error.empty() ? ec.message() : parsing_error; - - LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC, - HTTP_BAD_SERVER_RESPONSE_RECEIVED) - .arg(url_.toText()) - .arg(err); + LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC, + HTTP_SERVER_RESPONSE_RECEIVED) + .arg(url_.toText()); - // Only log the details if we have received anything and tried - // to parse it. - if (!parsing_error.empty()) { LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA, - HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS) + HTTP_SERVER_RESPONSE_RECEIVED_DETAILS) + .arg(url_.toText()) + .arg(parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE)); + + } else { + std::string err = parsing_error.empty() ? ec.message() : parsing_error; + + LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC, + HTTP_BAD_SERVER_RESPONSE_RECEIVED) .arg(url_.toText()) - .arg(parser_->getBufferAsString()); + .arg(err); + + // Only log the details if we have received anything and tried + // to parse it. + if (!parsing_error.empty()) { + LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA, + HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS) + .arg(url_.toText()) + .arg(parser_->getBufferAsString()); + } } - } + try { + // The callback should take care of its own exceptions but one + // never knows. + current_callback_(ec, response, parsing_error); - try { - // The callback should take care of its own exceptions but one - // never knows. - current_callback_(ec, response, parsing_error); + } catch (...) { + } - } catch (...) { - } + // If we're not requesting connection persistence, we should close the socket. + // We're going to reconnect for the next transaction. + if (!current_request_->isPersistent()) { + close(); + } - // If we're not requesting connection persistence, we should close the socket. - // We're going to reconnect for the next transaction. - if (!current_request_->isPersistent()) { - close(); + resetState(); } - resetState(); - // Check if there are any requests queued for this connection and start // another transaction if there is at least one. HttpRequestPtr request; @@ -625,6 +648,10 @@ Connection::doReceive() { void Connection::connectCallback(HttpClient::ConnectHandler connect_callback, const boost::system::error_code& ec) { + if (checkPrematureTimeout()) { + return; + } + // Run user defined connect callback if specified. if (connect_callback) { // If the user defined callback indicates that the connection @@ -634,11 +661,14 @@ Connection::connectCallback(HttpClient::ConnectHandler connect_callback, } } + if (ec && (ec.value() == boost::asio::error::operation_aborted)) { + return; + // In some cases the "in progress" status code may be returned. It doesn't // indicate an error. Sending the request over the socket is expected to // be successful. Getting such status appears to be highly dependent on // the operating system. - if (ec && + } else if (ec && (ec.value() != boost::asio::error::in_progress) && (ec.value() != boost::asio::error::already_connected)) { terminate(ec); @@ -651,10 +681,17 @@ Connection::connectCallback(HttpClient::ConnectHandler connect_callback, void Connection::sendCallback(const boost::system::error_code& ec, size_t length) { + if (checkPrematureTimeout()) { + return; + } + if (ec) { + if (ec.value() == boost::asio::error::operation_aborted) { + return; + // EAGAIN and EWOULDBLOCK don't really indicate an error. The length // should be 0 in this case but let's be sure. - if ((ec.value() == boost::asio::error::would_block) || + } else if ((ec.value() == boost::asio::error::would_block) || (ec.value() == boost::asio::error::try_again)) { length = 0; @@ -686,11 +723,18 @@ Connection::sendCallback(const boost::system::error_code& ec, size_t length) { void Connection::receiveCallback(const boost::system::error_code& ec, size_t length) { + if (checkPrematureTimeout()) { + return; + } + if (ec) { + if (ec.value() == boost::asio::error::operation_aborted) { + return; + // EAGAIN and EWOULDBLOCK don't indicate an error in this case. All // other errors should terminate the transaction. - if ((ec.value() != boost::asio::error::try_again) && - (ec.value() != boost::asio::error::would_block)) { + } if ((ec.value() != boost::asio::error::try_again) && + (ec.value() != boost::asio::error::would_block)) { terminate(ec); return; -- GitLab From e3e38736cc03176beaa3b426ee44ac0b3b2cbd22 Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Mon, 13 May 2019 16:52:21 +0200 Subject: [PATCH 2/7] [#599,!320] Implemented unit test for premature timeout. --- src/lib/http/client.cc | 2 +- src/lib/http/tests/server_client_unittests.cc | 63 ++++++++++++++++++- 2 files changed, 63 insertions(+), 2 deletions(-) diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc index c45f1fd435..c2c6b30f5f 100644 --- a/src/lib/http/client.cc +++ b/src/lib/http/client.cc @@ -1,4 +1,4 @@ -// Copyright (C) 2018 Internet Systems Consortium, Inc. ("ISC") +// Copyright (C) 2018-2019 Internet Systems Consortium, Inc. ("ISC") // // This Source Code Form is subject to the terms of the Mozilla Public // License, v. 2.0. If a copy of the MPL was not distributed with this diff --git a/src/lib/http/tests/server_client_unittests.cc b/src/lib/http/tests/server_client_unittests.cc index fe88cc0601..1478f5201f 100644 --- a/src/lib/http/tests/server_client_unittests.cc +++ b/src/lib/http/tests/server_client_unittests.cc @@ -1,4 +1,4 @@ -// Copyright (C) 2017-2018 Internet Systems Consortium, Inc. ("ISC") +// Copyright (C) 2017-2019 Internet Systems Consortium, Inc. ("ISC") // // This Source Code Form is subject to the terms of the Mozilla Public // License, v. 2.0. If a copy of the MPL was not distributed with this @@ -1249,6 +1249,67 @@ TEST_F(HttpClientTest, clientRequestTimeout) { ASSERT_NO_THROW(runIOService()); } +// This test verifies the behavior of the HTTP client when the premature +// (and unexpected) timeout occurs. The premature timeout may be caused +// by the system clock move. +TEST_F(HttpClientTest, clientRequestLateStart) { + // Start the server. + ASSERT_NO_THROW(listener_.start()); + + // Create the client. + HttpClient client(io_service_); + + // Specify the URL of the server. + Url url("http://127.0.0.1:18123"); + + unsigned cb_num = 0; + + // Generate first request. + PostHttpRequestJsonPtr request1 = createRequest("partial-response", true); + HttpResponseJsonPtr response1(new HttpResponseJson()); + + // Use very short timeout to make sure that it occurs before we actually + // run the transaction. + ASSERT_NO_THROW(client.asyncSendRequest(url, request1, response1, + [](const boost::system::error_code& ec, + const HttpResponsePtr& response, + const std::string&) { + // In this particular case we know exactly the type of the + // IO error returned, because the client explicitly sets this + // error code. + EXPECT_TRUE(ec.value() == boost::asio::error::timed_out); + // There should be no response returned. + EXPECT_FALSE(response); + }, HttpClient::RequestTimeout(1))); + + // This waits for 3ms to make sure that the timeout occurs before we + // run the transaction. This leads to an unusual situation that the + // transaction state is reset as a result of the timeout but the + // transaction is alive. We want to make sure that the client can + // gracefully deal with this situation. + usleep(3000); + + // Run the transaction and hope it will gracefully tear down. + ASSERT_NO_THROW(runIOService(100)); + + // Now try to send another request to make sure that the client + // is healthy. + PostHttpRequestJsonPtr request2 = createRequest("sequence", 1); + HttpResponseJsonPtr response2(new HttpResponseJson()); + ASSERT_NO_THROW(client.asyncSendRequest(url, request2, response2, + [this](const boost::system::error_code& ec, + const HttpResponsePtr&, + const std::string&) { + io_service_.stop(); + + // Everything should be ok. + EXPECT_TRUE(ec.value() == 0); + })); + + // Actually trigger the requests. + ASSERT_NO_THROW(runIOService()); +} + // Test that client times out when connection takes too long. TEST_F(HttpClientTest, clientConnectTimeout) { // Start the server. -- GitLab From 7bd2ab411c796dec555359490458e8a28c8267f3 Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Mon, 13 May 2019 17:21:23 +0200 Subject: [PATCH 3/7] [#599,!320] Added log message when premature http timeout occurred. --- src/lib/http/client.cc | 2 ++ src/lib/http/http_messages.cc | 4 +++- src/lib/http/http_messages.h | 3 ++- src/lib/http/http_messages.mes | 6 ++++++ 4 files changed, 13 insertions(+), 2 deletions(-) diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc index c2c6b30f5f..adfd0ef5c7 100644 --- a/src/lib/http/client.cc +++ b/src/lib/http/client.cc @@ -535,6 +535,8 @@ Connection::isTransactionOngoing() const { bool Connection::checkPrematureTimeout() const { if (!isTransactionOngoing()) { + // The transaction state is was reset, so we need to log a warning message. + LOG_WARN(http_logger, HTTP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED); return (true); } return (false); diff --git a/src/lib/http/http_messages.cc b/src/lib/http/http_messages.cc index cb84e76744..79a3cb346a 100644 --- a/src/lib/http/http_messages.cc +++ b/src/lib/http/http_messages.cc @@ -1,4 +1,4 @@ -// File created from ../../../src/lib/http/http_messages.mes on Fri Feb 08 2019 20:32 +// File created from ../../../src/lib/http/http_messages.mes on Mon May 13 2019 17:08 #include #include @@ -20,6 +20,7 @@ extern const isc::log::MessageID HTTP_CONNECTION_STOP = "HTTP_CONNECTION_STOP"; extern const isc::log::MessageID HTTP_CONNECTION_STOP_FAILED = "HTTP_CONNECTION_STOP_FAILED"; extern const isc::log::MessageID HTTP_DATA_RECEIVED = "HTTP_DATA_RECEIVED"; extern const isc::log::MessageID HTTP_IDLE_CONNECTION_TIMEOUT_OCCURRED = "HTTP_IDLE_CONNECTION_TIMEOUT_OCCURRED"; +extern const isc::log::MessageID HTTP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED = "HTTP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED"; extern const isc::log::MessageID HTTP_REQUEST_RECEIVE_START = "HTTP_REQUEST_RECEIVE_START"; extern const isc::log::MessageID HTTP_SERVER_RESPONSE_RECEIVED = "HTTP_SERVER_RESPONSE_RECEIVED"; extern const isc::log::MessageID HTTP_SERVER_RESPONSE_RECEIVED_DETAILS = "HTTP_SERVER_RESPONSE_RECEIVED_DETAILS"; @@ -45,6 +46,7 @@ const char* values[] = { "HTTP_CONNECTION_STOP_FAILED", "stopping HTTP connection failed", "HTTP_DATA_RECEIVED", "received %1 bytes from %2", "HTTP_IDLE_CONNECTION_TIMEOUT_OCCURRED", "closing persistent connection with %1 as a result of a timeout", + "HTTP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED", "premature connection timeout occurred, possibly caused by system clock change", "HTTP_REQUEST_RECEIVE_START", "start receiving request from %1 with timeout %2", "HTTP_SERVER_RESPONSE_RECEIVED", "received HTTP response from %1", "HTTP_SERVER_RESPONSE_RECEIVED_DETAILS", "detailed information about well formed response received from %1:\n%2", diff --git a/src/lib/http/http_messages.h b/src/lib/http/http_messages.h index 3f3788489c..658b081088 100644 --- a/src/lib/http/http_messages.h +++ b/src/lib/http/http_messages.h @@ -1,4 +1,4 @@ -// File created from ../../../src/lib/http/http_messages.mes on Fri Feb 08 2019 20:32 +// File created from ../../../src/lib/http/http_messages.mes on Mon May 13 2019 17:08 #ifndef HTTP_MESSAGES_H #define HTTP_MESSAGES_H @@ -21,6 +21,7 @@ extern const isc::log::MessageID HTTP_CONNECTION_STOP; extern const isc::log::MessageID HTTP_CONNECTION_STOP_FAILED; extern const isc::log::MessageID HTTP_DATA_RECEIVED; extern const isc::log::MessageID HTTP_IDLE_CONNECTION_TIMEOUT_OCCURRED; +extern const isc::log::MessageID HTTP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED; extern const isc::log::MessageID HTTP_REQUEST_RECEIVE_START; extern const isc::log::MessageID HTTP_SERVER_RESPONSE_RECEIVED; extern const isc::log::MessageID HTTP_SERVER_RESPONSE_RECEIVED_DETAILS; diff --git a/src/lib/http/http_messages.mes b/src/lib/http/http_messages.mes index 2c8e5cc8ed..5ba4614777 100644 --- a/src/lib/http/http_messages.mes +++ b/src/lib/http/http_messages.mes @@ -83,6 +83,12 @@ produced the data. This debug message is issued when the persistent HTTP connection is being closed as a result of being idle. +% HTTP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED premature connection timeout occurred, possibly caused by system clock change +This warning message is issued when unexpected timeout occurred during the +transaction. This is proven to occur when the system clock is moved manually +or as a result of synchronization with a time server. Any ongoing transactions +will be interrupted. New transactions should be conducted normally. + % HTTP_REQUEST_RECEIVE_START start receiving request from %1 with timeout %2 This debug message is issued when the server starts receiving new request over the established connection. The first argument specifies the address -- GitLab From 1e0d64d773918a75db2c6bed818385d61915b93f Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Tue, 14 May 2019 08:34:29 +0200 Subject: [PATCH 4/7] [#599,!320] Introduce transaction id into the HTTP client. --- src/lib/http/client.cc | 73 +++++++++++++++++++++++++++++------------- 1 file changed, 50 insertions(+), 23 deletions(-) diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc index adfd0ef5c7..91359e47f9 100644 --- a/src/lib/http/client.cc +++ b/src/lib/http/client.cc @@ -146,8 +146,12 @@ public: /// it is participating in is still alive. If it is not, it should simply /// return. This method also logs such situation. /// + /// @param transid identifier of the transaction for which the handler + /// is being invoked. It is compared against the current transaction + /// id for this connection. + /// /// @return true if the premature timeout is suspected, false otherwise. - bool checkPrematureTimeout() const; + bool checkPrematureTimeout(const uint64_t transid); private: @@ -177,12 +181,16 @@ private: /// @brief Asynchronously sends data over the socket. /// /// The data sent over the socket are stored in the @c buf_. - void doSend(); + /// + /// @param transid Current transaction id. + void doSend(const uint64_t transid); /// @brief Asynchronously receives data over the socket. /// /// The data received over the socket are store into the @c input_buf_. - void doReceive(); + /// + /// @param transid Current transaction id. + void doReceive(const uint64_t transid); /// @brief Local callback invoked when the connection is established. /// @@ -191,8 +199,10 @@ private: /// /// @param Pointer to the callback to be invoked when client connects to /// the server. + /// @param transid Current transaction id. /// @param ec Error code being a result of the connection attempt. void connectCallback(HttpClient::ConnectHandler connect_callback, + const uint64_t transid, const boost::system::error_code& ec); /// @brief Local callback invoked when an attempt to send a portion of data @@ -202,16 +212,20 @@ private: /// data from the buffer were sent, the callback will start to asynchronously /// receive a response from the server. /// + /// @param transid Current transaction id. /// @param ec Error code being a result of sending the data. /// @param length Number of bytes sent. - void sendCallback(const boost::system::error_code& ec, size_t length); + void sendCallback(const uint64_t transid, const boost::system::error_code& ec, + size_t length); /// @brief Local callback invoked when an attempt to receive a portion of data /// over the socket has ended. /// + /// @param transid Current transaction id. /// @param ec Error code being a result of receiving the data. /// @param length Number of bytes received. - void receiveCallback(const boost::system::error_code& ec, size_t length); + void receiveCallback(const uint64_t transid, const boost::system::error_code& ec, + size_t length); /// @brief Local callback invoked when request timeout occurs. void timerCallback(); @@ -248,6 +262,9 @@ private: /// @brief Input buffer. std::array input_buf_; + + /// @brief Identifier of the current transaction. + uint64_t current_transid_; }; /// @brief Shared pointer to the connection. @@ -449,7 +466,7 @@ Connection::Connection(IOService& io_service, const Url& url) : conn_pool_(conn_pool), url_(url), socket_(io_service), timer_(io_service), current_request_(), current_response_(), parser_(), current_callback_(), - buf_(), input_buf_() { + buf_(), input_buf_(), current_transid_(0) { } Connection::~Connection() { @@ -477,6 +494,9 @@ Connection::doTransaction(const HttpRequestPtr& request, parser_->initModel(); current_callback_ = callback; + // Starting new transaction. Generate new transaction id. + ++current_transid_; + buf_ = request->toString(); // If the socket is open we check if it is possible to transmit the data @@ -509,7 +529,7 @@ Connection::doTransaction(const HttpRequestPtr& request, TCPEndpoint endpoint(url_.getStrippedHostname(), static_cast(url_.getPort())); SocketCallback socket_cb(boost::bind(&Connection::connectCallback, shared_from_this(), - connect_callback, _1)); + connect_callback, current_transid_, _1)); // Establish new connection or use existing connection. socket_.open(&endpoint, socket_cb); @@ -533,9 +553,13 @@ Connection::isTransactionOngoing() const { } bool -Connection::checkPrematureTimeout() const { - if (!isTransactionOngoing()) { - // The transaction state is was reset, so we need to log a warning message. +Connection::checkPrematureTimeout(const uint64_t transid) { + // If there is no transaction but the handlers are invoked it means + // that the last transaction in the queue timed out prematurely. + // Also, if there is a transaction in progress but the ID of that + // transaction doesn't match the one associated with the handler it, + // also means that the transaction timed out prematurely. + if (!isTransactionOngoing() || (transid != current_transid_)) { LOG_WARN(http_logger, HTTP_PREMATURE_CONNECTION_TIMEOUT_OCCURRED); return (true); } @@ -622,9 +646,9 @@ Connection::scheduleTimer(const long request_timeout) { } void -Connection::doSend() { +Connection::doSend(const uint64_t transid) { SocketCallback socket_cb(boost::bind(&Connection::sendCallback, shared_from_this(), - _1, _2)); + transid, _1, _2)); try { socket_.asyncSend(&buf_[0], buf_.size(), socket_cb); @@ -634,10 +658,10 @@ Connection::doSend() { } void -Connection::doReceive() { +Connection::doReceive(const uint64_t transid) { TCPEndpoint endpoint; SocketCallback socket_cb(boost::bind(&Connection::receiveCallback, shared_from_this(), - _1, _2)); + transid, _1, _2)); try { socket_.asyncReceive(static_cast(input_buf_.data()), input_buf_.size(), 0, @@ -649,8 +673,9 @@ Connection::doReceive() { void Connection::connectCallback(HttpClient::ConnectHandler connect_callback, + const uint64_t transid, const boost::system::error_code& ec) { - if (checkPrematureTimeout()) { + if (checkPrematureTimeout(transid)) { return; } @@ -677,13 +702,14 @@ Connection::connectCallback(HttpClient::ConnectHandler connect_callback, } else { // Start sending the request asynchronously. - doSend(); + doSend(transid); } } void -Connection::sendCallback(const boost::system::error_code& ec, size_t length) { - if (checkPrematureTimeout()) { +Connection::sendCallback(const uint64_t transid, const boost::system::error_code& ec, + size_t length) { + if (checkPrematureTimeout(transid)) { return; } @@ -716,16 +742,17 @@ Connection::sendCallback(const boost::system::error_code& ec, size_t length) { // If there is no more data to be sent, start receiving a response. Otherwise, // continue sending. if (buf_.empty()) { - doReceive(); + doReceive(transid); } else { - doSend(); + doSend(transid); } } void -Connection::receiveCallback(const boost::system::error_code& ec, size_t length) { - if (checkPrematureTimeout()) { +Connection::receiveCallback(const uint64_t transid, const boost::system::error_code& ec, + size_t length) { + if (checkPrematureTimeout(transid)) { return; } @@ -758,7 +785,7 @@ Connection::receiveCallback(const boost::system::error_code& ec, size_t length) // If the parser still needs data, let's schedule another receive. if (parser_->needData()) { - doReceive(); + doReceive(transid); } else if (parser_->httpParseOk()) { // No more data needed and parsing has been successful so far. Let's -- GitLab From e5a22d3e864b2c9fccec423cc349c6578a86d182 Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Tue, 14 May 2019 09:22:49 +0200 Subject: [PATCH 5/7] [#599,!320] Added another variant of the premature timeout test. --- src/lib/http/tests/server_client_unittests.cc | 153 +++++++++++------- 1 file changed, 98 insertions(+), 55 deletions(-) diff --git a/src/lib/http/tests/server_client_unittests.cc b/src/lib/http/tests/server_client_unittests.cc index 1478f5201f..ecd1928e2f 100644 --- a/src/lib/http/tests/server_client_unittests.cc +++ b/src/lib/http/tests/server_client_unittests.cc @@ -1003,6 +1003,96 @@ public: EXPECT_NE(sequence1->intValue(), sequence2->intValue()); } + /// @brief Tests the behavior of the HTTP client when the premature + /// timeout occurs. + /// + /// The premature timeout may occur when the system clock is moved + /// during the transaction. This test simulates this behavior by + /// starting new transaction and waiting for the timeout to occur + /// before the IO service is ran. The timeout handler is invoked + /// first and it resets the transaction state. This test verifies + /// that the started transaction tears down gracefully after the + /// transaction state is reset. + /// + /// There are two variants of this test. The first variant schedules + /// one transaction before running the IO service. The second variant + /// schedules two transactions prior to running the IO service. The + /// second transaction is queued, so it is expected that it doesn't + /// time out and it runs successfully. + /// + /// @param queue_two_requests Boolean value indicating if a single + /// transaction should be queued (false), or two (true). + void testClientRequestLateStart(const bool queue_two_requests) { + // Start the server. + ASSERT_NO_THROW(listener_.start()); + + // Create the client. + HttpClient client(io_service_); + + // Specify the URL of the server. + Url url("http://127.0.0.1:18123"); + + // Generate first request. + PostHttpRequestJsonPtr request1 = createRequest("sequence", 1); + HttpResponseJsonPtr response1(new HttpResponseJson()); + + // Use very short timeout to make sure that it occurs before we actually + // run the transaction. + ASSERT_NO_THROW(client.asyncSendRequest(url, request1, response1, + [](const boost::system::error_code& ec, + const HttpResponsePtr& response, + const std::string&) { + + // In this particular case we know exactly the type of the + // IO error returned, because the client explicitly sets this + // error code. + EXPECT_TRUE(ec.value() == boost::asio::error::timed_out); + // There should be no response returned. + EXPECT_FALSE(response); + }, HttpClient::RequestTimeout(1))); + + if (queue_two_requests) { + PostHttpRequestJsonPtr request2 = createRequest("sequence", 2); + HttpResponseJsonPtr response2(new HttpResponseJson()); + ASSERT_NO_THROW(client.asyncSendRequest(url, request2, response2, + [](const boost::system::error_code& ec, + const HttpResponsePtr& response, + const std::string&) { + + // This second request should be successful. + EXPECT_TRUE(ec.value() == 0); + EXPECT_TRUE(response); + })); + } + + // This waits for 3ms to make sure that the timeout occurs before we + // run the transaction. This leads to an unusual situation that the + // transaction state is reset as a result of the timeout but the + // transaction is alive. We want to make sure that the client can + // gracefully deal with this situation. + usleep(3000); + + // Run the transaction and hope it will gracefully tear down. + ASSERT_NO_THROW(runIOService(100)); + + // Now try to send another request to make sure that the client + // is healthy. + PostHttpRequestJsonPtr request3 = createRequest("sequence", 3); + HttpResponseJsonPtr response3(new HttpResponseJson()); + ASSERT_NO_THROW(client.asyncSendRequest(url, request3, response3, + [this](const boost::system::error_code& ec, + const HttpResponsePtr&, + const std::string&) { + io_service_.stop(); + + // Everything should be ok. + EXPECT_TRUE(ec.value() == 0); + })); + + // Actually trigger the requests. + ASSERT_NO_THROW(runIOService()); + } + /// @brief Instance of the listener used in the tests. HttpListener listener_; @@ -1252,62 +1342,15 @@ TEST_F(HttpClientTest, clientRequestTimeout) { // This test verifies the behavior of the HTTP client when the premature // (and unexpected) timeout occurs. The premature timeout may be caused // by the system clock move. -TEST_F(HttpClientTest, clientRequestLateStart) { - // Start the server. - ASSERT_NO_THROW(listener_.start()); - - // Create the client. - HttpClient client(io_service_); - - // Specify the URL of the server. - Url url("http://127.0.0.1:18123"); - - unsigned cb_num = 0; - - // Generate first request. - PostHttpRequestJsonPtr request1 = createRequest("partial-response", true); - HttpResponseJsonPtr response1(new HttpResponseJson()); - - // Use very short timeout to make sure that it occurs before we actually - // run the transaction. - ASSERT_NO_THROW(client.asyncSendRequest(url, request1, response1, - [](const boost::system::error_code& ec, - const HttpResponsePtr& response, - const std::string&) { - // In this particular case we know exactly the type of the - // IO error returned, because the client explicitly sets this - // error code. - EXPECT_TRUE(ec.value() == boost::asio::error::timed_out); - // There should be no response returned. - EXPECT_FALSE(response); - }, HttpClient::RequestTimeout(1))); - - // This waits for 3ms to make sure that the timeout occurs before we - // run the transaction. This leads to an unusual situation that the - // transaction state is reset as a result of the timeout but the - // transaction is alive. We want to make sure that the client can - // gracefully deal with this situation. - usleep(3000); - - // Run the transaction and hope it will gracefully tear down. - ASSERT_NO_THROW(runIOService(100)); - - // Now try to send another request to make sure that the client - // is healthy. - PostHttpRequestJsonPtr request2 = createRequest("sequence", 1); - HttpResponseJsonPtr response2(new HttpResponseJson()); - ASSERT_NO_THROW(client.asyncSendRequest(url, request2, response2, - [this](const boost::system::error_code& ec, - const HttpResponsePtr&, - const std::string&) { - io_service_.stop(); - - // Everything should be ok. - EXPECT_TRUE(ec.value() == 0); - })); +TEST_F(HttpClientTest, clientRequestLateStartNoQueue) { + testClientRequestLateStart(false); +} - // Actually trigger the requests. - ASSERT_NO_THROW(runIOService()); +// This test verifies the behavior of the HTTP client when the premature +// timeout occurs and there are requests queued after the request which +// times out. +TEST_F(HttpClientTest, clientRequestLateStartQueue) { + testClientRequestLateStart(true); } // Test that client times out when connection takes too long. -- GitLab From 385bf32b43be1cb7feae669164edc542c9e1472e Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Tue, 14 May 2019 09:41:13 +0200 Subject: [PATCH 6/7] [#599,!320] Protect against null ptr dereferencing in HTTP log messages. As a result of review. --- src/lib/http/client.cc | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc index 91359e47f9..971e493e11 100644 --- a/src/lib/http/client.cc +++ b/src/lib/http/client.cc @@ -587,7 +587,8 @@ Connection::terminate(const boost::system::error_code& ec, LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA, HTTP_SERVER_RESPONSE_RECEIVED_DETAILS) .arg(url_.toText()) - .arg(parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE)); + .arg((parser_ ? parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE) + : "[HttpResponseParser is null]")); } else { std::string err = parsing_error.empty() ? ec.message() : parsing_error; @@ -603,7 +604,8 @@ Connection::terminate(const boost::system::error_code& ec, LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA, HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS) .arg(url_.toText()) - .arg(parser_->getBufferAsString()); + .arg((parser_ ? parser_->getBufferAsString() + : "[HttpResponseParser is null]")); } } -- GitLab From 63f4e781314be5f9911527aff7ec937f941f0291 Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Tue, 14 May 2019 11:02:56 +0200 Subject: [PATCH 7/7] [#599,!320] Added ChangeLog entry for #599. --- ChangeLog | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/ChangeLog b/ChangeLog index 33322520ca..49cc4ea86e 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,3 +1,8 @@ +1570. [bug] marcin + Corrected the bug in the Kea HTTP library which could cause a server + to assert when system clock was modified during the transaction. + (Gitlab #599,!320, git 958abe5063b6e602c0070e336524e313c3a87671) + 1569. [perf] fdupont Improved performance of the DHCPv4 server in cases when match-client-id set disabled by removing unnecessary query to the -- GitLab