105bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedelimport logging 205bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedelimport os 305bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedelimport sys 405bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedelimport time 505bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedelfrom autotest_lib.client.common_lib import utils 675cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 705bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel# Set up a simple catchall configuration for use during import time. Some code 875cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward# may log messages at import time and we don't want those to get completely 905bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel# thrown away. We'll clear this out when actual configuration takes place. 1075cdfee87bfaa3cf3f9860832b228a6d32aaed2fshowardlogging.basicConfig(level=logging.DEBUG) 1175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 1205bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel 1375cdfee87bfaa3cf3f9860832b228a6d32aaed2fshowardclass AllowBelowSeverity(logging.Filter): 141ef218db76c473c28627377d8f50d6e6c6743289mbligh """ 151ef218db76c473c28627377d8f50d6e6c6743289mbligh Allows only records less severe than a given level (the opposite of what 161ef218db76c473c28627377d8f50d6e6c6743289mbligh the normal logging level filtering does. 171ef218db76c473c28627377d8f50d6e6c6743289mbligh """ 1805bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel 191ef218db76c473c28627377d8f50d6e6c6743289mbligh def __init__(self, level): 201ef218db76c473c28627377d8f50d6e6c6743289mbligh self.level = level 2175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 221ef218db76c473c28627377d8f50d6e6c6743289mbligh def filter(self, record): 231ef218db76c473c28627377d8f50d6e6c6743289mbligh return record.levelno < self.level 2475cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 2575cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 2605bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedelclass VarLogMessageFormatter(logging.Formatter): 2705bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel """ 2805bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel Respews logging.* strings on the DUT to /var/log/messages for easier 2905bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel correlation of user mode test activity with kernel messages. 3005bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel """ 3105bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel _should_respew = True 3205bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel 3305bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel def format(self, record): 3405bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel s = super(VarLogMessageFormatter, self).format(record) 3505bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel # On Brillo the logger binary is not available. Disable after error. 3605bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel if self._should_respew: 3705bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel try: 3805bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel os.system('logger -t "autotest" "%s"' % utils.sh_escape(s)) 3905bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel except OSError: 4005bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel self._should_respew = False 4105bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel return s 4205bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel 4305bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel 4475cdfee87bfaa3cf3f9860832b228a6d32aaed2fshowardclass LoggingConfig(object): 4510d8417b8c3576e1ba80ce00b6ae2e9cea826bc0showard global_level = logging.DEBUG 4610d8417b8c3576e1ba80ce00b6ae2e9cea826bc0showard stdout_level = logging.INFO 4710d8417b8c3576e1ba80ce00b6ae2e9cea826bc0showard stderr_level = logging.ERROR 4875cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 494055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu FILE_FORMAT = ('%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:' 504055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu '%(lineno)4.4d| %(message)s') 511724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi FILE_FORMAT_WITH_THREADNAME = ( 521724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi '%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:' 531724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi '%(lineno)4.4d| %(threadName)10.10s| %(message)s') 541724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi DATE_FORMAT = '%m/%d %H:%M:%S' 554055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu 561724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi file_formatter = logging.Formatter(fmt=FILE_FORMAT, datefmt=DATE_FORMAT) 574055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu 584055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu CONSOLE_FORMAT = '%(asctime)s %(levelname)-5.5s| %(message)s' 5975cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 6005bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel console_formatter = logging.Formatter(fmt=CONSOLE_FORMAT, 6105bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel datefmt='%H:%M:%S') 6205bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel 6305bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel system_formatter = VarLogMessageFormatter(fmt=FILE_FORMAT, 6405bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel datefmt='%H:%M:%S') 6575cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 6674a314b490ff542c4dd2ae4aa0d11c6394d92960Dale Curtis def __init__(self, use_console=True): 671ef218db76c473c28627377d8f50d6e6c6743289mbligh self.logger = logging.getLogger() 681ef218db76c473c28627377d8f50d6e6c6743289mbligh self.global_level = logging.DEBUG 6974a314b490ff542c4dd2ae4aa0d11c6394d92960Dale Curtis self.use_console = use_console 7075cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 7175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward @classmethod 7275cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward def get_timestamped_log_name(cls, base_name): 7375cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward return '%s.log.%s' % (base_name, time.strftime('%Y-%m-%d-%H.%M.%S')) 7475cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 7575cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward @classmethod 7675cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward def get_autotest_root(cls): 7775cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward common_lib_dir = os.path.dirname(__file__) 7875cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward return os.path.abspath(os.path.join(common_lib_dir, '..', '..')) 7975cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 8075cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward @classmethod 8175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward def get_server_log_dir(cls): 8275cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward return os.path.join(cls.get_autotest_root(), 'logs') 8375cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 844055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu def add_stream_handler(self, stream, level=logging.DEBUG, datefmt=None): 8575cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward handler = logging.StreamHandler(stream) 8675cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward handler.setLevel(level) 874055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu formatter = self.console_formatter 884055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu if datefmt: 894055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu formatter = logging.Formatter(fmt=self.CONSOLE_FORMAT, 904055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu datefmt=datefmt) 914055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu handler.setFormatter(formatter) 9275cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward self.logger.addHandler(handler) 9375cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward return handler 9475cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 954055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu def add_console_handlers(self, datefmt=None): 9605bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel stdout_handler = self.add_stream_handler(sys.stdout, 9705bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel level=self.stdout_level, 9805bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel datefmt=datefmt) 9975cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward # only pass records *below* STDERR_LEVEL to stdout, to avoid duplication 10010d8417b8c3576e1ba80ce00b6ae2e9cea826bc0showard stdout_handler.addFilter(AllowBelowSeverity(self.stderr_level)) 10175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 1024055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu self.add_stream_handler(sys.stderr, self.stderr_level, datefmt) 10375cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 10405bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel def add_file_handler(self, 10505bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel file_path, 10605bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel level=logging.DEBUG, 10705bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel log_dir=None, 1084055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu datefmt=None): 10975cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward if log_dir: 11075cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward file_path = os.path.join(log_dir, file_path) 11175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward handler = logging.FileHandler(file_path) 11275cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward handler.setLevel(level) 1134055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu formatter = self.file_formatter 1144055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu if datefmt: 1154055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu formatter = logging.Formatter(fmt=self.FILE_FORMAT, datefmt=datefmt) 11605bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel # Respew the content of the selected file to /var/log/messages. 11705bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel if file_path == '/usr/local/autotest/results/default/debug/client.0.WARNING': 11805bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel formatter = self.system_formatter 1194055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu handler.setFormatter(formatter) 12075cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward self.logger.addHandler(handler) 12175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward return handler 12275cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 123f2de81b7f4f563ee8cad2686b71477a6e91a932ashoward def _add_file_handlers_for_all_levels(self, log_dir, log_name): 124f2de81b7f4f563ee8cad2686b71477a6e91a932ashoward for level in (logging.DEBUG, logging.INFO, logging.WARNING, 125f2de81b7f4f563ee8cad2686b71477a6e91a932ashoward logging.ERROR): 126f2de81b7f4f563ee8cad2686b71477a6e91a932ashoward file_name = '%s.%s' % (log_name, logging.getLevelName(level)) 127f2de81b7f4f563ee8cad2686b71477a6e91a932ashoward self.add_file_handler(file_name, level=level, log_dir=log_dir) 128f2de81b7f4f563ee8cad2686b71477a6e91a932ashoward 12975cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward def add_debug_file_handlers(self, log_dir, log_name=None): 130456d3c115952bf1ae984770e226c5a50676b31c0Dale Curtis raise NotImplementedError 13175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 13275cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward def _clear_all_handlers(self): 13375cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward for handler in list(self.logger.handlers): 13475cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward self.logger.removeHandler(handler) 1352d0c926f262bbec53de2019e4318ea96dd2ee2edDale Curtis # Attempt to close the handler. If it's already closed a KeyError 1362d0c926f262bbec53de2019e4318ea96dd2ee2edDale Curtis # will be generated. http://bugs.python.org/issue8581 1372d0c926f262bbec53de2019e4318ea96dd2ee2edDale Curtis try: 1382d0c926f262bbec53de2019e4318ea96dd2ee2edDale Curtis handler.close() 1392d0c926f262bbec53de2019e4318ea96dd2ee2edDale Curtis except KeyError: 1402d0c926f262bbec53de2019e4318ea96dd2ee2edDale Curtis pass 14175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 1424055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu def configure_logging(self, use_console=True, verbose=False, datefmt=None): 14305bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel self._clear_all_handlers() # see comment at top of file 14410d8417b8c3576e1ba80ce00b6ae2e9cea826bc0showard self.logger.setLevel(self.global_level) 14575cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 14610d8417b8c3576e1ba80ce00b6ae2e9cea826bc0showard if verbose: 14710d8417b8c3576e1ba80ce00b6ae2e9cea826bc0showard self.stdout_level = logging.DEBUG 14875cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward if use_console: 1494055704ec6c3ed559d35d61e5f0b8b4fcda797f6MK Ryu self.add_console_handlers(datefmt) 15075cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 15175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 15275cdfee87bfaa3cf3f9860832b228a6d32aaed2fshowardclass TestingConfig(LoggingConfig): 15305bcd7973513dc868a5479f5df8165874a71947eIlja H. Friedel 15475cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward def add_stream_handler(self, *args, **kwargs): 15575cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward pass 15675cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 15775cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward def add_file_handler(self, *args, **kwargs): 15875cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward pass 15975cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward 16075cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward def configure_logging(self, **kwargs): 16175cdfee87bfaa3cf3f9860832b228a6d32aaed2fshoward pass 1621724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi 1631724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi 1641724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shidef add_threadname_in_log(): 1651724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi """Change logging formatter to include thread name. 1661724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi 1671724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi This is to help logs from each thread runs to include its thread name. 1681724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi """ 1691724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi log = logging.getLogger() 1701724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi for handler in logging.getLogger().handlers: 1711724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi if isinstance(handler, logging.FileHandler): 1721724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi log.removeHandler(handler) 1731724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi handler.setFormatter(logging.Formatter( 1741724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi LoggingConfig.FILE_FORMAT_WITH_THREADNAME, 1751724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi LoggingConfig.DATE_FORMAT)) 1761724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi log.addHandler(handler) 1771724f9573c8b4bd7eebb587bdd39f30cda70c58aDan Shi logging.debug('Logging handler\'s format updated with thread name.') 178