Merge #1190

Msgq logs using the logging library (but to stdout, see #2582 for that)

configure.ac

@@ -1354,7 +1354,6 @@ AC_OUTPUT([doc/version.ent
            src/bin/usermgr/run_b10-cmdctl-usermgr.sh
            src/bin/usermgr/b10-cmdctl-usermgr.py
            src/bin/msgq/msgq.py
-           src/bin/msgq/tests/msgq_test
            src/bin/msgq/run_msgq.sh
            src/bin/auth/auth.spec.pre
            src/bin/auth/spec_config.h.pre
@@ -1420,7 +1419,6 @@ AC_OUTPUT([doc/version.ent
            chmod +x src/bin/sysinfo/run_sysinfo.sh
            chmod +x src/bin/usermgr/run_b10-cmdctl-usermgr.sh
            chmod +x src/bin/msgq/run_msgq.sh
-           chmod +x src/bin/msgq/tests/msgq_test
            chmod +x src/lib/dns/gen-rdatacode.py
            chmod +x src/lib/log/tests/console_test.sh
            chmod +x src/lib/log/tests/destination_test.sh

src/bin/msgq/Makefile.am

@@ -5,10 +5,16 @@ pkglibexecdir = $(libexecdir)/@PACKAGE@
 pkglibexec_SCRIPTS = b10-msgq
 
 CLEANFILES = b10-msgq msgq.pyc
+CLEANFILES += $(PYTHON_LOGMSGPKG_DIR)/work/msgq_messages.py
+CLEANFILES += $(PYTHON_LOGMSGPKG_DIR)/work/msgq_messages.pyc
 
 man_MANS = b10-msgq.8
 DISTCLEANFILES = $(man_MANS)
-EXTRA_DIST = $(man_MANS) msgq.xml
+EXTRA_DIST = $(man_MANS) msgq.xml msgq_messages.mes
+
+nodist_pylogmessage_PYTHON = $(PYTHON_LOGMSGPKG_DIR)/work/msgq_messages.py
+pylogmessagedir = $(pyexecdir)/isc/log_messages/
+BUILT_SOURCES = $(PYTHON_LOGMSGPKG_DIR)/work/msgq_messages.py
 
 if GENERATE_DOCS
 
@@ -23,6 +29,11 @@ $(man_MANS):
 
 endif
 
+# Define rule to build logging source files from message file
+$(PYTHON_LOGMSGPKG_DIR)/work/msgq_messages.py : msgq_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message \
+	-d $(PYTHON_LOGMSGPKG_DIR)/work -p $(srcdir)/msgq_messages.mes
+
 # this is done here since configure.ac AC_OUTPUT doesn't expand exec_prefix
 b10-msgq: msgq.py
 	$(SED) "s|@@PYTHONPATH@@|@pyexecdir@|" msgq.py >$@

src/bin/msgq/msgq.py.in

@@ -31,10 +31,16 @@ import select
 import random
 from optparse import OptionParser, OptionValueError
 import isc.util.process
+import isc.log
+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
@@ -51,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):
@@ -162,9 +168,7 @@ class MsgQ:
 
     def setup_listener(self):
         """Set up the listener socket.  Internal function."""
-        if self.verbose:
+        logger.debug(TRACE_BASIC, MSGQ_LISTENER_SETUP, self.socket_file)
-            sys.stdout.write("[b10-msgq] Setting up socket at %s\n" %
-                             self.socket_file)
 
         self.listen_socket = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
 
@@ -179,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"
+            logger.fatal(MSGQ_LISTENER_FAILED, self.socket_file, e)
-                             % (self.socket_file, str(e)))
             raise e
 
         if self.poller:
@@ -197,8 +200,7 @@ class MsgQ:
         self.setup_poller()
         self.setup_listener()
 
-        if self.verbose:
+        logger.debug(TRACE_START, MSGQ_LISTENER_STARTED);
-            sys.stdout.write("[b10-msgq] Listening\n")
 
         self.runnable = True
 
@@ -226,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)
@@ -243,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
@@ -285,15 +287,15 @@ class MsgQ:
         try:
             routing, data = self.read_packet(fd, sock)
         except MsgQReceiveError as err:
+            logger.error(MSGQ_RECV_ERR, fd, err)
             self.kill_socket(fd, sock)
-            sys.stderr.write("[b10-msgq] Receive error: %s\n" % 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)
@@ -301,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
+        logger.debug(TRACE_DETAIL, MSGQ_RECV_HDR, routing)
-        # routing envelope). When we have logging with multiple levels,
-        # we might want to re-add that on a high debug verbosity.
         cmd = routing["type"]
         if cmd == 'send':
             self.process_command_send(sock, routing, data)
@@ -319,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:
@@ -363,8 +363,8 @@ class MsgQ:
             elif e.errno in [ errno.EPIPE,
                               errno.ECONNRESET,
                               errno.ENOBUFS ]:
-                print("[b10-msgq] " + errno.errorcode[e.errno] +
+                logger.error(MSGQ_SEND_ERR, sock.fileno(),
-                      " on send, dropping message and closing connection")
+                             errno.errorcode[e.errno])
                 self.kill_socket(sock.fileno(), sock)
                 return None
             else:
@@ -491,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.fatal(MSGQ_POLL_ERR, err)
                     break
             for (fd, event) in events:
                 if fd == self.listen_socket.fileno():
@@ -502,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, fd, event)
 
     def run_kqueue(self):
         while self.running:
@@ -563,18 +563,25 @@ if __name__ == "__main__":
                       help="UNIX domain socket file the msgq daemon will use")
     (options, args) = parser.parse_args()
 
