[ovs-dev] [PATCH v3 1/1] Python Logging Formatting Improvements

Dave Tucker dave at dtucker.co.uk
Sun Mar 30 11:45:28 UTC 2014


In v2 I addressed the comments on v1.
	- Added myself to AUTHORS
	- Updated the manpage
	- Added a NEWS item
	- Fixed getting program name and process id
	- Fixed TODO for subprogram (thread) name

The v2 implementation for getting the thread name was for this to be passed in when the class is instantiated. I wasn't happy with this...

So, in v3, I replaced this with a call to 'threading.current_thread().name'

-- Dave

On 30 Mar 2014, at 12:26, Dave Tucker wrote:

> 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 at dtucker.co.uk>
> ---
> AUTHORS            |   1 +
> NEWS               |   1 +
> lib/vlog.man       |   7 +--
> python/ovs/vlog.py | 128 ++++++++++++++++++++++++++++++++++++++++++++++++-----
> tests/vlog.at      |  82 ++++++++++++++++++----------------
> 5 files changed, 164 insertions(+), 55 deletions(-)
>
> diff --git a/AUTHORS b/AUTHORS
> index b189957..f7d175c 100644
> --- a/AUTHORS
> +++ b/AUTHORS
> @@ -32,6 +32,7 @@ Daniel Roman            droman at nicira.com
> Daniele Di Proietto     daniele.di.proietto at gmail.com
> Daniele Venturino       daniele.venturino at m3s.it
> Danny Kukawka           danny.kukawka at bisect.de
> +Dave Tucker             dave at dtucker.co.uk
> David Erickson          derickso at stanford.edu
> David S. Miller         davem at davemloft.net
> David Yang              davidy at vmware.com
> diff --git a/NEWS b/NEWS
> index 5f4632c..353086b 100644
> --- a/NEWS
> +++ b/NEWS
> @@ -11,6 +11,7 @@ Post-v2.1.0
> - Support for Linux kernels up to 3.12. On Kernel 3.12 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
> diff --git a/lib/vlog.man b/lib/vlog.man
> index 2ccef7f..c62e407 100644
> --- 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).
> .
> -.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
> @@ -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]
> diff --git a/python/ovs/vlog.py b/python/ovs/vlog.py
> index 478f08e..580b1bc 100644
> --- a/python/ovs/vlog.py
> +++ b/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();
> -        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)
> -            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:
> -                    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)
> @@ -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:
> @@ -191,12 +275,31 @@ class Vlog:
>              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."""
> diff --git a/tests/vlog.at b/tests/vlog.at
> index 35336ce..2622565 100644
> --- 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([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
> -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
> -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
> -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
> -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
> -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
> -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.
> -message
> -message2
> + Entering run loop.
> + message
> + 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.
> -message
> + Entering run loop.
> + 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
> -- 
> 1.9.1
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 882 bytes
Desc: OpenPGP digital signature
URL: <http://mail.openvswitch.org/pipermail/ovs-dev/attachments/20140330/790dd391/attachment-0005.sig>


More information about the dev mailing list