diff --git a/ChangeLog b/ChangeLog index 33322520cacefe9017e465383ac9086ae8e1891d..49cc4ea86e739d8f064211ea7a985b8b74051617 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 diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc index b1474fb4e72cb1de11c3405956783356e37d470e..971e493e11a3238d9323b8a1ca492f10d01b73ac 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 @@ -136,6 +136,23 @@ 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. + /// + /// @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 uint64_t transid); + private: /// @brief Resets the state of the object. @@ -164,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. /// @@ -178,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 @@ -189,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(); @@ -235,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. @@ -436,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() { @@ -464,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 @@ -496,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); @@ -519,62 +552,80 @@ Connection::isTransactionOngoing() const { return (static_cast(current_request_)); } +bool +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); + } + 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_SERVER_RESPONSE_RECEIVED) + .arg(url_.toText()); - LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC, - HTTP_BAD_SERVER_RESPONSE_RECEIVED) - .arg(url_.toText()) - .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) + HTTP_SERVER_RESPONSE_RECEIVED_DETAILS) + .arg(url_.toText()) + .arg((parser_ ? parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE) + : "[HttpResponseParser is null]")); + + } 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_ ? parser_->getBufferAsString() + : "[HttpResponseParser is null]")); + } } - } + 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; @@ -597,9 +648,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); @@ -609,10 +660,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, @@ -624,7 +675,12 @@ Connection::doReceive() { void Connection::connectCallback(HttpClient::ConnectHandler connect_callback, + const uint64_t transid, const boost::system::error_code& ec) { + if (checkPrematureTimeout(transid)) { + return; + } + // Run user defined connect callback if specified. if (connect_callback) { // If the user defined callback indicates that the connection @@ -634,27 +690,38 @@ 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); } else { // Start sending the request asynchronously. - doSend(); + doSend(transid); } } void -Connection::sendCallback(const boost::system::error_code& ec, size_t length) { +Connection::sendCallback(const uint64_t transid, const boost::system::error_code& ec, + size_t length) { + if (checkPrematureTimeout(transid)) { + 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; @@ -677,20 +744,28 @@ 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) { +Connection::receiveCallback(const uint64_t transid, const boost::system::error_code& ec, + size_t length) { + if (checkPrematureTimeout(transid)) { + 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; @@ -712,7 +787,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 diff --git a/src/lib/http/http_messages.cc b/src/lib/http/http_messages.cc index cb84e76744607a934dfe54de4dbf0952e83651e6..79a3cb346af9cd85a5f3da5b475fdbfca791b43b 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 3f3788489cd6f0cfec237a0a8f79798127507d10..658b0810885f74cdfbbaf68b0041e98565039285 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 2c8e5cc8ed0ce1e25dfde4179c94a862184780d3..5ba461477705635f11f7bbfe6b01f6cc930055c1 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 diff --git a/src/lib/http/tests/server_client_unittests.cc b/src/lib/http/tests/server_client_unittests.cc index fe88cc0601039f45066c046cc98be7f2ddb03429..ecd1928e2f20af0e77b0462623fabdc49fc0b3c9 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 @@ -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_; @@ -1249,6 +1339,20 @@ 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, clientRequestLateStartNoQueue) { + testClientRequestLateStart(false); +} + +// 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. TEST_F(HttpClientTest, clientConnectTimeout) { // Start the server.