| OLD | NEW |
| (Empty) |
| 1 # Copyright 2014 The Chromium Authors. All rights reserved. | |
| 2 # Use of this source code is governed by a BSD-style license that can be | |
| 3 # found in the LICENSE file. | |
| 4 | |
| 5 """Utilities for logging. | |
| 6 | |
| 7 Example usage: | |
| 8 | |
| 9 .. code-block:: python | |
| 10 | |
| 11 import argparse | |
| 12 import logging | |
| 13 import infra_libs.logs | |
| 14 | |
| 15 parser = argparse.ArgumentParser() | |
| 16 infra_libs.logs.add_argparse_options(parser) | |
| 17 | |
| 18 options = parser.parse_args() | |
| 19 infra_libs.logs.process_argparse_options(options) | |
| 20 | |
| 21 LOGGER = logging.getLogger(__name__) | |
| 22 LOGGER.info('test message') | |
| 23 | |
| 24 The last line should print something like:: | |
| 25 | |
| 26 [I2014-06-27T11:42:32.418716-07:00 7082 logs:71] test message | |
| 27 | |
| 28 """ | |
| 29 | |
| 30 import datetime | |
| 31 import getpass | |
| 32 import inspect | |
| 33 import logging | |
| 34 import logging.handlers | |
| 35 import os | |
| 36 import re | |
| 37 import socket | |
| 38 import sys | |
| 39 import tempfile | |
| 40 import textwrap | |
| 41 | |
| 42 import pytz | |
| 43 | |
| 44 from infra_libs.ts_mon.common.metrics import CumulativeMetric | |
| 45 | |
| 46 log_metric = CumulativeMetric( | |
| 47 'proc/log_lines', description="Number of log lines, per severity level.") | |
| 48 | |
| 49 if sys.platform.startswith('win'): # pragma: no cover | |
| 50 DEFAULT_LOG_DIRECTORIES = os.pathsep.join([ | |
| 51 'E:\\chrome-infra-logs', | |
| 52 'C:\\chrome-infra-logs', | |
| 53 ]) | |
| 54 else: | |
| 55 DEFAULT_LOG_DIRECTORIES = '/var/log/chrome-infra' | |
| 56 | |
| 57 | |
| 58 class InfraFilter(logging.Filter): # pragma: no cover | |
| 59 """Adds fields used by the infra-specific formatter. | |
| 60 | |
| 61 Fields added: | |
| 62 | |
| 63 - 'iso8601': timestamp | |
| 64 - 'severity': one-letter indicator of log level (first letter of levelname). | |
| 65 - 'fullModuleName': name of the module including the package name. | |
| 66 | |
| 67 Args: | |
| 68 timezone (str): timezone in which timestamps should be printed. | |
| 69 module_name_blacklist (str): do not print log lines from modules whose name | |
| 70 matches this regular expression. | |
| 71 """ | |
| 72 def __init__(self, timezone, module_name_blacklist=None): | |
| 73 super(InfraFilter, self).__init__() | |
| 74 self.module_name_blacklist = None | |
| 75 | |
| 76 if module_name_blacklist: | |
| 77 self.module_name_blacklist = re.compile(module_name_blacklist) | |
| 78 | |
| 79 self.tz = pytz.timezone(timezone) | |
| 80 | |
| 81 def filter(self, record): | |
| 82 dt = datetime.datetime.fromtimestamp(record.created, tz=pytz.utc) | |
| 83 record.iso8601 = self.tz.normalize(dt).isoformat() | |
| 84 record.severity = record.levelname[0] | |
| 85 log_metric.increment(fields={'level': record.severity}) | |
| 86 record.fullModuleName = self._full_module_name() or record.module | |
| 87 if self.module_name_blacklist: | |
| 88 if self.module_name_blacklist.search(record.fullModuleName): | |
| 89 return False | |
| 90 return True | |
| 91 | |
| 92 def _full_module_name(self): | |
| 93 frame = inspect.currentframe() | |
| 94 try: | |
| 95 while frame is not None: | |
| 96 try: | |
| 97 name = frame.f_globals['__name__'] | |
| 98 except KeyError: | |
| 99 continue | |
| 100 | |
| 101 if name not in (__name__, 'logging'): | |
| 102 return name | |
| 103 frame = frame.f_back | |
| 104 finally: | |
| 105 del frame | |
| 106 | |
| 107 return None | |
| 108 | |
| 109 | |
| 110 class InfraFormatter(logging.Formatter): # pragma: no cover | |
| 111 """Formats log messages in a standard way. | |
| 112 | |
| 113 This object processes fields added by :class:`InfraFilter`. | |
| 114 """ | |
| 115 def __init__(self): | |
| 116 super(InfraFormatter, self).__init__( | |
| 117 '[%(severity)s%(iso8601)s %(process)d %(thread)d ' | |
| 118 '%(fullModuleName)s:%(lineno)s] %(message)s') | |
| 119 | |
| 120 | |
| 121 def add_handler(logger, handler=None, timezone='UTC', | |
| 122 level=logging.WARNING, | |
| 123 module_name_blacklist=None): # pragma: no cover | |
| 124 """Configures and adds a handler to a logger the standard way for infra. | |
| 125 | |
| 126 Args: | |
| 127 logger (logging.Logger): logger object obtained from `logging.getLogger`. | |
| 128 | |
| 129 Keyword Args: | |
| 130 handler (logging.Handler): handler to add to the logger. defaults to | |
| 131 logging.StreamHandler. | |
| 132 timezone (str): timezone to use for timestamps. | |
| 133 level (int): logging level. Could be one of DEBUG, INFO, WARNING, CRITICAL | |
| 134 module_name_blacklist (str): do not print log lines from modules whose name | |
| 135 matches this regular expression. | |
| 136 | |
| 137 Example usage:: | |
| 138 | |
| 139 import logging | |
| 140 import infra_libs.logs | |
| 141 logger = logging.getLogger('foo') | |
| 142 infra_libs.logs.add_handler(logger, timezone='US/Pacific') | |
| 143 logger.info('test message') | |
| 144 | |
| 145 The last line should print something like:: | |
| 146 | |
| 147 [I2014-06-27T11:42:32.418716-07:00 7082 logs:71] test message | |
| 148 | |
| 149 """ | |
| 150 handler = handler or logging.StreamHandler() | |
| 151 handler.addFilter(InfraFilter(timezone, | |
| 152 module_name_blacklist=module_name_blacklist)) | |
| 153 handler.setFormatter(InfraFormatter()) | |
| 154 handler.setLevel(level=level) | |
| 155 logger.addHandler(handler) | |
| 156 | |
| 157 # Formatters only get messages that pass this filter: let everything through. | |
| 158 logger.setLevel(level=logging.DEBUG) | |
| 159 | |
| 160 | |
| 161 def default_program_name(): | |
| 162 # Use argv[0] as the program name, except when it's '__main__.py' which is the | |
| 163 # case when we were invoked by run.py. In this case look at the main module's | |
| 164 # __package__ variable which is set by runpy. | |
| 165 ret = os.path.basename(sys.argv[0]) | |
| 166 if ret == '__main__.py': | |
| 167 package = sys.modules['__main__'].__package__ | |
| 168 if package is not None: | |
| 169 return package.split('.')[-1] | |
| 170 return ret | |
| 171 | |
| 172 | |
| 173 def add_argparse_options(parser, | |
| 174 default_level=logging.WARNING): # pragma: no cover | |
| 175 """Adds logging related options to an argparse.ArgumentParser. | |
| 176 | |
| 177 See also: :func:`process_argparse_options` | |
| 178 """ | |
| 179 | |
| 180 parser = parser.add_argument_group('Logging Options') | |
| 181 g = parser.add_mutually_exclusive_group() | |
| 182 g.set_defaults(log_level=default_level) | |
| 183 g.add_argument('--logs-quiet', '--quiet', | |
| 184 action='store_const', const=logging.ERROR, | |
| 185 dest='log_level', help='Make the output quieter (ERROR).') | |
| 186 g.add_argument('--logs-warning', '--warning', | |
| 187 action='store_const', const=logging.WARNING, | |
| 188 dest='log_level', | |
| 189 help='Set the output to an average verbosity (WARNING).') | |
| 190 g.add_argument('--logs-verbose', '--verbose', | |
| 191 action='store_const', const=logging.INFO, | |
| 192 dest='log_level', help='Make the output louder (INFO).') | |
| 193 g.add_argument('--logs-debug', '--debug', | |
| 194 action='store_const', const=logging.DEBUG, | |
| 195 dest='log_level', help='Make the output really loud (DEBUG).') | |
| 196 parser.add_argument('--logs-black-list', metavar='REGEX', | |
| 197 help='hide log lines emitted by modules whose name ' | |
| 198 'matches\nthis regular expression.') | |
| 199 parser.add_argument( | |
| 200 '--logs-directory', | |
| 201 default=DEFAULT_LOG_DIRECTORIES, | |
| 202 help=textwrap.fill( | |
| 203 'directory into which to write logs (default: %%(default)s). If ' | |
| 204 'this directory does not exist or is not writable, the temporary ' | |
| 205 'directory (%s) will be used instead. If this is explicitly set ' | |
| 206 'to the empty string, logs will not be written at all. May be set ' | |
| 207 'to multiple directories separated by the "%s" character, in ' | |
| 208 'which case the first one that exists and is writable is used.' % ( | |
| 209 tempfile.gettempdir(), os.pathsep), width=56)) | |
| 210 parser.add_argument( | |
| 211 '--logs-program-name', | |
| 212 default=default_program_name(), | |
| 213 help='the program name used to name the log files created in ' | |
| 214 '--logs-directory (default: %(default)s).') | |
| 215 parser.add_argument( | |
| 216 '--logs-debug-file', | |
| 217 action='store_true', | |
| 218 help='by default only INFO, WARNING and ERROR log files are written to ' | |
| 219 'disk. This flag causes a DEBUG log to be written as well.') | |
| 220 | |
| 221 | |
| 222 def process_argparse_options(options, logger=None): # pragma: no cover | |
| 223 """Handles logging argparse options added in 'add_argparse_options'. | |
| 224 | |
| 225 Configures 'logging' module. | |
| 226 | |
| 227 Args: | |
| 228 options: return value of argparse.ArgumentParser.parse_args. | |
| 229 logger (logging.Logger): logger to apply the configuration to. | |
| 230 | |
| 231 Example usage:: | |
| 232 | |
| 233 import argparse | |
| 234 import sys | |
| 235 import infra_libs.logs | |
| 236 | |
| 237 parser = argparse.ArgumentParser() | |
| 238 infra_libs.logs.add_argparse_options(parser) | |
| 239 | |
| 240 options = parser.parse_args(sys.path[1:]) | |
| 241 infra_libs.logs.process_argparse_options(options) | |
| 242 """ | |
| 243 | |
| 244 if logger is None: | |
| 245 logger = logging.root | |
| 246 | |
| 247 add_handler(logger, level=options.log_level, | |
| 248 module_name_blacklist=options.logs_black_list) | |
| 249 | |
| 250 if options.logs_directory: | |
| 251 _add_file_handlers(options, logger) | |
| 252 | |
| 253 | |
| 254 def _add_file_handlers(options, logger): # pragma: no cover | |
| 255 # Test whether we can write to the log directory. If not, write to a | |
| 256 # temporary directory instead. One of the DEFAULT_LOG_DIRECTORIES are created | |
| 257 # on the real production machines by puppet, so /tmp should only be used when | |
| 258 # running locally on developers' workstations. | |
| 259 logs_directory = tempfile.gettempdir() | |
| 260 for directory in options.logs_directory.split(os.pathsep): | |
| 261 if not os.path.isdir(directory): | |
| 262 continue | |
| 263 | |
| 264 try: | |
| 265 with tempfile.TemporaryFile(dir=directory): | |
| 266 pass | |
| 267 except OSError: | |
| 268 pass | |
| 269 else: | |
| 270 logs_directory = directory | |
| 271 break | |
| 272 | |
| 273 # Log files are named with this pattern: | |
| 274 # <program>.<hostname>.<username>.log.<level>.YYYYMMDD-HHMMSS.<pid> | |
| 275 pattern = "%s.%s.%s.log.%%s.%s.%d" % ( | |
| 276 options.logs_program_name, | |
| 277 socket.getfqdn().split('.')[0], | |
| 278 getpass.getuser(), | |
| 279 datetime.datetime.utcnow().strftime('%Y%m%d-%H%M%S'), | |
| 280 os.getpid()) | |
| 281 | |
| 282 file_levels = [logging.INFO, logging.WARNING, logging.ERROR] | |
| 283 if options.logs_debug_file: | |
| 284 file_levels.append(logging.DEBUG) | |
| 285 | |
| 286 for level in file_levels: | |
| 287 add_handler( | |
| 288 logger, | |
| 289 handler=logging.handlers.RotatingFileHandler( | |
| 290 filename=os.path.join( | |
| 291 logs_directory, pattern % logging.getLevelName(level)), | |
| 292 maxBytes=10 * 1024 * 1024, | |
| 293 backupCount=10, | |
| 294 delay=True), | |
| 295 level=level) | |
| OLD | NEW |