2 # -*- coding: utf-8 -*-
4 """Utilities related to logging."""
15 from logging.config import fileConfig
16 from logging.handlers import RotatingFileHandler, SysLogHandler
17 from typing import Any, Callable, Dict, Iterable, List, Optional
20 from overrides import overrides
22 # This module is commonly used by others in here and should avoid
23 # taking any unnecessary dependencies back on them.
27 cfg = config.add_commandline_args(f'Logging ({__file__})', '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',
72 default=(1024 * 1024),
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',
116 metavar='SYSLOG_FACILITY_LIST',
117 help='The default syslog message facility identifier',
120 '--logging_debug_threads',
121 action=argparse_utils.ActionNoYes,
123 help='Should we prepend pid/tid data to all log messages?',
126 '--logging_debug_modules',
127 action=argparse_utils.ActionNoYes,
129 help='Should we prepend module/function data to all log messages?',
132 '--logging_info_is_print',
133 action=argparse_utils.ActionNoYes,
135 help='logging.info also prints to stdout.',
138 '--logging_squelch_repeats',
139 action=argparse_utils.ActionNoYes,
141 help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?',
144 '--logging_probabilistically',
145 action=argparse_utils.ActionNoYes,
147 help='Do we allow probabilistic logging (for code that wants it) or should we always log?',
149 # See also: OutputMultiplexer
151 '--logging_captures_prints',
152 action=argparse_utils.ActionNoYes,
154 help='When calling print, also log.info automatically.',
159 metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
161 'Allows per-scope logging levels which override the global level set with --logging-level.'
162 + 'Pass a space separated list of <scope>=<level> where <scope> is one of: module, '
163 + 'module:function, or :function and <level> is a logging level (e.g. INFO, DEBUG...)'
167 '--logging_clear_preexisting_handlers',
168 action=argparse_utils.ActionNoYes,
171 'Should logging code clear preexisting global logging handlers and thus insist that is '
172 + 'alone can add handlers. Use this to work around annoying modules that insert global '
173 + 'handlers with formats and logging levels you might now want. Caveat emptor, this may '
174 + 'cause you to miss logging messages.'
178 BUILT_IN_PRINT = print
179 LOGGING_INITIALIZED = False
182 # A map from logging_callsite_id -> count of logged messages.
183 squelched_logging_counts: Dict[str, int] = {}
186 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
188 A decorator that marks a function as interested in having the logging
189 messages that it produces be squelched (ignored) after it logs the
190 same message more than N times.
192 Note: this decorator affects *ALL* logging messages produced
193 within the decorated function. That said, messages must be
194 identical in order to be squelched. For example, if the same line
195 of code produces different messages (because of, e.g., a format
196 string), the messages are considered to be different.
200 def squelch_logging_wrapper(f: Callable):
201 import function_utils
203 identifier = function_utils.function_identifier(f)
204 squelched_logging_counts[identifier] = squelch_after_n_repeats
207 return squelch_logging_wrapper
210 class SquelchRepeatedMessagesFilter(logging.Filter):
212 A filter that only logs messages from a given site with the same
213 (exact) message at the same logging level N times and ignores
214 subsequent attempts to log.
216 This filter only affects logging messages that repeat more than
217 a threshold number of times from functions that are tagged with
218 the @logging_utils.squelched_logging_ok decorator; others are
221 This functionality is enabled by default but can be disabled via
222 the --no_logging_squelch_repeats commandline flag.
226 def __init__(self) -> None:
228 self.counters: collections.Counter = collections.Counter()
231 def filter(self, record: logging.LogRecord) -> bool:
232 id1 = f'{record.module}:{record.funcName}'
233 if id1 not in squelched_logging_counts:
235 threshold = squelched_logging_counts[id1]
236 logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
237 count = self.counters[logsite]
238 self.counters[logsite] += 1
239 return count < threshold
242 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
243 """This filter only allows logging messages from an allow list of
244 module names or module:function names. Blocks others.
249 def level_name_to_level(name: str) -> int:
250 numeric_level = getattr(logging, name, None)
251 if not isinstance(numeric_level, int):
252 raise ValueError(f'Invalid level: {name}')
257 default_logging_level: int,
258 per_scope_logging_levels: str,
261 self.valid_levels = set(['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.',
288 self.level_by_scope[scope] = DynamicPerScopeLoggingLevelFilter.level_name_to_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: Dict[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 # type: ignore
387 def formatTime(self, record, datefmt=None):
388 ct = MillisecondAwareFormatter.converter(record.created, pytz.timezone("US/Pacific"))
390 s = ct.strftime(datefmt)
392 t = ct.strftime("%Y-%m-%d %H:%M:%S")
393 s = f"{t},{record.msecs:%03d}"
397 def log_about_logging(
399 default_logging_level,
400 preexisting_handlers_count,
404 level_name = logging._levelToName.get(default_logging_level, str(default_logging_level))
405 logger.debug('Initialized global logging; default logging level is %s.', level_name)
406 if config.config['logging_clear_preexisting_handlers'] and preexisting_handlers_count > 0:
408 'Logging cleared %d global handlers (--logging_clear_preexisting_handlers)',
409 preexisting_handlers_count,
411 logger.debug('Logging format specification is "%s"', fmt)
412 if config.config['logging_debug_threads']:
413 logger.debug('...Logging format spec captures tid/pid. (--logging_debug_threads)')
414 if config.config['logging_debug_modules']:
416 '...Logging format spec captures files/functions/lineno. (--logging_debug_modules)'
418 if config.config['logging_syslog']:
420 'Logging to syslog as %s with priority mapping based on level. (--logging_syslog)',
423 if config.config['logging_filename']:
425 'Logging to file "%s". (--logging_filename)', config.config["logging_filename"]
428 '...with %d bytes max file size. (--logging_filename_maxsize)',
429 config.config["logging_filename_maxsize"],
432 '...and %d rotating backup file count. (--logging_filename_count)',
433 config.config["logging_filename_count"],
435 if config.config['logging_console']:
436 logger.debug('Logging to the console (stderr). (--logging_console)')
437 if config.config['logging_info_is_print']:
439 'Logging logger.info messages will be repeated on stdout. (--logging_info_is_print)'
441 if config.config['logging_squelch_repeats']:
443 'Logging code allowed to request repeated messages be squelched. (--logging_squelch_repeats)'
447 'Logging code forbidden to request messages be squelched; all messages logged. (--no_logging_squelch_repeats)'
449 if config.config['logging_probabilistically']:
451 'Logging code is allowed to request probabilistic logging. (--logging_probabilistically)'
455 'Logging code is forbidden to request probabilistic logging; messages always logged. (--no_logging_probabilistically)'
457 if config.config['lmodule']:
459 f'Logging dynamic per-module logging enabled. (--lmodule={config.config["lmodule"]})'
461 if config.config['logging_captures_prints']:
463 'Logging will capture printed data as logger.info messages. (--logging_captures_prints)'
467 def initialize_logging(logger=None) -> logging.Logger:
468 global LOGGING_INITIALIZED
469 if LOGGING_INITIALIZED:
470 return logging.getLogger()
471 LOGGING_INITIALIZED = True
474 logger = logging.getLogger()
476 # --logging_clear_preexisting_handlers removes logging handlers
477 # that were registered by global statements during imported module
479 preexisting_handlers_count = 0
480 assert config.has_been_parsed()
481 if config.config['logging_clear_preexisting_handlers']:
482 while logger.hasHandlers():
483 logger.removeHandler(logger.handlers[0])
484 preexisting_handlers_count += 1
486 # --logging_config_file pulls logging settings from a config file
487 # skipping the rest of this setup.
488 if config.config['logging_config_file'] is not None:
489 fileConfig(config.config['logging_config_file'])
492 handlers: List[logging.Handler] = []
493 handler: Optional[logging.Handler] = None
495 # Global default logging level (--logging_level); messages below
496 # this level will be silenced.
497 default_logging_level = getattr(logging, config.config['logging_level'].upper(), None)
498 if not isinstance(default_logging_level, int):
499 raise ValueError(f'Invalid level: {config.config["logging_level"]}')
501 # Custom or default --logging_format?
502 if config.config['logging_format']:
503 fmt = config.config['logging_format']
505 if config.config['logging_syslog']:
506 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
508 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
510 # --logging_debug_threads and --logging_debug_modules both affect
511 # the format by prepending information about the pid/tid or
513 if config.config['logging_debug_threads']:
514 fmt = f'%(process)d.%(thread)d|{fmt}'
515 if config.config['logging_debug_modules']:
516 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
518 # --logging_syslog (optionally with --logging_syslog_facility)
519 # sets up for logging to use the standard system syslogd as a
522 if config.config['logging_syslog']:
523 if sys.platform not in ('win32', 'cygwin'):
524 if config.config['logging_syslog_facility']:
525 facility_name = 'LOG_' + config.config['logging_syslog_facility']
526 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER) # type: ignore
527 assert facility is not None
528 handler = SysLogHandler(facility=facility, address='/dev/log')
529 handler.setFormatter(
530 MillisecondAwareFormatter(
532 datefmt=config.config['logging_date_format'],
535 handlers.append(handler)
537 # --logging_filename (with friends --logging_filename_count and
538 # --logging_filename_maxsize) set up logging to a file on the
539 # filesystem with automatic rotation when it gets too big.
540 if config.config['logging_filename']:
541 handler = RotatingFileHandler(
542 config.config['logging_filename'],
543 maxBytes=config.config['logging_filename_maxsize'],
544 backupCount=config.config['logging_filename_count'],
546 handler.setFormatter(
547 MillisecondAwareFormatter(
549 datefmt=config.config['logging_date_format'],
552 handlers.append(handler)
554 # --logging_console is, ahem, logging to the console.
555 if config.config['logging_console']:
556 handler = logging.StreamHandler(sys.stderr)
557 handler.setFormatter(
558 MillisecondAwareFormatter(
560 datefmt=config.config['logging_date_format'],
563 handlers.append(handler)
565 if len(handlers) == 0:
566 handlers.append(logging.NullHandler())
567 for handler in handlers:
568 logger.addHandler(handler)
570 # --logging_info_is_print echoes any message to logger.info(x) as
571 # a print statement on stdout.
572 if config.config['logging_info_is_print']:
573 handler = logging.StreamHandler(sys.stdout)
574 handler.addFilter(OnlyInfoFilter())
575 logger.addHandler(handler)
577 # --logging_squelch_repeats allows code to request repeat logging
578 # messages (identical log site and message contents) to be
579 # silenced. Logging code must request this explicitly, it isn't
580 # automatic. This option just allows the silencing to happen.
581 if config.config['logging_squelch_repeats']:
582 for handler in handlers:
583 handler.addFilter(SquelchRepeatedMessagesFilter())
585 # --logging_probabilistically allows code to request
586 # non-deterministic logging where messages have some probability
587 # of being produced. Logging code must request this explicitly.
588 # This option just allows the non-deterministic behavior to
589 # happen. Disabling it will cause every log message to be
591 if config.config['logging_probabilistically']:
592 for handler in handlers:
593 handler.addFilter(ProbabilisticFilter())
595 # --lmodule is a way to have a special logging level for just on
596 # module or one set of modules that is different than the one set
597 # globally via --logging_level.
598 for handler in handlers:
600 DynamicPerScopeLoggingLevelFilter(
601 default_logging_level,
602 config.config['lmodule'],
606 logger.propagate = False
608 # --logging_captures_prints, if set, will capture and log.info
609 # anything printed on stdout.
610 if config.config['logging_captures_prints']:
613 def print_and_also_log(*arg, **kwarg):
614 f = kwarg.get('file', None)
619 BUILT_IN_PRINT(*arg, **kwarg)
621 builtins.print = print_and_also_log
623 # At this point the logger is ready, handlers are set up,
624 # etc... so log about the logging configuration.
627 default_logging_level,
628 preexisting_handlers_count,
635 def get_logger(name: str = ""):
636 logger = logging.getLogger(name)
637 return initialize_logging(logger)
640 def tprint(*args, **kwargs) -> None:
641 """Legacy function for printing a message augmented with thread id
642 still needed by some code. Please use --logging_debug_threads in
646 if config.config['logging_debug_threads']:
647 from thread_utils import current_thread_id
649 print(f'{current_thread_id()}', end="")
650 print(*args, **kwargs)
655 def dprint(*args, **kwargs) -> None:
656 """Legacy function used to print to stderr still needed by some code.
657 Please just use normal logging with --logging_console which
658 accomplishes the same thing in new code.
661 print(*args, file=sys.stderr, **kwargs)
664 class OutputMultiplexer(object):
666 A class that broadcasts printed messages to several sinks (including
667 various logging levels, different files, different file handles,
668 the house log, etc...). See also OutputMultiplexerContext for an
673 class Destination(enum.IntEnum):
674 """Bits in the destination_bitv bitvector. Used to indicate the
675 output destination."""
680 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
682 LOG_CRITICAL = 0x10 # ⎭
683 FILENAMES = 0x20 # Must provide a filename to the c'tor.
684 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
686 ALL_LOG_DESTINATIONS = (
687 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
689 ALL_OUTPUT_DESTINATIONS = 0x8F
694 destination_bitv: int,
697 filenames: Optional[Iterable[str]] = None,
698 handles: Optional[Iterable[io.TextIOWrapper]] = None,
701 logger = logging.getLogger(None)
704 self.f: Optional[List[Any]] = None
705 if filenames is not None:
706 self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
708 if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
709 raise ValueError("Filenames argument is required if bitv & FILENAMES")
712 self.h: Optional[List[Any]] = None
713 if handles is not None:
714 self.h = list(handles)
716 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
717 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
720 self.set_destination_bitv(destination_bitv)
722 def get_destination_bitv(self):
723 return self.destination_bitv
725 def set_destination_bitv(self, destination_bitv: int):
726 if destination_bitv & self.Destination.FILENAMES and self.f is None:
727 raise ValueError("Filename argument is required if bitv & FILENAMES")
728 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
729 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
730 self.destination_bitv = destination_bitv
732 def print(self, *args, **kwargs):
733 from string_utils import sprintf, strip_escape_sequences
735 end = kwargs.pop("end", None)
737 if not isinstance(end, str):
738 raise TypeError("end must be None or a string")
739 sep = kwargs.pop("sep", None)
741 if not isinstance(sep, str):
742 raise TypeError("sep must be None or a string")
744 raise TypeError("invalid keyword arguments to print()")
745 buf = sprintf(*args, end="", sep=sep)
752 if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
754 _.write(buf.encode('utf-8'))
757 if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
762 buf = strip_escape_sequences(buf)
763 if self.logger is not None:
764 if self.destination_bitv & self.Destination.LOG_DEBUG:
765 self.logger.debug(buf)
766 if self.destination_bitv & self.Destination.LOG_INFO:
767 self.logger.info(buf)
768 if self.destination_bitv & self.Destination.LOG_WARNING:
769 self.logger.warning(buf)
770 if self.destination_bitv & self.Destination.LOG_ERROR:
771 self.logger.error(buf)
772 if self.destination_bitv & self.Destination.LOG_CRITICAL:
773 self.logger.critical(buf)
774 if self.destination_bitv & self.Destination.HLOG:
778 if self.f is not None:
783 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
785 A context that uses an OutputMultiplexer. e.g.
787 with OutputMultiplexerContext(
788 OutputMultiplexer.LOG_INFO |
789 OutputMultiplexer.LOG_DEBUG |
790 OutputMultiplexer.FILENAMES |
791 OutputMultiplexer.FILEHANDLES,
792 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
795 mplex.print("This is a log message!")
801 destination_bitv: OutputMultiplexer.Destination,
817 def __exit__(self, etype, value, traceback) -> bool:
819 if etype is not None:
824 def hlog(message: str) -> None:
825 """Write a message to the house log (syslog facility local7 priority
826 info) by calling /usr/bin/logger. This is pretty hacky but used
827 by a bunch of code. Another way to do this would be to use
828 --logging_syslog and --logging_syslog_facility but I can't
829 actually say that's easier.
832 message = message.replace("'", "'\"'\"'")
833 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
836 if __name__ == '__main__':