blob: 9e18e9c38d866cd3a7ae13ee3f1c9c62ec273c59 [file] [log] [blame]
import logging
import os
import sys
import time
from autotest_lib.client.common_lib import utils
# Set up a simple catchall configuration for use during import time. Some code
# may log messages at import time and we don't want those to get completely
# thrown away. We'll clear this out when actual configuration takes place.
logging.basicConfig(level=logging.DEBUG)
class AllowBelowSeverity(logging.Filter):
"""
Allows only records less severe than a given level (the opposite of what
the normal logging level filtering does.
"""
def __init__(self, level):
self.level = level
def filter(self, record):
return record.levelno < self.level
class VarLogMessageFormatter(logging.Formatter):
"""
Respews logging.* strings on the DUT to /var/log/messages for easier
correlation of user mode test activity with kernel messages.
"""
_should_respew = True
def format(self, record):
s = super(VarLogMessageFormatter, self).format(record)
# On Brillo the logger binary is not available. Disable after error.
if self._should_respew:
try:
if isinstance(s, unicode):
s = s.encode('utf8')
os.system('logger -t "autotest" "%s"' % utils.sh_escape(s))
except OSError:
self._should_respew = False
return s
class LoggingConfig(object):
global_level = logging.DEBUG
stdout_level = logging.INFO
stderr_level = logging.ERROR
FILE_FORMAT = ('%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:'
'%(lineno)4.4d| %(message)s')
FILE_FORMAT_WITH_THREADNAME = (
'%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:'
'%(lineno)4.4d| %(threadName)16.16s| %(message)s')
DATE_FORMAT = '%m/%d %H:%M:%S'
file_formatter = logging.Formatter(fmt=FILE_FORMAT, datefmt=DATE_FORMAT)
CONSOLE_FORMAT = '%(asctime)s %(levelname)-5.5s| %(message)s'
console_formatter = logging.Formatter(fmt=CONSOLE_FORMAT,
datefmt='%H:%M:%S')
system_formatter = VarLogMessageFormatter(fmt=FILE_FORMAT,
datefmt='%H:%M:%S')
def __init__(self, use_console=True):
self.logger = logging.getLogger()
self.global_level = logging.DEBUG
self.use_console = use_console
@classmethod
def get_timestamped_log_name(cls, base_name):
return '%s.log.%s' % (base_name, time.strftime('%Y-%m-%d-%H.%M.%S'))
@classmethod
def get_autotest_root(cls):
common_lib_dir = os.path.dirname(__file__)
return os.path.abspath(os.path.join(common_lib_dir, '..', '..'))
@classmethod
def get_server_log_dir(cls):
return os.path.join(cls.get_autotest_root(), 'logs')
def add_stream_handler(self, stream, level=logging.DEBUG, datefmt=None):
handler = logging.StreamHandler(stream)
handler.setLevel(level)
formatter = self.console_formatter
if datefmt:
formatter = logging.Formatter(fmt=self.CONSOLE_FORMAT,
datefmt=datefmt)
handler.setFormatter(formatter)
self.logger.addHandler(handler)
return handler
def add_console_handlers(self, datefmt=None):
stdout_handler = self.add_stream_handler(sys.stdout,
level=self.stdout_level,
datefmt=datefmt)
# only pass records *below* STDERR_LEVEL to stdout, to avoid duplication
stdout_handler.addFilter(AllowBelowSeverity(self.stderr_level))
self.add_stream_handler(sys.stderr, self.stderr_level, datefmt)
def add_file_handler(self,
file_path,
level=logging.DEBUG,
log_dir=None,
datefmt=None):
if log_dir:
file_path = os.path.join(log_dir, file_path)
handler = logging.FileHandler(file_path)
handler.setLevel(level)
formatter = self.file_formatter
if datefmt:
formatter = logging.Formatter(fmt=self.FILE_FORMAT, datefmt=datefmt)
# Respew the content of the selected file to /var/log/messages.
if file_path == '/usr/local/autotest/results/default/debug/client.0.WARNING':
formatter = self.system_formatter
handler.setFormatter(formatter)
self.logger.addHandler(handler)
return handler
def _add_file_handlers_for_all_levels(self, log_dir, log_name):
for level in (logging.DEBUG, logging.INFO, logging.WARNING,
logging.ERROR):
file_name = '%s.%s' % (log_name, logging.getLevelName(level))
self.add_file_handler(file_name, level=level, log_dir=log_dir)
def add_debug_file_handlers(self, log_dir, log_name=None):
raise NotImplementedError
def _clear_all_handlers(self):
for handler in list(self.logger.handlers):
self.logger.removeHandler(handler)
# Attempt to close the handler. If it's already closed a KeyError
# will be generated. http://bugs.python.org/issue8581
try:
handler.close()
except KeyError:
pass
def configure_logging(self, use_console=True, verbose=False, datefmt=None):
self._clear_all_handlers() # see comment at top of file
self.logger.setLevel(self.global_level)
if verbose:
self.stdout_level = logging.DEBUG
if use_console:
self.add_console_handlers(datefmt)
class TestingConfig(LoggingConfig):
def add_stream_handler(self, *args, **kwargs):
pass
def add_file_handler(self, *args, **kwargs):
pass
def configure_logging(self, **kwargs):
pass
def add_threadname_in_log():
"""Change logging formatter to include thread name.
This is to help logs from each thread runs to include its thread name.
"""
log = logging.getLogger()
for handler in logging.getLogger().handlers:
if isinstance(handler, logging.FileHandler):
log.removeHandler(handler)
handler.setFormatter(logging.Formatter(
LoggingConfig.FILE_FORMAT_WITH_THREADNAME,
LoggingConfig.DATE_FORMAT))
log.addHandler(handler)
logging.debug('Logging handler\'s format updated with thread name.')