Python Logging Formatting Improvements

The Open vSwitch daemons written in C support user-configured logging
patterns as described in ovs-appctl(8). This commit adds this capability
to the daemons written in Python.

- Add a '__log_patterns' attribute to the Vlog class
- Populate this using the default patterns in ovs-appctl(8)
- Add a '__start_time' attribute to the Vlog class to support '%r'
- Update the '_log' method to build the log message according to the
  pattern
- Add a 'set_pattern' method to allow the default patterns to be changed
- Update 'set_levels_from_string' to support setting the pattern from a
  string

Signed-off-by: Dave Tucker <dave@dtucker.co.uk>
Signed-off-by: Ben Pfaff <blp@nicira.com>

AUTHORS

@@ -32,6 +32,7 @@ Daniel Roman            droman@nicira.com
 Daniele Di Proietto     daniele.di.proietto@gmail.com
 Daniele Venturino       daniele.venturino@m3s.it
 Danny Kukawka           danny.kukawka@bisect.de
+Dave Tucker             dave@dtucker.co.uk
 David Erickson          derickso@stanford.edu
 David S. Miller         davem@davemloft.net
 David Yang              davidy@vmware.com

NEWS

@@ -16,6 +16,7 @@ Post-v2.1.0
    - Support for Linux kernels up to 3.13. From Kernel 3.12 onwards OVS uses
      tunnel API for GRE and VXLAN.
    - Added DPDK support.
+   - Added support for custom vlog patterns in Python
 
 
 v2.1.0 - xx xxx xxxx

lib/vlog.man

@@ -49,15 +49,10 @@ a word but has no effect.
 Sets the maximum logging verbosity level, equivalent to
 \fB\-\-verbose=dbg\fR.
 .
-.\" Python vlog doesn't implement -vPATTERN so only document it if
-.\" \*(PY is empty:
-.ie dPY
-.el \{
 .IP "\fB\-vPATTERN:\fIfacility\fB:\fIpattern\fR"
 .IQ "\fB\-\-verbose=PATTERN:\fIfacility\fB:\fIpattern\fR"
 Sets the log pattern for \fIfacility\fR to \fIpattern\fR.  Refer to
 \fBovs\-appctl\fR(8) for a description of the valid syntax for \fIpattern\fR.
-\}
 .
 .TP
 \fB\-\-log\-file\fR[\fB=\fIfile\fR]

python/ovs/vlog.py

@@ -16,15 +16,22 @@
 import datetime
 import logging
 import logging.handlers
+import os
 import re
 import socket
 import sys
+import threading
 
 import ovs.dirs
 import ovs.unixctl
 import ovs.util
 
 FACILITIES = {"console": "info", "file": "info", "syslog": "info"}
