From: Dave Tucker Date: Sun, 30 Mar 2014 11:26:55 +0000 (+0100) Subject: Python Logging Formatting Improvements X-Git-Tag: sliver-openvswitch-2.2.90-1~3^2~67 X-Git-Url: http://git.onelab.eu/?p=sliver-openvswitch.git;a=commitdiff_plain;h=a5ed8fe32cb3c996837c61af2e358fa34dc9936f 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 Signed-off-by: Ben Pfaff --- diff --git a/AUTHORS b/AUTHORS index 16255d4f4..e0abdb950 100644 --- 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 +Dave Tucker dave@dtucker.co.uk David Erickson derickso@stanford.edu David S. Miller davem@davemloft.net David Yang davidy@vmware.com diff --git a/NEWS b/NEWS index 79255980d..02ecf5b54 100644 --- 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. + - 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 2ccef7ffe..c62e40711 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 478f08e86..580b1bc23 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: @@ -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.""" diff --git a/tests/vlog.at b/tests/vlog.at index 35336ce55..262256578 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 , line ,/' \ 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 , line , in main assert fail AssertionError -6|module_0|ERR|error exception + 6 | module_0 | ERR | error exception Traceback (most recent call last): File , line , in main assert fail AssertionError -7|module_0|WARN|warn exception + 7 | module_0 | WARN | warn exception Traceback (most recent call last): File , line , in main assert fail AssertionError -8|module_0|INFO|information exception + 8 | module_0 | INFO | information exception Traceback (most recent call last): File , line , in main assert fail AssertionError -9|module_0|DBG|debug exception + 9 | module_0 | DBG | debug exception Traceback (most recent call last): File , line , in main assert fail AssertionError -10|module_0|ERR|exception + 10 | module_0 | ERR | exception Traceback (most recent call last): File , line , 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 , line , in main assert fail AssertionError -17|module_1|ERR|error exception + 17 | module_1 | ERR | error exception Traceback (most recent call last): File , line , in main assert fail AssertionError -18|module_1|WARN|warn exception + 18 | module_1 | WARN | warn exception Traceback (most recent call last): File , line , in main assert fail AssertionError -19|module_1|INFO|information exception + 19 | module_1 | INFO | information exception Traceback (most recent call last): File , line , in main assert fail AssertionError -21|module_1|ERR|exception + 21 | module_1 | ERR | exception Traceback (most recent call last): File , line , 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 , line , in main assert fail AssertionError -28|module_2|ERR|error exception + 28 | module_2 | ERR | error exception Traceback (most recent call last): File , line , in main assert fail AssertionError -29|module_2|WARN|warn exception + 29 | module_2 | WARN | warn exception Traceback (most recent call last): File , line , in main assert fail AssertionError -32|module_2|ERR|exception + 32 | module_2 | ERR | exception Traceback (most recent call last): File , line , 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