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(
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',
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',
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_preexisting_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.'
158 built_in_print = print
159 logging_initialized = False
162 # A map from logging_callsite_id -> count of logged messages.
163 squelched_logging_counts: Mapping[str, int] = {}
166 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
168 A decorator that marks a function as interested in having the logging
169 messages that it produces be squelched (ignored) after it logs the
170 same message more than N times.
172 Note: this decorator affects *ALL* logging messages produced
173 within the decorated function. That said, messages must be
174 identical in order to be squelched. For example, if the same line
175 of code produces different messages (because of, e.g., a format
176 string), the messages are considered to be different.
179 def squelch_logging_wrapper(f: Callable):
180 import function_utils
181 identifier = function_utils.function_identifier(f)
182 squelched_logging_counts[identifier] = squelch_after_n_repeats
184 return squelch_logging_wrapper
187 class SquelchRepeatedMessagesFilter(logging.Filter):
189 A filter that only logs messages from a given site with the same
190 (exact) message at the same logging level N times and ignores
191 subsequent attempts to log.
193 This filter only affects logging messages that repeat more than
194 a threshold number of times from functions that are tagged with
195 the @logging_utils.squelched_logging_ok decorator; others are
198 This functionality is enabled by default but can be disabled via
199 the --no_logging_squelch_repeats commandline flag.
202 def __init__(self) -> None:
203 self.counters = collections.Counter()
207 def filter(self, record: logging.LogRecord) -> bool:
208 id1 = f'{record.module}:{record.funcName}'
209 if id1 not in squelched_logging_counts:
211 threshold = squelched_logging_counts[id1]
212 logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
213 count = self.counters[logsite]
214 self.counters[logsite] += 1
215 return count < threshold
218 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
219 """This filter only allows logging messages from an allow list of
220 module names or module:function names. Blocks others.
224 def level_name_to_level(name: str) -> int:
225 numeric_level = getattr(
230 if not isinstance(numeric_level, int):
231 raise ValueError('Invalid level: {name}')
236 default_logging_level: int,
237 per_scope_logging_levels: str,
240 self.valid_levels = set(['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'])
241 self.default_logging_level = default_logging_level
242 self.level_by_scope = {}
243 if per_scope_logging_levels is not None:
244 for chunk in per_scope_logging_levels.split(','):
247 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
252 (scope, level) = chunk.split('=')
255 f'Malformed lmodule directive: "{chunk}". Ignored.',
259 scope = scope.strip()
260 level = level.strip().upper()
261 if level not in self.valid_levels:
263 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
267 self.level_by_scope[scope] = (
268 DynamicPerScopeLoggingLevelFilter.level_name_to_level(
274 def filter(self, record: logging.LogRecord) -> bool:
275 # First try to find a logging level by scope (--lmodule)
276 if len(self.level_by_scope) > 0:
280 f'{record.module}:{record.funcName}',
281 f':{record.funcName}'
283 level = self.level_by_scope.get(scope, None)
284 if level is not None:
285 if min_level is None or level < min_level:
288 # If we found one, use it instead of the global default level.
289 if min_level is not None:
290 return record.levelno >= min_level
292 # Otherwise, use the global logging level (--logging_level)
293 return record.levelno >= self.default_logging_level
296 # A map from function_identifier -> probability of logging (0.0%..100.0%)
297 probabilistic_logging_levels: Mapping[str, float] = {}
300 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
302 A decorator that indicates that all logging statements within the
303 scope of a particular (marked) function are not deterministic
304 (i.e. they do not always unconditionally log) but rather are
305 probabilistic (i.e. they log N% of the time randomly).
307 Note that this functionality can be disabled (forcing all logged
308 messages to produce output) via the --no_logging_probabilistically
311 This affects *ALL* logging statements within the marked function.
314 def probabilistic_logging_wrapper(f: Callable):
315 import function_utils
316 identifier = function_utils.function_identifier(f)
317 probabilistic_logging_levels[identifier] = probability_of_logging
319 return probabilistic_logging_wrapper
322 class ProbabilisticFilter(logging.Filter):
324 A filter that logs messages probabilistically (i.e. randomly at some
327 This filter only affects logging messages from functions that have
328 been tagged with the @logging_utils.probabilistic_logging decorator.
332 def filter(self, record: logging.LogRecord) -> bool:
333 id1 = f'{record.module}:{record.funcName}'
334 if id1 not in probabilistic_logging_levels:
336 threshold = probabilistic_logging_levels[id1]
337 return (random.random() * 100.0) <= threshold
340 class OnlyInfoFilter(logging.Filter):
342 A filter that only logs messages produced at the INFO logging
343 level. This is used by the logging_info_is_print commandline
344 option to select a subset of the logging stream to send to a
349 def filter(self, record: logging.LogRecord):
350 return record.levelno == logging.INFO
353 class MillisecondAwareFormatter(logging.Formatter):
355 A formatter for adding milliseconds to log messages which, for
356 whatever reason, the default python logger doesn't do.
359 converter = datetime.datetime.fromtimestamp
362 def formatTime(self, record, datefmt=None):
363 ct = MillisecondAwareFormatter.converter(
364 record.created, pytz.timezone("US/Pacific")
367 s = ct.strftime(datefmt)
369 t = ct.strftime("%Y-%m-%d %H:%M:%S")
370 s = "%s,%03d" % (t, record.msecs)
374 def initialize_logging(logger=None) -> logging.Logger:
375 global logging_initialized
376 if logging_initialized:
378 logging_initialized = True
381 logger = logging.getLogger()
383 preexisting_handlers_count = 0
384 assert config.has_been_parsed()
385 if config.config['logging_clear_preexisting_handlers']:
386 while logger.hasHandlers():
387 logger.removeHandler(logger.handlers[0])
388 preexisting_handlers_count += 1
390 if config.config['logging_config_file'] is not None:
391 logging.config.fileConfig('logging.conf')
396 # Global default logging level (--logging_level)
397 default_logging_level = getattr(
399 config.config['logging_level'].upper(),
402 if not isinstance(default_logging_level, int):
403 raise ValueError('Invalid level: %s' % config.config['logging_level'])
405 if config.config['logging_format']:
406 fmt = config.config['logging_format']
408 if config.config['logging_syslog']:
409 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
411 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
412 if config.config['logging_debug_threads']:
413 fmt = f'%(process)d.%(thread)d|{fmt}'
414 if config.config['logging_debug_modules']:
415 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
417 if config.config['logging_syslog']:
418 if sys.platform not in ('win32', 'cygwin'):
419 if config.config['logging_syslog_facility']:
420 facility_name = 'LOG_' + config.config['logging_syslog_facility']
421 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)
422 handler = SysLogHandler(facility=facility, address='/dev/log')
423 handler.setFormatter(
424 MillisecondAwareFormatter(
426 datefmt=config.config['logging_date_format'],
429 handlers.append(handler)
431 if config.config['logging_filename']:
432 handler = RotatingFileHandler(
433 config.config['logging_filename'],
434 maxBytes = config.config['logging_filename_maxsize'],
435 backupCount = config.config['logging_filename_count'],
437 handler.setFormatter(
438 MillisecondAwareFormatter(
440 datefmt=config.config['logging_date_format'],
443 handlers.append(handler)
445 if config.config['logging_console']:
446 handler = logging.StreamHandler(sys.stderr)
447 handler.setFormatter(
448 MillisecondAwareFormatter(
450 datefmt=config.config['logging_date_format'],
453 handlers.append(handler)
455 if len(handlers) == 0:
456 handlers.append(logging.NullHandler())
458 for handler in handlers:
459 logger.addHandler(handler)
461 if config.config['logging_info_is_print']:
462 handler = logging.StreamHandler(sys.stdout)
463 handler.addFilter(OnlyInfoFilter())
464 logger.addHandler(handler)
466 if config.config['logging_squelch_repeats']:
467 for handler in handlers:
468 handler.addFilter(SquelchRepeatedMessagesFilter())
470 if config.config['logging_probabilistically']:
471 for handler in handlers:
472 handler.addFilter(ProbabilisticFilter())
474 for handler in handlers:
476 DynamicPerScopeLoggingLevelFilter(
477 default_logging_level,
478 config.config['lmodule'],
482 logger.propagate = False
484 if config.config['logging_captures_prints']:
486 global built_in_print
488 def print_and_also_log(*arg, **kwarg):
489 f = kwarg.get('file', None)
494 built_in_print(*arg, **kwarg)
495 builtins.print = print_and_also_log
497 # At this point the logger is ready, handlers are set up,
498 # etc... so log about the logging configuration.
500 level_name = logging._levelToName.get(default_logging_level, str(default_logging_level))
502 f'Initialized global logging; default logging level is {level_name}.'
504 if config.config['logging_clear_preexisting_handlers'] and preexisting_handlers_count > 0:
505 msg = f'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'
507 logger.debug(f'Logging format specification is "{fmt}"')
508 if config.config['logging_debug_threads']:
509 logger.debug('...Logging format spec captures tid/pid (--logging_debug_threads)')
510 if config.config['logging_debug_modules']:
511 logger.debug('...Logging format spec captures files/functions/lineno (--logging_debug_modules)')
512 if config.config['logging_syslog']:
513 logger.debug(f'Logging to syslog as {facility_name} with priority mapping based on level')
514 if config.config['logging_filename']:
515 logger.debug(f'Logging to filename {config.config["logging_filename"]}')
516 logger.debug(f'...with {config.config["logging_filename_maxsize"]} bytes max file size.')
517 logger.debug(f'...and {config.config["logging_filename_count"]} rotating backup file count.')
518 if config.config['logging_console']:
519 logger.debug('Logging to the console (stderr).')
520 if config.config['logging_info_is_print']:
522 'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
524 if config.config['logging_squelch_repeats']:
526 'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
530 'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'
532 if config.config['logging_probabilistically']:
534 'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
538 'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'
540 if config.config['lmodule']:
542 'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
544 if config.config['logging_captures_prints']:
545 logger.debug('Logging will capture printed data as logger.info messages (--logging_captures_prints)')
549 def get_logger(name: str = ""):
550 logger = logging.getLogger(name)
551 return initialize_logging(logger)
554 def tprint(*args, **kwargs) -> None:
555 """Legacy function for printing a message augmented with thread id
556 still needed by some code. Please use --logging_debug_threads in
560 if config.config['logging_debug_threads']:
561 from thread_utils import current_thread_id
562 print(f'{current_thread_id()}', end="")
563 print(*args, **kwargs)
568 def dprint(*args, **kwargs) -> None:
569 """Legacy function used to print to stderr still needed by some code.
570 Please just use normal logging with --logging_console which
571 accomplishes the same thing in new code.
574 print(*args, file=sys.stderr, **kwargs)
577 class OutputMultiplexer(object):
579 A class that broadcasts printed messages to several sinks (including
580 various logging levels, different files, different file handles,
581 the house log, etc...). See also OutputMultiplexerContext for an
585 class Destination(enum.IntEnum):
586 """Bits in the destination_bitv bitvector. Used to indicate the
587 output destination."""
590 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
592 LOG_CRITICAL = 0x10 # ⎭
593 FILENAMES = 0x20 # Must provide a filename to the c'tor.
594 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
596 ALL_LOG_DESTINATIONS = (
597 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
599 ALL_OUTPUT_DESTINATIONS = 0x8F
602 destination_bitv: int,
605 filenames: Optional[Iterable[str]] = None,
606 handles: Optional[Iterable[io.TextIOWrapper]] = None):
608 logger = logging.getLogger(None)
611 if filenames is not None:
613 open(filename, 'wb', buffering=0) for filename in filenames
616 if destination_bitv & OutputMultiplexer.FILENAMES:
618 "Filenames argument is required if bitv & FILENAMES"
622 if handles is not None:
623 self.h = [handle for handle in handles]
625 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
627 "Handle argument is required if bitv & FILEHANDLES"
631 self.set_destination_bitv(destination_bitv)
633 def get_destination_bitv(self):
634 return self.destination_bitv
636 def set_destination_bitv(self, destination_bitv: int):
637 if destination_bitv & self.Destination.FILENAMES and self.f is None:
639 "Filename argument is required if bitv & FILENAMES"
641 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
643 "Handle argument is required if bitv & FILEHANDLES"
645 self.destination_bitv = destination_bitv
647 def print(self, *args, **kwargs):
648 from string_utils import sprintf, strip_escape_sequences
649 end = kwargs.pop("end", None)
651 if not isinstance(end, str):
652 raise TypeError("end must be None or a string")
653 sep = kwargs.pop("sep", None)
655 if not isinstance(sep, str):
656 raise TypeError("sep must be None or a string")
658 raise TypeError("invalid keyword arguments to print()")
659 buf = sprintf(*args, end="", sep=sep)
667 self.destination_bitv & self.Destination.FILENAMES and
671 _.write(buf.encode('utf-8'))
675 self.destination_bitv & self.Destination.FILEHANDLES and
682 buf = strip_escape_sequences(buf)
683 if self.logger is not None:
684 if self.destination_bitv & self.Destination.LOG_DEBUG:
685 self.logger.debug(buf)
686 if self.destination_bitv & self.Destination.LOG_INFO:
687 self.logger.info(buf)
688 if self.destination_bitv & self.Destination.LOG_WARNING:
689 self.logger.warning(buf)
690 if self.destination_bitv & self.Destination.LOG_ERROR:
691 self.logger.error(buf)
692 if self.destination_bitv & self.Destination.LOG_CRITICAL:
693 self.logger.critical(buf)
694 if self.destination_bitv & self.Destination.HLOG:
698 if self.f is not None:
703 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
705 A context that uses an OutputMultiplexer. e.g.
707 with OutputMultiplexerContext(
708 OutputMultiplexer.LOG_INFO |
709 OutputMultiplexer.LOG_DEBUG |
710 OutputMultiplexer.FILENAMES |
711 OutputMultiplexer.FILEHANDLES,
712 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
715 mplex.print("This is a log message!")
719 destination_bitv: OutputMultiplexer.Destination,
733 def __exit__(self, etype, value, traceback) -> bool:
735 if etype is not None:
740 def hlog(message: str) -> None:
741 """Write a message to the house log (syslog facility local7 priority
742 info) by calling /usr/bin/logger. This is pretty hacky but used
743 by a bunch of code. Another way to do this would be to use
744 --logging_syslog and --logging_syslog_facility but I can't
745 actually say that's easier.
748 message = message.replace("'", "'\"'\"'")
749 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
752 if __name__ == '__main__':