• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1# Lint as: python2, python3
2from __future__ import absolute_import
3from __future__ import division
4from __future__ import print_function
5
6import logging
7import os
8import six
9import sys
10import time
11
12from autotest_lib.client.common_lib import utils
13
14# Set up a simple catchall configuration for use during import time.  Some code
15# may log messages at import time and we don't want those to get completely
16# thrown away.  We'll clear this out when actual configuration takes place.
17logging.basicConfig(level=logging.DEBUG)
18
19
20class AllowBelowSeverity(logging.Filter):
21    """
22    Allows only records less severe than a given level (the opposite of what
23    the normal logging level filtering does.
24    """
25
26    def __init__(self, level):
27        self.level = level
28
29    def filter(self, record):
30        return record.levelno < self.level
31
32
33class VarLogMessageFormatter(logging.Formatter):
34    """
35    Respews logging.* strings on the DUT to /var/log/messages for easier
36    correlation of user mode test activity with kernel messages.
37    """
38    _should_respew = True
39
40    def format(self, record):
41        s = super(VarLogMessageFormatter, self).format(record)
42        # On Brillo the logger binary is not available. Disable after error.
43        if self._should_respew:
44            try:
45                # in python2 unicode != string, so encode the record into a
46                # string for logging. In py3 this is just not needed.
47                # Additionally, encoding in py3 results in bytes, which breaks
48                # logging.
49                if six.PY2 and isinstance(s, unicode):
50                    s = s.encode('utf8')
51                os.system('logger -t "autotest" "%s"' % utils.sh_escape(s))
52            except OSError:
53                self._should_respew = False
54        return s
55
56
57class LoggingConfig(object):
58    global_level = logging.DEBUG
59    stdout_level = logging.INFO
60    stderr_level = logging.ERROR
61
62    FILE_FORMAT = ('%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:'
63                   '%(lineno)4.4d| %(message)s')
64    FILE_FORMAT_WITH_THREADNAME = (
65            '%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:'
66            '%(lineno)4.4d| %(threadName)16.16s| %(message)s')
67    DATE_FORMAT = '%m/%d %H:%M:%S'
68
69    file_formatter = logging.Formatter(fmt=FILE_FORMAT, datefmt=DATE_FORMAT)
70
71    CONSOLE_FORMAT = '%(asctime)s %(levelname)-5.5s| %(message)s'
72
73    console_formatter = logging.Formatter(fmt=CONSOLE_FORMAT,
74                                          datefmt='%H:%M:%S')
75
76    system_formatter = VarLogMessageFormatter(fmt=FILE_FORMAT,
77                                              datefmt='%H:%M:%S')
78
79    def __init__(self, use_console=True):
80        self.logger = logging.getLogger()
81        self.global_level = logging.DEBUG
82        self.use_console = use_console
83
84    @classmethod
85    def get_timestamped_log_name(cls, base_name):
86        return '%s.log.%s' % (base_name, time.strftime('%Y-%m-%d-%H.%M.%S'))
87
88    @classmethod
89    def get_autotest_root(cls):
90        common_lib_dir = os.path.dirname(__file__)
91        return os.path.abspath(os.path.join(common_lib_dir, '..', '..'))
92
93    @classmethod
94    def get_server_log_dir(cls):
95        return os.path.join(cls.get_autotest_root(), 'logs')
96
97    def add_stream_handler(self, stream, level=logging.DEBUG, datefmt=None):
98        handler = logging.StreamHandler(stream)
99        handler.setLevel(level)
100        formatter = self.console_formatter
101        if datefmt:
102            formatter = logging.Formatter(fmt=self.CONSOLE_FORMAT,
103                                          datefmt=datefmt)
104        handler.setFormatter(formatter)
105        self.logger.addHandler(handler)
106        return handler
107
108    def add_console_handlers(self, datefmt=None):
109        stdout_handler = self.add_stream_handler(sys.stdout,
110                                                 level=self.stdout_level,
111                                                 datefmt=datefmt)
112        # only pass records *below* STDERR_LEVEL to stdout, to avoid duplication
113        stdout_handler.addFilter(AllowBelowSeverity(self.stderr_level))
114
115        self.add_stream_handler(sys.stderr, self.stderr_level, datefmt)
116
117    def add_file_handler(self,
118                         file_path,
119                         level=logging.DEBUG,
120                         log_dir=None,
121                         datefmt=None):
122        if log_dir:
123            file_path = os.path.join(log_dir, file_path)
124        handler = logging.FileHandler(file_path)
125        handler.setLevel(level)
126        formatter = self.file_formatter
127        if datefmt:
128            formatter = logging.Formatter(fmt=self.FILE_FORMAT, datefmt=datefmt)
129        # Respew the content of the selected file to /var/log/messages.
130        if file_path == '/usr/local/autotest/results/default/debug/client.0.WARNING':
131            formatter = self.system_formatter
132        handler.setFormatter(formatter)
133        self.logger.addHandler(handler)
134        return handler
135
136    def _add_file_handlers_for_all_levels(self, log_dir, log_name):
137        for level in (logging.DEBUG, logging.INFO, logging.WARNING,
138                      logging.ERROR):
139            file_name = '%s.%s' % (log_name, logging.getLevelName(level))
140            self.add_file_handler(file_name, level=level, log_dir=log_dir)
141
142    def add_debug_file_handlers(self, log_dir, log_name=None):
143        raise NotImplementedError
144
145    def _clear_all_handlers(self):
146        for handler in list(self.logger.handlers):
147            self.logger.removeHandler(handler)
148            # Attempt to close the handler. If it's already closed a KeyError
149            # will be generated. http://bugs.python.org/issue8581
150            try:
151                handler.close()
152            except KeyError:
153                pass
154
155    def configure_logging(self, use_console=True, verbose=False, datefmt=None):
156        self._clear_all_handlers()  # see comment at top of file
157        self.logger.setLevel(self.global_level)
158
159        if verbose:
160            self.stdout_level = logging.DEBUG
161        if use_console:
162            self.add_console_handlers(datefmt)
163
164
165class TestingConfig(LoggingConfig):
166
167    def add_stream_handler(self, *args, **kwargs):
168        pass
169
170    def add_file_handler(self, *args, **kwargs):
171        pass
172
173    def configure_logging(self, **kwargs):
174        pass
175
176
177def add_threadname_in_log():
178    """Change logging formatter to include thread name.
179
180    This is to help logs from each thread runs to include its thread name.
181    """
182    log = logging.getLogger()
183    for handler in logging.getLogger().handlers:
184        if isinstance(handler, logging.FileHandler):
185            log.removeHandler(handler)
186            handler.setFormatter(logging.Formatter(
187                    LoggingConfig.FILE_FORMAT_WITH_THREADNAME,
188                    LoggingConfig.DATE_FORMAT))
189            log.addHandler(handler)
190    logging.debug('Logging handler\'s format updated with thread name.')
191