From: Marcin Siodelski Date: Tue, 29 May 2018 14:08:03 +0000 (+0200) Subject: [5205] Improved HTTP server side logging. X-Git-Tag: trac5117_base~3^2~4 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=27cf2123e5710c9fb603c1f58e870ecf8a8c2feb;p=thirdparty%2Fkea.git [5205] Improved HTTP server side logging. --- diff --git a/src/lib/http/connection.cc b/src/lib/http/connection.cc index c6f3f36caa..11a272a03a 100644 --- a/src/lib/http/connection.cc +++ b/src/lib/http/connection.cc @@ -13,6 +13,15 @@ using namespace isc::asiolink; +namespace { + +/// @brief Maximum size of the HTTP message that can be logged. +/// +/// The part of the HTTP message beyond this value is truncated. +constexpr size_t MAX_LOGGED_MESSAGE_SIZE = 1024; + +} + namespace isc { namespace http { @@ -203,12 +212,28 @@ HttpConnection::socketReadCallback(boost::system::error_code ec, size_t length) doRead(); } else { - LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_DETAIL, - HTTP_REQUEST_RECEIVED) - .arg(getRemoteEndpointAddressAsText()); try { request_->finalize(); - } catch (...) { + + LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC, + HTTP_REQUEST_RECEIVED) + .arg(getRemoteEndpointAddressAsText()); + + LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA, + HTTP_REQUEST_DETAILS) + .arg(getRemoteEndpointAddressAsText()) + .arg(parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE)); + + } catch (const std::exception& ex) { + LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC, + HTTP_BAD_REQUEST_RECEIVED) + .arg(getRemoteEndpointAddressAsText()) + .arg(ex.what()); + + LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_BASIC_DATA, + HTTP_BAD_REQUEST_DETAILS) + .arg(getRemoteEndpointAddressAsText()) + .arg(parser_->getBufferAsString(MAX_LOGGED_MESSAGE_SIZE)); } HttpResponsePtr response = response_creator_->createHttpResponse(request_); @@ -216,6 +241,13 @@ HttpConnection::socketReadCallback(boost::system::error_code ec, size_t length) HTTP_RESPONSE_SEND) .arg(response->toBriefString()) .arg(getRemoteEndpointAddressAsText()); + + LOG_DEBUG(http_logger, isc::log::DBGLVL_TRACE_DETAIL_DATA, + HTTP_RESPONSE_DETAILS) + .arg(getRemoteEndpointAddressAsText()) + .arg(HttpMessageParserBase::logFormatHttpMessage(response->toString(), + MAX_LOGGED_MESSAGE_SIZE)); + asyncSendResponse(response); } } diff --git a/src/lib/http/http_message_parser_base.cc b/src/lib/http/http_message_parser_base.cc index a5d84c660e..715a435269 100644 --- a/src/lib/http/http_message_parser_base.cc +++ b/src/lib/http/http_message_parser_base.cc @@ -6,6 +6,7 @@ #include #include +#include using namespace isc::util; @@ -23,7 +24,8 @@ const int HttpMessageParserBase::HTTP_PARSE_FAILED_EVT; HttpMessageParserBase::HttpMessageParserBase(HttpMessage& message) - : StateModel(), message_(message), buffer_(), error_message_() { + : StateModel(), message_(message), buffer_(), buffer_pos_(0), + error_message_() { } void @@ -68,6 +70,33 @@ HttpMessageParserBase::postBuffer(const void* buf, const size_t buf_size) { } } +std::string +HttpMessageParserBase::getBufferAsString(const size_t limit) const { + std::string message(buffer_.begin(), buffer_.end()); + return (logFormatHttpMessage(message, limit)); +} + +std::string +HttpMessageParserBase::logFormatHttpMessage(const std::string& message, + const size_t limit) { + if (!message.empty()) { + if (limit < message.size()) { + std::ostringstream s; + s << ".........\n(truncating HTTP message larger than " + << limit << " characters)\n"; + s << message.substr(0, limit) + << ".........\n(truncating HTTP message larger than " + << limit << " characters)\n"; + return (s.str()); + } + } + + // Return original message if it is empty or does not exceed the + // limit. + return (message); +} + + void HttpMessageParserBase::defineEvents() { StateModel::defineEvents(); @@ -197,9 +226,8 @@ HttpMessageParserBase::parseEndedHandler() { bool HttpMessageParserBase::popNextFromBuffer(char& next) { // If there are any characters in the buffer, pop next. - if (!buffer_.empty()) { - next = buffer_.front(); - buffer_.pop_front(); + if (buffer_pos_ < buffer_.size()) { + next = buffer_[buffer_pos_++]; return (true); } return (false); diff --git a/src/lib/http/http_message_parser_base.h b/src/lib/http/http_message_parser_base.h index 7d10abc264..5dc9e90ddb 100644 --- a/src/lib/http/http_message_parser_base.h +++ b/src/lib/http/http_message_parser_base.h @@ -11,8 +11,8 @@ #include #include #include -#include #include +#include namespace isc { namespace http { @@ -142,6 +142,27 @@ public: /// @param buf_size Size of the data within the buffer. void postBuffer(const void* buf, const size_t buf_size); + /// @brief Returns parser's input buffer as string. + /// + /// @param limit Maximum length of the buffer to be output. If the limit is 0, + /// the length of the output is unlimited. + /// @return Textual representation of the input buffer. + std::string getBufferAsString(const size_t limit = 0) const; + + /// @brief Formats provided HTTP message for logging. + /// + /// This method is useful in cases when there is a need to log a HTTP message + /// (as text). If the @c limit is specified the message output is limited to + /// this size. If the @c limit is set to 0 (default), the whole message is + /// output. The @c getBufferAsString method calls this method internally. + /// + /// @param message HTTP message to be logged. + /// @param limit Maximum length of the buffer to be output. If the limit is 0, + /// the length of the output is unlimited. + /// @return HTTP message formatted for logging. + static std::string logFormatHttpMessage(const std::string& message, + const size_t limit = 0); + private: /// @brief Make @ref runModel private to make sure that the caller uses @@ -257,7 +278,10 @@ protected: HttpMessage& message_; /// @brief Internal buffer from which parser reads data. - std::list buffer_; + std::vector buffer_; + + /// @brief Position of the next character to read from the buffer. + size_t buffer_pos_; /// @brief Error message set by @ref onModelFailure. std::string error_message_; diff --git a/src/lib/http/http_messages.mes b/src/lib/http/http_messages.mes index 414eab53df..a22f42f1be 100644 --- a/src/lib/http/http_messages.mes +++ b/src/lib/http/http_messages.mes @@ -1,4 +1,4 @@ -# Copyright (C) 2016-2017 Internet Systems Consortium, Inc. ("ISC") +# Copyright (C) 2016-2018 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 @@ -6,6 +6,21 @@ $NAMESPACE isc::http +% HTTP_BAD_REQUEST_DETAILS detailed information about bad request received from %1:\n%2 +This debug message is issued when a HTTP client sends malformed request to +the server. It includes detailed information about the received request +rejected by the server. The first argument specifies an address of +the remote endpoint which sent the request. The second argument provides +a request in the textual format. The request is truncated by the logger +if it is too large to be printed. + +% HTTP_BAD_REQUEST_RECEIVED bad request received from %1: %2 +This debug message is issued when a HTTP client sends malformed request to +the server. This includes HTTP requests using unexpected content types, +including malformed JSON etc. The first argument specifies an address of +the remote endpoint which sent the request. The second argument provides +a detailed error message. + % HTTP_CONNECTION_STOP stopping HTTP connection from %1 This debug message is issued when one of the HTTP connections is stopped. The connection can be stopped as a result of an error or after the @@ -26,6 +41,13 @@ produced the data. This debug message is issued when the persistent HTTP connection is being closed as a result of being idle. +% HTTP_REQUEST_DETAILS detailed information about well formed request received from %1:\n%2 +This debug message is issued when the HTTP server receives a well formed +request. It includes detailed information about the received request. The +first argument specifies an address of the remote endpoint which sent the +request. The second argument provides the request in the textual format. +The request is truncated by the logger if it is too large to be printed. + % HTTP_REQUEST_RECEIVED received HTTP request from %1 This debug message is issued when the server finished receiving a HTTP request from the remote endpoint. The address of the remote endpoint is @@ -42,6 +64,14 @@ This debug message is issued when the HTTP request timeout has occurred and the server is going to send a response with Http Request timeout status code. +% HTTP_RESPONSE_DETAILS detailed information about response sent to %1:\n%2 +This debug message is issued right before the server sends a HTTP response +to the client. It includes detailed information about the response. The +first argument specifies an address of the remote endpoint to which the +response is being sent. The second argument provides a response in the +textual form. The response is truncated by the logger if it is too large +to be printed. + % HTTP_RESPONSE_SEND sending HTTP response %1 to %2 This debug message is issued when the server is starting to send a HTTP response to a remote endpoint. The first argument holds basic information