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