+    # Init logging, according to the parameters.
+    # FIXME: Do proper logger configuration, this is just a hack
+    # This is #2582
+    sev = 'INFO'
+    if options.verbose:
+        sev = 'DEBUG'
+    isc.log.init("b10-msgq", buffer=False, severity=sev, debuglevel=99)
+
     signal.signal(signal.SIGTERM, signal_handler)
 
     # Announce startup.
-    if options.verbose:
+    logger.debug(TRACE_START, MSGQ_START, VERSION)
-        sys.stdout.write("[b10-msgq] %s\n" % 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,88 @@
+# 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_HDR_DECODE_ERR Error decoding header received from socket %1: %2
+The socket with mentioned file descriptor sent a packet. However, it was not
+possible to decode the routing header of the packet. The packet is ignored.
+This may be caused by a programmer error (one of the components sending invalid
+data) or possibly by incompatible version of msgq and the component (but that's
+unlikely, as the protocol is not changed often).
+
+% MSGQ_LISTENER_FAILED Failed to initialize listener on socket file '%1': %2
+The message queue daemon tried to listen on a file socket (the path is in the
+message), but it failed. The error from the operating system is logged.
+
+% MSGQ_LISTENER_SETUP Starting to listen on socket file '%1'
+Debug message. The listener is trying to open a listening socket.
+
+% MSGQ_LISTENER_STARTED Successfully started to listen
+Debug message. The message queue successfully opened a listening socket and
+waits for incoming connections.
+
+% MSGQ_POLL_ERR Error while polling for events: %1
+A low-level error happened when waiting for events, the error is logged. The
+reason for this varies, but it usually means the system is short on some
+resources.
+
+% MSGQ_POLL_UNKNOWN_EVENT Got an unknown event from the poller for fd %1: %2
+An unknown event got out from the poll() system call. This should generally not
+happen and it is either a programmer error or OS bug. The event is ignored. The
+number noted as the event is the raw encoded value, which might be useful to
+the authors when figuring the problem out.
+
+% MSGQ_READ_UNKNOWN_FD Got read on strange socket %1
+The OS reported a file descriptor is ready to read. But the daemon doesn't know
+the mentioned file descriptor, which is either a programmer error or OS bug.
+The read event is ignored.
+
+% MSGQ_RECV_ERR Error reading from socket %1: %2
+There was a low-level error when reading from a socket. The error is logged and
+the corresponding socket is dropped.
+
+% MSGQ_RECV_HDR Received header: %1
+Debug message. This message includes the whole routing header of a packet.
+
+% MSGQ_INVALID_CMD Received invalid command: %1
+An unknown command listed in the log has been received. It is ignored. This
+indicates either a programmer error (eg. a typo in the command name) or
+incompatible version of a module and message queue daemon.
+
+% MSGQ_SEND_ERR Error while sending to socket %1: %2
+There was a low-level error when sending data to a socket. The error is logged
+and the corresponding socket is dropped.
+
+% MSGQ_SOCK_CLOSE Closing socket fd %1
+Debug message. Closing the mentioned socket.
+
+% MSGQ_START Msgq version %1 starting
+Debug message. The message queue is starting up.
+
+% MSGQ_START_FAIL Error during startup: %1
+There was an error during early startup of the daemon. More concrete error is
+in the log. The daemon terminates as a result.
+
+% MSGQ_SUBS_APPEND_TARGET Appending to existing target for subscription to group '%1' for instance '%2'
+Debug message. Creating a new subscription by appending it to already existing
+data structure.
+
+% MSGQ_SUBS_NEW_TARGET Creating new target for subscription to group '%1' for instance '%2'
+Debug message. Creating a new subscription. Also creating a new data structure
+to hold it.

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/Makefile.am

@@ -21,6 +21,8 @@ endif
 	$(LIBRARY_PATH_PLACEHOLDER) \
 	PYTHONPATH=$(COMMON_PYTHON_PATH):$(abs_top_builddir)/src/bin/msgq \
 	BIND10_TEST_SOCKET_FILE=$(builddir)/test_msgq_socket.sock \
+	B10_FROM_SOURCE=$(abs_top_srcdir) \
+	B10_FROM_BUILD=$(abs_top_builddir) \
 	$(PYCOVERAGE_RUN) $(abs_srcdir)/$$pytest || exit ; \
 	done
 

src/bin/msgq/tests/msgq_test.in

@@ -1,28 +0,0 @@
-#! /bin/sh
-
-# Copyright (C) 2010  Internet Systems Consortium.
-#
-# Permission to use, copy, modify, and 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 INTERNET SYSTEMS CONSORTIUM
-# DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE INCLUDING ALL
-# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
-# INTERNET SYSTEMS CONSORTIUM 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.
-
-PYTHON_EXEC=${PYTHON_EXEC:-@PYTHON@}
-export PYTHON_EXEC
-
-MYPATH_PATH=@abs_top_srcdir@/src/bin/msgq/tests
-
-PYTHONPATH=@abs_top_srcdir@/src/bin/msgq:@abs_top_srcdir@/src/lib/python
-
-export PYTHONPATH
-
-cd ${MYPATH_PATH}
-exec ${PYTHON_EXEC} -O msgq_test.py $*

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,6 @@ class SendNonblock(unittest.TestCase):
 
 
 if __name__ == '__main__':
+    isc.log.init("b10-msgq")
+    isc.log.resetUnitTestRootLogger()
     unittest.main()

src/lib/python/isc/log_messages/Makefile.am

@@ -17,6 +17,7 @@ EXTRA_DIST += libxfrin_messages.py
 EXTRA_DIST += loadzone_messages.py
 EXTRA_DIST += server_common_messages.py
 EXTRA_DIST += dbutil_messages.py
+EXTRA_DIST += msgq_messages.py
 
 CLEANFILES = __init__.pyc
 CLEANFILES += bind10_messages.pyc
@@ -35,6 +36,7 @@ CLEANFILES += libxfrin_messages.pyc
 CLEANFILES += loadzone_messages.pyc
 CLEANFILES += server_common_messages.pyc
 CLEANFILES += dbutil_messages.pyc
+CLEANFILES += msgq_messages.pyc
 
 CLEANDIRS = __pycache__
 

src/lib/python/isc/log_messages/msgq_messages.py

@@ -0,0 +1 @@
+from work.msgq_messages import *