From af01e66fde8c0055319c47d775b0af1408a3e18a Mon Sep 17 00:00:00 2001 From: Stephen Morris Date: Thu, 24 Feb 2011 08:58:58 +0000 Subject: [PATCH] [trac499] Add logging of errors to IOFetch --- src/lib/asiolink/Makefile.am | 24 +++++++------ src/lib/asiolink/io_fetch.cc | 64 ++++++++++++++++++++++++++++++++--- src/lib/asiolink/io_fetch.h | 37 ++++++++++++++++---- src/lib/asiolink/udp_socket.h | 11 ++++-- src/lib/log/Makefile.am | 2 ++ 5 files changed, 116 insertions(+), 22 deletions(-) diff --git a/src/lib/asiolink/Makefile.am b/src/lib/asiolink/Makefile.am index b3968f0661..b7bf530c24 100644 --- a/src/lib/asiolink/Makefile.am +++ b/src/lib/asiolink/Makefile.am @@ -13,28 +13,32 @@ CLEANFILES = *.gcno *.gcda # which would make the build fail with -Werror (our default setting). lib_LTLIBRARIES = libasiolink.la libasiolink_la_SOURCES = asiolink.h +libasiolink_la_SOURCES += asiodef.cc asiodef.h libasiolink_la_SOURCES += dns_answer.h libasiolink_la_SOURCES += dns_lookup.h libasiolink_la_SOURCES += dns_server.h -libasiolink_la_SOURCES += dns_service.h dns_service.cc +libasiolink_la_SOURCES += dns_service.cc dns_service.h libasiolink_la_SOURCES += dummy_io_cb.h -libasiolink_la_SOURCES += interval_timer.h interval_timer.cc -libasiolink_la_SOURCES += io_address.h io_address.cc +libasiolink_la_SOURCES += interval_timer.cc interval_timer.h +libasiolink_la_SOURCES += io_address.cc io_address.h libasiolink_la_SOURCES += io_asio_socket.h -libasiolink_la_SOURCES += io_endpoint.h io_endpoint.cc +libasiolink_la_SOURCES += io_endpoint.cc io_endpoint.h libasiolink_la_SOURCES += io_error.h -libasiolink_la_SOURCES += io_fetch.h io_fetch.cc +libasiolink_la_SOURCES += io_fetch.cc io_fetch.h libasiolink_la_SOURCES += io_message.h -libasiolink_la_SOURCES += io_service.h io_service.cc -libasiolink_la_SOURCES += io_socket.h io_socket.cc -libasiolink_la_SOURCES += recursive_query.h recursive_query.cc +libasiolink_la_SOURCES += io_service.cc io_service.h +libasiolink_la_SOURCES += io_socket.cc io_socket.h +libasiolink_la_SOURCES += recursive_query.cc recursive_query.h libasiolink_la_SOURCES += simple_callback.h libasiolink_la_SOURCES += tcp_endpoint.h -libasiolink_la_SOURCES += tcp_server.h tcp_server.cc +libasiolink_la_SOURCES += tcp_server.cc tcp_server.h libasiolink_la_SOURCES += tcp_socket.h libasiolink_la_SOURCES += udp_endpoint.h -libasiolink_la_SOURCES += udp_server.h udp_server.cc +libasiolink_la_SOURCES += udp_server.cc udp_server.h libasiolink_la_SOURCES += udp_socket.h + +EXTRA_DIST = asiodef.msg + # Note: the ordering matters: -Wno-... must follow -Wextra (defined in # B10_CXXFLAGS) libasiolink_la_CXXFLAGS = $(AM_CXXFLAGS) diff --git a/src/lib/asiolink/io_fetch.cc b/src/lib/asiolink/io_fetch.cc index d1f722cf86..307ae8f498 100644 --- a/src/lib/asiolink/io_fetch.cc +++ b/src/lib/asiolink/io_fetch.cc @@ -25,8 +25,12 @@ #include #include #include +#include #include +#include +#include +#include #include using namespace asio; @@ -36,6 +40,10 @@ using namespace std; namespace asiolink { +/// Use the ASIO logger + +isc::log::Logger logger("asio"); + /// IOFetch Constructor - just initialize the private data IOFetch::IOFetch(int protocol, IOService& service, @@ -52,7 +60,10 @@ IOFetch::IOFetch(int protocol, IOService& service, void IOFetch::operator()(error_code ec, size_t length) { - if (ec || data_->stopped) { + if (data_->stopped) { + return; + } else if (ec) { + logIOFailure(ec); return; } @@ -93,11 +104,13 @@ IOFetch::operator()(error_code ec, size_t length) { // Open a connection to the target system. For speed, if the operation // was completed synchronously (i.e. UDP operation) we bypass the yield. if (data_->socket->open(data_->remote.get(), *this)) { + data_->origin = OPEN; CORO_YIELD; } // Begin an asynchronous send, and then yield. When the send completes // send completes, we will resume immediately after this point. + data_->origin = SEND; CORO_YIELD data_->socket->asyncSend(data_->msgbuf->getData(), data_->msgbuf->getLength(), data_->remote.get(), *this); @@ -108,6 +121,7 @@ IOFetch::operator()(error_code ec, size_t length) { // we need to yield ... and we *really* don't want to set up another // coroutine within that method.) So after each receive (and yield), // we check if the operation is complete and if not, loop to read again. + data_->origin = RECEIVE; do { CORO_YIELD data_->socket->asyncReceive(data_->data.get(), static_cast(MAX_LENGTH), data_->cumulative, @@ -156,20 +170,30 @@ IOFetch::stop(Result result) { // variable should be done inside a mutex (and the stopped_ variable // declared as "volatile"). // + // Although Logger::debug checks the debug flag internally, doing it + // in below avoids the overhead of a string conversion in the common + // case when debug is not enabled. + // // TODO: Update testing of stopped_ if threads are used. data_->stopped = true; switch (result) { case TIME_OUT: - dlog("Query timed out"); + if (logger.isDebugEnabled(1)) { + logger.debug(1, ASIO_RECVTMO, + data_->remote->getAddress().toText().c_str()); + } break; case STOPPED: - dlog("Query stopped"); + if (logger.isDebugEnabled(50)) { + logger.debug(50, ASIO_FETCOMP, + data_->remote->getAddress().toText().c_str()); + } break; default: - ; + logger.error(ASIO_UNKRESULT, static_cast(result)); } // Stop requested, cancel and I/O's on the socket and shut it down, @@ -189,5 +213,37 @@ IOFetch::stop(Result result) { } } +// Log an error - called on I/O failure + +void IOFetch::logIOFailure(asio::error_code& ec) { + + // Get information that will be in all messages + static const char* PROTOCOL[2] = {"TCP", "UDP"}; + const char* prot = (data_->remote->getProtocol() == IPPROTO_TCP) ? + PROTOCOL[0] : PROTOCOL[1]; + + int errcode = ec.value(); + + std::string str_address = data_->remote->getAddress().toText(); + const char* address = str_address.c_str(); + + switch (data_->origin) { + case OPEN: + logger.error(ASIO_OPENSOCK, errcode, prot, address); + break; + + case SEND: + logger.error(ASIO_SENDSOCK, errcode, prot, address); + break; + + case RECEIVE: + logger.error(ASIO_RECVSOCK, errcode, prot, address); + break; + + default: + logger.error(ASIO_UNKORIGIN, errcode, prot, address); + } +} + } // namespace asiolink diff --git a/src/lib/asiolink/io_fetch.h b/src/lib/asiolink/io_fetch.h index 8158c6c05c..957831d67f 100644 --- a/src/lib/asiolink/io_fetch.h +++ b/src/lib/asiolink/io_fetch.h @@ -51,6 +51,17 @@ namespace asiolink { class IOFetch : public coroutine { public: + /// \brief Origin of Asynchronous I/O Call + /// + /// Indicates what initiated an asynchronous I/O call and used in deciding + /// what error message to output if the I/O fails. + enum Origin { + NONE = 0, ///< No asynchronous call outstanding + OPEN = 1, + SEND = 2, + RECEIVE = 3, + CLOSE = 4 + }; /// \brief Result of Upstream Fetch /// @@ -95,7 +106,12 @@ public: virtual ~Callback() {} - /// \brief Callback method called when the fetch completes + /// \brief Callback method called when the fetch completes /// \brief Origin of Asynchronous I/O Call + /// + + // The next enum is a "trick" to allow constants to be defined in a class + // declaration. + /// /// \brief result Result of the fetch virtual void operator()(Result result) = 0; @@ -127,12 +143,13 @@ public: bool stopped; ///< Have we stopped running? asio::deadline_timer timer; ///< Timer to measure timeouts int timeout; ///< Timeout in ms + Origin origin; ///< Origin of last asynchronous I/O /// \brief Constructor /// /// Just fills in the data members of the IOFetchData structure /// - /// \param protocol either IPPROTO_UDP or IPPROTO_TCP + /// \param proto either IPPROTO_UDP or IPPROTO_TCP /// \param service I/O Service object to handle the asynchronous /// operations. /// \param query DNS question to send to the upstream server. @@ -146,18 +163,18 @@ public: /// \param wait Timeout for the fetch (in ms). /// /// TODO: May need to alter constructor (see comment 4 in Trac ticket #554) - IOFetchData(int protocol, IOService& service, + IOFetchData(int proto, IOService& service, const isc::dns::Question& query, const IOAddress& address, uint16_t port, isc::dns::OutputBufferPtr& buff, Callback* cb, int wait) : - socket((protocol == IPPROTO_UDP) ? + socket((proto == IPPROTO_UDP) ? static_cast*>( new UDPSocket(service)) : static_cast*>( new TCPSocket(service)) ), - remote((protocol == IPPROTO_UDP) ? + remote((proto == IPPROTO_UDP) ? static_cast(new UDPEndpoint(address, port)) : static_cast(new TCPEndpoint(address, port)) ), @@ -169,7 +186,8 @@ public: cumulative(0), stopped(false), timer(service.get_io_service()), - timeout(wait) + timeout(wait), + origin(NONE) {} }; @@ -217,6 +235,13 @@ public: void stop(Result reason = STOPPED); private: + /// \brief Log I/O Failure + /// + /// Records an I/O failure to the log file + /// + /// \param ec ASIO error code + void logIOFailure(asio::error_code& ec); + boost::shared_ptr data_; ///< Private data }; diff --git a/src/lib/asiolink/udp_socket.h b/src/lib/asiolink/udp_socket.h index bb94ad56f2..8cb2232cfa 100644 --- a/src/lib/asiolink/udp_socket.h +++ b/src/lib/asiolink/udp_socket.h @@ -70,8 +70,15 @@ public: /// \brief Destructor virtual ~UDPSocket(); - virtual int getNative() const { return (socket_.native()); } - virtual int getProtocol() const { return (IPPROTO_UDP); } + /// \brief Return file descriptor of underlying socket + virtual int getNative() const { + return (socket_.native()); + } + + /// \brief Return protocol of socket + virtual int getProtocol() const { + return (IPPROTO_UDP); + } /// \brief Open Socket /// diff --git a/src/lib/log/Makefile.am b/src/lib/log/Makefile.am index 416fd06d0e..584ae5a9ca 100644 --- a/src/lib/log/Makefile.am +++ b/src/lib/log/Makefile.am @@ -24,6 +24,8 @@ liblog_la_SOURCES += message_types.h liblog_la_SOURCES += root_logger_name.cc root_logger_name.h liblog_la_SOURCES += strutil.h strutil.cc +EXTRA_DIST = messagedef.mes + # Note: the ordering matters: -Wno-... must follow -Wextra (defined in # B10_CXXFLAGS) liblog_la_CXXFLAGS = $(AM_CXXFLAGS)