Merge branch 'work/log/cc'

src/lib/cc/Makefile.am

@@ -22,10 +22,18 @@ endif
 
 lib_LTLIBRARIES = libcc.la
 libcc_la_SOURCES = data.cc data.h session.cc session.h
+libcc_la_SOURCES += logger.cc logger.h
+nodist_libcc_la_SOURCES = cc_messages.cc cc_messages.h
+libcc_la_LIBADD = $(top_builddir)/src/lib/log/liblog.la
 
-CLEANFILES = *.gcno *.gcda session_config.h
+CLEANFILES = *.gcno *.gcda session_config.h cc_messages.cc cc_messages.h
 
 session_config.h: session_config.h.pre
 	$(SED) -e "s|@@LOCALSTATEDIR@@|$(localstatedir)|" session_config.h.pre >$@
 
-BUILT_SOURCES = session_config.h 
+cc_messages.cc cc_messages.h: cc_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/cc/cc_messages.mes
+
+BUILT_SOURCES = session_config.h cc_messages.cc cc_messages.h
+
+EXTRA_DIST = cc_messages.mes

src/lib/cc/cc_messages.mes

@@ -0,0 +1,108 @@
+# Copyright (C) 2010  Internet Systems Consortium, Inc. ("ISC")
+#
+# Permission to use, copy, modify, and/or distribute this software for any
+# purpose with or without fee is hereby granted, provided that the above
+# copyright notice and this permission notice appear in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+# AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+# PERFORMANCE OF THIS SOFTWARE.
+
+$NAMESPACE isc::cc
+
+% CC_ASYNC_READ_FAILED asynchronous read failed
+This marks a low level error, we tried to read data from the message queue
+daemon asynchronously, but the ASIO library returned an error.
+
+% CC_CONN_ERROR error connecting to message queue (%1)
+It is impossible to reach the message queue daemon for the reason given. It
+is unlikely there'll be reason for whatever program this currently is to
+continue running, as the communication with the rest of BIND 10 is vital
+for the components.
+
+% CC_DISCONNECT disconnecting from message queue daemon
+The library is disconnecting from the message queue daemon. This debug message
+indicates that the program is trying to shut down gracefully.
+
+% CC_ESTABLISH trying to establish connection with message queue daemon at %1
+This debug message indicates that the command channel library is about to
+connect to the message queue daemon, which should be listening on the UNIX-domain
+socket listed in the output.
+
+% CC_ESTABLISHED successfully connected to message queue daemon
+This debug message indicates that the connection was successfully made, this
+should follow CC_ESTABLISH.
+
+% CC_GROUP_RECEIVE trying to receive a message
+Debug message, noting that a message is expected to come over the command
+channel.
+
+% CC_GROUP_RECEIVED message arrived ('%1', '%2')
+Debug message, noting that we successfully received a message (its envelope and
+payload listed). This follows CC_GROUP_RECEIVE, but might happen some time
+later, depending if we waited for it or just polled.
+
+% CC_GROUP_SEND sending message '%1' to group '%2'
+Debug message, we're about to send a message over the command channel.
+
+% CC_INVALID_LENGTHS invalid length parameters (%1, %2)
+This happens when garbage comes over the command channel or some kind of
+confusion happens in the program. The data received from the socket make no
+sense if we interpret it as lengths of message. The first one is total length
+of message, the second length of the header. The header and it's length
+(2 bytes) is counted in the total length.
+
+% CC_LENGTH_NOT_READY length not ready
+There should be data representing length of message on the socket, but it
+is not there.
+
+% CC_NO_MESSAGE no message ready to be received yet
+The program polled for incoming messages, but there was no message waiting.
+This is a debug message which may happen only after CC_GROUP_RECEIVE.
+
+% CC_NO_MSGQ unable to connect to message queue (%1)
+It isn't possible to connect to the message queue daemon, for reason listed.
+It is unlikely any program will be able continue without the communication.
+
+% CC_READ_ERROR error reading data from command channel (%1)
+A low level error happened when the library tried to read data from the
+command channel socket. The reason is listed.
+
+% CC_READ_EXCEPTION error reading data from command channel (%1)
+We received an exception while trying to read data from the command
+channel socket. The reason is listed.
+
+% CC_REPLY replying to message from '%1' with '%2'
+Debug message, noting we're sending a response to the original message
+with the given envelope.
+
+% CC_SET_TIMEOUT setting timeout to %1ms
+Debug message. A timeout for which the program is willing to wait for a reply
+is being set.
+
+% CC_START_READ starting asynchronous read
+Debug message. From now on, when a message (or command) comes, it'll wake the
+program and the library will automatically pass it over to correct place.
+
+% CC_SUBSCRIBE subscribing to communication group %1
+Debug message. The program wants to receive messages addressed to this group.
+
+% CC_TIMEOUT timeout reading data from command channel
+The program waited too long for data from the command channel (usually when it
+sent a query to different program and it didn't answer for whatever reason).
+
+% CC_UNSUBSCRIBE unsubscribing from communication group %1
+Debug message. The program no longer wants to receive messages addressed to
+this group.
+
+% CC_WRITE_ERROR error writing data to command channel (%1)
+A low level error happened when the library tried to write data to the command
+channel socket.
+
+% CC_ZERO_LENGTH invalid message length (0)
+The library received a message length being zero, which makes no sense, since
+all messages must contain at least the envelope.

src/lib/cc/data.cc

@@ -52,13 +52,6 @@ Element::toWire(std::ostream& ss) const {
     toJSON(ss);
 }
 
-//
-// The following methods are effectively empty, and their parameters are
-// unused.  To silence compilers that warn unused function parameters,
-// we specify a (compiler dependent) special keyword when available.
-// It's defined in config.h, and to avoid including this header file from
-// installed files we define the methods here.
-//
 bool
 Element::getValue(long int&) {
     return (false);

src/lib/cc/logger.cc

@@ -0,0 +1,23 @@
+// Copyright (C) 2010  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#include <cc/logger.h>
+
+namespace isc {
+namespace cc {
+
+isc::log::Logger logger("cc");
+
+}
+}

src/lib/cc/logger.h

@@ -0,0 +1,47 @@
+// Copyright (C) 2010  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#ifndef CC_LOGGER_H
+#define CC_LOGGER_H
+
+#include <cc/cc_messages.h>
+#include <log/macros.h>
+
+/// \file logger.h
+/// \brief Command Channel library global logger
+///
+/// This holds the logger for the CC library. It is a private header
+/// and should not be included in any publicly used header, only in local
+/// cc files.
+
+namespace isc {
+namespace cc {
+
+enum {
+    /// \brief Trace basic operation
+    DBG_TRACE_BASIC = 10,
+    /// \brief Trace even details
+    ///
+    /// This includes messages being sent and received, waiting for messages
+    /// and alike.
+    DBG_TRACE_DETAILED = 80
+};
+
+/// \brief Logger for this library
+extern isc::log::Logger logger;
+
+}
+}
+
+#endif

src/lib/cc/session.cc

@@ -14,6 +14,7 @@
 
 #include <config.h>
 #include <cc/session_config.h>
+#include <cc/logger.h>
 
 #include <stdint.h>
 
@@ -118,12 +119,16 @@ private:
 void
 SessionImpl::establish(const char& socket_file) {
     try {
+        LOG_DEBUG(logger, DBG_TRACE_BASIC, CC_ESTABLISH).arg(socket_file);
         socket_.connect(asio::local::stream_protocol::endpoint(&socket_file),
                         error_);
+        LOG_DEBUG(logger, DBG_TRACE_BASIC, CC_ESTABLISHED);
     } catch(const asio::system_error& se) {
+        LOG_FATAL(logger, CC_CONN_ERROR).arg(se.what());
         isc_throw(SessionError, se.what());
     }
     if (error_) {
+        LOG_FATAL(logger, CC_NO_MSGQ).arg(error_.message());
         isc_throw(SessionError, "Unable to connect to message queue: " <<
                   error_.message());
     }
@@ -131,6 +136,7 @@ SessionImpl::establish(const char& socket_file) {
 
 void
 SessionImpl::disconnect() {
+    LOG_DEBUG(logger, DBG_TRACE_BASIC, CC_DISCONNECT);
     socket_.close();
     data_length_ = 0;
 }
@@ -140,6 +146,7 @@ SessionImpl::writeData(const void* data, size_t datalen) {
     try {
         asio::write(socket_, asio::buffer(data, datalen));
     } catch (const asio::system_error& asio_ex) {
+        LOG_FATAL(logger, CC_WRITE_ERROR).arg(asio_ex.what());
         isc_throw(SessionError, "ASIO write failed: " << asio_ex.what());
     }
 }
@@ -151,6 +158,7 @@ SessionImpl::readDataLength() {
     if (ret_len == 0) {
         readData(&data_length_, sizeof(data_length_));
         if (data_length_ == 0) {
+            LOG_ERROR(logger, CC_LENGTH_NOT_READY);
             isc_throw(SessionError, "ASIO read: data length is not ready");
         }
         ret_len = ntohl(data_length_);
@@ -199,9 +207,11 @@ SessionImpl::readData(void* data, size_t datalen) {
         // asio::error_code evaluates to false if there was no error
         if (*read_result) {
             if (*read_result == asio::error::operation_aborted) {
+                LOG_ERROR(logger, CC_TIMEOUT);
                 isc_throw(SessionTimeout,
                           "Timeout while reading data from cc session");
             } else {
+                LOG_ERROR(logger, CC_READ_ERROR).arg(read_result->message());
                 isc_throw(SessionError,
                           "Error while reading data from cc session: " <<
                           read_result->message());
@@ -210,6 +220,7 @@ SessionImpl::readData(void* data, size_t datalen) {
     } catch (const asio::system_error& asio_ex) {
         // to hide ASIO specific exceptions, we catch them explicitly
         // and convert it to SessionError.
+        LOG_FATAL(logger, CC_READ_EXCEPTION).arg(asio_ex.what());
         isc_throw(SessionError, "ASIO read failed: " << asio_ex.what());
     }
 }
@@ -233,10 +244,12 @@ SessionImpl::internalRead(const asio::error_code& error,
         assert(bytes_transferred == sizeof(data_length_));
         data_length_ = ntohl(data_length_);
         if (data_length_ == 0) {
+            LOG_ERROR(logger, CC_ZERO_LENGTH);
             isc_throw(SessionError, "Invalid message length (0)");
         }
         user_handler_();
     } else {
+        LOG_ERROR(logger, CC_ASYNC_READ_FAILED);
         isc_throw(SessionError, "asynchronous read failed");
     }
 }
@@ -255,6 +268,7 @@ Session::disconnect() {
 
 void
 Session::startRead(boost::function<void()> read_callback) {
+    LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_START_READ);
     impl_->startRead(read_callback);
 }
 
@@ -374,6 +388,7 @@ Session::recvmsg(ConstElementPtr& env, ConstElementPtr& msg,
 
     unsigned short header_length = ntohs(header_length_net);
     if (header_length > length || length < 2) {
+        LOG_ERROR(logger, CC_INVALID_LENGTHS).arg(length).arg(header_length);
         isc_throw(SessionError, "Length parameters invalid: total=" << length
                   << ", header=" << header_length);
     }
@@ -417,6 +432,7 @@ Session::recvmsg(ConstElementPtr& env, ConstElementPtr& msg,
 
 void
 Session::subscribe(std::string group, std::string instance) {
+    LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_SUBSCRIBE).arg(group);
     ElementPtr env = Element::createMap();
 
     env->set("type", Element::create("subscribe"));
@@ -428,6 +444,7 @@ Session::subscribe(std::string group, std::string instance) {
 
 void
 Session::unsubscribe(std::string group, std::string instance) {
+    LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_UNSUBSCRIBE).arg(group);
     ElementPtr env = Element::createMap();
 
     env->set("type", Element::create("unsubscribe"));
@@ -441,6 +458,8 @@ int
 Session::group_sendmsg(ConstElementPtr msg, std::string group,
                        std::string instance, std::string to)
 {
+    LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_GROUP_SEND).arg(msg->str()).
+        arg(group);
     ElementPtr env = Element::createMap();
     long int nseq = ++impl_->sequence_;
     
@@ -460,11 +479,21 @@ bool
 Session::group_recvmsg(ConstElementPtr& envelope, ConstElementPtr& msg,
                        bool nonblock, int seq)
 {
-    return (recvmsg(envelope, msg, nonblock, seq));
+    LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_GROUP_RECEIVE);
+    bool result(recvmsg(envelope, msg, nonblock, seq));
+    if (result) {
+        LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_GROUP_RECEIVED).
+            arg(envelope->str()).arg(msg->str());
+    } else {
+        LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_NO_MESSAGE);
+    }
+    return (result);
 }
 
 int
 Session::reply(ConstElementPtr envelope, ConstElementPtr newmsg) {
+    LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_REPLY).arg(envelope->str()).
+        arg(newmsg->str());
     ElementPtr env = Element::createMap();
     long int nseq = ++impl_->sequence_;
     
@@ -488,6 +517,7 @@ Session::hasQueuedMsgs() const {
 
 void
 Session::setTimeout(size_t milliseconds) {
+    LOG_DEBUG(logger, DBG_TRACE_DETAILED, CC_SET_TIMEOUT).arg(milliseconds);
     impl_->setTimeout(milliseconds);
 }
 

src/lib/cc/tests/Makefile.am

@@ -26,6 +26,7 @@ run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)
 
 run_unittests_LDADD = $(GTEST_LDADD)
 run_unittests_LDADD +=  $(top_builddir)/src/lib/cc/libcc.la
+run_unittests_LDADD +=  $(top_builddir)/src/lib/log/liblog.la
 run_unittests_LDADD +=  $(top_builddir)/src/lib/util/unittests/libutil_unittests.la
 run_unittests_LDADD +=  $(top_builddir)/src/lib/exceptions/libexceptions.la
 

src/lib/cc/tests/run_unittests.cc

@@ -14,9 +14,13 @@
 
 #include <gtest/gtest.h>
 #include <util/unittests/run_all.h>
+#include <log/logger_support.h>
 
 int
 main(int argc, char* argv[]) {
     ::testing::InitGoogleTest(&argc, argv);
+
+    isc::log::initLogger();
+
     return (isc::util::unittests::run_all());
 }