python: Create new vlog module.

Currently, each python daemon has to come up with it's own logging
solution.  These logging strategies are not consistent across the
python code or with the C vlog module.  This patch adds a new
logging module which hopes to solve the problem.  This new module
generates log messages in a manner consistent with the C code.
Furthermore, it can easily be extended to support things like rate
limiters in the future.

This patch does not update any python code to use the new module.

6 files changed, 359 insertions, 2 deletions

diff --git a/python/ovs/automake.mk b/python/ovs/automake.mk
index a1787ba5c..224732809 100644
--- a/python/ovs/automake.mk
+++ b/python/ovs/automake.mk
@@ -20,6 +20,7 @@ ovs_pyfiles = \
 	python/ovs/socket_util.py \
 	python/ovs/stream.py \
 	python/ovs/timeval.py \
+	python/ovs/vlog.py \
 	python/ovs/util.py
 EXTRA_DIST += $(ovs_pyfiles) python/ovs/dirs.py
 
diff --git a/python/ovs/vlog.py b/python/ovs/vlog.py
new file mode 100644
index 000000000..ad5378117
--- /dev/null
+++ b/python/ovs/vlog.py
@@ -0,0 +1,200 @@
+
+# Copyright (c) 2011 Nicira Networks
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at:
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import datetime
+import logging
+import logging.handlers
+import socket
+import sys
+
+import ovs.dirs
+import ovs.util
+
+FACILITIES = {"console": "info", "file": "info", "syslog": "info"}
+LEVELS = {
+    "dbg": logging.DEBUG,
+    "info": logging.INFO,
+    "warn": logging.WARNING,
+    "err": logging.ERROR,
+    "emer": logging.CRITICAL,
+    "off": logging.CRITICAL
+}
+
+
+def get_level(level_str):
+    return LEVELS.get(level_str.lower())
+
+
+class Vlog:
+    __inited = False
+    __msg_num = 0
+    __mfl = {}  # Module -> facility -> level
+
+    def __init__(self, name):
+        """Creates a new Vlog object representing a module called 'name'.  The
+        created Vlog object will do nothing until the Vlog.init() static method
+        is called.  Once called, no more Vlog objects may be created."""
+
+        assert not Vlog.__inited
+        self.name = name.lower()
+        if name not in Vlog.__mfl:
+            Vlog.__mfl[self.name] = FACILITIES.copy()
+
+    def __log(self, level, message, **kwargs):
+        if not Vlog.__inited:
+            return
+
+        now = datetime.datetime.now().strftime("%b %d %H:%M:%S")
+        message = ("%s|%s|%s|%s|%s"
+                   % (now, Vlog.__msg_num, self.name, level, message))
+
+        level = LEVELS.get(level.lower(), logging.DEBUG)
+        Vlog.__msg_num += 1
+
+        for f, f_level in Vlog.__mfl[self.name].iteritems():
+            f_level = LEVELS.get(f_level, logging.CRITICAL)
+            if level >= f_level:
+                logging.getLogger(f).log(level, message, **kwargs)
+
+    def emer(self, message, **kwargs):
+        self.__log("EMER", message, **kwargs)
+
+    def err(self, message, **kwargs):
+        self.__log("ERR", message, **kwargs)
+
+    def warn(self, message, **kwargs):
+        self.__log("WARN", message, **kwargs)
+
+    def info(self, message, **kwargs):
+        self.__log("INFO", message, **kwargs)
+
+    def dbg(self, message, **kwargs):
+        self.__log("DBG", message, **kwargs)
+
+    def exception(self, message):
+        """Logs 'message' at ERR log level.  Includes a backtrace when in
+        exception context."""
+        self.err(message, exc_info=True)
+
+    @staticmethod
+    def init(log_file=None):
+        """Intializes the Vlog module.  Causes Vlog to write to 'log_file' if
+        not None.  Should be called after all Vlog objects have been created.
+        No logging will occur until this function is called."""
+
+        if Vlog.__inited:
+            return
+
+        Vlog.__inited = True
+        logging.raiseExceptions = False
+        for f in FACILITIES:
+            logger = logging.getLogger(f)
+            logger.setLevel(logging.DEBUG)
+
+            try:
+                if f == "console":
+                    logger.addHandler(logging.StreamHandler(sys.stderr))
+                elif f == "syslog":
+                    logger.addHandler(logging.handlers.SysLogHandler(
+                        address="/dev/log",
+                        facility=logging.handlers.SysLogHandler.LOG_DAEMON))
+                elif f == "file" and log_file:
+                    logger.addHandler(logging.FileHandler(log_file))
+            except (IOError, socket.error):
+                logger.setLevel(logging.CRITICAL)
+
+    @staticmethod
+    def set_level(module, facility, level):
+        """ Sets the log level of the 'module'-'facility' tuple to 'level'.
+        All three arguments are strings which are interpreted the same as
+        arguments to the --verbose flag.  Should be called after all Vlog
+        objects have already been created."""
+
+        module = module.lower()
+        facility = facility.lower()
+        level = level.lower()
+
+        if facility != "any" and facility not in FACILITIES:
+            return
+
+        if module != "any" and module not in Vlog.__mfl:
+            return
+
+        if level not in LEVELS:
+            return
+
+        if module == "any":
+            modules = Vlog.__mfl.keys()
+        else:
+            modules = [module]
+
+        if facility == "any":
+            facilities = FACILITIES.keys()
+        else:
+            facilities = [facility]
+
+        for m in modules:
+            for f in facilities:
+                Vlog.__mfl[m][f] = level
+
+
+def add_args(parser):
+    """Adds vlog related options to 'parser', an ArgumentParser object.  The
+    resulting arguments parsed by 'parser' should be passed to handle_args."""
+
+    group = parser.add_argument_group(title="Logging Options")
+    group.add_argument("--log-file", nargs="?", const="default",
+                       help="Enables logging to a file.  Default log file"
+                       " is used if LOG_FILE is omitted.")
+    group.add_argument("-v", "--verbose", nargs="*",
+                       help="Sets logging levels, see ovs-vswitchd(8)."
+                       "  Defaults to ANY:ANY:dbg.")
+
+
+def handle_args(args):
+    """ Handles command line arguments ('args') parsed by an ArgumentParser.
+    The ArgumentParser should have been primed by add_args().  Also takes care
+    of initializing the Vlog module."""
+
+    log_file = args.log_file
+    if log_file == "default":
+        log_file = "%s/%s.log" % (ovs.dirs.LOGDIR, ovs.util.PROGRAM_NAME)
+
+    if args.verbose is None:
+        args.verbose = []
+    elif args.verbose == []:
+        args.verbose = ["any:any:dbg"]
+
+    for verbose in args.verbose:
+        args = verbose.split(':')
+
+        if len(args) >= 3:
+            level = args[2]
+        else:
+            level = "dbg"
+
+        if len(args) >= 2:
+            facility = args[1]
+        else:
+            facility = "any"
+
+        if len(args) >= 1:
+            module = args[0]
+        else:
+            module = "any"
+
+        Vlog.set_level(module, facility, level)
+
+    Vlog.init(log_file)
diff --git a/tests/automake.mk b/tests/automake.mk
index 581bdc817..54c0c99d8 100644
--- a/tests/automake.mk
+++ b/tests/automake.mk
@@ -53,7 +53,8 @@ TESTSUITE_AT = \
 	tests/ovs-vsctl.at \
 	tests/ovs-monitor-ipsec.at \
 	tests/ovs-xapi-sync.at \
