[trac499] Add logging of errors to IOFetch

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)

src/lib/asiolink/io_fetch.cc

@@ -25,8 +25,12 @@
 #include <dns/opcode.h>
 #include <dns/rcode.h>
 #include <log/dummylog.h>
+#include <log/logger.h>
 
 #include <asio.hpp>
+#include <asiolink/asiodef.h>
+#include <asiolink/io_address.h>
+#include <asiolink/io_endpoint.h>
 #include <asiolink/io_fetch.h>
 
 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<size_t>(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<int>(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
 

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<IOAsioSocket<IOFetch>*>(
                     new UDPSocket<IOFetch>(service)) :
                 static_cast<IOAsioSocket<IOFetch>*>(
                     new TCPSocket<IOFetch>(service))
                 ),
-            remote((protocol == IPPROTO_UDP) ?
+            remote((proto == IPPROTO_UDP) ?
                 static_cast<IOEndpoint*>(new UDPEndpoint(address, port)) :
                 static_cast<IOEndpoint*>(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<IOFetchData>  data_;   ///< Private data
 
 };

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
     ///

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)