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 if isinstance(s, unicode): 39 s = s.encode('utf8') 40 os.system('logger -t "autotest" "%s"' % utils.sh_escape(s)) 41 except OSError: 42 self._should_respew = False 43 return s 44 45 46class LoggingConfig(object): 47 global_level = logging.DEBUG 48 stdout_level = logging.INFO 49 stderr_level = logging.ERROR 50 51 FILE_FORMAT = ('%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:' 52 '%(lineno)4.4d| %(message)s') 53 FILE_FORMAT_WITH_THREADNAME = ( 54 '%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:' 55 '%(lineno)4.4d| %(threadName)16.16s| %(message)s') 56 DATE_FORMAT = '%m/%d %H:%M:%S' 57 58 file_formatter = logging.Formatter(fmt=FILE_FORMAT, datefmt=DATE_FORMAT) 59 60 CONSOLE_FORMAT = '%(asctime)s %(levelname)-5.5s| %(message)s' 61 62 console_formatter = logging.Formatter(fmt=CONSOLE_FORMAT, 63 datefmt='%H:%M:%S') 64 65 system_formatter = VarLogMessageFormatter(fmt=FILE_FORMAT, 66 datefmt='%H:%M:%S') 67 68 def __init__(self, use_console=True): 69 self.logger = logging.getLogger() 70 self.global_level = logging.DEBUG 71 self.use_console = use_console 72 73 @classmethod 74 def get_timestamped_log_name(cls, base_name): 75 return '%s.log.%s' % (base_name, time.strftime('%Y-%m-%d-%H.%M.%S')) 76 77 @classmethod 78 def get_autotest_root(cls): 79 common_lib_dir = os.path.dirname(__file__) 80 return os.path.abspath(os.path.join(common_lib_dir, '..', '..')) 81 82 @classmethod 83 def get_server_log_dir(cls): 84 return os.path.join(cls.get_autotest_root(), 'logs') 85 86 def add_stream_handler(self, stream, level=logging.DEBUG, datefmt=None): 87 handler = logging.StreamHandler(stream) 88 handler.setLevel(level) 89 formatter = self.console_formatter 90 if datefmt: 91 formatter = logging.Formatter(fmt=self.CONSOLE_FORMAT, 92 datefmt=datefmt) 93 handler.setFormatter(formatter) 94 self.logger.addHandler(handler) 95 return handler 96 97 def add_console_handlers(self, datefmt=None): 98 stdout_handler = self.add_stream_handler(sys.stdout, 99 level=self.stdout_level, 100 datefmt=datefmt) 101 # only pass records *below* STDERR_LEVEL to stdout, to avoid duplication 102 stdout_handler.addFilter(AllowBelowSeverity(self.stderr_level)) 103 104 self.add_stream_handler(sys.stderr, self.stderr_level, datefmt) 105 106 def add_file_handler(self, 107 file_path, 108 level=logging.DEBUG, 109 log_dir=None, 110 datefmt=None): 111 if log_dir: 112 file_path = os.path.join(log_dir, file_path) 113 handler = logging.FileHandler(file_path) 114 handler.setLevel(level) 115 formatter = self.file_formatter 116 if datefmt: 117 formatter = logging.Formatter(fmt=self.FILE_FORMAT, datefmt=datefmt) 118 # Respew the content of the selected file to /var/log/messages. 119 if file_path == '/usr/local/autotest/results/default/debug/client.0.WARNING': 120 formatter = self.system_formatter 121 handler.setFormatter(formatter) 122 self.logger.addHandler(handler) 123 return handler 124 125 def _add_file_handlers_for_all_levels(self, log_dir, log_name): 126 for level in (logging.DEBUG, logging.INFO, logging.WARNING, 127 logging.ERROR): 128 file_name = '%s.%s' % (log_name, logging.getLevelName(level)) 129 self.add_file_handler(file_name, level=level, log_dir=log_dir) 130 131 def add_debug_file_handlers(self, log_dir, log_name=None): 132 raise NotImplementedError 133 134 def _clear_all_handlers(self): 135 for handler in list(self.logger.handlers): 136 self.logger.removeHandler(handler) 137 # Attempt to close the handler. If it's already closed a KeyError 138 # will be generated. http://bugs.python.org/issue8581 139 try: 140 handler.close() 141 except KeyError: 142 pass 143 144 def configure_logging(self, use_console=True, verbose=False, datefmt=None): 145 self._clear_all_handlers() # see comment at top of file 146 self.logger.setLevel(self.global_level) 147 148 if verbose: 149 self.stdout_level = logging.DEBUG 150 if use_console: 151 self.add_console_handlers(datefmt) 152 153 154class TestingConfig(LoggingConfig): 155 156 def add_stream_handler(self, *args, **kwargs): 157 pass 158 159 def add_file_handler(self, *args, **kwargs): 160 pass 161 162 def configure_logging(self, **kwargs): 163 pass 164 165 166def add_threadname_in_log(): 167 """Change logging formatter to include thread name. 168 169 This is to help logs from each thread runs to include its thread name. 170 """ 171 log = logging.getLogger() 172 for handler in logging.getLogger().handlers: 173 if isinstance(handler, logging.FileHandler): 174 log.removeHandler(handler) 175 handler.setFormatter(logging.Formatter( 176 LoggingConfig.FILE_FORMAT_WITH_THREADNAME, 177 LoggingConfig.DATE_FORMAT)) 178 log.addHandler(handler) 179 logging.debug('Logging handler\'s format updated with thread name.') 180