1
2# Copyright (c) 2011, 2012, 2013, 2015, 2016 Nicira, Inc.
3#
4# Licensed under the Apache License, Version 2.0 (the "License");
5# you may not use this file except in compliance with the License.
6# You may obtain a copy of the License at:
7#
8#     http://www.apache.org/licenses/LICENSE-2.0
9#
10# Unless required by applicable law or agreed to in writing, software
11# distributed under the License is distributed on an "AS IS" BASIS,
12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13# See the License for the specific language governing permissions and
14# limitations under the License.
15
16import datetime
17import logging
18import logging.handlers
19import os
20import re
21import socket
22import sys
23import threading
24
25import ovs.dirs
26import ovs.unixctl
27import ovs.util
28
29import six
30from six.moves import range
31
32DESTINATIONS = {"console": "info", "file": "info", "syslog": "info"}
33PATTERNS = {
34    "console": "%D{%Y-%m-%dT%H:%M:%SZ}|%05N|%c%T|%p|%m",
35    "file": "%D{%Y-%m-%dT%H:%M:%S.###Z}|%05N|%c%T|%p|%m",
36    "syslog": "ovs|%05N|%c%T|%p|%m",
37}
38LEVELS = {
39    "dbg": logging.DEBUG,
40    "info": logging.INFO,
41    "warn": logging.WARNING,
42    "err": logging.ERROR,
43    "emer": logging.CRITICAL,
44    "off": logging.CRITICAL
45}
46FACILITIES = ['auth', 'authpriv', 'cron', 'daemon', 'ftp', 'kern', 'lpr',
47              'mail', 'news', 'syslog', 'user', 'uucp', 'local0', 'local1',
48              'local2', 'local3', 'local4', 'local5', 'local6', 'local7']
49syslog_facility = "daemon"
50syslog_handler = ''
51
52
53def get_level(level_str):
54    return LEVELS.get(level_str.lower())
55
56
57class Vlog(object):
58    __inited = False
59    __msg_num = 0
60    __start_time = 0
61    __mfl = {}  # Module -> destination -> level
62    __log_file = None
63    __file_handler = None
64    __log_patterns = PATTERNS
65
66    def __init__(self, name):
67        """Creates a new Vlog object representing a module called 'name'.  The
68        created Vlog object will do nothing until the Vlog.init() static method
69        is called.  Once called, no more Vlog objects may be created."""
70
71        assert not Vlog.__inited
72        self.name = name.lower()
73        if name not in Vlog.__mfl:
74            Vlog.__mfl[self.name] = DESTINATIONS.copy()
75
76    def __log(self, level, message, **kwargs):
77        if not Vlog.__inited:
78            return
79
80        level_num = LEVELS.get(level.lower(), logging.DEBUG)
81        msg_num = Vlog.__msg_num
82        Vlog.__msg_num += 1
83
84        for f, f_level in six.iteritems(Vlog.__mfl[self.name]):
85            f_level = LEVELS.get(f_level, logging.CRITICAL)
86            if level_num >= f_level:
87                msg = self._build_message(message, f, level, msg_num)
88                logging.getLogger(f).log(level_num, msg, **kwargs)
89
90    def _build_message(self, message, destination, level, msg_num):
91        pattern = self.__log_patterns[destination]
92        tmp = pattern
93
94        tmp = self._format_time(tmp)
95
96        matches = re.findall("(%-?[0]?[0-9]?[AcmNnpPrtT])", tmp)
97        for m in matches:
98            if "A" in m:
99                tmp = self._format_field(tmp, m, ovs.util.PROGRAM_NAME)
100            elif "c" in m:
101                tmp = self._format_field(tmp, m, self.name)
102            elif "m" in m:
103                tmp = self._format_field(tmp, m, message)
104            elif "N" in m:
105                tmp = self._format_field(tmp, m, str(msg_num))
106            elif "n" in m:
107                tmp = re.sub(m, "\n", tmp)
108            elif "p" in m:
109                tmp = self._format_field(tmp, m, level.upper())
110            elif "P" in m:
111                self._format_field(tmp, m, str(os.getpid()))
112            elif "r" in m:
113                now = datetime.datetime.utcnow()
114                delta = now - self.__start_time
115                ms = delta.microseconds / 1000
116                tmp = self._format_field(tmp, m, str(ms))
117            elif "t" in m:
118                subprogram = threading.currentThread().getName()
119                if subprogram == "MainThread":
120                    subprogram = "main"
121                tmp = self._format_field(tmp, m, subprogram)
122            elif "T" in m:
123                subprogram = threading.currentThread().getName()
124                if not subprogram == "MainThread":
125                    subprogram = "({})".format(subprogram)
126                else:
127                    subprogram = ""
128                tmp = self._format_field(tmp, m, subprogram)
129        return tmp.strip()
130
131    def _format_field(self, tmp, match, replace):
132        formatting = re.compile("^%(0)?([1-9])?")
133        matches = formatting.match(match)
134        # Do we need to apply padding?
135        if not matches.group(1) and replace != "":
136            replace = replace.center(len(replace) + 2)
137        # Does the field have a minimum width
138        if matches.group(2):
139            min_width = int(matches.group(2))
140            if len(replace) < min_width:
141                replace = replace.center(min_width)
142        return re.sub(match, replace, tmp)
143
144    def _format_time(self, tmp):
145        date_regex = re.compile('(%(0?[1-9]?[dD])(\{(.*)\})?)')
146        match = date_regex.search(tmp)
147
148        if match is None:
149            return tmp
150
151        # UTC date or Local TZ?
152        if match.group(2) == "d":
153            now = datetime.datetime.now()
154        elif match.group(2) == "D":
155            now = datetime.datetime.utcnow()
156
157        # Custom format or ISO format?
158        if match.group(3):
159            time = datetime.date.strftime(now, match.group(4))
160            try:
161                i = len(re.search("#+", match.group(4)).group(0))
162                msec = '{0:0>{i}.{i}}'.format(str(now.microsecond / 1000), i=i)
163                time = re.sub('#+', msec, time)
164            except AttributeError:
165                pass
166        else:
167            time = datetime.datetime.isoformat(now.replace(microsecond=0))
168
169        return self._format_field(tmp, match.group(1), time)
170
171    def emer(self, message, **kwargs):
172        self.__log("EMER", message, **kwargs)
173
174    def err(self, message, **kwargs):
175        self.__log("ERR", message, **kwargs)
176
177    def warn(self, message, **kwargs):
178        self.__log("WARN", message, **kwargs)
179
180    def info(self, message, **kwargs):
181        self.__log("INFO", message, **kwargs)
182
183    def dbg(self, message, **kwargs):
184        self.__log("DBG", message, **kwargs)
185
186    def __is_enabled(self, level):
187        level = LEVELS.get(level.lower(), logging.DEBUG)
188        for f, f_level in six.iteritems(Vlog.__mfl[self.name]):
189            f_level = LEVELS.get(f_level, logging.CRITICAL)
190            if level >= f_level:
191                return True
192        return False
193
194    def emer_is_enabled(self):
195        return self.__is_enabled("EMER")
196
197    def err_is_enabled(self):
198        return self.__is_enabled("ERR")
199
200    def warn_is_enabled(self):
201        return self.__is_enabled("WARN")
202
203    def info_is_enabled(self):
204        return self.__is_enabled("INFO")
205
206    def dbg_is_enabled(self):
207        return self.__is_enabled("DBG")
208
209    def exception(self, message):
210        """Logs 'message' at ERR log level.  Includes a backtrace when in
211        exception context."""
212        self.err(message, exc_info=True)
213
214    @staticmethod
215    def init(log_file=None):
216        """Intializes the Vlog module.  Causes Vlog to write to 'log_file' if
217        not None.  Should be called after all Vlog objects have been created.
218        No logging will occur until this function is called."""
219
220        if Vlog.__inited:
221            return
222
223        Vlog.__inited = True
224        Vlog.__start_time = datetime.datetime.utcnow()
225        logging.raiseExceptions = False
226        Vlog.__log_file = log_file
227        for f in DESTINATIONS:
228            logger = logging.getLogger(f)
229            logger.setLevel(logging.DEBUG)
230
231            try:
232                if f == "console":
233                    logger.addHandler(logging.StreamHandler(sys.stderr))
234                elif f == "syslog":
235                    Vlog.add_syslog_handler()
236                elif f == "file" and Vlog.__log_file:
237                    Vlog.__file_handler = logging.FileHandler(Vlog.__log_file)
238                    logger.addHandler(Vlog.__file_handler)
239            except (IOError, socket.error):
240                logger.setLevel(logging.CRITICAL)
241
242        ovs.unixctl.command_register("vlog/reopen", "", 0, 0,
243                                     Vlog._unixctl_vlog_reopen, None)
244        ovs.unixctl.command_register("vlog/close", "", 0, 0,
245                                     Vlog._unixctl_vlog_close, None)
246        try:
247            # Windows limitation on Python 2, sys.maxsize is a long number
248            # on 64 bits environments, while sys.maxint is the maximum int
249            # number. Python 3 works as expected.
250            maxsize_int = sys.maxint
251        except AttributeError:
252            maxsize_int = sys.maxsize
253        ovs.unixctl.command_register("vlog/set", "spec", 1, maxsize_int,
254                                     Vlog._unixctl_vlog_set, None)
255        ovs.unixctl.command_register("vlog/list", "", 0, 0,
256                                     Vlog._unixctl_vlog_list, None)
257
258    @staticmethod
259    def set_level(module, destination, level):
260        """ Sets the log level of the 'module'-'destination' tuple to 'level'.
261        All three arguments are strings which are interpreted the same as
262        arguments to the --verbose flag.  Should be called after all Vlog
263        objects have already been created."""
264
265        module = module.lower()
266        destination = destination.lower()
267        level = level.lower()
268
269        if destination != "any" and destination not in DESTINATIONS:
270            return
271
272        if module != "any" and module not in Vlog.__mfl:
273            return
274
275        if level not in LEVELS:
276            return
277
278        if module == "any":
279            modules = list(Vlog.__mfl.keys())
280        else:
281            modules = [module]
282
283        if destination == "any":
284            destinations = list(DESTINATIONS.keys())
285        else:
286            destinations = [destination]
287
288        for m in modules:
289            for f in destinations:
290                Vlog.__mfl[m][f] = level
291
292    @staticmethod
293    def set_pattern(destination, pattern):
294        """ Sets the log pattern of the 'destination' to 'pattern' """
295        destination = destination.lower()
296        Vlog.__log_patterns[destination] = pattern
297
298    @staticmethod
299    def add_syslog_handler(facility=None):
300        global syslog_facility, syslog_handler
301
302        # If handler is already added and there is no change in 'facility',
303        # there is nothing to do.
304        if (not facility or facility == syslog_facility) and syslog_handler:
305            return
306
307        logger = logging.getLogger('syslog')
308        # If there is no infrastructure to support python syslog, disable
309        # the logger to avoid repeated errors.
310        if not os.path.exists("/dev/log"):
311            logger.disabled = True
312            return
313
314        if syslog_handler:
315            logger.removeHandler(syslog_handler)
316
317        if facility:
318            syslog_facility = facility
319
320        syslog_handler = logging.handlers.SysLogHandler(address="/dev/log",
321                                                    facility=syslog_facility)
322        logger.addHandler(syslog_handler)
323        return
324
325    @staticmethod
326    def set_levels_from_string(s):
327        module = None
328        level = None
329        destination = None
330
331        words = re.split('[ :]', s)
332        if words[0] == "pattern":
333            try:
334                if words[1] in DESTINATIONS and words[2]:
335                    segments = [words[i] for i in range(2, len(words))]
336                    pattern = "".join(segments)
337                    Vlog.set_pattern(words[1], pattern)
338                    return
339                else:
340                    return "Destination %s does not exist" % words[1]
341            except IndexError:
342                return "Please supply a valid pattern and destination"
343        elif words[0] == "FACILITY":
344            if words[1] in FACILITIES:
345                Vlog.add_syslog_handler(words[1])
346                return
347            else:
348                return "Facility %s is invalid" % words[1]
349
350        for word in [w.lower() for w in words]:
351            if word == "any":
352                pass
353            elif word in DESTINATIONS:
354                if destination:
355                    return "cannot specify multiple destinations"
356                destination = word
357            elif word in LEVELS:
358                if level:
359                    return "cannot specify multiple levels"
360                level = word
361            elif word in Vlog.__mfl:
362                if module:
363                    return "cannot specify multiple modules"
364                module = word
365            else:
366                return "no destination, level, or module \"%s\"" % word
367
368        Vlog.set_level(module or "any", destination or "any", level or "any")
369
370    @staticmethod
371    def get_levels():
372        lines = ["                 console    syslog    file\n",
373                 "                 -------    ------    ------\n"]
374        lines.extend(sorted(["%-16s  %4s       %4s       %4s\n"
375                             % (m,
376                                Vlog.__mfl[m]["console"],
377                                Vlog.__mfl[m]["syslog"],
378                                Vlog.__mfl[m]["file"]) for m in Vlog.__mfl]))
379        return ''.join(lines)
380
381    @staticmethod
382    def reopen_log_file():
383        """Closes and then attempts to re-open the current log file.  (This is
384        useful just after log rotation, to ensure that the new log file starts
385        being used.)"""
386
387        if Vlog.__log_file:
388            logger = logging.getLogger("file")
389            logger.removeHandler(Vlog.__file_handler)
390            Vlog.__file_handler = logging.FileHandler(Vlog.__log_file)
391            logger.addHandler(Vlog.__file_handler)
392
393    @staticmethod
394    def close_log_file():
395        """Closes the current log file. (This is useful on Windows, to ensure
396        that a reference to the file is not kept by the daemon in case of
397        detach.)"""
398        if Vlog.__log_file:
399            logger = logging.getLogger("file")
400            logger.removeHandler(Vlog.__file_handler)
401            Vlog.__file_handler.close()
402
403    @staticmethod
404    def _unixctl_vlog_reopen(conn, unused_argv, unused_aux):
405        if Vlog.__log_file:
406            Vlog.reopen_log_file()
407            conn.reply(None)
408        else:
409            conn.reply("Logging to file not configured")
410
411    @staticmethod
412    def _unixctl_vlog_close(conn, unused_argv, unused_aux):
413        if Vlog.__log_file:
414            if sys.platform != 'win32':
415                logger = logging.getLogger("file")
416                logger.removeHandler(Vlog.__file_handler)
417            else:
418                Vlog.close_log_file()
419        conn.reply(None)
420
421    @staticmethod
422    def _unixctl_vlog_set(conn, argv, unused_aux):
423        for arg in argv:
424            msg = Vlog.set_levels_from_string(arg)
425            if msg:
426                conn.reply(msg)
427                return
428        conn.reply(None)
429
430    @staticmethod
431    def _unixctl_vlog_list(conn, unused_argv, unused_aux):
432        conn.reply(Vlog.get_levels())
433
434
435def add_args(parser):
436    """Adds vlog related options to 'parser', an ArgumentParser object.  The
437    resulting arguments parsed by 'parser' should be passed to handle_args."""
438
439    group = parser.add_argument_group(title="Logging Options")
440    group.add_argument("--log-file", nargs="?", const="default",
441                       help="Enables logging to a file.  Default log file"
442                       " is used if LOG_FILE is omitted.")
443    group.add_argument("-v", "--verbose", nargs="*",
444                       help="Sets logging levels, see ovs-vswitchd(8)."
445                       "  Defaults to dbg.")
446
447
448def handle_args(args):
449    """ Handles command line arguments ('args') parsed by an ArgumentParser.
450    The ArgumentParser should have been primed by add_args().  Also takes care
451    of initializing the Vlog module."""
452
453    log_file = args.log_file
454    if log_file == "default":
455        log_file = "%s/%s.log" % (ovs.dirs.LOGDIR, ovs.util.PROGRAM_NAME)
456
457    if args.verbose is None:
458        args.verbose = []
459    elif args.verbose == []:
460        args.verbose = ["any:any:dbg"]
461
462    for verbose in args.verbose:
463        msg = Vlog.set_levels_from_string(verbose)
464        if msg:
465            ovs.util.ovs_fatal(0, "processing \"%s\": %s" % (verbose, msg))
466
467    Vlog.init(log_file)
468