-	tests/interface-reconfigure.at
+	tests/interface-reconfigure.at \
+	tests/vlog.at
 TESTSUITE = $(srcdir)/tests/testsuite
 DISTCLEANFILES += tests/atconfig tests/atlocal
 EXTRA_DIST += tests/compare-odp-actions.pl
@@ -338,7 +339,8 @@ EXTRA_DIST += \
 	tests/test-jsonrpc.py \
 	tests/test-ovsdb.py \
 	tests/test-reconnect.py \
-	tests/MockXenAPI.py
+	tests/MockXenAPI.py \
+	tests/test-vlog.py
 
 if HAVE_OPENSSL
 TESTPKI_FILES = \
diff --git a/tests/test-vlog.py b/tests/test-vlog.py
new file mode 100644
index 000000000..1c6a2df12
--- /dev/null
+++ b/tests/test-vlog.py
@@ -0,0 +1,48 @@
+# Copyright (c) 2011 Nicira Networks.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at:
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import argparse
+
+import ovs.vlog
+
+
+def main():
+    modules = [ovs.vlog.Vlog("module_%d" % i) for i in xrange(3)]
+
+    parser = argparse.ArgumentParser(description="Vlog Module Tester")
+    ovs.vlog.add_args(parser)
+    args = parser.parse_args()
+    ovs.vlog.handle_args(args)
+
+    for m in modules:
+        m.emer("emergency")
+        m.err("error")
+        m.warn("warning")
+        m.info("information")
+        m.dbg("debug")
+
+        try:
+            fail = False  # Silence pychecker warning.
+            assert fail
+        except AssertionError:
+            m.emer("emergency exception", exc_info=True)
+            m.err("error exception", exc_info=True)
+            m.warn("warn exception", exc_info=True)
+            m.info("information exception", exc_info=True)
+            m.dbg("debug exception", exc_info=True)
+            m.exception("exception")
+
+
+if __name__ == '__main__':
+    main()
diff --git a/tests/testsuite.at b/tests/testsuite.at
index 86085724e..b6fe7c336 100644
--- a/tests/testsuite.at
+++ b/tests/testsuite.at
@@ -67,3 +67,4 @@ m4_include([tests/ovs-vsctl.at])
 m4_include([tests/ovs-monitor-ipsec.at])
 m4_include([tests/ovs-xapi-sync.at])
 m4_include([tests/interface-reconfigure.at])
