Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 1 | import logging |
| 2 | import os |
| 3 | import sys |
| 4 | import time |
| 5 | from autotest_lib.client.common_lib import utils |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 6 | |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 7 | # Set up a simple catchall configuration for use during import time. Some code |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 8 | # may log messages at import time and we don't want those to get completely |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 9 | # thrown away. We'll clear this out when actual configuration takes place. |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 10 | logging.basicConfig(level=logging.DEBUG) |
| 11 | |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 12 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 13 | class AllowBelowSeverity(logging.Filter): |
mbligh | 1ef218d | 2009-08-03 16:57:56 +0000 | [diff] [blame] | 14 | """ |
| 15 | Allows only records less severe than a given level (the opposite of what |
| 16 | the normal logging level filtering does. |
| 17 | """ |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 18 | |
mbligh | 1ef218d | 2009-08-03 16:57:56 +0000 | [diff] [blame] | 19 | def __init__(self, level): |
| 20 | self.level = level |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 21 | |
mbligh | 1ef218d | 2009-08-03 16:57:56 +0000 | [diff] [blame] | 22 | def filter(self, record): |
| 23 | return record.levelno < self.level |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 24 | |
| 25 | |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 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: |
Kuang-che Wu | 4178d21 | 2019-05-06 19:49:21 +0800 | [diff] [blame] | 38 | if isinstance(s, unicode): |
| 39 | s = s.encode('utf8') |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 40 | os.system('logger -t "autotest" "%s"' % utils.sh_escape(s)) |
| 41 | except OSError: |
| 42 | self._should_respew = False |
| 43 | return s |
| 44 | |
| 45 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 46 | class LoggingConfig(object): |
showard | 10d8417 | 2009-06-18 23:16:50 +0000 | [diff] [blame] | 47 | global_level = logging.DEBUG |
| 48 | stdout_level = logging.INFO |
| 49 | stderr_level = logging.ERROR |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 50 | |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 51 | FILE_FORMAT = ('%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:' |
| 52 | '%(lineno)4.4d| %(message)s') |
Dan Shi | 1724f95 | 2016-05-26 09:45:43 -0700 | [diff] [blame] | 53 | FILE_FORMAT_WITH_THREADNAME = ( |
| 54 | '%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:' |
markdr | e9386a7 | 2017-05-03 12:30:46 -0700 | [diff] [blame] | 55 | '%(lineno)4.4d| %(threadName)16.16s| %(message)s') |
Dan Shi | 1724f95 | 2016-05-26 09:45:43 -0700 | [diff] [blame] | 56 | DATE_FORMAT = '%m/%d %H:%M:%S' |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 57 | |
Dan Shi | 1724f95 | 2016-05-26 09:45:43 -0700 | [diff] [blame] | 58 | file_formatter = logging.Formatter(fmt=FILE_FORMAT, datefmt=DATE_FORMAT) |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 59 | |
| 60 | CONSOLE_FORMAT = '%(asctime)s %(levelname)-5.5s| %(message)s' |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 61 | |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 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') |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 67 | |
Dale Curtis | 74a314b | 2011-06-23 14:55:46 -0700 | [diff] [blame] | 68 | def __init__(self, use_console=True): |
mbligh | 1ef218d | 2009-08-03 16:57:56 +0000 | [diff] [blame] | 69 | self.logger = logging.getLogger() |
| 70 | self.global_level = logging.DEBUG |
Dale Curtis | 74a314b | 2011-06-23 14:55:46 -0700 | [diff] [blame] | 71 | self.use_console = use_console |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 72 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 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 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 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 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 82 | @classmethod |
| 83 | def get_server_log_dir(cls): |
| 84 | return os.path.join(cls.get_autotest_root(), 'logs') |
| 85 | |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 86 | def add_stream_handler(self, stream, level=logging.DEBUG, datefmt=None): |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 87 | handler = logging.StreamHandler(stream) |
| 88 | handler.setLevel(level) |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 89 | formatter = self.console_formatter |
| 90 | if datefmt: |
| 91 | formatter = logging.Formatter(fmt=self.CONSOLE_FORMAT, |
| 92 | datefmt=datefmt) |
| 93 | handler.setFormatter(formatter) |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 94 | self.logger.addHandler(handler) |
| 95 | return handler |
| 96 | |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 97 | def add_console_handlers(self, datefmt=None): |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 98 | stdout_handler = self.add_stream_handler(sys.stdout, |
| 99 | level=self.stdout_level, |
| 100 | datefmt=datefmt) |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 101 | # only pass records *below* STDERR_LEVEL to stdout, to avoid duplication |
showard | 10d8417 | 2009-06-18 23:16:50 +0000 | [diff] [blame] | 102 | stdout_handler.addFilter(AllowBelowSeverity(self.stderr_level)) |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 103 | |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 104 | self.add_stream_handler(sys.stderr, self.stderr_level, datefmt) |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 105 | |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 106 | def add_file_handler(self, |
| 107 | file_path, |
| 108 | level=logging.DEBUG, |
| 109 | log_dir=None, |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 110 | datefmt=None): |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 111 | if log_dir: |
| 112 | file_path = os.path.join(log_dir, file_path) |
| 113 | handler = logging.FileHandler(file_path) |
| 114 | handler.setLevel(level) |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 115 | formatter = self.file_formatter |
| 116 | if datefmt: |
| 117 | formatter = logging.Formatter(fmt=self.FILE_FORMAT, datefmt=datefmt) |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 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 |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 121 | handler.setFormatter(formatter) |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 122 | self.logger.addHandler(handler) |
| 123 | return handler |
| 124 | |
showard | f2de81b | 2009-06-15 20:23:10 +0000 | [diff] [blame] | 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 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 131 | def add_debug_file_handlers(self, log_dir, log_name=None): |
Dale Curtis | 456d3c1 | 2011-07-19 11:42:51 -0700 | [diff] [blame] | 132 | raise NotImplementedError |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 133 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 134 | def _clear_all_handlers(self): |
| 135 | for handler in list(self.logger.handlers): |
| 136 | self.logger.removeHandler(handler) |
Dale Curtis | 2d0c926 | 2011-07-06 19:22:49 -0700 | [diff] [blame] | 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 |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 143 | |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 144 | def configure_logging(self, use_console=True, verbose=False, datefmt=None): |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 145 | self._clear_all_handlers() # see comment at top of file |
showard | 10d8417 | 2009-06-18 23:16:50 +0000 | [diff] [blame] | 146 | self.logger.setLevel(self.global_level) |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 147 | |
showard | 10d8417 | 2009-06-18 23:16:50 +0000 | [diff] [blame] | 148 | if verbose: |
| 149 | self.stdout_level = logging.DEBUG |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 150 | if use_console: |
MK Ryu | 4055704 | 2015-08-18 10:59:47 -0700 | [diff] [blame] | 151 | self.add_console_handlers(datefmt) |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 152 | |
| 153 | |
| 154 | class TestingConfig(LoggingConfig): |
Ilja H. Friedel | 05bcd79 | 2016-04-14 21:51:05 -0700 | [diff] [blame] | 155 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 156 | def add_stream_handler(self, *args, **kwargs): |
| 157 | pass |
| 158 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 159 | def add_file_handler(self, *args, **kwargs): |
| 160 | pass |
| 161 | |
showard | 75cdfee | 2009-06-10 17:40:41 +0000 | [diff] [blame] | 162 | def configure_logging(self, **kwargs): |
| 163 | pass |
Dan Shi | 1724f95 | 2016-05-26 09:45:43 -0700 | [diff] [blame] | 164 | |
| 165 | |
| 166 | def 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.') |