3 """Utilities related to logging."""
11 from logging.handlers import RotatingFileHandler, SysLogHandler
16 from typing import Callable, Iterable, Mapping, Optional
18 from overrides import overrides
20 # This module is commonly used by others in here and should avoid
21 # taking any unnecessary dependencies back on them.
25 cfg = config.add_commandline_args(
26 f'Logging ({__file__})',
27 'Args related to logging')
29 '--logging_config_file',
30 type=argparse_utils.valid_filename,
33 help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
39 choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
41 help='The global default level below which to squelch log messages; see also --lmodule',
47 help='The format for lines logged via the logger module. See: https://docs.python.org/3/library/logging.html#formatter-objects'
50 '--logging_date_format',
52 default='%Y/%m/%dT%H:%M:%S.%f%z',
54 help='The format of any dates in --logging_format.'
58 action=argparse_utils.ActionNoYes,
60 help='Should we log to the console (stderr)',
67 help='The filename of the logfile to write.'
70 '--logging_filename_maxsize',
74 help='The maximum size (in bytes) to write to the logging_filename.'
77 '--logging_filename_count',
81 help='The number of logging_filename copies to keep before deleting.'
85 action=argparse_utils.ActionNoYes,
87 help='Should we log to localhost\'s syslog.'
90 '--logging_syslog_facility',
93 choices=['NOTSET', 'AUTH', 'AUTH_PRIV', 'CRON', 'DAEMON', 'FTP', 'KERN', 'LPR', 'MAIL', 'NEWS',
94 'SYSLOG', 'USER', 'UUCP', 'LOCAL0', 'LOCAL1', 'LOCAL2', 'LOCAL3', 'LOCAL4', 'LOCAL5',
96 metavar='SYSLOG_FACILITY_LIST',
97 help='The default syslog message facility identifier',
100 '--logging_debug_threads',
101 action=argparse_utils.ActionNoYes,
103 help='Should we prepend pid/tid data to all log messages?'
106 '--logging_debug_modules',
107 action=argparse_utils.ActionNoYes,
109 help='Should we prepend module/function data to all log messages?'
112 '--logging_info_is_print',
113 action=argparse_utils.ActionNoYes,
115 help='logging.info also prints to stdout.'
118 '--logging_squelch_repeats_enabled',
119 action=argparse_utils.ActionNoYes,
121 help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?'
124 '--logging_probabilistically_enabled',
125 action=argparse_utils.ActionNoYes,
127 help='Do we allow probabilistic logging (for code that wants it) or should we always log?'
129 # See also: OutputMultiplexer
131 '--logging_captures_prints',
132 action=argparse_utils.ActionNoYes,
134 help='When calling print, also log.info automatically.'
139 metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
141 'Allows per-scope logging levels which override the global level set with --logging-level.' +
142 'Pass a space separated list of <scope>=<level> where <scope> is one of: module, ' +
143 'module:function, or :function and <level> is a logging level (e.g. INFO, DEBUG...)'
147 '--logging_clear_spammy_handlers',
148 action=argparse_utils.ActionNoYes,
151 'Should logging code clear preexisting global logging handlers and thus insist that is ' +
152 'alone can add handlers. Use this to work around annoying modules that insert global ' +
153 'handlers with formats and logging levels you might now want. Caveat emptor, this may ' +
154 'cause you to miss logging messages.'
159 built_in_print = print
162 def function_identifier(f: Callable) -> str:
164 Given a callable function, return a string that identifies it.
165 Usually that string is just __module__:__name__ but there's a
166 corner case: when __module__ is __main__ (i.e. the callable is
167 defined in the same module as __main__). In this case,
168 f.__module__ returns "__main__" instead of the file that it is
169 defined in. Work around this using pathlib.Path (see below).
171 >>> function_identifier(function_identifier)
172 'logging_utils:function_identifier'
175 if f.__module__ == '__main__':
176 from pathlib import Path
178 module = __main__.__file__
179 module = Path(module).stem
180 return f'{module}:{f.__name__}'
182 return f'{f.__module__}:{f.__name__}'
185 # A map from logging_callsite_id -> count of logged messages.
186 squelched_logging_counts: Mapping[str, int] = {}
189 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
191 A decorator that marks a function as interested in having the logging
192 messages that it produces be squelched (ignored) after it logs the
193 same message more than N times.
195 Note: this decorator affects *ALL* logging messages produced
196 within the decorated function. That said, messages must be
197 identical in order to be squelched. For example, if the same line
198 of code produces different messages (because of, e.g., a format
199 string), the messages are considered to be different.
202 def squelch_logging_wrapper(f: Callable):
203 identifier = function_identifier(f)
204 squelched_logging_counts[identifier] = squelch_after_n_repeats
206 return squelch_logging_wrapper
209 class SquelchRepeatedMessagesFilter(logging.Filter):
211 A filter that only logs messages from a given site with the same
212 (exact) message at the same logging level N times and ignores
213 subsequent attempts to log.
215 This filter only affects logging messages that repeat more than
216 a threshold number of times from functions that are tagged with
217 the @logging_utils.squelched_logging_ok decorator.
220 def __init__(self) -> None:
221 self.counters = collections.Counter()
225 def filter(self, record: logging.LogRecord) -> bool:
226 id1 = f'{record.module}:{record.funcName}'
227 if id1 not in squelched_logging_counts:
229 threshold = squelched_logging_counts[id1]
230 logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
231 count = self.counters[logsite]
232 self.counters[logsite] += 1
233 return count < threshold
236 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
237 """Only interested in seeing logging messages from an allow list of
238 module names or module:function names. Block others.
242 def level_name_to_level(name: str) -> int:
243 numeric_level = getattr(
248 if not isinstance(numeric_level, int):
249 raise ValueError('Invalid level: {name}')
254 default_logging_level: int,
255 per_scope_logging_levels: str,
258 self.valid_levels = set(['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'])
259 self.default_logging_level = default_logging_level
260 self.level_by_scope = {}
261 if per_scope_logging_levels is not None:
262 for chunk in per_scope_logging_levels.split(','):
265 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
270 (scope, level) = chunk.split('=')
273 f'Malformed lmodule directive: "{chunk}". Ignored.',
277 scope = scope.strip()
278 level = level.strip().upper()
279 if level not in self.valid_levels:
281 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
285 self.level_by_scope[scope] = (
286 DynamicPerScopeLoggingLevelFilter.level_name_to_level(
292 def filter(self, record: logging.LogRecord) -> bool:
293 # First try to find a logging level by scope (--lmodule)
294 if len(self.level_by_scope) > 0:
298 f'{record.module}:{record.funcName}',
299 f':{record.funcName}'
301 level = self.level_by_scope.get(scope, None)
302 if level is not None:
303 if min_level is None or level < min_level:
306 # If we found one, use it instead of the global default level.
307 if min_level is not None:
308 return record.levelno >= min_level
310 # Otherwise, use the global logging level (--logging_level)
311 return record.levelno >= self.default_logging_level
314 # A map from function_identifier -> probability of logging (0.0%..100.0%)
315 probabilistic_logging_levels: Mapping[str, float] = {}
318 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
320 A decorator that indicates that all logging statements within the
321 scope of a particular (marked) function are not deterministic
322 (i.e. they do not always unconditionally log) but rather are
323 probabilistic (i.e. they log N% of the time randomly).
325 This affects *ALL* logging statements within the marked function.
328 def probabilistic_logging_wrapper(f: Callable):
329 identifier = function_identifier(f)
330 probabilistic_logging_levels[identifier] = probability_of_logging
332 return probabilistic_logging_wrapper
335 class ProbabilisticFilter(logging.Filter):
337 A filter that logs messages probabilistically (i.e. randomly at some
340 This filter only affects logging messages from functions that have
341 been tagged with the @logging_utils.probabilistic_logging decorator.
345 def filter(self, record: logging.LogRecord) -> bool:
346 id1 = f'{record.module}:{record.funcName}'
347 if id1 not in probabilistic_logging_levels:
349 threshold = probabilistic_logging_levels[id1]
350 return (random.random() * 100.0) <= threshold
353 class OnlyInfoFilter(logging.Filter):
355 A filter that only logs messages produced at the INFO logging
356 level. This is used by the logging_info_is_print commandline
357 option to select a subset of the logging stream to send to a
362 def filter(self, record: logging.LogRecord):
363 return record.levelno == logging.INFO
366 class MillisecondAwareFormatter(logging.Formatter):
368 A formatter for adding milliseconds to log messages.
371 converter = datetime.datetime.fromtimestamp
374 def formatTime(self, record, datefmt=None):
375 ct = MillisecondAwareFormatter.converter(
376 record.created, pytz.timezone("US/Pacific")
379 s = ct.strftime(datefmt)
381 t = ct.strftime("%Y-%m-%d %H:%M:%S")
382 s = "%s,%03d" % (t, record.msecs)
386 def initialize_logging(logger=None) -> logging.Logger:
387 assert config.has_been_parsed()
389 logger = logging.getLogger() # Root logger
392 if config.config['logging_clear_spammy_handlers']:
393 while logger.hasHandlers():
394 logger.removeHandler(logger.handlers[0])
397 if config.config['logging_config_file'] is not None:
398 logging.config.fileConfig('logging.conf')
403 # Global default logging level (--logging_level)
404 default_logging_level = getattr(
406 config.config['logging_level'].upper(),
409 if not isinstance(default_logging_level, int):
410 raise ValueError('Invalid level: %s' % config.config['logging_level'])
412 if config.config['logging_format']:
413 fmt = config.config['logging_format']
415 if config.config['logging_syslog']:
416 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
418 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
420 if config.config['logging_debug_threads']:
421 fmt = f'%(process)d.%(thread)d|{fmt}'
422 if config.config['logging_debug_modules']:
423 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
425 if config.config['logging_syslog']:
426 if sys.platform not in ('win32', 'cygwin'):
427 if config.config['logging_syslog_facility']:
428 facility_name = 'LOG_' + config.config['logging_syslog_facility']
429 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)
430 handler = SysLogHandler(facility=facility, address='/dev/log')
431 handler.setFormatter(
432 MillisecondAwareFormatter(
434 datefmt=config.config['logging_date_format'],
437 handlers.append(handler)
439 if config.config['logging_filename']:
440 handler = RotatingFileHandler(
441 config.config['logging_filename'],
442 maxBytes = config.config['logging_filename_maxsize'],
443 backupCount = config.config['logging_filename_count'],
445 handler.setFormatter(
446 MillisecondAwareFormatter(
448 datefmt=config.config['logging_date_format'],
451 handlers.append(handler)
453 if config.config['logging_console']:
454 handler = logging.StreamHandler(sys.stderr)
455 handler.setFormatter(
456 MillisecondAwareFormatter(
458 datefmt=config.config['logging_date_format'],
461 handlers.append(handler)
463 if len(handlers) == 0:
464 handlers.append(logging.NullHandler())
466 for handler in handlers:
467 logger.addHandler(handler)
469 if config.config['logging_info_is_print']:
470 handler = logging.StreamHandler(sys.stdout)
471 handler.addFilter(OnlyInfoFilter())
472 logger.addHandler(handler)
474 if config.config['logging_squelch_repeats_enabled']:
475 for handler in handlers:
476 handler.addFilter(SquelchRepeatedMessagesFilter())
478 if config.config['logging_probabilistically_enabled']:
479 for handler in handlers:
480 handler.addFilter(ProbabilisticFilter())
482 for handler in handlers:
484 DynamicPerScopeLoggingLevelFilter(
485 default_logging_level,
486 config.config['lmodule'],
490 logger.propagate = False
492 if config.config['logging_captures_prints']:
494 global built_in_print
496 def print_and_also_log(*arg, **kwarg):
497 f = kwarg.get('file', None)
502 built_in_print(*arg, **kwarg)
503 builtins.print = print_and_also_log
505 logger.debug(f'Initialized logger; default logging level is {default_logging_level}.')
506 if config.config['logging_clear_spammy_handlers'] and spammy_handlers > 0:
508 'Logging cleared {spammy_handlers} global handlers (--logging_clear_spammy_handlers)'
510 logger.debug(f'Logging format is "{fmt}"')
511 if config.config['logging_syslog']:
512 logger.debug(f'Logging to syslog as {facility_name} with normal severity mapping')
513 if config.config['logging_filename']:
514 logger.debug(f'Logging to filename {config.config["logging_filename"]} with rotation')
515 if config.config['logging_console']:
516 logger.debug(f'Logging to the console.')
517 if config.config['logging_info_is_print']:
519 'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
521 if config.config['logging_squelch_repeats_enabled']:
523 'Logging code is allowed to request repeated messages be squelched (--logging_squelch_repeats_enabled)'
525 if config.config['logging_probabilistically_enabled']:
527 'Logging code is allowed to request probabilistic logging (--logging_probabilistically_enabled)'
529 if config.config['lmodule']:
531 'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
533 if config.config['logging_captures_prints']:
534 logger.debug('Logging will capture printed messages (--logging_captures_prints)')
538 def get_logger(name: str = ""):
539 logger = logging.getLogger(name)
540 return initialize_logging(logger)
543 def tprint(*args, **kwargs) -> None:
544 """Legacy function for printing a message augmented with thread id."""
546 if config.config['logging_debug_threads']:
547 from thread_utils import current_thread_id
548 print(f'{current_thread_id()}', end="")
549 print(*args, **kwargs)
554 def dprint(*args, **kwargs) -> None:
555 """Legacy function used to print to stderr."""
557 print(*args, file=sys.stderr, **kwargs)
560 class OutputMultiplexer(object):
562 A class that broadcasts printed messages to several sinks (including
563 various logging levels, different files, different file handles,
564 the house log, etc...)
567 class Destination(enum.IntEnum):
568 """Bits in the destination_bitv bitvector. Used to indicate the
569 output destination."""
572 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
574 LOG_CRITICAL = 0x10 # ⎭
575 FILENAMES = 0x20 # Must provide a filename to the c'tor.
576 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
578 ALL_LOG_DESTINATIONS = (
579 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
581 ALL_OUTPUT_DESTINATIONS = 0x8F
584 destination_bitv: int,
587 filenames: Optional[Iterable[str]] = None,
588 handles: Optional[Iterable[io.TextIOWrapper]] = None):
590 logger = logging.getLogger(None)
593 if filenames is not None:
595 open(filename, 'wb', buffering=0) for filename in filenames
598 if destination_bitv & OutputMultiplexer.FILENAMES:
600 "Filenames argument is required if bitv & FILENAMES"
604 if handles is not None:
605 self.h = [handle for handle in handles]
607 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
609 "Handle argument is required if bitv & FILEHANDLES"
613 self.set_destination_bitv(destination_bitv)
615 def get_destination_bitv(self):
616 return self.destination_bitv
618 def set_destination_bitv(self, destination_bitv: int):
619 if destination_bitv & self.Destination.FILENAMES and self.f is None:
621 "Filename argument is required if bitv & FILENAMES"
623 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
625 "Handle argument is required if bitv & FILEHANDLES"
627 self.destination_bitv = destination_bitv
629 def print(self, *args, **kwargs):
630 from string_utils import sprintf, strip_escape_sequences
631 end = kwargs.pop("end", None)
633 if not isinstance(end, str):
634 raise TypeError("end must be None or a string")
635 sep = kwargs.pop("sep", None)
637 if not isinstance(sep, str):
638 raise TypeError("sep must be None or a string")
640 raise TypeError("invalid keyword arguments to print()")
641 buf = sprintf(*args, end="", sep=sep)
649 self.destination_bitv & self.Destination.FILENAMES and
653 _.write(buf.encode('utf-8'))
657 self.destination_bitv & self.Destination.FILEHANDLES and
664 buf = strip_escape_sequences(buf)
665 if self.logger is not None:
666 if self.destination_bitv & self.Destination.LOG_DEBUG:
667 self.logger.debug(buf)
668 if self.destination_bitv & self.Destination.LOG_INFO:
669 self.logger.info(buf)
670 if self.destination_bitv & self.Destination.LOG_WARNING:
671 self.logger.warning(buf)
672 if self.destination_bitv & self.Destination.LOG_ERROR:
673 self.logger.error(buf)
674 if self.destination_bitv & self.Destination.LOG_CRITICAL:
675 self.logger.critical(buf)
676 if self.destination_bitv & self.Destination.HLOG:
680 if self.f is not None:
685 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
687 A context that uses an OutputMultiplexer. e.g.
689 with OutputMultiplexerContext(
690 OutputMultiplexer.LOG_INFO |
691 OutputMultiplexer.LOG_DEBUG |
692 OutputMultiplexer.FILENAMES |
693 OutputMultiplexer.FILEHANDLES,
694 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
697 mplex.print("This is a log message!")
701 destination_bitv: OutputMultiplexer.Destination,
715 def __exit__(self, etype, value, traceback) -> bool:
717 if etype is not None:
722 def hlog(message: str) -> None:
723 """Write a message to the house log."""
725 message = message.replace("'", "'\"'\"'")
726 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
729 if __name__ == '__main__':