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...)'
148 built_in_print = print
151 def function_identifier(f: Callable) -> str:
153 Given a callable function, return a string that identifies it.
154 Usually that string is just __module__:__name__ but there's a
155 corner case: when __module__ is __main__ (i.e. the callable is
156 defined in the same module as __main__). In this case,
157 f.__module__ returns "__main__" instead of the file that it is
158 defined in. Work around this using pathlib.Path (see below).
160 >>> function_identifier(function_identifier)
161 'logging_utils:function_identifier'
164 if f.__module__ == '__main__':
165 from pathlib import Path
167 module = __main__.__file__
168 module = Path(module).stem
169 return f'{module}:{f.__name__}'
171 return f'{f.__module__}:{f.__name__}'
174 # A map from logging_callsite_id -> count of logged messages.
175 squelched_logging_counts: Mapping[str, int] = {}
178 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
180 A decorator that marks a function as interested in having the logging
181 messages that it produces be squelched (ignored) after it logs the
182 same message more than N times.
184 Note: this decorator affects *ALL* logging messages produced
185 within the decorated function. That said, messages must be
186 identical in order to be squelched. For example, if the same line
187 of code produces different messages (because of, e.g., a format
188 string), the messages are considered to be different.
191 def squelch_logging_wrapper(f: Callable):
192 identifier = function_identifier(f)
193 squelched_logging_counts[identifier] = squelch_after_n_repeats
195 return squelch_logging_wrapper
198 class SquelchRepeatedMessagesFilter(logging.Filter):
200 A filter that only logs messages from a given site with the same
201 (exact) message at the same logging level N times and ignores
202 subsequent attempts to log.
204 This filter only affects logging messages that repeat more than
205 a threshold number of times from functions that are tagged with
206 the @logging_utils.squelched_logging_ok decorator.
209 def __init__(self) -> None:
210 self.counters = collections.Counter()
214 def filter(self, record: logging.LogRecord) -> bool:
215 id1 = f'{record.module}:{record.funcName}'
216 if id1 not in squelched_logging_counts:
218 threshold = squelched_logging_counts[id1]
219 logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
220 count = self.counters[logsite]
221 self.counters[logsite] += 1
222 return count < threshold
225 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
226 """Only interested in seeing logging messages from an allow list of
227 module names or module:function names. Block others.
231 def level_name_to_level(name: str) -> int:
232 numeric_level = getattr(
237 if not isinstance(numeric_level, int):
238 raise ValueError('Invalid level: {name}')
243 default_logging_level: int,
244 per_scope_logging_levels: str,
247 self.valid_levels = set(['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'])
248 self.default_logging_level = default_logging_level
249 self.level_by_scope = {}
250 if per_scope_logging_levels is not None:
251 for chunk in per_scope_logging_levels.split(','):
254 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
259 (scope, level) = chunk.split('=')
262 f'Malformed lmodule directive: "{chunk}". Ignored.',
266 scope = scope.strip()
267 level = level.strip().upper()
268 if level not in self.valid_levels:
270 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
274 self.level_by_scope[scope] = (
275 DynamicPerScopeLoggingLevelFilter.level_name_to_level(
281 def filter(self, record: logging.LogRecord) -> bool:
282 # First try to find a logging level by scope (--lmodule)
283 if len(self.level_by_scope) > 0:
287 f'{record.module}:{record.funcName}',
288 f':{record.funcName}'
290 level = self.level_by_scope.get(scope, None)
291 if level is not None:
292 if min_level is None or level < min_level:
295 # If we found one, use it instead of the global default level.
296 if min_level is not None:
297 return record.levelno >= min_level
299 # Otherwise, use the global logging level (--logging_level)
300 return record.levelno >= self.default_logging_level
303 # A map from function_identifier -> probability of logging (0.0%..100.0%)
304 probabilistic_logging_levels: Mapping[str, float] = {}
307 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
309 A decorator that indicates that all logging statements within the
310 scope of a particular (marked) function are not deterministic
311 (i.e. they do not always unconditionally log) but rather are
312 probabilistic (i.e. they log N% of the time randomly).
314 This affects *ALL* logging statements within the marked function.
317 def probabilistic_logging_wrapper(f: Callable):
318 identifier = function_identifier(f)
319 probabilistic_logging_levels[identifier] = probability_of_logging
321 return probabilistic_logging_wrapper
324 class ProbabilisticFilter(logging.Filter):
326 A filter that logs messages probabilistically (i.e. randomly at some
329 This filter only affects logging messages from functions that have
330 been tagged with the @logging_utils.probabilistic_logging decorator.
334 def filter(self, record: logging.LogRecord) -> bool:
335 id1 = f'{record.module}:{record.funcName}'
336 if id1 not in probabilistic_logging_levels:
338 threshold = probabilistic_logging_levels[id1]
339 return (random.random() * 100.0) <= threshold
342 class OnlyInfoFilter(logging.Filter):
344 A filter that only logs messages produced at the INFO logging
345 level. This is used by the logging_info_is_print commandline
346 option to select a subset of the logging stream to send to a
351 def filter(self, record: logging.LogRecord):
352 return record.levelno == logging.INFO
355 class MillisecondAwareFormatter(logging.Formatter):
357 A formatter for adding milliseconds to log messages.
360 converter = datetime.datetime.fromtimestamp
363 def formatTime(self, record, datefmt=None):
364 ct = MillisecondAwareFormatter.converter(
365 record.created, pytz.timezone("US/Pacific")
368 s = ct.strftime(datefmt)
370 t = ct.strftime("%Y-%m-%d %H:%M:%S")
371 s = "%s,%03d" % (t, record.msecs)
375 def initialize_logging(logger=None) -> logging.Logger:
376 assert config.has_been_parsed()
378 logger = logging.getLogger() # Root logger
380 if config.config['logging_config_file'] is not None:
381 logging.config.fileConfig('logging.conf')
386 # Global default logging level (--logging_level)
387 default_logging_level = getattr(
389 config.config['logging_level'].upper(),
392 if not isinstance(default_logging_level, int):
393 raise ValueError('Invalid level: %s' % config.config['logging_level'])
395 if config.config['logging_format']:
396 fmt = config.config['logging_format']
398 if config.config['logging_syslog']:
399 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
401 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
403 if config.config['logging_debug_threads']:
404 fmt = f'%(process)d.%(thread)d|{fmt}'
405 if config.config['logging_debug_modules']:
406 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
408 if config.config['logging_syslog']:
409 if sys.platform not in ('win32', 'cygwin'):
410 if config.config['logging_syslog_facility']:
411 facility_name = 'LOG_' + config.config['logging_syslog_facility']
412 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)
413 handler = SysLogHandler(facility=SysLogHandler.LOG_CRON, address='/dev/log')
414 handler.setFormatter(
415 MillisecondAwareFormatter(
417 datefmt=config.config['logging_date_format'],
420 handlers.append(handler)
422 if config.config['logging_filename']:
423 handler = RotatingFileHandler(
424 config.config['logging_filename'],
425 maxBytes = config.config['logging_filename_maxsize'],
426 backupCount = config.config['logging_filename_count'],
428 handler.setFormatter(
429 MillisecondAwareFormatter(
431 datefmt=config.config['logging_date_format'],
434 handlers.append(handler)
436 if config.config['logging_console']:
437 handler = logging.StreamHandler(sys.stderr)
438 handler.setFormatter(
439 MillisecondAwareFormatter(
441 datefmt=config.config['logging_date_format'],
444 handlers.append(handler)
446 if len(handlers) == 0:
447 handlers.append(logging.NullHandler())
449 for handler in handlers:
450 logger.addHandler(handler)
452 if config.config['logging_info_is_print']:
453 handler = logging.StreamHandler(sys.stdout)
454 handler.addFilter(OnlyInfoFilter())
455 logger.addHandler(handler)
457 if config.config['logging_squelch_repeats_enabled']:
458 for handler in handlers:
459 handler.addFilter(SquelchRepeatedMessagesFilter())
461 if config.config['logging_probabilistically_enabled']:
462 for handler in handlers:
463 handler.addFilter(ProbabilisticFilter())
465 for handler in handlers:
467 DynamicPerScopeLoggingLevelFilter(
468 default_logging_level,
469 config.config['lmodule'],
473 logger.propagate = False
475 if config.config['logging_captures_prints']:
477 global built_in_print
479 def print_and_also_log(*arg, **kwarg):
480 f = kwarg.get('file', None)
485 built_in_print(*arg, **kwarg)
486 builtins.print = print_and_also_log
491 def get_logger(name: str = ""):
492 logger = logging.getLogger(name)
493 return initialize_logging(logger)
496 def tprint(*args, **kwargs) -> None:
497 """Legacy function for printing a message augmented with thread id."""
499 if config.config['logging_debug_threads']:
500 from thread_utils import current_thread_id
501 print(f'{current_thread_id()}', end="")
502 print(*args, **kwargs)
507 def dprint(*args, **kwargs) -> None:
508 """Legacy function used to print to stderr."""
510 print(*args, file=sys.stderr, **kwargs)
513 class OutputMultiplexer(object):
515 A class that broadcasts printed messages to several sinks (including
516 various logging levels, different files, different file handles,
517 the house log, etc...)
520 class Destination(enum.IntEnum):
521 """Bits in the destination_bitv bitvector. Used to indicate the
522 output destination."""
525 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
527 LOG_CRITICAL = 0x10 # ⎭
528 FILENAMES = 0x20 # Must provide a filename to the c'tor.
529 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
531 ALL_LOG_DESTINATIONS = (
532 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
534 ALL_OUTPUT_DESTINATIONS = 0x8F
537 destination_bitv: int,
540 filenames: Optional[Iterable[str]] = None,
541 handles: Optional[Iterable[io.TextIOWrapper]] = None):
543 logger = logging.getLogger(None)
546 if filenames is not None:
548 open(filename, 'wb', buffering=0) for filename in filenames
551 if destination_bitv & OutputMultiplexer.FILENAMES:
553 "Filenames argument is required if bitv & FILENAMES"
557 if handles is not None:
558 self.h = [handle for handle in handles]
560 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
562 "Handle argument is required if bitv & FILEHANDLES"
566 self.set_destination_bitv(destination_bitv)
568 def get_destination_bitv(self):
569 return self.destination_bitv
571 def set_destination_bitv(self, destination_bitv: int):
572 if destination_bitv & self.Destination.FILENAMES and self.f is None:
574 "Filename argument is required if bitv & FILENAMES"
576 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
578 "Handle argument is required if bitv & FILEHANDLES"
580 self.destination_bitv = destination_bitv
582 def print(self, *args, **kwargs):
583 from string_utils import sprintf, strip_escape_sequences
584 end = kwargs.pop("end", None)
586 if not isinstance(end, str):
587 raise TypeError("end must be None or a string")
588 sep = kwargs.pop("sep", None)
590 if not isinstance(sep, str):
591 raise TypeError("sep must be None or a string")
593 raise TypeError("invalid keyword arguments to print()")
594 buf = sprintf(*args, end="", sep=sep)
602 self.destination_bitv & self.Destination.FILENAMES and
606 _.write(buf.encode('utf-8'))
610 self.destination_bitv & self.Destination.FILEHANDLES and
617 buf = strip_escape_sequences(buf)
618 if self.logger is not None:
619 if self.destination_bitv & self.Destination.LOG_DEBUG:
620 self.logger.debug(buf)
621 if self.destination_bitv & self.Destination.LOG_INFO:
622 self.logger.info(buf)
623 if self.destination_bitv & self.Destination.LOG_WARNING:
624 self.logger.warning(buf)
625 if self.destination_bitv & self.Destination.LOG_ERROR:
626 self.logger.error(buf)
627 if self.destination_bitv & self.Destination.LOG_CRITICAL:
628 self.logger.critical(buf)
629 if self.destination_bitv & self.Destination.HLOG:
633 if self.f is not None:
638 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
640 A context that uses an OutputMultiplexer. e.g.
642 with OutputMultiplexerContext(
643 OutputMultiplexer.LOG_INFO |
644 OutputMultiplexer.LOG_DEBUG |
645 OutputMultiplexer.FILENAMES |
646 OutputMultiplexer.FILEHANDLES,
647 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
650 mplex.print("This is a log message!")
654 destination_bitv: OutputMultiplexer.Destination,
668 def __exit__(self, etype, value, traceback) -> bool:
670 if etype is not None:
675 def hlog(message: str) -> None:
676 """Write a message to the house log."""
678 message = message.replace("'", "'\"'\"'")
679 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
682 if __name__ == '__main__':