3 """Utilities related to logging."""
11 from logging.handlers import RotatingFileHandler, SysLogHandler
15 from typing import Callable, Iterable, Mapping, Optional
17 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(f'Logging ({__file__})', 'Args related to logging')
27 '--logging_config_file',
28 type=argparse_utils.valid_filename,
31 help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
37 choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
39 help='The global default level below which to squelch log messages; see also --lmodule',
45 help='The format for lines logged via the logger module. See: https://docs.python.org/3/library/logging.html#formatter-objects',
48 '--logging_date_format',
50 default='%Y/%m/%dT%H:%M:%S.%f%z',
52 help='The format of any dates in --logging_format.',
56 action=argparse_utils.ActionNoYes,
58 help='Should we log to the console (stderr)',
65 help='The filename of the logfile to write.',
68 '--logging_filename_maxsize',
70 default=(1024 * 1024),
72 help='The maximum size (in bytes) to write to the logging_filename.',
75 '--logging_filename_count',
79 help='The number of logging_filename copies to keep before deleting.',
83 action=argparse_utils.ActionNoYes,
85 help='Should we log to localhost\'s syslog.',
88 '--logging_syslog_facility',
114 metavar='SYSLOG_FACILITY_LIST',
115 help='The default syslog message facility identifier',
118 '--logging_debug_threads',
119 action=argparse_utils.ActionNoYes,
121 help='Should we prepend pid/tid data to all log messages?',
124 '--logging_debug_modules',
125 action=argparse_utils.ActionNoYes,
127 help='Should we prepend module/function data to all log messages?',
130 '--logging_info_is_print',
131 action=argparse_utils.ActionNoYes,
133 help='logging.info also prints to stdout.',
136 '--logging_squelch_repeats',
137 action=argparse_utils.ActionNoYes,
139 help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?',
142 '--logging_probabilistically',
143 action=argparse_utils.ActionNoYes,
145 help='Do we allow probabilistic logging (for code that wants it) or should we always log?',
147 # See also: OutputMultiplexer
149 '--logging_captures_prints',
150 action=argparse_utils.ActionNoYes,
152 help='When calling print, also log.info automatically.',
157 metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
159 'Allows per-scope logging levels which override the global level set with --logging-level.'
160 + 'Pass a space separated list of <scope>=<level> where <scope> is one of: module, '
161 + 'module:function, or :function and <level> is a logging level (e.g. INFO, DEBUG...)'
165 '--logging_clear_preexisting_handlers',
166 action=argparse_utils.ActionNoYes,
169 'Should logging code clear preexisting global logging handlers and thus insist that is '
170 + 'alone can add handlers. Use this to work around annoying modules that insert global '
171 + 'handlers with formats and logging levels you might now want. Caveat emptor, this may '
172 + 'cause you to miss logging messages.'
176 built_in_print = print
177 logging_initialized = False
180 # A map from logging_callsite_id -> count of logged messages.
181 squelched_logging_counts: Mapping[str, int] = {}
184 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
186 A decorator that marks a function as interested in having the logging
187 messages that it produces be squelched (ignored) after it logs the
188 same message more than N times.
190 Note: this decorator affects *ALL* logging messages produced
191 within the decorated function. That said, messages must be
192 identical in order to be squelched. For example, if the same line
193 of code produces different messages (because of, e.g., a format
194 string), the messages are considered to be different.
198 def squelch_logging_wrapper(f: Callable):
199 import function_utils
201 identifier = function_utils.function_identifier(f)
202 squelched_logging_counts[identifier] = squelch_after_n_repeats
205 return squelch_logging_wrapper
208 class SquelchRepeatedMessagesFilter(logging.Filter):
210 A filter that only logs messages from a given site with the same
211 (exact) message at the same logging level N times and ignores
212 subsequent attempts to log.
214 This filter only affects logging messages that repeat more than
215 a threshold number of times from functions that are tagged with
216 the @logging_utils.squelched_logging_ok decorator; others are
219 This functionality is enabled by default but can be disabled via
220 the --no_logging_squelch_repeats commandline flag.
224 def __init__(self) -> None:
225 self.counters = collections.Counter()
229 def filter(self, record: logging.LogRecord) -> bool:
230 id1 = f'{record.module}:{record.funcName}'
231 if id1 not in squelched_logging_counts:
233 threshold = squelched_logging_counts[id1]
234 logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
235 count = self.counters[logsite]
236 self.counters[logsite] += 1
237 return count < threshold
240 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
241 """This filter only allows logging messages from an allow list of
242 module names or module:function names. Blocks others.
247 def level_name_to_level(name: str) -> int:
248 numeric_level = getattr(logging, name, None)
249 if not isinstance(numeric_level, int):
250 raise ValueError(f'Invalid level: {name}')
255 default_logging_level: int,
256 per_scope_logging_levels: str,
259 self.valid_levels = set(
260 ['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL']
262 self.default_logging_level = default_logging_level
263 self.level_by_scope = {}
264 if per_scope_logging_levels is not None:
265 for chunk in per_scope_logging_levels.split(','):
268 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
273 (scope, level) = chunk.split('=')
276 f'Malformed lmodule directive: "{chunk}". Ignored.',
280 scope = scope.strip()
281 level = level.strip().upper()
282 if level not in self.valid_levels:
284 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
290 ] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(level)
293 def filter(self, record: logging.LogRecord) -> bool:
294 # First try to find a logging level by scope (--lmodule)
295 if len(self.level_by_scope) > 0:
299 f'{record.module}:{record.funcName}',
300 f':{record.funcName}',
302 level = self.level_by_scope.get(scope, None)
303 if level is not None:
304 if min_level is None or level < min_level:
307 # If we found one, use it instead of the global default level.
308 if min_level is not None:
309 return record.levelno >= min_level
311 # Otherwise, use the global logging level (--logging_level)
312 return record.levelno >= self.default_logging_level
315 # A map from function_identifier -> probability of logging (0.0%..100.0%)
316 probabilistic_logging_levels: Mapping[str, float] = {}
319 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
321 A decorator that indicates that all logging statements within the
322 scope of a particular (marked) function are not deterministic
323 (i.e. they do not always unconditionally log) but rather are
324 probabilistic (i.e. they log N% of the time randomly).
326 Note that this functionality can be disabled (forcing all logged
327 messages to produce output) via the --no_logging_probabilistically
330 This affects *ALL* logging statements within the marked function.
334 def probabilistic_logging_wrapper(f: Callable):
335 import function_utils
337 identifier = function_utils.function_identifier(f)
338 probabilistic_logging_levels[identifier] = probability_of_logging
341 return probabilistic_logging_wrapper
344 class ProbabilisticFilter(logging.Filter):
346 A filter that logs messages probabilistically (i.e. randomly at some
349 This filter only affects logging messages from functions that have
350 been tagged with the @logging_utils.probabilistic_logging decorator.
355 def filter(self, record: logging.LogRecord) -> bool:
356 id1 = f'{record.module}:{record.funcName}'
357 if id1 not in probabilistic_logging_levels:
359 threshold = probabilistic_logging_levels[id1]
360 return (random.random() * 100.0) <= threshold
363 class OnlyInfoFilter(logging.Filter):
365 A filter that only logs messages produced at the INFO logging
366 level. This is used by the logging_info_is_print commandline
367 option to select a subset of the logging stream to send to a
373 def filter(self, record: logging.LogRecord):
374 return record.levelno == logging.INFO
377 class MillisecondAwareFormatter(logging.Formatter):
379 A formatter for adding milliseconds to log messages which, for
380 whatever reason, the default python logger doesn't do.
384 converter = datetime.datetime.fromtimestamp
387 def formatTime(self, record, datefmt=None):
388 ct = MillisecondAwareFormatter.converter(
389 record.created, pytz.timezone("US/Pacific")
392 s = ct.strftime(datefmt)
394 t = ct.strftime("%Y-%m-%d %H:%M:%S")
395 s = "%s,%03d" % (t, record.msecs)
399 def initialize_logging(logger=None) -> logging.Logger:
400 global logging_initialized
401 if logging_initialized:
403 logging_initialized = True
406 logger = logging.getLogger()
408 preexisting_handlers_count = 0
409 assert config.has_been_parsed()
410 if config.config['logging_clear_preexisting_handlers']:
411 while logger.hasHandlers():
412 logger.removeHandler(logger.handlers[0])
413 preexisting_handlers_count += 1
415 if config.config['logging_config_file'] is not None:
416 logging.config.fileConfig('logging.conf')
421 # Global default logging level (--logging_level)
422 default_logging_level = getattr(
423 logging, config.config['logging_level'].upper(), None
425 if not isinstance(default_logging_level, int):
426 raise ValueError('Invalid level: %s' % config.config['logging_level'])
428 if config.config['logging_format']:
429 fmt = config.config['logging_format']
431 if config.config['logging_syslog']:
432 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
434 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
435 if config.config['logging_debug_threads']:
436 fmt = f'%(process)d.%(thread)d|{fmt}'
437 if config.config['logging_debug_modules']:
438 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
440 if config.config['logging_syslog']:
441 if sys.platform not in ('win32', 'cygwin'):
442 if config.config['logging_syslog_facility']:
443 facility_name = 'LOG_' + config.config['logging_syslog_facility']
444 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)
445 handler = SysLogHandler(facility=facility, address='/dev/log')
446 handler.setFormatter(
447 MillisecondAwareFormatter(
449 datefmt=config.config['logging_date_format'],
452 handlers.append(handler)
454 if config.config['logging_filename']:
455 handler = RotatingFileHandler(
456 config.config['logging_filename'],
457 maxBytes=config.config['logging_filename_maxsize'],
458 backupCount=config.config['logging_filename_count'],
460 handler.setFormatter(
461 MillisecondAwareFormatter(
463 datefmt=config.config['logging_date_format'],
466 handlers.append(handler)
468 if config.config['logging_console']:
469 handler = logging.StreamHandler(sys.stderr)
470 handler.setFormatter(
471 MillisecondAwareFormatter(
473 datefmt=config.config['logging_date_format'],
476 handlers.append(handler)
478 if len(handlers) == 0:
479 handlers.append(logging.NullHandler())
481 for handler in handlers:
482 logger.addHandler(handler)
484 if config.config['logging_info_is_print']:
485 handler = logging.StreamHandler(sys.stdout)
486 handler.addFilter(OnlyInfoFilter())
487 logger.addHandler(handler)
489 if config.config['logging_squelch_repeats']:
490 for handler in handlers:
491 handler.addFilter(SquelchRepeatedMessagesFilter())
493 if config.config['logging_probabilistically']:
494 for handler in handlers:
495 handler.addFilter(ProbabilisticFilter())
497 for handler in handlers:
499 DynamicPerScopeLoggingLevelFilter(
500 default_logging_level,
501 config.config['lmodule'],
505 logger.propagate = False
507 if config.config['logging_captures_prints']:
510 global built_in_print
512 def print_and_also_log(*arg, **kwarg):
513 f = kwarg.get('file', None)
518 built_in_print(*arg, **kwarg)
520 builtins.print = print_and_also_log
522 # At this point the logger is ready, handlers are set up,
523 # etc... so log about the logging configuration.
525 level_name = logging._levelToName.get(
526 default_logging_level, str(default_logging_level)
528 logger.debug(f'Initialized global logging; default logging level is {level_name}.')
530 config.config['logging_clear_preexisting_handlers']
531 and preexisting_handlers_count > 0
533 msg = f'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'
535 logger.debug(f'Logging format specification is "{fmt}"')
536 if config.config['logging_debug_threads']:
538 '...Logging format spec captures tid/pid (--logging_debug_threads)'
540 if config.config['logging_debug_modules']:
542 '...Logging format spec captures files/functions/lineno (--logging_debug_modules)'
544 if config.config['logging_syslog']:
546 f'Logging to syslog as {facility_name} with priority mapping based on level'
548 if config.config['logging_filename']:
549 logger.debug(f'Logging to filename {config.config["logging_filename"]}')
551 f'...with {config.config["logging_filename_maxsize"]} bytes max file size.'
554 f'...and {config.config["logging_filename_count"]} rotating backup file count.'
556 if config.config['logging_console']:
557 logger.debug('Logging to the console (stderr).')
558 if config.config['logging_info_is_print']:
560 'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
562 if config.config['logging_squelch_repeats']:
564 'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
568 'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'
570 if config.config['logging_probabilistically']:
572 'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
576 'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'
578 if config.config['lmodule']:
580 f'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
582 if config.config['logging_captures_prints']:
584 'Logging will capture printed data as logger.info messages (--logging_captures_prints)'
589 def get_logger(name: str = ""):
590 logger = logging.getLogger(name)
591 return initialize_logging(logger)
594 def tprint(*args, **kwargs) -> None:
595 """Legacy function for printing a message augmented with thread id
596 still needed by some code. Please use --logging_debug_threads in
600 if config.config['logging_debug_threads']:
601 from thread_utils import current_thread_id
603 print(f'{current_thread_id()}', end="")
604 print(*args, **kwargs)
609 def dprint(*args, **kwargs) -> None:
610 """Legacy function used to print to stderr still needed by some code.
611 Please just use normal logging with --logging_console which
612 accomplishes the same thing in new code.
615 print(*args, file=sys.stderr, **kwargs)
618 class OutputMultiplexer(object):
620 A class that broadcasts printed messages to several sinks (including
621 various logging levels, different files, different file handles,
622 the house log, etc...). See also OutputMultiplexerContext for an
627 class Destination(enum.IntEnum):
628 """Bits in the destination_bitv bitvector. Used to indicate the
629 output destination."""
633 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
635 LOG_CRITICAL = 0x10 # ⎭
636 FILENAMES = 0x20 # Must provide a filename to the c'tor.
637 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
639 ALL_LOG_DESTINATIONS = (
640 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
642 ALL_OUTPUT_DESTINATIONS = 0x8F
646 destination_bitv: int,
649 filenames: Optional[Iterable[str]] = None,
650 handles: Optional[Iterable[io.TextIOWrapper]] = None,
653 logger = logging.getLogger(None)
656 if filenames is not None:
657 self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
659 if destination_bitv & OutputMultiplexer.FILENAMES:
660 raise ValueError("Filenames argument is required if bitv & FILENAMES")
663 if handles is not None:
664 self.h = [handle for handle in handles]
666 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
667 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
670 self.set_destination_bitv(destination_bitv)
672 def get_destination_bitv(self):
673 return self.destination_bitv
675 def set_destination_bitv(self, destination_bitv: int):
676 if destination_bitv & self.Destination.FILENAMES and self.f is None:
677 raise ValueError("Filename argument is required if bitv & FILENAMES")
678 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
679 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
680 self.destination_bitv = destination_bitv
682 def print(self, *args, **kwargs):
683 from string_utils import sprintf, strip_escape_sequences
685 end = kwargs.pop("end", None)
687 if not isinstance(end, str):
688 raise TypeError("end must be None or a string")
689 sep = kwargs.pop("sep", None)
691 if not isinstance(sep, str):
692 raise TypeError("sep must be None or a string")
694 raise TypeError("invalid keyword arguments to print()")
695 buf = sprintf(*args, end="", sep=sep)
702 if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
704 _.write(buf.encode('utf-8'))
707 if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
712 buf = strip_escape_sequences(buf)
713 if self.logger is not None:
714 if self.destination_bitv & self.Destination.LOG_DEBUG:
715 self.logger.debug(buf)
716 if self.destination_bitv & self.Destination.LOG_INFO:
717 self.logger.info(buf)
718 if self.destination_bitv & self.Destination.LOG_WARNING:
719 self.logger.warning(buf)
720 if self.destination_bitv & self.Destination.LOG_ERROR:
721 self.logger.error(buf)
722 if self.destination_bitv & self.Destination.LOG_CRITICAL:
723 self.logger.critical(buf)
724 if self.destination_bitv & self.Destination.HLOG:
728 if self.f is not None:
733 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
735 A context that uses an OutputMultiplexer. e.g.
737 with OutputMultiplexerContext(
738 OutputMultiplexer.LOG_INFO |
739 OutputMultiplexer.LOG_DEBUG |
740 OutputMultiplexer.FILENAMES |
741 OutputMultiplexer.FILEHANDLES,
742 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
745 mplex.print("This is a log message!")
751 destination_bitv: OutputMultiplexer.Destination,
758 destination_bitv, logger=logger, filenames=filenames, handles=handles
764 def __exit__(self, etype, value, traceback) -> bool:
766 if etype is not None:
771 def hlog(message: str) -> None:
772 """Write a message to the house log (syslog facility local7 priority
773 info) by calling /usr/bin/logger. This is pretty hacky but used
774 by a bunch of code. Another way to do this would be to use
775 --logging_syslog and --logging_syslog_facility but I can't
776 actually say that's easier.
779 message = message.replace("'", "'\"'\"'")
780 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
783 if __name__ == '__main__':