[1190] Put logging into MSGQ

Add the logging calls. Other things need to be tweaked (putting it into
a file, making tests work, etc).

src/bin/msgq/msgq.py.in

@@ -37,6 +37,10 @@ from isc.log_messages.msgq_messages import *
 import isc.cc
 
 isc.util.process.rename()
+logger = isc.log.Logger("msgq")
+TRACE_START = logger.DBGLVL_START_SHUT
+TRACE_BASIC = logger.DBGLVL_TRACE_BASIC
+TRACE_DETAIL = logger.DBGLVL_TRACE_DETAIL
 
 # This is the version that gets displayed to the user.
 # The VERSION string consists of the module name, the module version
@@ -53,11 +57,11 @@ class SubscriptionManager:
         """Add a subscription."""
         target = ( group, instance )
         if target in self.subscriptions:
-            print("[b10-msgq] Appending to existing target")
+            logger.debug(TRACE_BASIC, MSGQ_SUBS_APPEND_TARGET, group, instance)
             if socket not in self.subscriptions[target]:
                 self.subscriptions[target].append(socket)
         else:
-            print("[b10-msgq] Creating new target")
+            logger.debug(TRACE_BASIC, MSGQ_SUBS_NEW_TARGET, group, instance)
             self.subscriptions[target] = [ socket ]
 
     def unsubscribe(self, group, instance, socket):
@@ -164,9 +168,7 @@ class MsgQ:
 
     def setup_listener(self):
         """Set up the listener socket.  Internal function."""
-        if self.verbose:
-            sys.stdout.write("[b10-msgq] Setting up socket at %s\n" %
-                             self.socket_file)
+        logger.debug(TRACE_BASIC, MSGQ_LISTENER_SETUP, self.socket_file)
 
         self.listen_socket = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
 
@@ -181,8 +183,7 @@ class MsgQ:
             if os.path.exists(self.socket_file):
                 os.remove(self.socket_file)
             self.listen_socket.close()
-            sys.stderr.write("[b10-msgq] failed to setup listener on %s: %s\n"
-                             % (self.socket_file, str(e)))
+            logger.fatal(MSGQ_LISTENER_FAILED, self.socket_file, e)
             raise e
 
         if self.poller:
@@ -199,8 +200,7 @@ class MsgQ:
         self.setup_poller()
         self.setup_listener()
 
-        if self.verbose:
-            sys.stdout.write("[b10-msgq] Listening\n")
+        logger.debug(TRACE_START, MSGQ_LISTENER_STARTED);
 
         self.runnable = True
 
@@ -228,7 +228,7 @@ class MsgQ:
     def process_socket(self, fd):
         """Process a read on a socket."""
         if not fd in self.sockets:
-            sys.stderr.write("[b10-msgq] Got read on Strange Socket fd %d\n" % fd)
+            logger.error(MSGQ_READ_UNKNOWN_FD, fd)
             return
         sock = self.sockets[fd]
 #        sys.stderr.write("[b10-msgq] Got read on fd %d\n" %fd)
@@ -245,7 +245,7 @@ class MsgQ:
         del self.sockets[fd]
         if fd in self.sendbuffs:
             del self.sendbuffs[fd]