+m4_include([tests/vlog.at])
diff --git a/tests/vlog.at b/tests/vlog.at
new file mode 100644
index 000000000..bb3b3c108
--- /dev/null
+++ b/tests/vlog.at
@@ -0,0 +1,105 @@
+AT_BANNER([vlog])
+
+AT_SETUP([vlog - Python])
+AT_SKIP_IF([test $HAVE_PYTHON = no])
+AT_CHECK([$PYTHON $srcdir/test-vlog.py --log-file log_file \
+-v ANY:ANY:dbg module_1:ANY:info module_2:ANY:warn ANY:syslog:off \
+2>stderr_log])
+AT_CAPTURE_FILE([log_file])
+AT_CAPTURE_FILE([stderr_log])
+
+AT_CHECK([diff log_file stderr_log])
+
+AT_CHECK([sed -e 's/.* .* ..:..:..|//' \
+-e 's/File "[[^"]]*", line [[0-9]][[0-9]]*,/File <name>, line <number>,/' \
+stderr_log], [0], [dnl
+0|module_0|EMER|emergency
+1|module_0|ERR|error
+2|module_0|WARN|warning
+3|module_0|INFO|information
+4|module_0|DBG|debug
+5|module_0|EMER|emergency exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+6|module_0|ERR|error exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+7|module_0|WARN|warn exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+8|module_0|INFO|information exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+9|module_0|DBG|debug exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+10|module_0|ERR|exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+11|module_1|EMER|emergency
+12|module_1|ERR|error
+13|module_1|WARN|warning
+14|module_1|INFO|information
+16|module_1|EMER|emergency exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+17|module_1|ERR|error exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+18|module_1|WARN|warn exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+19|module_1|INFO|information exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+21|module_1|ERR|exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+22|module_2|EMER|emergency
+23|module_2|ERR|error
+24|module_2|WARN|warning
+27|module_2|EMER|emergency exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+28|module_2|ERR|error exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+29|module_2|WARN|warn exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+32|module_2|ERR|exception
+Traceback (most recent call last):
+  File <name>, line <number>, in main
+    assert fail
+AssertionError
+])
+
+AT_CLEANUP