2 # -*- coding: utf-8 -*-
4 # © Copyright 2021-2022, Scott Gasch
6 """Utilities related to logging."""
17 from logging.config import fileConfig
18 from logging.handlers import RotatingFileHandler, SysLogHandler
19 from typing import Any, Callable, Dict, Iterable, List, Optional
22 from overrides import overrides
24 # This module is commonly used by others in here and should avoid
25 # taking any unnecessary dependencies back on them.
29 cfg = config.add_commandline_args(f'Logging ({__file__})', 'Args related to logging')
31 '--logging_config_file',
32 type=argparse_utils.valid_filename,
35 help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
41 choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
43 help='The global default level below which to squelch log messages; see also --lmodule',
49 help='The format for lines logged via the logger module. See: https://docs.python.org/3/library/logging.html#formatter-objects',
52 '--logging_date_format',
54 default='%Y/%m/%dT%H:%M:%S.%f%z',
56 help='The format of any dates in --logging_format.',
60 action=argparse_utils.ActionNoYes,
62 help='Should we log to the console (stderr)',
69 help='The filename of the logfile to write.',
72 '--logging_filename_maxsize',
74 default=(1024 * 1024),
76 help='The maximum size (in bytes) to write to the logging_filename.',
79 '--logging_filename_count',
83 help='The number of logging_filename copies to keep before deleting.',
87 action=argparse_utils.ActionNoYes,
89 help='Should we log to localhost\'s syslog.',
92 '--logging_syslog_facility',
118 metavar='SYSLOG_FACILITY_LIST',
119 help='The default syslog message facility identifier',
122 '--logging_debug_threads',
123 action=argparse_utils.ActionNoYes,
125 help='Should we prepend pid/tid data to all log messages?',
128 '--logging_debug_modules',
129 action=argparse_utils.ActionNoYes,
131 help='Should we prepend module/function data to all log messages?',
134 '--logging_info_is_print',
135 action=argparse_utils.ActionNoYes,
137 help='logging.info also prints to stdout.',
140 '--logging_squelch_repeats',
141 action=argparse_utils.ActionNoYes,
143 help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?',
146 '--logging_probabilistically',
147 action=argparse_utils.ActionNoYes,
149 help='Do we allow probabilistic logging (for code that wants it) or should we always log?',
151 # See also: OutputMultiplexer
153 '--logging_captures_prints',
154 action=argparse_utils.ActionNoYes,
156 help='When calling print, also log.info automatically.',
161 metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
163 'Allows per-scope logging levels which override the global level set with --logging-level.'
164 + 'Pass a space separated list of <scope>=<level> where <scope> is one of: module, '
165 + 'module:function, or :function and <level> is a logging level (e.g. INFO, DEBUG...)'
169 '--logging_clear_preexisting_handlers',
170 action=argparse_utils.ActionNoYes,
173 'Should logging code clear preexisting global logging handlers and thus insist that is '
174 + 'alone can add handlers. Use this to work around annoying modules that insert global '
175 + 'handlers with formats and logging levels you might now want. Caveat emptor, this may '
176 + 'cause you to miss logging messages.'
180 BUILT_IN_PRINT = print
181 LOGGING_INITIALIZED = False
184 # A map from logging_callsite_id -> count of logged messages.
185 squelched_logging_counts: Dict[str, int] = {}
188 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
190 A decorator that marks a function as interested in having the logging
191 messages that it produces be squelched (ignored) after it logs the
192 same message more than N times.
194 Note: this decorator affects *ALL* logging messages produced
195 within the decorated function. That said, messages must be
196 identical in order to be squelched. For example, if the same line
197 of code produces different messages (because of, e.g., a format
198 string), the messages are considered to be different.
202 def squelch_logging_wrapper(f: Callable):
203 import function_utils
205 identifier = function_utils.function_identifier(f)
206 squelched_logging_counts[identifier] = squelch_after_n_repeats
209 return squelch_logging_wrapper
212 class SquelchRepeatedMessagesFilter(logging.Filter):
214 A filter that only logs messages from a given site with the same
215 (exact) message at the same logging level N times and ignores
216 subsequent attempts to log.
218 This filter only affects logging messages that repeat more than
219 a threshold number of times from functions that are tagged with
220 the @logging_utils.squelched_logging_ok decorator; others are
223 This functionality is enabled by default but can be disabled via
224 the --no_logging_squelch_repeats commandline flag.
228 def __init__(self) -> None:
230 self.counters: collections.Counter = collections.Counter()
233 def filter(self, record: logging.LogRecord) -> bool:
234 id1 = f'{record.module}:{record.funcName}'
235 if id1 not in squelched_logging_counts:
237 threshold = squelched_logging_counts[id1]
238 logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
239 count = self.counters[logsite]
240 self.counters[logsite] += 1
241 return count < threshold
244 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
245 """This filter only allows logging messages from an allow list of
246 module names or module:function names. Blocks others.
251 def level_name_to_level(name: str) -> int:
252 numeric_level = getattr(logging, name, None)
253 if not isinstance(numeric_level, int):
254 raise ValueError(f'Invalid level: {name}')
259 default_logging_level: int,
260 per_scope_logging_levels: str,
263 self.valid_levels = set(['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'])
264 self.default_logging_level = default_logging_level
265 self.level_by_scope = {}
266 if per_scope_logging_levels is not None:
267 for chunk in per_scope_logging_levels.split(','):
270 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
275 (scope, level) = chunk.split('=')
278 f'Malformed lmodule directive: "{chunk}". Ignored.',
282 scope = scope.strip()
283 level = level.strip().upper()
284 if level not in self.valid_levels:
286 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
290 self.level_by_scope[scope] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(
295 def filter(self, record: logging.LogRecord) -> bool:
296 # First try to find a logging level by scope (--lmodule)
297 if len(self.level_by_scope) > 0:
301 f'{record.module}:{record.funcName}',
302 f':{record.funcName}',
304 level = self.level_by_scope.get(scope, None)
305 if level is not None:
306 if min_level is None or level < min_level:
309 # If we found one, use it instead of the global default level.
310 if min_level is not None:
311 return record.levelno >= min_level
313 # Otherwise, use the global logging level (--logging_level)
314 return record.levelno >= self.default_logging_level
317 # A map from function_identifier -> probability of logging (0.0%..100.0%)
318 probabilistic_logging_levels: Dict[str, float] = {}
321 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
323 A decorator that indicates that all logging statements within the
324 scope of a particular (marked) function are not deterministic
325 (i.e. they do not always unconditionally log) but rather are
326 probabilistic (i.e. they log N% of the time randomly).
328 Note that this functionality can be disabled (forcing all logged
329 messages to produce output) via the --no_logging_probabilistically
332 This affects *ALL* logging statements within the marked function.
336 def probabilistic_logging_wrapper(f: Callable):
337 import function_utils
339 identifier = function_utils.function_identifier(f)
340 probabilistic_logging_levels[identifier] = probability_of_logging
343 return probabilistic_logging_wrapper
346 class ProbabilisticFilter(logging.Filter):
348 A filter that logs messages probabilistically (i.e. randomly at some
351 This filter only affects logging messages from functions that have
352 been tagged with the @logging_utils.probabilistic_logging decorator.
357 def filter(self, record: logging.LogRecord) -> bool:
358 id1 = f'{record.module}:{record.funcName}'
359 if id1 not in probabilistic_logging_levels:
361 threshold = probabilistic_logging_levels[id1]
362 return (random.random() * 100.0) <= threshold
365 class OnlyInfoFilter(logging.Filter):
367 A filter that only logs messages produced at the INFO logging
368 level. This is used by the logging_info_is_print commandline
369 option to select a subset of the logging stream to send to a
375 def filter(self, record: logging.LogRecord):
376 return record.levelno == logging.INFO
379 class MillisecondAwareFormatter(logging.Formatter):
381 A formatter for adding milliseconds to log messages which, for
382 whatever reason, the default python logger doesn't do.
386 converter = datetime.datetime.fromtimestamp # type: ignore
389 def formatTime(self, record, datefmt=None):
390 ct = MillisecondAwareFormatter.converter(record.created, pytz.timezone("US/Pacific"))
392 s = ct.strftime(datefmt)
394 t = ct.strftime("%Y-%m-%d %H:%M:%S")
395 s = f"{t},{record.msecs:%03d}"
399 def log_about_logging(
401 default_logging_level,
402 preexisting_handlers_count,
406 level_name = logging._levelToName.get(default_logging_level, str(default_logging_level))
407 logger.debug('Initialized global logging; default logging level is %s.', level_name)
408 if config.config['logging_clear_preexisting_handlers'] and preexisting_handlers_count > 0:
410 'Logging cleared %d global handlers (--logging_clear_preexisting_handlers)',
411 preexisting_handlers_count,
413 logger.debug('Logging format specification is "%s"', fmt)
414 if config.config['logging_debug_threads']:
415 logger.debug('...Logging format spec captures tid/pid. (--logging_debug_threads)')
416 if config.config['logging_debug_modules']:
418 '...Logging format spec captures files/functions/lineno. (--logging_debug_modules)'
420 if config.config['logging_syslog']:
422 'Logging to syslog as %s with priority mapping based on level. (--logging_syslog)',
425 if config.config['logging_filename']:
427 'Logging to file "%s". (--logging_filename)', config.config["logging_filename"]
430 '...with %d bytes max file size. (--logging_filename_maxsize)',
431 config.config["logging_filename_maxsize"],
434 '...and %d rotating backup file count. (--logging_filename_count)',
435 config.config["logging_filename_count"],
437 if config.config['logging_console']:
438 logger.debug('Logging to the console (stderr). (--logging_console)')
439 if config.config['logging_info_is_print']:
441 'Logging logger.info messages will be repeated on stdout. (--logging_info_is_print)'
443 if config.config['logging_squelch_repeats']:
445 'Logging code allowed to request repeated messages be squelched. (--logging_squelch_repeats)'
449 'Logging code forbidden to request messages be squelched; all messages logged. (--no_logging_squelch_repeats)'
451 if config.config['logging_probabilistically']:
453 'Logging code is allowed to request probabilistic logging. (--logging_probabilistically)'
457 'Logging code is forbidden to request probabilistic logging; messages always logged. (--no_logging_probabilistically)'
459 if config.config['lmodule']:
461 f'Logging dynamic per-module logging enabled. (--lmodule={config.config["lmodule"]})'
463 if config.config['logging_captures_prints']:
465 'Logging will capture printed data as logger.info messages. (--logging_captures_prints)'
469 def initialize_logging(logger=None) -> logging.Logger:
470 global LOGGING_INITIALIZED
471 if LOGGING_INITIALIZED:
472 return logging.getLogger()
473 LOGGING_INITIALIZED = True
476 logger = logging.getLogger()
478 # --logging_clear_preexisting_handlers removes logging handlers
479 # that were registered by global statements during imported module
481 preexisting_handlers_count = 0
482 assert config.has_been_parsed()
483 if config.config['logging_clear_preexisting_handlers']:
484 while logger.hasHandlers():
485 logger.removeHandler(logger.handlers[0])
486 preexisting_handlers_count += 1
488 # --logging_config_file pulls logging settings from a config file
489 # skipping the rest of this setup.
490 if config.config['logging_config_file'] is not None:
491 fileConfig(config.config['logging_config_file'])
494 handlers: List[logging.Handler] = []
495 handler: Optional[logging.Handler] = None
497 # Global default logging level (--logging_level); messages below
498 # this level will be silenced.
499 default_logging_level = getattr(logging, config.config['logging_level'].upper(), None)
500 if not isinstance(default_logging_level, int):
501 raise ValueError(f'Invalid level: {config.config["logging_level"]}')
503 # Custom or default --logging_format?
504 if config.config['logging_format']:
505 fmt = config.config['logging_format']
507 if config.config['logging_syslog']:
508 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
510 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
512 # --logging_debug_threads and --logging_debug_modules both affect
513 # the format by prepending information about the pid/tid or
515 if config.config['logging_debug_threads']:
516 fmt = f'%(process)d.%(thread)d|{fmt}'
517 if config.config['logging_debug_modules']:
518 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
520 # --logging_syslog (optionally with --logging_syslog_facility)
521 # sets up for logging to use the standard system syslogd as a
524 if config.config['logging_syslog']:
525 if sys.platform not in ('win32', 'cygwin'):
526 if config.config['logging_syslog_facility']:
527 facility_name = 'LOG_' + config.config['logging_syslog_facility']
528 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER) # type: ignore
529 assert facility is not None
530 handler = SysLogHandler(facility=facility, address='/dev/log')
531 handler.setFormatter(
532 MillisecondAwareFormatter(
534 datefmt=config.config['logging_date_format'],
537 handlers.append(handler)
539 # --logging_filename (with friends --logging_filename_count and
540 # --logging_filename_maxsize) set up logging to a file on the
541 # filesystem with automatic rotation when it gets too big.
542 if config.config['logging_filename']:
543 handler = RotatingFileHandler(
544 config.config['logging_filename'],
545 maxBytes=config.config['logging_filename_maxsize'],
546 backupCount=config.config['logging_filename_count'],
548 handler.setFormatter(
549 MillisecondAwareFormatter(
551 datefmt=config.config['logging_date_format'],
554 handlers.append(handler)
556 # --logging_console is, ahem, logging to the console.
557 if config.config['logging_console']:
558 handler = logging.StreamHandler(sys.stderr)
559 handler.setFormatter(
560 MillisecondAwareFormatter(
562 datefmt=config.config['logging_date_format'],
565 handlers.append(handler)
567 if len(handlers) == 0:
568 handlers.append(logging.NullHandler())
569 for handler in handlers:
570 logger.addHandler(handler)
572 # --logging_info_is_print echoes any message to logger.info(x) as
573 # a print statement on stdout.
574 if config.config['logging_info_is_print']:
575 handler = logging.StreamHandler(sys.stdout)
576 handler.addFilter(OnlyInfoFilter())
577 logger.addHandler(handler)
579 # --logging_squelch_repeats allows code to request repeat logging
580 # messages (identical log site and message contents) to be
581 # silenced. Logging code must request this explicitly, it isn't
582 # automatic. This option just allows the silencing to happen.
583 if config.config['logging_squelch_repeats']:
584 for handler in handlers:
585 handler.addFilter(SquelchRepeatedMessagesFilter())
587 # --logging_probabilistically allows code to request
588 # non-deterministic logging where messages have some probability
589 # of being produced. Logging code must request this explicitly.
590 # This option just allows the non-deterministic behavior to
591 # happen. Disabling it will cause every log message to be
593 if config.config['logging_probabilistically']:
594 for handler in handlers:
595 handler.addFilter(ProbabilisticFilter())
597 # --lmodule is a way to have a special logging level for just on
598 # module or one set of modules that is different than the one set
599 # globally via --logging_level.
600 for handler in handlers:
602 DynamicPerScopeLoggingLevelFilter(
603 default_logging_level,
604 config.config['lmodule'],
608 logger.propagate = False
610 # --logging_captures_prints, if set, will capture and log.info
611 # anything printed on stdout.
612 if config.config['logging_captures_prints']:
615 def print_and_also_log(*arg, **kwarg):
616 f = kwarg.get('file', None)
621 BUILT_IN_PRINT(*arg, **kwarg)
623 builtins.print = print_and_also_log
625 # At this point the logger is ready, handlers are set up,
626 # etc... so log about the logging configuration.
629 default_logging_level,
630 preexisting_handlers_count,
637 def get_logger(name: str = ""):
638 logger = logging.getLogger(name)
639 return initialize_logging(logger)
642 def tprint(*args, **kwargs) -> None:
643 """Legacy function for printing a message augmented with thread id
644 still needed by some code. Please use --logging_debug_threads in
648 if config.config['logging_debug_threads']:
649 from thread_utils import current_thread_id
651 print(f'{current_thread_id()}', end="")
652 print(*args, **kwargs)
657 def dprint(*args, **kwargs) -> None:
658 """Legacy function used to print to stderr still needed by some code.
659 Please just use normal logging with --logging_console which
660 accomplishes the same thing in new code.
663 print(*args, file=sys.stderr, **kwargs)
666 class OutputMultiplexer(object):
668 A class that broadcasts printed messages to several sinks (including
669 various logging levels, different files, different file handles,
670 the house log, etc...). See also OutputMultiplexerContext for an
675 class Destination(enum.IntEnum):
676 """Bits in the destination_bitv bitvector. Used to indicate the
677 output destination."""
682 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
684 LOG_CRITICAL = 0x10 # ⎭
685 FILENAMES = 0x20 # Must provide a filename to the c'tor.
686 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
688 ALL_LOG_DESTINATIONS = (
689 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
691 ALL_OUTPUT_DESTINATIONS = 0x8F
696 destination_bitv: int,
699 filenames: Optional[Iterable[str]] = None,
700 handles: Optional[Iterable[io.TextIOWrapper]] = None,
703 logger = logging.getLogger(None)
706 self.f: Optional[List[Any]] = None
707 if filenames is not None:
708 self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
710 if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
711 raise ValueError("Filenames argument is required if bitv & FILENAMES")
714 self.h: Optional[List[Any]] = None
715 if handles is not None:
716 self.h = list(handles)
718 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
719 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
722 self.set_destination_bitv(destination_bitv)
724 def get_destination_bitv(self):
725 return self.destination_bitv
727 def set_destination_bitv(self, destination_bitv: int):
728 if destination_bitv & self.Destination.FILENAMES and self.f is None:
729 raise ValueError("Filename argument is required if bitv & FILENAMES")
730 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
731 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
732 self.destination_bitv = destination_bitv
734 def print(self, *args, **kwargs):
735 from string_utils import sprintf, strip_escape_sequences
737 end = kwargs.pop("end", None)
739 if not isinstance(end, str):
740 raise TypeError("end must be None or a string")
741 sep = kwargs.pop("sep", None)
743 if not isinstance(sep, str):
744 raise TypeError("sep must be None or a string")
746 raise TypeError("invalid keyword arguments to print()")
747 buf = sprintf(*args, end="", sep=sep)
754 if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
756 _.write(buf.encode('utf-8'))
759 if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
764 buf = strip_escape_sequences(buf)
765 if self.logger is not None:
766 if self.destination_bitv & self.Destination.LOG_DEBUG:
767 self.logger.debug(buf)
768 if self.destination_bitv & self.Destination.LOG_INFO:
769 self.logger.info(buf)
770 if self.destination_bitv & self.Destination.LOG_WARNING:
771 self.logger.warning(buf)
772 if self.destination_bitv & self.Destination.LOG_ERROR:
773 self.logger.error(buf)
774 if self.destination_bitv & self.Destination.LOG_CRITICAL:
775 self.logger.critical(buf)
776 if self.destination_bitv & self.Destination.HLOG:
780 if self.f is not None:
785 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
787 A context that uses an OutputMultiplexer. e.g.
789 with OutputMultiplexerContext(
790 OutputMultiplexer.LOG_INFO |
791 OutputMultiplexer.LOG_DEBUG |
792 OutputMultiplexer.FILENAMES |
793 OutputMultiplexer.FILEHANDLES,
794 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
797 mplex.print("This is a log message!")
803 destination_bitv: OutputMultiplexer.Destination,
819 def __exit__(self, etype, value, traceback) -> bool:
821 if etype is not None:
826 def hlog(message: str) -> None:
827 """Write a message to the house log (syslog facility local7 priority
828 info) by calling /usr/bin/logger. This is pretty hacky but used
829 by a bunch of code. Another way to do this would be to use
830 --logging_syslog and --logging_syslog_facility but I can't
831 actually say that's easier.
834 message = message.replace("'", "'\"'\"'")
835 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
838 if __name__ == '__main__':