-        sys.stderr.write("[b10-msgq] Closing socket fd %d\n" % fd)
+        logger.debug(TRACE_BASIC, MSGQ_SOCK_CLOSE, fd)
 
     def getbytes(self, fd, sock, length):
         """Get exactly the requested bytes, or raise an exception if
@@ -288,14 +288,14 @@ class MsgQ:
             routing, data = self.read_packet(fd, sock)
         except MsgQReceiveError as err:
             self.kill_socket(fd, sock)
-            sys.stderr.write("[b10-msgq] Receive error: %s\n" % err)
+            logger.error(MSGQ_RECV_ERR, fd, err)
             return
 
         try:
             routingmsg = isc.cc.message.from_wire(routing)
         except DecodeError as err:
             self.kill_socket(fd, sock)
-            sys.stderr.write("[b10-msgq] Routing decode error: %s\n" % err)
+            logger.error(MSGQ_HDR_DECODE_ERR, fd, err)
             return
 
         self.process_command(fd, sock, routingmsg, data)
@@ -303,9 +303,7 @@ class MsgQ:
     def process_command(self, fd, sock, routing, data):
         """Process a single command.  This will split out into one of the
            other functions."""
-        # TODO: A print statement got removed here (one that prints the
-        # routing envelope). When we have logging with multiple levels,
-        # we might want to re-add that on a high debug verbosity.
+        logger.debug(TRACE_DETAIL, MSGQ_RECV_HDR, routing)
         cmd = routing["type"]
         if cmd == 'send':
             self.process_command_send(sock, routing, data)
@@ -321,7 +319,7 @@ class MsgQ:
         elif cmd == 'stop':
             self.stop()
         else:
-            sys.stderr.write("[b10-msgq] Invalid command: %s\n" % cmd)
+            logger.error(MSGQ_INVALID_CMD, cmd)
 
     def preparemsg(self, env, msg = None):
         if type(env) == dict:
@@ -365,8 +363,8 @@ class MsgQ:
             elif e.errno in [ errno.EPIPE,
                               errno.ECONNRESET,
                               errno.ENOBUFS ]:
-                print("[b10-msgq] " + errno.errorcode[e.errno] +
-                      " on send, dropping message and closing connection")
+                logger.error(MSGQ_SEND_ERR, sock.fileno(),
+                             errno.errorcode[e.errno])
                 self.kill_socket(sock.fileno(), sock)
                 return None
             else:
@@ -493,7 +491,7 @@ class MsgQ:
                 if err.args[0] == errno.EINTR:
                     events = []
                 else:
-                    sys.stderr.write("[b10-msgq] Error with poll(): %s\n" % err)
+                    logger.error(MSGQ_POLL_ERR, err)
                     break
             for (fd, event) in events:
                 if fd == self.listen_socket.fileno():
@@ -504,7 +502,7 @@ class MsgQ:
                     elif event & select.POLLIN:
                         self.process_socket(fd)
                     else:
-                        print("[b10-msgq] Error: Unknown even in run_poller()")
+                        logger.error(MSGQ_POLL_UNKNOWN_EVENT, event)
 
     def run_kqueue(self):
         while self.running:
@@ -572,21 +570,19 @@ if __name__ == "__main__":
         sev = 'DEBUG'
     LOG_FILE = os.path.join("@localstatedir@", "@PACKAGE_NAME@",
                             "msgq.log").replace("${prefix}", "@prefix@")
-    isc.log.init("b10-msgq", buffer=False, severity=sev, debuglevel=99,
-                 file=LOG_FILE)
+    isc.log.init("b10-msgq", buffer=False, severity=sev, debuglevel=99)
 
     signal.signal(signal.SIGTERM, signal_handler)
 
     # Announce startup.
-    if options.verbose:
-        sys.stdout.write("[b10-msgq] %s\n" % VERSION)
+    logger.debug(TRACE_START, MSGQ_START, VERSION)
 
     msgq = MsgQ(options.msgq_socket_file, options.verbose)
 
     try:
         msgq.setup()
     except Exception as e:
-        sys.stderr.write("[b10-msgq] Error on startup: %s\n" % str(e))
+        logger.fatal(MSGQ_START_FAIL, e)
         sys.exit(1)
 
     try:

src/bin/msgq/msgq_messages.mes

@@ -0,0 +1,67 @@
+# Copyright (C) 2012  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.
+
+# No namespace declaration - these constants go in the global namespace
+# of the ddns messages python module.
+
+# When you add a message to this file, it is a good idea to run
+# <topsrcdir>/tools/reorder_message_file.py to make sure the
+# messages are in the correct order.
+
+% MSGQ_SUBS_NEW_TARGET Creating new target for subscription to group '%1' for instance '%2'
+Debug
+
+% MSGQ_SUBS_APPEND_TARGET Appending to existing target for subscription to group '%1' for instance '%2'
+Debug
+
+% MSGQ_LISTENER_SETUP Starting to listen on socket file '%1'
+Debug
+
+% MSGQ_LISTENER_FAILED Failed to initialize listener on socket file '%1': %2
+Fatal
+
+% MSGQ_LISTENER_STARTED Successfully started to listen
+Debug
+
+% MSGQ_READ_UNKNOWN_FD Got read on strange socket %1
+Error, ignoring
+
+% MSGQ_SOCK_CLOSE Closing socket fd %1
+Debug
+
+% MSGQ_RECV_ERR Error reading from socket %1: %2
+Error
+
+% MSGQ_HDR_DECODE_ERR Error decoding header received from socket %1: %2
+Error
+
+% MSGQ_RECV_HDR Received header: %1
+Debug
+
+% MSGQ_RECV_INVALID_CMD Received invalid command: %1
+Error
+
+% MSGQ_SEND_ERR Error while sending to socket %1: %2
+Error
+
+% MSGQ_POLL_ERR Error while polling for events: %1
+Error
+
+% MSGQ_POLL_UNKNOWN_EVENT Got an unknown event from the poller: %1
+Error
+
+% MSGQ_START Msgq version %1 starting
+Debug
+
+% MSGQ_START_FAIL Error during startup: %1

src/bin/msgq/run_msgq.sh.in

@@ -20,9 +20,25 @@ export PYTHON_EXEC
 
 MYPATH_PATH=@abs_top_builddir@/src/bin/msgq
 
-PYTHONPATH=@abs_top_srcdir@/src/lib/python
+PYTHONPATH=@abs_top_builddir@/src/lib/python/isc/log_messages:@abs_top_builddir@/src/lib/python:@abs_top_builddir@/src/lib/log/.libs
 export PYTHONPATH
 
+# If necessary (rare cases), explicitly specify paths to dynamic libraries
+# required by loadable python modules.
+SET_ENV_LIBRARY_PATH=@SET_ENV_LIBRARY_PATH@
+if test $SET_ENV_LIBRARY_PATH = yes; then
+    @ENV_LIBRARY_PATH@=@abs_top_builddir@/src/lib/dns/.libs:@abs_top_builddir@/src/lib/dns/python/.libs:@abs_top_builddir@/src/lib/cryptolink/.libs:@abs_top_builddir@/src/lib/cc/.libs:@abs_top_builddir@/src/lib/config/.libs:@abs_top_builddir@/src/lib/log/.libs:@abs_top_builddir@/src/lib/acl/.libs:@abs_top_builddir@/src/lib/util/.libs:@abs_top_builddir@/src/lib/util/io/.libs:@abs_top_builddir@/src/lib/exceptions/.libs:@abs_top_builddir@/src/lib/datasrc/.libs:$@ENV_LIBRARY_PATH@
+    export @ENV_LIBRARY_PATH@
+fi
+
+B10_FROM_SOURCE=@abs_top_srcdir@
+export B10_FROM_SOURCE
+# TODO: We need to do this feature based (ie. no general from_source)
+# But right now we need a second one because some spec files are
+# generated and hence end up under builddir
+B10_FROM_BUILD=@abs_top_builddir@
+export B10_FROM_BUILD
+
 BIND10_MSGQ_SOCKET_FILE=@abs_top_builddir@/msgq_socket
 export BIND10_MSGQ_SOCKET_FILE
 

src/bin/msgq/tests/msgq_test.py

@@ -10,6 +10,7 @@ import errno
 import threading
 import isc.cc
 import collections
+import isc.log
 
 #
 # Currently only the subscription part and some sending is implemented...
@@ -457,4 +458,5 @@ class SendNonblock(unittest.TestCase):
 
 
 if __name__ == '__main__':
+    isc.log.resetUnitTestRootLogger()
     unittest.main()