From b40cd6851ace87bc97a095cf76b2a0ddee3666ed Mon Sep 17 00:00:00 2001 From: Michal 'vorner' Vaner Date: Mon, 17 Dec 2012 20:10:13 +0100 Subject: [PATCH 1/8] [1190] Init logging in msgq Using some hardcoded values for file and severity. This is a temporary solution, and we should improve on that, but currently it is not possible to get the configuration in msgq (even though the msgq is used to send it everywhere else). --- src/bin/msgq/msgq.py.in | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/src/bin/msgq/msgq.py.in b/src/bin/msgq/msgq.py.in index bd13a1c188..fda1b2371a 100755 --- a/src/bin/msgq/msgq.py.in +++ b/src/bin/msgq/msgq.py.in @@ -31,6 +31,7 @@ import select import random from optparse import OptionParser, OptionValueError import isc.util.process +import isc.log import isc.cc @@ -563,6 +564,16 @@ 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 + sev = 'INFO' + if options.verbose: + 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) + signal.signal(signal.SIGTERM, signal_handler) # Announce startup. From 44f6dc45fffe9a44d8700bbb601dab169568f7ac Mon Sep 17 00:00:00 2001 From: Michal 'vorner' Vaner Date: Tue, 18 Dec 2012 12:11:23 +0100 Subject: [PATCH 2/8] [1190] Generate the msgq message file It is empty now, just updating the build system - yes, we really do need 2 new files and 2 makefiles to generate one message file :-|. --- src/bin/msgq/Makefile.am | 13 ++++++++++++- src/bin/msgq/msgq.py.in | 1 + src/bin/msgq/msgq_messages.mes | 0 src/lib/python/isc/log_messages/Makefile.am | 2 ++ src/lib/python/isc/log_messages/msgq_messages.py | 1 + 5 files changed, 16 insertions(+), 1 deletion(-) create mode 100644 src/bin/msgq/msgq_messages.mes create mode 100644 src/lib/python/isc/log_messages/msgq_messages.py diff --git a/src/bin/msgq/Makefile.am b/src/bin/msgq/Makefile.am index 4244d07c42..5f377b1eef 100644 --- a/src/bin/msgq/Makefile.am +++ b/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 >$@ diff --git a/src/bin/msgq/msgq.py.in b/src/bin/msgq/msgq.py.in index fda1b2371a..71b8d28414 100755 --- a/src/bin/msgq/msgq.py.in +++ b/src/bin/msgq/msgq.py.in @@ -32,6 +32,7 @@ import random from optparse import OptionParser, OptionValueError import isc.util.process import isc.log +from isc.log_messages.msgq_messages import * import isc.cc diff --git a/src/bin/msgq/msgq_messages.mes b/src/bin/msgq/msgq_messages.mes new file mode 100644 index 0000000000..e69de29bb2 diff --git a/src/lib/python/isc/log_messages/Makefile.am b/src/lib/python/isc/log_messages/Makefile.am index 6d23df3b5d..e0310465d4 100644 --- a/src/lib/python/isc/log_messages/Makefile.am +++ b/src/lib/python/isc/log_messages/Makefile.am @@ -16,6 +16,7 @@ EXTRA_DIST += libddns_messages.py EXTRA_DIST += libxfrin_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 @@ -33,6 +34,7 @@ CLEANFILES += libddns_messages.pyc CLEANFILES += libxfrin_messages.pyc CLEANFILES += server_common_messages.pyc CLEANFILES += dbutil_messages.pyc +CLEANFILES += msgq_messages.pyc CLEANDIRS = __pycache__ diff --git a/src/lib/python/isc/log_messages/msgq_messages.py b/src/lib/python/isc/log_messages/msgq_messages.py new file mode 100644 index 0000000000..81efa416e9 --- /dev/null +++ b/src/lib/python/isc/log_messages/msgq_messages.py @@ -0,0 +1 @@ +from work.msgq_messages import * From 95483cb529b42683002528186eb29d6854e7ce0e Mon Sep 17 00:00:00 2001 From: Michal 'vorner' Vaner Date: Wed, 19 Dec 2012 12:49:05 +0100 Subject: [PATCH 3/8] [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 | 48 +++++++++++------------ src/bin/msgq/msgq_messages.mes | 67 +++++++++++++++++++++++++++++++++ src/bin/msgq/run_msgq.sh.in | 18 ++++++++- src/bin/msgq/tests/msgq_test.py | 2 + 4 files changed, 108 insertions(+), 27 deletions(-) diff --git a/src/bin/msgq/msgq.py.in b/src/bin/msgq/msgq.py.in index 71b8d28414..49e9e4c68d 100755 --- a/src/bin/msgq/msgq.py.in +++ b/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: diff --git a/src/bin/msgq/msgq_messages.mes b/src/bin/msgq/msgq_messages.mes index e69de29bb2..af5ee64f48 100644 --- a/src/bin/msgq/msgq_messages.mes +++ b/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 +# /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 diff --git a/src/bin/msgq/run_msgq.sh.in b/src/bin/msgq/run_msgq.sh.in index 3e464bedca..3ab4024718 100644 --- a/src/bin/msgq/run_msgq.sh.in +++ b/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 diff --git a/src/bin/msgq/tests/msgq_test.py b/src/bin/msgq/tests/msgq_test.py index 4060190913..e74f118195 100644 --- a/src/bin/msgq/tests/msgq_test.py +++ b/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() From 774a4996dafc7a5809ab0ae08851d412e996e970 Mon Sep 17 00:00:00 2001 From: Michal 'vorner' Vaner Date: Wed, 19 Dec 2012 13:11:40 +0100 Subject: [PATCH 4/8] [1190] Make the tests work Do the initialization in tests too (the executable script initializes it only when run separately, to know the correct parameters). Also, remove deprecated and unused auxiliary script that doesn't and didn't work. --- configure.ac | 2 -- src/bin/msgq/tests/Makefile.am | 2 ++ src/bin/msgq/tests/msgq_test.in | 28 ---------------------------- src/bin/msgq/tests/msgq_test.py | 1 + 4 files changed, 3 insertions(+), 30 deletions(-) delete mode 100755 src/bin/msgq/tests/msgq_test.in diff --git a/configure.ac b/configure.ac index 3f7a269b19..adbf042b62 100644 --- a/configure.ac +++ b/configure.ac @@ -1355,7 +1355,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 @@ -1422,7 +1421,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 diff --git a/src/bin/msgq/tests/Makefile.am b/src/bin/msgq/tests/Makefile.am index 50b218b915..c9ef5d304d 100644 --- a/src/bin/msgq/tests/Makefile.am +++ b/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 diff --git a/src/bin/msgq/tests/msgq_test.in b/src/bin/msgq/tests/msgq_test.in deleted file mode 100755 index e3aae89249..0000000000 --- a/src/bin/msgq/tests/msgq_test.in +++ /dev/null @@ -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 $* diff --git a/src/bin/msgq/tests/msgq_test.py b/src/bin/msgq/tests/msgq_test.py index e74f118195..417418f34b 100644 --- a/src/bin/msgq/tests/msgq_test.py +++ b/src/bin/msgq/tests/msgq_test.py @@ -458,5 +458,6 @@ class SendNonblock(unittest.TestCase): if __name__ == '__main__': + isc.log.init("b10-msgq") isc.log.resetUnitTestRootLogger() unittest.main() From 96c1a3cc7becc69e4bb24cd3e40aaa605e3d90e3 Mon Sep 17 00:00:00 2001 From: Michal 'vorner' Vaner Date: Wed, 19 Dec 2012 13:15:12 +0100 Subject: [PATCH 5/8] [1190] Reorder the messages alphabetically And do nothing more, so it's easy to review. --- src/bin/msgq/msgq_messages.mes | 38 +++++++++++++++++----------------- 1 file changed, 19 insertions(+), 19 deletions(-) diff --git a/src/bin/msgq/msgq_messages.mes b/src/bin/msgq/msgq_messages.mes index af5ee64f48..8f9c341a40 100644 --- a/src/bin/msgq/msgq_messages.mes +++ b/src/bin/msgq/msgq_messages.mes @@ -19,33 +19,30 @@ # /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_HDR_DECODE_ERR Error decoding header received from socket %1: %2 +Error % MSGQ_LISTENER_FAILED Failed to initialize listener on socket file '%1': %2 Fatal +% MSGQ_LISTENER_SETUP Starting to listen on socket file '%1' +Debug + % MSGQ_LISTENER_STARTED Successfully started to listen Debug +% MSGQ_POLL_ERR Error while polling for events: %1 +Error + +% MSGQ_POLL_UNKNOWN_EVENT Got an unknown event from the poller: %1 +Error + % 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 @@ -55,13 +52,16 @@ 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_SOCK_CLOSE Closing socket fd %1 +Debug % MSGQ_START Msgq version %1 starting Debug % MSGQ_START_FAIL Error during startup: %1 + +% MSGQ_SUBS_APPEND_TARGET Appending to existing target for subscription to group '%1' for instance '%2' +Debug + +% MSGQ_SUBS_NEW_TARGET Creating new target for subscription to group '%1' for instance '%2' +Debug From 15f662d68bbce471df63609cf8deccb280670048 Mon Sep 17 00:00:00 2001 From: Michal 'vorner' Vaner Date: Wed, 19 Dec 2012 13:39:30 +0100 Subject: [PATCH 6/8] [1190] Provide logging descriptions --- src/bin/msgq/msgq.py.in | 6 ++-- src/bin/msgq/msgq_messages.mes | 53 ++++++++++++++++++++++++---------- 2 files changed, 40 insertions(+), 19 deletions(-) diff --git a/src/bin/msgq/msgq.py.in b/src/bin/msgq/msgq.py.in index 49e9e4c68d..5f09f91e1d 100755 --- a/src/bin/msgq/msgq.py.in +++ b/src/bin/msgq/msgq.py.in @@ -287,8 +287,8 @@ class MsgQ: try: routing, data = self.read_packet(fd, sock) except MsgQReceiveError as err: - self.kill_socket(fd, sock) logger.error(MSGQ_RECV_ERR, fd, err) + self.kill_socket(fd, sock) return try: @@ -491,7 +491,7 @@ class MsgQ: if err.args[0] == errno.EINTR: events = [] else: - logger.error(MSGQ_POLL_ERR, 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: - logger.error(MSGQ_POLL_UNKNOWN_EVENT, event) + logger.error(MSGQ_POLL_UNKNOWN_EVENT, fd, event) def run_kqueue(self): while self.running: diff --git a/src/bin/msgq/msgq_messages.mes b/src/bin/msgq/msgq_messages.mes index 8f9c341a40..d30e3eba21 100644 --- a/src/bin/msgq/msgq_messages.mes +++ b/src/bin/msgq/msgq_messages.mes @@ -20,48 +20,69 @@ # messages are in the correct order. % MSGQ_HDR_DECODE_ERR Error decoding header received from socket %1: %2 -Error +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 -Fatal +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 +Debug message. The listener is trying to open a listening socket. % MSGQ_LISTENER_STARTED Successfully started to listen -Debug +Debug message. The message queue successfully opened a listening socket and +waits for incoming connections. % MSGQ_POLL_ERR Error while polling for events: %1 -Error +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: %1 -Error +% 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 -Error, ignoring +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 -Error +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 +Debug message. This message includes the whole routing header of a packet. % MSGQ_RECV_INVALID_CMD Received invalid command: %1 -Error +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 -Error +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 +Debug message. Closing the mentioned socket. % MSGQ_START Msgq version %1 starting -Debug +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 +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 +Debug message. Creating a new subscription. Also creating a new data structure +to hold it. From 291591772d83ff6b5ec9412b03624d2c9f13dc82 Mon Sep 17 00:00:00 2001 From: Michal 'vorner' Vaner Date: Fri, 21 Dec 2012 14:45:24 +0100 Subject: [PATCH 7/8] [1190] Minor fixes according to review One leftover variable and one mismatched name. --- src/bin/msgq/msgq.py.in | 2 -- src/bin/msgq/msgq_messages.mes | 2 +- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/src/bin/msgq/msgq.py.in b/src/bin/msgq/msgq.py.in index 5f09f91e1d..cf160cb189 100755 --- a/src/bin/msgq/msgq.py.in +++ b/src/bin/msgq/msgq.py.in @@ -568,8 +568,6 @@ if __name__ == "__main__": sev = 'INFO' if options.verbose: 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) signal.signal(signal.SIGTERM, signal_handler) diff --git a/src/bin/msgq/msgq_messages.mes b/src/bin/msgq/msgq_messages.mes index d30e3eba21..21c5aa8a06 100644 --- a/src/bin/msgq/msgq_messages.mes +++ b/src/bin/msgq/msgq_messages.mes @@ -60,7 +60,7 @@ the corresponding socket is dropped. % MSGQ_RECV_HDR Received header: %1 Debug message. This message includes the whole routing header of a packet. -% MSGQ_RECV_INVALID_CMD Received invalid command: %1 +% 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. From daf78976a3df91027c2a82cd0a794255b60507b0 Mon Sep 17 00:00:00 2001 From: Michal 'vorner' Vaner Date: Fri, 21 Dec 2012 15:07:02 +0100 Subject: [PATCH 8/8] [1190] Note a ticket number for TODO --- src/bin/msgq/msgq.py.in | 1 + 1 file changed, 1 insertion(+) diff --git a/src/bin/msgq/msgq.py.in b/src/bin/msgq/msgq.py.in index cf160cb189..693760078c 100755 --- a/src/bin/msgq/msgq.py.in +++ b/src/bin/msgq/msgq.py.in @@ -565,6 +565,7 @@ if __name__ == "__main__": # 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'