1 import logging 2 import os 3 import sys 4 import time 5 from 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. 10 logging.basicConfig(level=logging.DEBUG) 11 12 13 class 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 26 class 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 44 class 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 152 class 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 164 def 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