+PATTERNS = {
+    "console": "%D{%Y-%m-%dT%H:%M:%SZ}|%05N|%c%T|%p|%m",
+    "file": "%D{%Y-%m-%dT%H:%M:%S.###Z}|%05N|%c%T|%p|%m",
+    "syslog": "ovs|%05N|%c%T|%p|%m",
+}
 LEVELS = {
     "dbg": logging.DEBUG,
     "info": logging.INFO,
@@ -42,9 +49,11 @@ def get_level(level_str):
 class Vlog:
     __inited = False
     __msg_num = 0
+    __start_time = 0
     __mfl = {}  # Module -> facility -> level
     __log_file = None
     __file_handler = None
+    __log_patterns = PATTERNS
 
     def __init__(self, name):
         """Creates a new Vlog object representing a module called 'name'.  The
@@ -60,22 +69,96 @@ class Vlog:
         if not Vlog.__inited:
             return
 
-        dt = datetime.datetime.utcnow();
+        level_num = LEVELS.get(level.lower(), logging.DEBUG)
-        now = dt.strftime("%Y-%m-%dT%H:%M:%S.%%03iZ") % (dt.microsecond/1000)
+        msg_num = Vlog.__msg_num
-        syslog_message = ("%s|%s|%s|%s"
-                           % (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:
+            if level_num >= f_level:
-                if f == "syslog":
+                msg = self._build_message(message, f, level, msg_num)
-                    message = "ovs|" + syslog_message
+                logging.getLogger(f).log(level_num, msg, **kwargs)
+
+    def _build_message(self, message, facility, level, msg_num):
+        pattern = self.__log_patterns[facility]
+        tmp = pattern
+
+        tmp = self._format_time(tmp)
+
+        matches = re.findall("(%-?[0]?[0-9]?[AcmNnpPrtT])", tmp)
+        for m in matches:
+            if "A" in m:
+                tmp = self._format_field(tmp, m, ovs.util.PROGRAM_NAME)
+            elif "c" in m:
+                tmp = self._format_field(tmp, m, self.name)
+            elif "m" in m:
+                tmp = self._format_field(tmp, m, message)
+            elif "N" in m:
+                tmp = self._format_field(tmp, m, str(msg_num))
+            elif "n" in m:
+                tmp = re.sub(m, "\n", tmp)
+            elif "p" in m:
+                tmp = self._format_field(tmp, m, level.upper())
+            elif "P" in m:
+                self._format_field(tmp, m, str(os.getpid()))
+            elif "r" in m:
+                now = datetime.datetime.utcnow()
+                delta = now - self.__start_time
+                ms = delta.microseconds / 1000
+                tmp = self._format_field(tmp, m, str(ms))
+            elif "t" in m:
+                subprogram = threading.current_thread().name
+                if subprogram == "MainThread":
+                    subprogram = "main"
+                tmp = self._format_field(tmp, m, subprogram)
+            elif "T" in m:
+                subprogram = threading.current_thread().name
+                if not subprogram == "MainThread":
+                    subprogram = "({})".format(subprogram)
                 else:
-                    message = "%s|%s" % (now, syslog_message)
+                    subprogram = ""
-                logging.getLogger(f).log(level, message, **kwargs)
+                tmp = self._format_field(tmp, m, subprogram)
+        return tmp.strip()
+
+    def _format_field(self, tmp, match, replace):
+        formatting = re.compile("^%(0)?([1-9])?")
+        matches = formatting.match(match)
+        # Do we need to apply padding?
+        if not matches.group(1) and replace != "":
+            replace = replace.center(len(replace)+2)
+        # Does the field have a minimum width
+        if matches.group(2):
+            min_width = int(matches.group(2))
+            if len(replace) < min_width:
+                replace = replace.center(min_width)
+        return re.sub(match, replace, tmp)
+
+    def _format_time(self, tmp):
+        date_regex = re.compile('(%(0?[1-9]?[dD])(\{(.*)\})?)')
+        match = date_regex.search(tmp)
+
+        if match is None:
+            return tmp
+
+        # UTC date or Local TZ?
+        if match.group(2) == "d":
+            now = datetime.datetime.now()
+        elif match.group(2) == "D":
+            now = datetime.datetime.utcnow()
+
+        # Custom format or ISO format?
+        if match.group(3):
+            time = datetime.date.strftime(now, match.group(4))
+            try:
+                i = len(re.search("#+", match.group(4)).group(0))
+                msec = '{0:0>{i}.{i}}'.format(str(now.microsecond / 1000), i=i)
+                time = re.sub('#+', msec, time)
+            except AttributeError:
+                pass
+        else:
+            time = datetime.datetime.isoformat(now.replace(microsecond=0))
+
+        return self._format_field(tmp, match.group(1), time)
 
     def emer(self, message, **kwargs):
         self.__log("EMER", message, **kwargs)
@@ -130,6 +213,7 @@ class Vlog:
             return
 
         Vlog.__inited = True
+        Vlog.__start_time = datetime.datetime.utcnow()
         logging.raiseExceptions = False
         Vlog.__log_file = log_file
         for f in FACILITIES:
@@ -190,13 +274,32 @@ class Vlog:
             for f in facilities:
                 Vlog.__mfl[m][f] = level
 
+    @staticmethod
+    def set_pattern(facility, pattern):
+        """ Sets the log pattern of the 'facility' to 'pattern' """
+        facility = facility.lower()
+        Vlog.__log_patterns[facility] = pattern
+
     @staticmethod
     def set_levels_from_string(s):
         module = None
         level = None
         facility = None
 
-        for word in [w.lower() for w in re.split('[ :]', s)]:
+        words = re.split('[ :]', s)
+        if words[0] == "pattern":
+            try:
+                if words[1] in FACILITIES and words[2]:
+                    segments = [words[i] for i in range(2, len(words))]
+                    pattern = "".join(segments)
+                    Vlog.set_pattern(words[1], pattern)
+                    return
+                else:
+                    return "Facility %s does not exist" % words[1]
+            except IndexError:
+                return "Please supply a valid pattern and facility"
+
+        for word in [w.lower() for w in words]:
             if word == "any":
                 pass
             elif word in FACILITIES:
@@ -260,6 +363,7 @@ class Vlog:
     def _unixctl_vlog_list(conn, unused_argv, unused_aux):
         conn.reply(Vlog.get_levels())
 
+
 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."""

tests/vlog.at

@@ -7,94 +7,92 @@ AT_CAPTURE_FILE([stderr_log])
 AT_CHECK([$PYTHON $srcdir/test-vlog.py --log-file log_file \
 -v dbg module_1:info module_2:warn syslog:off 2>stderr_log])
 
-AT_CHECK([diff log_file stderr_log])
+AT_CHECK([sed -e 's/.*-.*-.*T..:..:..Z |//' \
-
-AT_CHECK([sed -e 's/.*-.*-.*T..:..:..\....Z|//' \
 -e 's/File ".*", line [[0-9]][[0-9]]*,/File <name>, line <number>,/' \
 stderr_log], [0], [dnl
-0|module_0|EMER|emergency
+  0  | module_0 | EMER | emergency
-1|module_0|ERR|error
+  1  | module_0 | ERR | error
-2|module_0|WARN|warning
+  2  | module_0 | WARN | warning
-3|module_0|INFO|information
+  3  | module_0 | INFO | information
-4|module_0|DBG|debug
+  4  | module_0 | DBG | debug
-5|module_0|EMER|emergency exception
+  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
+  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
+  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
+  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
+  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
+  10 | module_0 | ERR | exception
 Traceback (most recent call last):
   File <name>, line <number>, in main
     assert fail
 AssertionError
-11|module_1|EMER|emergency
+  11 | module_1 | EMER | emergency
-12|module_1|ERR|error
+  12 | module_1 | ERR | error
-13|module_1|WARN|warning
+  13 | module_1 | WARN | warning
-14|module_1|INFO|information
+  14 | module_1 | INFO | information
-16|module_1|EMER|emergency exception
+  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
+  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
+  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
+  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
+  21 | module_1 | ERR | exception
 Traceback (most recent call last):
   File <name>, line <number>, in main
     assert fail
 AssertionError
-22|module_2|EMER|emergency
+  22 | module_2 | EMER | emergency
-23|module_2|ERR|error
+  23 | module_2 | ERR | error
-24|module_2|WARN|warning
+  24 | module_2 | WARN | warning
-27|module_2|EMER|emergency exception
+  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
+  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
+  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
+  32 | module_2 | ERR | exception
 Traceback (most recent call last):
   File <name>, line <number>, in main
     assert fail
@@ -123,12 +121,12 @@ AT_CHECK([APPCTL -t test-unixctl.py log message3])
 AT_CHECK([APPCTL -t test-unixctl.py exit])
 
 AT_CHECK([sed 's/.*|//' log.old], [0], [dnl
-Entering run loop.
+ Entering run loop.
-message
+ message
-message2
+ message2
 ])
 AT_CHECK([sed 's/.*|//' log], [0], [dnl
-message3
+ message3
 ])
 AT_CLEANUP
 
@@ -174,11 +172,11 @@ AT_CHECK([APPCTL -t test-unixctl.py vlog/reopen])
 AT_CHECK([APPCTL -t test-unixctl.py log message3])
 AT_CHECK([APPCTL -t test-unixctl.py exit])
 AT_CHECK([sed 's/.*|//' log.old], [0], [dnl
-Entering run loop.
+ Entering run loop.
-message
+ message
 ])
 AT_CHECK([sed 's/.*|//' log], [0], [dnl
-message3
+ message3
 ])
 AT_CLEANUP
 
@@ -225,4 +223,14 @@ stream            info       info        dbg
 test-unixctl      info       info        dbg
 unixctl_server    info       info        dbg
 ])
+
+AT_CHECK([APPCTL -t test-unixctl.py vlog/set pattern], [0],
+  [Please supply a valid pattern and facility
+])
+AT_CHECK([APPCTL -t test-unixctl.py vlog/set pattern:nonexistent], [0],
+  [Facility nonexistent does not exist
+])
+AT_CHECK([APPCTL -t test-unixctl.py vlog/set pattern:file:'I<3OVS|%m'])
+AT_CHECK([APPCTL -t test-unixctl.py log patterntest])
+AT_CHECK([grep -q 'I<3OVS' log])
 AT_CLEANUP