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>

diff --git a/AUTHORS b/AUTHORS
index 16255d4..e0abdb9 100644 (file)
--- a/AUTHORS
+++ b/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
 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
 David Erickson          derickso@stanford.edu
 David S. Miller         davem@davemloft.net
 David Yang              davidy@vmware.com

diff --git a/NEWS b/NEWS
index 7925598..02ecf5b 100644 (file)
--- a/NEWS
+++ b/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.
    - 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
 
 
 v2.1.0 - xx xxx xxxx

diff --git a/lib/vlog.man b/lib/vlog.man
index 2ccef7f..c62e407 100644 (file)
--- a/lib/vlog.man
+++ b/lib/vlog.man
@@ -26,7 +26,7 @@ On Windows platform, \fBsyslog\fR is accepted as a word and is only
 useful along with the \fB\-\-syslog\-target\fR option (the word has no
 effect otherwise).
 .
 useful along with the \fB\-\-syslog\-target\fR option (the word has no
 effect otherwise).
 .

-.IP \(bu 
+.IP \(bu

 \fBoff\fR, \fBemer\fR, \fBerr\fR, \fBwarn\fR, \fBinfo\fR, or
 \fBdbg\fR, to control the log level.  Messages of the given severity
 or higher will be logged, and messages of lower severity will be
 \fBoff\fR, \fBemer\fR, \fBerr\fR, \fBwarn\fR, \fBinfo\fR, or
 \fBdbg\fR, to control the log level.  Messages of the given severity
 or higher will be logged, and messages of lower severity will be


@@ -49,15 +49,10 @@ a word but has no effect.
 Sets the maximum logging verbosity level, equivalent to
 \fB\-\-verbose=dbg\fR.
 .
 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.
 .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]
 .
 .TP
 \fB\-\-log\-file\fR[\fB=\fIfile\fR]

diff --git a/python/ovs/vlog.py b/python/ovs/vlog.py
index 478f08e..580b1bc 100644 (file)
--- a/python/ovs/vlog.py
+++ b/python/ovs/vlog.py
@@ -16,15 +16,22 @@
 import datetime
 import logging
 import logging.handlers
 import datetime
 import logging
 import logging.handlers

+import os

 import re
 import socket
 import sys
 import re
 import socket
 import sys

+import threading

 
 import ovs.dirs
 import ovs.unixctl
 import ovs.util
 
 FACILITIES = {"console": "info", "file": "info", "syslog": "info"}
 
 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,
 LEVELS = {
     "dbg": logging.DEBUG,
     "info": logging.INFO,


@@ -42,9 +49,11 @@ def get_level(level_str):
 class Vlog:
     __inited = False
     __msg_num = 0
 class Vlog:
     __inited = False
     __msg_num = 0

+    __start_time = 0

     __mfl = {}  # Module -> facility -> level
     __log_file = None
     __file_handler = None
     __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
 
     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
 
         if not Vlog.__inited:
             return
 

-        dt = datetime.datetime.utcnow();
-        now = dt.strftime("%Y-%m-%dT%H:%M:%S.%%03iZ") % (dt.microsecond/1000)
-        syslog_message = ("%s|%s|%s|%s"
-                           % (Vlog.__msg_num, self.name, level, message))
-
-        level = LEVELS.get(level.lower(), logging.DEBUG)
+        level_num = LEVELS.get(level.lower(), logging.DEBUG)
+        msg_num = Vlog.__msg_num

         Vlog.__msg_num += 1
 
         for f, f_level in Vlog.__mfl[self.name].iteritems():
             f_level = LEVELS.get(f_level, logging.CRITICAL)
         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 f == "syslog":
-                    message = "ovs|" + syslog_message
+            if level_num >= f_level:
+                msg = self._build_message(message, f, level, msg_num)
+                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:
                 else:

-                    message = "%s|%s" % (now, syslog_message)
-                logging.getLogger(f).log(level, message, **kwargs)
+                    subprogram = ""
+                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)
 
     def emer(self, message, **kwargs):
         self.__log("EMER", message, **kwargs)


@@ -130,6 +213,7 @@ class Vlog:
             return
 
         Vlog.__inited = True
             return
 
         Vlog.__inited = True

+        Vlog.__start_time = datetime.datetime.utcnow()

         logging.raiseExceptions = False
         Vlog.__log_file = log_file
         for f in FACILITIES:
         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
 
             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
 
     @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:
             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 _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."""
 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."""

diff --git a/tests/vlog.at b/tests/vlog.at
index 35336ce..2622565 100644 (file)
--- a/tests/vlog.at
+++ b/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([$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
 -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
+  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
 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
 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
 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
 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
 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
 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
+  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
 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
 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
 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
 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
 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
+  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
 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
 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
 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
 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
 AT_CHECK([APPCTL -t test-unixctl.py exit])
 
 AT_CHECK([sed 's/.*|//' log.old], [0], [dnl

-Entering run loop.
-message
-message2
+ Entering run loop.
+ message
+ message2

 ])
 AT_CHECK([sed 's/.*|//' log], [0], [dnl
 ])
 AT_CHECK([sed 's/.*|//' log], [0], [dnl

-message3
+ message3

 ])
 AT_CLEANUP
 
 ])
 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
 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.
-message
+ Entering run loop.
+ message

 ])
 AT_CHECK([sed 's/.*|//' log], [0], [dnl
 ])
 AT_CHECK([sed 's/.*|//' log], [0], [dnl

-message3
+ message3

 ])
 AT_CLEANUP
 
 ])
 AT_CLEANUP
 


@@ -225,4 +223,14 @@ stream            info       info        dbg
 test-unixctl      info       info        dbg
 unixctl_server    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
 AT_CLEANUP