Log the site that raised the exception.
[pyutils.git] / src / pyutils / logging_utils.py
1 #!/usr/bin/env python3
2 # -*- coding: utf-8 -*-
3
4 # © Copyright 2021-2023, Scott Gasch
5
6 """
7 This is a module that offers an opinionated take on how whole program
8 logging should be initialized and controlled.  It uses the standard
9 Python :mod:`logging` but gives you control, via commandline config,
10 to do things such as:
11
12     * Set the logging default level (debug, info, warning, error, critical)
13       of the whole program (see: :code:`--logging_level`)... and to override
14       the logging level with :class:`LoggingContext`.
15     * Prepend or append a message to every log record also with
16       :class:`LoggingContext`.
17     * define the logging message format (see :code:`--logging_format` and
18       :code:`--logging_date_format`) including easily adding a PID/TID
19       marker on all messages to help with multithreaded debugging
20       (:code:`--logging_debug_threads`) and force module names of code
21       that emits log messages to be included in the format
22       (:code:`--logging_debug_modules`),
23     * control the destination of logged messages:
24
25         - log to the console/stderr (:code:`--logging_console`) and/or
26         - log to a rotated file (:code:`--logging_filename`,
27           :code:`--logging_filename_maxsize` and :code:`--logging_filename_count`)
28           and/or
29         - log to the UNIX syslog (:code:`--logging_syslog` and
30           :code:`--logging_syslog_facility`)
31
32     * optionally squelch repeated messages (:code:`--logging_squelch_repeats`),
33     * optionally log probalistically (:code:`--logging_probabilistically`),
34     * capture printed messages into the info log (:code:`--logging_captures_prints`),
35     * optionally clear unwanted logging handlers added by other imports
36       before this one (:code:`--logging_clear_preexisting_handlers`).
37     * optionally append to system-wide records of non-zero exits
38       (:code:`--logging_non_zero_exits_record_path`) and unhandled exceptions
39       (:code:`--logging_unhandled_top_level_exceptions_record_path`) in
40       cooperation with :mod:`pyutils.bootstrap`.
41     * There are also :class:`LoggerAdapter` classes to implement prefix/suffix
42       functionality without using :class:`LoggingContext` by wrapping the
43       logger included.
44
45 To use this functionality, call :meth:`initialize_logging` early
46 in your program entry point.  If you use the
47 :meth:`pyutils.bootstrap.initialize` decorator on your program's entry
48 point, it will call this for you automatically.
49 """
50
51 import collections
52 import contextlib
53 import datetime
54 import enum
55 import io
56 import logging
57 import os
58 import re
59 import sys
60 from logging import FileHandler
61 from logging.config import fileConfig
62 from logging.handlers import RotatingFileHandler, SysLogHandler
63 from types import TracebackType
64 from typing import Any, Callable, Dict, Iterable, List, Optional, Union
65
66 import pytz
67 from overrides import overrides
68
69 # This module is commonly used by others in here and should avoid
70 # taking any unnecessary dependencies back on them.
71 from pyutils import argparse_utils, config, misc_utils
72
73 cfg = config.add_commandline_args(f"Logging ({__file__})", "Args related to logging")
74 cfg.add_argument(
75     "--logging_config_file",
76     type=argparse_utils.valid_filename,
77     default=None,
78     metavar="FILENAME",
79     help="Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial",
80 )
81 cfg.add_argument(
82     "--logging_level",
83     type=str,
84     default="INFO",
85     choices=["NOTSET", "DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"],
86     metavar="LEVEL",
87     help="The global default level below which to squelch log messages",
88 )
89 cfg.add_argument(
90     "--logging_format",
91     type=str,
92     default=None,
93     help="The format for lines logged via the logger module.  See: https://docs.python.org/3/library/logging.html#formatter-objects",
94 )
95 cfg.add_argument(
96     "--logging_date_format",
97     type=str,
98     default="%Y/%m/%dT%H:%M:%S.%f%z",
99     metavar="DATEFMT",
100     help="The format of any dates in --logging_format.",
101 )
102 cfg.add_argument(
103     "--logging_console",
104     action=argparse_utils.ActionNoYes,
105     default=True,
106     help="Should we log to the console (stderr)",
107 )
108 cfg.add_argument(
109     "--logging_filename",
110     type=str,
111     default=None,
112     metavar="FILENAME",
113     help="The filename of the logfile to write.",
114 )
115 cfg.add_argument(
116     "--logging_filename_maxsize",
117     type=argparse_utils.valid_byte_count,
118     default=(1024 * 1024),
119     metavar="#BYTES",
120     help="The maximum size (in bytes) to write to the logging_filename.",
121 )
122 cfg.add_argument(
123     "--logging_filename_count",
124     type=int,
125     default=7,
126     metavar="COUNT",
127     help="The number of logging_filename copies to keep before deleting.",
128 )
129 cfg.add_argument(
130     "--logging_syslog",
131     action=argparse_utils.ActionNoYes,
132     default=False,
133     help="Should we log to localhost's syslog.",
134 )
135 cfg.add_argument(
136     "--logging_syslog_facility",
137     type=str,
138     default="USER",
139     choices=[
140         "NOTSET",
141         "AUTH",
142         "AUTH_PRIV",
143         "CRON",
144         "DAEMON",
145         "FTP",
146         "KERN",
147         "LPR",
148         "MAIL",
149         "NEWS",
150         "SYSLOG",
151         "USER",
152         "UUCP",
153         "LOCAL0",
154         "LOCAL1",
155         "LOCAL2",
156         "LOCAL3",
157         "LOCAL4",
158         "LOCAL5",
159         "LOCAL6",
160         "LOCAL7",
161     ],
162     metavar="SYSLOG_FACILITY_LIST",
163     help="The default syslog message facility identifier",
164 )
165 cfg.add_argument(
166     "--logging_debug_threads",
167     action=argparse_utils.ActionNoYes,
168     default=False,
169     help="Should we prepend pid/tid data to all log messages?",
170 )
171 cfg.add_argument(
172     "--logging_debug_modules",
173     action=argparse_utils.ActionNoYes,
174     default=False,
175     help="Should we prepend module/function data to all log messages?",
176 )
177 cfg.add_argument(
178     "--logging_info_is_print",
179     action=argparse_utils.ActionNoYes,
180     default=False,
181     help="logging.info also prints to stdout.",
182 )
183 cfg.add_argument(
184     "--logging_squelch_repeats",
185     action=argparse_utils.ActionNoYes,
186     default=True,
187     help="Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?",
188 )
189 cfg.add_argument(
190     "--logging_probabilistically",
191     action=argparse_utils.ActionNoYes,
192     default=True,
193     help="Do we allow probabilistic logging (for code that wants it) or should we always log?",
194 )
195 # See also: OutputMultiplexer
196 cfg.add_argument(
197     "--logging_captures_prints",
198     action=argparse_utils.ActionNoYes,
199     default=False,
200     help="When calling print, also log.info automatically.",
201 )
202 cfg.add_argument(
203     "--logging_clear_preexisting_handlers",
204     action=argparse_utils.ActionNoYes,
205     default=True,
206     help=(
207         "Should logging code clear preexisting global logging handlers and thus insist that is "
208         + "alone can add handlers.  Use this to work around annoying modules that insert global "
209         + "handlers with formats and logging levels you might now want.  Caveat emptor, this may "
210         + "cause you to miss logging messages."
211     ),
212 )
213 cfg.add_argument(
214     "--logging_non_zero_exits_record_path",
215     type=str,
216     default="/var/log/abnormal_python_exits.log",
217     metavar="FILENAME",
218     help="The filename in which to record non-zero exits.",
219 )
220 cfg.add_argument(
221     "--logging_unhandled_top_level_exceptions_record_path",
222     type=str,
223     default="/var/log/abnormal_python_exits.log",
224     metavar="FILENAME",
225     help="The filename in which to record unhandled top level exceptions.",
226 )
227
228 BUILT_IN_PRINT = print
229 LOGGING_INITIALIZED = False
230
231
232 # A map from logging_callsite_id -> count of logged messages.
233 squelched_logging_counts: Dict[str, int] = {}
234
235
236 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
237     """
238     A decorator that marks a function as interested in having the logging
239     messages that it produces be squelched (ignored) after it logs the
240     same message more than N times.
241
242     .. note::
243
244         This decorator affects *ALL* logging messages produced
245         within the decorated function.  That said, messages must be
246         identical in order to be squelched.  For example, if the same line
247         of code produces different messages (because of, e.g., a format
248         string), the messages are considered to be different.
249
250     An example of this from the pyutils code itself can be found in
251     :meth:`pyutils.ansi.fg` and :meth:`pyutils.ansi.bg` methods::
252
253         @logging_utils.squelch_repeated_log_messages(1)
254         def fg(
255             name: Optional[str] = "",
256             red: Optional[int] = None,
257             green: Optional[int] = None,
258             blue: Optional[int] = None,
259             *,
260             force_16color: bool = False,
261             force_216color: bool = False,
262         ) -> str:
263             ...
264
265     These methods log stuff like "Using 24-bit color strategy" which
266     gets old really fast and fills up the logs.  By decorating the methods
267     with :code:`@logging_utils.squelch_repeated_log_messages(1)` the code
268     is requesting that its logged messages be dropped silently after the
269     first one is produced (note the argument 1).
270
271     Users can insist that all logged messages always be reflected in the
272     logs using the :code:`--no_logging_squelch_repeats` flag but the default
273     behavior is to allow code to request it be squelched.
274
275     :code:`--logging_squelch_repeats` only affects code with this decorator
276     on it; it ignores all other code.
277
278     Args:
279         squelch_after_n_repeats: the number of repeated messages allowed to
280             log before subsequent messages are silently dropped.
281     """
282
283     def squelch_logging_wrapper(f: Callable):
284         from pyutils import function_utils
285
286         identifier = function_utils.function_identifier(f)
287
288         # Get rid of module paths, e.g. pyutils.ansi:bg -> ansi:bg which
289         # is what we're going to need below.
290         identifier = re.sub(r"[^\.]+\.", "", identifier)
291         squelched_logging_counts[identifier] = squelch_after_n_repeats
292         return f
293
294     return squelch_logging_wrapper
295
296
297 class SquelchRepeatedMessagesFilter(logging.Filter):
298     """A filter that only logs messages from a given site with the same
299     (exact) message at the same logging level N times and ignores
300     subsequent attempts to log.
301
302     This filter only affects logging messages that repeat more than a
303     threshold number of times from functions that are tagged with the
304     :code:`@logging_utils.squelched_logging_ok` decorator (see above);
305     all others are ignored.
306
307     This functionality is enabled by default but can be disabled via
308     the :code:`--no_logging_squelch_repeats` commandline flag.
309     """
310
311     def __init__(self) -> None:
312         super().__init__()
313         self.counters: collections.Counter = collections.Counter()
314
315     @overrides
316     def filter(self, record: logging.LogRecord) -> bool:
317         """Should we drop this log message?"""
318         id1 = f"{record.module}:{record.funcName}"
319         if id1 not in squelched_logging_counts:
320             return True
321         threshold = squelched_logging_counts[id1]
322         logsite = f"{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}"
323         count = self.counters[logsite]
324         self.counters[logsite] += 1
325         return count < threshold
326
327
328 # A map from function_identifier -> probability of logging (0.0%..100.0%)
329 probabilistic_logging_levels: Dict[str, float] = {}
330
331
332 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
333     """A decorator that indicates that all logging statements within the
334     scope of a particular (marked via decorator) function are not
335     deterministic (i.e. they do not always unconditionally log) but rather
336     are probabilistic (i.e. they log N% of the time, randomly) when the
337     user passes the :code:`--logging_probabilistically` commandline flag
338     (which is enabled by default).
339
340     .. note::
341
342         This affects *ALL* logging statements within the marked function.
343         If you want it to only affect a subset of logging statements,
344         log those statements in a separate function that you invoke
345         from within the "too large" scope and mark that separate function
346         with the :code:`logging_is_probabilistic` decorator instead.
347
348     That this functionality can be disabled (forcing all logged
349     messages to produce output) via the
350     :code:`--no_logging_probabilistically` cmdline argument.
351     """
352
353     def probabilistic_logging_wrapper(f: Callable):
354         from pyutils import function_utils
355
356         identifier = function_utils.function_identifier(f)
357         probabilistic_logging_levels[identifier] = probability_of_logging
358         return f
359
360     return probabilistic_logging_wrapper
361
362
363 class ProbabilisticFilter(logging.Filter):
364     """
365     A filter that logs messages probabilistically (i.e. randomly at some
366     percent chance).  This filter is used with a decorator (see
367     :meth:`logging_is_probabilistic`) to implement the
368     :code:`--logging_probabilistically` commandline flag.
369
370     This filter only affects logging messages from functions that have
371     been tagged with the `@logging_utils.probabilistic_logging` decorator.
372     """
373
374     @overrides
375     def filter(self, record: logging.LogRecord) -> bool:
376         """Should the message be logged?"""
377         identifier = f"{record.module}:{record.funcName}"
378         threshold = probabilistic_logging_levels.get(identifier, 100.0)
379         return misc_utils.execute_probabilistically(threshold)
380
381
382 class OnlyInfoFilter(logging.Filter):
383     """A filter that only logs messages produced at the INFO logging
384     level.  This is used by the :code:`--logging_info_is_print`
385     commandline option to select a subset of the logging stream to
386     send to a stdout handler.
387     """
388
389     @overrides
390     def filter(self, record: logging.LogRecord):
391         return record.levelno == logging.INFO
392
393
394 class PrefixAddingFilter(logging.Filter):
395     """A filter that adds a string prefix to the log record for the
396     formatter to later fill in.  Requires a %(prefix)s in the format
397     string.
398     """
399
400     def __init__(self, prefix: str, klobber: bool = False):
401         """
402         Args:
403             prefix: the prefix string to add
404             klobber: should we overwrite other prefixes?
405         """
406         super().__init__()
407         if prefix:
408             self.prefix = prefix
409         else:
410             self.prefix = ""
411         self.klobber = klobber
412
413     @overrides
414     def filter(self, record: logging.LogRecord):
415         if self.klobber:
416             record.prefix = self.prefix
417         elif "prefix" not in record.__dict__:
418             record.prefix = self.prefix
419         return True
420
421
422 class SuffixAddingFilter(logging.Filter):
423     """A filter that adds a string suffix to the log record for the
424     formatter to later fill in.  Requires a %(suffix)s in the format
425     string.
426     """
427
428     def __init__(self, suffix: str, klobber: bool = False):
429         """
430         Args:
431             suffix: the suffix string to add
432             klobber: should we overwrite other suffixes?
433         """
434         super().__init__()
435         if suffix:
436             self.suffix = suffix
437         else:
438             self.suffix = ""
439         self.klobber = klobber
440
441     @overrides
442     def filter(self, record: logging.LogRecord):
443         if self.klobber:
444             record.suffix = self.suffix
445         elif "suffix" not in record.__dict__:
446             record.suffix = self.suffix
447         return True
448
449
450 class PrependingLogAdapter(logging.LoggerAdapter):
451     """:class:`LoggingContext` adds prefixes and suffixes using a
452     logging.Filter that must insert "prefix" or "suffix" members into
453     each log record by using :class:`PrefixAddingFilter` and
454     :class:`SuffixAddingFilter`.  This relies on the logging format
455     string containing a %(prefix)s and a %(suffix)s to work correctly.
456
457     This is an alternate approach that basically just wraps the logger
458     in a class that has the same interface and thunks most calls down
459     to the wrapped logger.  It might be useful if you don't want to use
460     :class:`LoggingContext` or its friends.
461
462         >>> logger = logging.getLogger(__name__ + ".PrependingLogAdapter")
463         >>> logger.setLevel(logging.INFO)
464         >>> logger.addHandler(logging.StreamHandler(sys.stdout))
465
466     At this point logger doesn't have any format string and so it is
467     missing %(prefix)s and %(suffix)s.  It also doesn't have a
468     :class:`PrefixAddingFilter` or :class:`SuffixAddingFilter` added.
469     So using it in a :class:`LoggingContext` will not work.
470
471     But we can still add a prefix or suffix by just wrapping it:
472
473         >>> logger.info("TEST")
474         TEST
475
476         >>> log = PrependingLogAdapter.wrap_logger('prefix> ', logger)
477         >>> log.info("TEST")
478         prefix> TEST
479     """
480
481     def process(self, msg, kwargs):
482         return f'{self.extra.get("prefix", "")}{msg}', kwargs
483
484     @staticmethod
485     def wrap_logger(prefix: str, logger: logging.Logger) -> logging.LoggerAdapter:
486         """Helper method around the creation of a LogAdapter that prepends
487         a given string to every log message produced.
488
489         Args:
490             prefix: the message to prepend to every log message.
491             logger: the logger whose messages to modify.
492
493         Returns:
494             A new logger wrapping the old one with the given behavior.
495             The old logger will continue to behave as usual; simply drop
496             the reference to this wrapper when it's no longer needed.
497         """
498         assert prefix
499         return PrependingLogAdapter(logger, {"prefix": prefix})
500
501
502 class AppendingLogAdapter(logging.LoggerAdapter):
503     """:class:`LoggingContext` adds prefixes and suffixes using a
504     logging.Filter that must insert "prefix" or "suffix" members into
505     each log record by using :class:`PrefixAddingFilter` and
506     :class:`SuffixAddingFilter`.  This relies on the logging format
507     string containing a %(prefix)s and a %(suffix)s to work correctly.
508
509     This is an alternate approach that basically just wraps the logger
510     in a class that has the same interface and thunks most calls down
511     to the wrapped logger.  It might be useful if you don't want to use
512     :class:`LoggingContext` or its friends.
513
514         >>> logger = logging.getLogger(__name__ + ".AppendingLogAdapter")
515         >>> logger.setLevel(logging.INFO)
516         >>> logger.addHandler(logging.StreamHandler(sys.stdout))
517
518     At this point logger doesn't have any format string and so it is
519     missing %(prefix)s and %(suffix)s.  It also doesn't have a
520     :class:`PrefixAddingFilter` or :class:`SuffixAddingFilter` added.
521     So using it in a :class:`LoggingContext` will not work.
522
523     But we can still add a prefix or suffix by just wrapping it:
524
525         >>> logger.info("TEST")
526         TEST
527
528         >>> log = AppendingLogAdapter.wrap_logger('!!!', logger)
529         >>> log.info("TEST")
530         TEST!!!
531     """
532
533     def process(self, msg, kwargs):
534         return f'{msg}{self.extra.get("suffix", "")}', kwargs
535
536     @staticmethod
537     def wrap_logger(suffix: str, logger: logging.Logger) -> logging.LoggerAdapter:
538         """Helper method around the creation of a LoggerAdapter that appends
539         a given string to every log message produced.
540
541         Args:
542             suffix: the message to prepend to every log message.
543             logger: the logger whose messages to modify.
544
545         Returns:
546             A new logger wrapping the old one with the given behavior.
547             The old logger will continue to behave as usual; simply drop
548             the reference to this wrapper when it's no longer needed.
549         """
550         assert suffix
551         return AppendingLogAdapter(logger, {"suffix": suffix})
552
553
554 class LoggingContext(contextlib.ContextDecorator):
555     def __init__(
556         self,
557         logger: logging.Logger,
558         *,
559         level: Optional[int] = None,
560         handlers: Optional[List[logging.Handler]] = None,
561         prefix: Optional[str] = None,
562         suffix: Optional[str] = None,
563     ):
564         """This is a logging context that can be used to temporarily change the
565         way we are logging within its scope.  Logging changes may include:
566
567             - Changing the logging level (e.g. from INFO to DEBUG)
568             - Adding a prefix or suffix to every log message produced
569             - Adding temporary Handlers to direct the logging output elsewhere
570
571         Setup for doctest / examples.  This will normally be taken care of
572         by code in :meth:`initialize_logging` so you don't have to worry
573         about it.
574
575             >>> logging_format = "%(prefix)s%(message)s%(suffix)s"
576             >>> logger = logging.getLogger(__name__ + ".LoggingContext")
577             >>> logger.setLevel(logging.INFO)
578             >>> handler = logging.StreamHandler(sys.stdout)
579             >>> handler.setFormatter(
580             ...     MillisecondAwareFormatter(
581             ...         fmt=logging_format,
582             ...         datefmt='',
583             ...     )
584             ... )
585             >>> logger.addHandler(handler)
586             >>> logger.addFilter(PrefixAddingFilter(None))
587             >>> logger.addFilter(SuffixAddingFilter(None))
588
589         First, this logger should be currently be configured to send
590         INFO+ messages to sys.stdout.  Let's see it in action:
591
592             >>> logger.info("Hello world!")
593             Hello world!
594             >>> logger.debug("You should not see this")
595
596         The first example is to simply change the level of the logger.
597         Here we temporarily change it to DEBUG within the body of the
598         :class:`LoggingContext`:
599
600             >>> with LoggingContext(logger, level=logging.DEBUG):
601             ...     logger.debug("You should see this now")
602             ...     logger.info("Of course you should still see this too")
603             You should see this now
604             Of course you should still see this too
605
606             >>> logger.debug("Outside of the context we are at INFO again")
607             >>> logger.debug("(which is why you don't see these)")
608             >>> logger.info("But you should see this at INFO level")
609             But you should see this at INFO level
610
611         The prefix and suffix argument prepend or append a message to
612         all log output.  To do this, you need %(prefix)s and
613         %(suffix)s placeholders in your logger format string
614         indicating where to insert the data.  This is useful, for
615         example, to add an active request identifier to the set of log
616         messages produced while processing it.
617
618             >>> logger.info("About to work on a new request")
619             About to work on a new request
620
621             >>> with LoggingContext(logger, prefix='10.0.0.13> '):
622             ...     logger.info("Working on it now")
623             10.0.0.13> Working on it now
624
625             >>> logger.info("Done with that request")
626             Done with that request
627
628         LoggingContext can also be used to add temporary handler(s).
629         This code temporarily uses two stdout handlers to double the
630         output for testing purporses but you could also temporarily,
631         e.g., add a RotatingFileHandler or SysLogHandler etc...
632
633             >>> with LoggingContext(logger, handlers=[logging.StreamHandler(sys.stdout)]):
634             ...     logger.info("TEST")
635             TEST
636             TEST
637
638         Once leaving the context, logger's behavior is restored.  In
639         this case, the extra handler is removed so output will not
640         longer be doubled.
641
642             >>> logger.info("OUTSIDE")
643             OUTSIDE
644
645         LoggingContext can also be used as a decorator if that is more
646         convenient:
647
648             >>> @LoggingContext(logger, level=logging.DEBUG)
649             ... def log_stuff(logger):
650             ...     logger.debug("But inside, the decorator has changed us to DEBUG")
651
652             >>> logger.debug("Outside, we're at INFO level and you don't see this")
653             >>> log_stuff(logger)
654             But inside, the decorator has changed us to DEBUG
655             >>> logger.debug("And, of course, out here we're still at INFO afterwards")
656
657         Args:
658             logger: the logger on which to operate
659             level: the new level to set for the duration of the context
660             handlers: additional handlers to add for the duration of the context
661             prefix: the prefix string to set for the duration of the context
662             suffix: the suffix string to set for the duration of the context
663
664         Returns:
665             The modified logger.
666
667         """
668         self.logger = logger
669         self.level = level
670         self.old_level: Optional[int] = None
671         self.handlers = handlers
672         if prefix:
673             self.prefix: Optional[logging.Filter] = PrefixAddingFilter(prefix, True)
674         else:
675             self.prefix = None
676         if suffix:
677             self.suffix: Optional[logging.Filter] = SuffixAddingFilter(suffix, True)
678         else:
679             self.suffix = None
680
681     def __enter__(self) -> Union[logging.Logger, logging.LoggerAdapter]:
682         assert self.logger
683         if self.level:
684             self.old_level = self.logger.level
685             self.logger.setLevel(self.level)
686
687         if self.handlers:
688             for handler in self.handlers:
689                 self.logger.addHandler(handler)
690
691         if self.prefix:
692             self.logger.addFilter(self.prefix)
693
694         if self.suffix:
695             self.logger.addFilter(self.suffix)
696         return self.logger
697
698     def __exit__(self, et, ev, tb) -> None:
699         if self.suffix:
700             self.logger.removeFilter(self.suffix)
701
702         if self.prefix:
703             self.logger.removeFilter(self.prefix)
704
705         if self.handlers:
706             for handler in self.handlers:
707                 self.logger.removeHandler(handler)
708                 handler.close()
709
710         if self.old_level:
711             self.logger.setLevel(self.old_level)
712         return None  # propagate exceptions out
713
714
715 class MillisecondAwareFormatter(logging.Formatter):
716     """A formatter for adding milliseconds to log messages which, for
717     whatever reason, the default Python logger doesn't do.
718
719     .. note::
720
721         You probably don't need to use this directly but it is
722         wired in under :meth:`initialize_logging` so that the
723         timestamps in log messages have millisecond level
724         precision.
725     """
726
727     converter = datetime.datetime.fromtimestamp  # type: ignore
728
729     @overrides
730     def formatTime(self, record, datefmt=None):
731         ct = MillisecondAwareFormatter.converter(
732             record.created, pytz.timezone("US/Pacific")
733         )
734         if datefmt:
735             s = ct.strftime(datefmt)
736         else:
737             t = ct.strftime("%Y-%m-%d %H:%M:%S")
738             s = f"{t},{record.msecs:%03d}"
739         return s
740
741
742 def _log_about_logging(
743     logger,
744     default_logging_level,
745     preexisting_handlers_count,
746     fmt,
747     facility_name,
748 ):
749     """This is invoked automatically after logging is initialized such
750     that the first messages in the log are about how logging itself
751     was configured.
752     """
753     level_name = logging._levelToName.get(
754         default_logging_level, str(default_logging_level)
755     )
756     logger.debug("Initialized global logging; logging level is %s.", level_name)
757     if (
758         config.config["logging_clear_preexisting_handlers"]
759         and preexisting_handlers_count > 0
760     ):
761         logger.debug(
762             "Logging cleared %d global handlers (--logging_clear_preexisting_handlers)",
763             preexisting_handlers_count,
764         )
765     logger.debug('Logging format specification is "%s"', fmt)
766     if config.config["logging_debug_threads"]:
767         logger.debug(
768             "...Logging format spec captures tid/pid. (--logging_debug_threads)"
769         )
770     if config.config["logging_debug_modules"]:
771         logger.debug(
772             "...Logging format spec captures files/functions/lineno. (--logging_debug_modules)"
773         )
774     if config.config["logging_syslog"]:
775         logger.debug(
776             "Logging to syslog as %s with priority mapping based on level. (--logging_syslog)",
777             facility_name,
778         )
779     if config.config["logging_filename"]:
780         logger.debug(
781             'Logging to file "%s". (--logging_filename)',
782             config.config["logging_filename"],
783         )
784         logger.debug(
785             "...with %d bytes max file size. (--logging_filename_maxsize)",
786             config.config["logging_filename_maxsize"],
787         )
788         logger.debug(
789             "...and %d rotating backup file count. (--logging_filename_count)",
790             config.config["logging_filename_count"],
791         )
792     if config.config["logging_console"]:
793         logger.debug("Logging to the console (stderr). (--logging_console)")
794     if config.config["logging_info_is_print"]:
795         logger.debug(
796             "Logging logger.info messages will be repeated on stdout. (--logging_info_is_print)"
797         )
798     if config.config["logging_squelch_repeats"]:
799         logger.debug(
800             "Logging code allowed to request repeated messages be squelched. (--logging_squelch_repeats)"
801         )
802     else:
803         logger.debug(
804             "Logging code forbidden to request messages be squelched; all messages logged. (--no_logging_squelch_repeats)"
805         )
806     if config.config["logging_probabilistically"]:
807         logger.debug(
808             "Logging code is allowed to request probabilistic logging. (--logging_probabilistically)"
809         )
810     else:
811         logger.debug(
812             "Logging code is forbidden to request probabilistic logging; messages always logged. (--no_logging_probabilistically)"
813         )
814     if config.config["logging_captures_prints"]:
815         logger.debug(
816             "Logging will capture printed data as logger.info messages. (--logging_captures_prints)"
817         )
818
819
820 def _construct_logging_format() -> str:
821     """Figure out the root logging format string based on commandling args."""
822
823     # Custom or default --logging_format?
824     if config.config["logging_format"]:
825         fmt = config.config["logging_format"]
826     elif config.config["logging_syslog"]:
827         fmt = "%(levelname).1s:%(filename)s[%(process)d]: "
828     else:
829         fmt = "%(levelname).1s:%(asctime)s: "
830
831     fmt += "%(prefix)s%(message)s%(suffix)s"
832
833     # --logging_debug_threads and --logging_debug_modules both affect
834     # the format by prepending information about the pid/tid or
835     # file/function.
836     if config.config["logging_debug_threads"]:
837         fmt = f"%(process)d.%(thread)d|{fmt}"
838     if config.config["logging_debug_modules"]:
839         fmt = f"%(filename)s:%(funcName)s:%(lineno)s|{fmt}"
840     return fmt
841
842
843 def _construct_handlers_list(
844     logging_format: str, facility_name: Optional[str]
845 ) -> List[logging.Handler]:
846     """Create the list of handlers to be added to the root logger
847     based on commandline flags.
848     """
849
850     retval: List[logging.Handler] = []
851
852     # --logging_syslog (optionally with --logging_syslog_facility)
853     # sets up for logging to use the standard system syslogd as a
854     # sink.
855     if config.config["logging_syslog"]:
856         if sys.platform not in ("win32", "cygwin"):
857             assert facility_name
858             facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)
859             assert facility
860             syslog_handler = SysLogHandler(facility=facility, address="/dev/log")
861             syslog_handler.setFormatter(
862                 MillisecondAwareFormatter(
863                     fmt=logging_format,
864                     datefmt=config.config["logging_date_format"],
865                 )
866             )
867             retval.append(syslog_handler)
868
869     # --logging_filename (with friends --logging_filename_count and
870     # --logging_filename_maxsize) set up logging to a file on the
871     # filesystem with automatic rotation when it gets too big.
872     if config.config["logging_filename"]:
873         max_bytes = config.config["logging_filename_maxsize"]
874         assert max_bytes and isinstance(max_bytes, int)
875         backup_count = config.config["logging_filename_count"]
876         assert backup_count and isinstance(backup_count, int)
877         file_handler = RotatingFileHandler(
878             config.config["logging_filename"],
879             maxBytes=max_bytes,
880             backupCount=backup_count,
881         )
882         file_handler.setFormatter(
883             MillisecondAwareFormatter(
884                 fmt=logging_format,
885                 datefmt=config.config["logging_date_format"],
886             )
887         )
888         retval.append(file_handler)
889
890     # --logging_console is, ahem, logging to the console.
891     if config.config["logging_console"]:
892         console_handler = logging.StreamHandler(sys.stderr)
893         console_handler.setFormatter(
894             MillisecondAwareFormatter(
895                 fmt=logging_format,
896                 datefmt=config.config["logging_date_format"],
897             )
898         )
899         retval.append(console_handler)
900
901     # --logging_info_is_print echoes any message to logger.info(x) as
902     # a print statement on stdout.
903     if config.config["logging_info_is_print"]:
904         print_handler = logging.StreamHandler(sys.stdout)
905         print_handler.addFilter(OnlyInfoFilter())
906         retval.append(print_handler)
907
908     if len(retval) == 0:
909         retval.append(logging.NullHandler())
910     return retval
911
912
913 def _add_logging_handlers_and_filters(
914     logger: logging.Logger, handlers: List[logging.Handler]
915 ) -> None:
916     """Adds a list of handlers to the root logger."""
917
918     for handler in handlers:
919         # These two are always present and set %(prefix) and %(suffix)
920         # if appropriate (see :class:`LoggingContext`) or make them
921         # empty string.
922         handler.addFilter(PrefixAddingFilter("", False))
923         handler.addFilter(SuffixAddingFilter("", False))
924
925         # --logging_squelch_repeats allows code to request repeat logging
926         # messages (identical log site and message contents) to be
927         # silenced.  Logging code must request this explicitly, it isn't
928         # automatic.  This option just allows the silencing to happen.
929         if config.config["logging_squelch_repeats"]:
930             handler.addFilter(SquelchRepeatedMessagesFilter())
931
932         # --logging_probabilistically allows code to request
933         # non-deterministic logging where messages have some probability
934         # of being produced.  Logging code must request this explicitly.
935         # This option just allows the non-deterministic behavior to
936         # happen.  Disabling it will cause every log message to be
937         # produced.
938         if config.config["logging_probabilistically"]:
939             handler.addFilter(ProbabilisticFilter())
940         logger.addHandler(handler)
941
942
943 def initialize_logging(logger=None) -> logging.Logger:
944     """Initialize logging for the program.  See module level comments
945     for information about what functionality this provides and how to
946     enable or disable functionality via the commandline.
947
948     If you use the
949     :meth:`bootstrap.initialize` decorator on your program's entry point,
950     it will call this for you.  See :meth:`pyutils.bootstrap.initialize`
951     for more details.
952     """
953
954     global LOGGING_INITIALIZED
955     if LOGGING_INITIALIZED:
956         return logging.getLogger()
957     LOGGING_INITIALIZED = True
958
959     clear_preexisting = config.config["logging_clear_preexisting_handlers"]
960     preexisting_handlers_count = 0
961     if logger is None:
962         logging.basicConfig(force=clear_preexisting)
963         logger = logging.getLogger()
964
965     # --logging_clear_preexisting_handlers removes logging handlers
966     # that were registered by global statements during imported module
967     # setup.
968     if clear_preexisting:
969         while logger.hasHandlers():
970             logger.removeHandler(logger.handlers[0])
971             preexisting_handlers_count += 1
972
973     # --logging_config_file pulls logging settings from a config file
974     # skipping the rest of this setup.
975     if config.config["logging_config_file"] is not None:
976         fileConfig(config.config["logging_config_file"])
977         return logger
978
979     # Global default logging level (--logging_level); messages below
980     # this level will be silenced.
981     logging_level = config.config["logging_level"]
982     assert logging_level
983     logging_level = logging_level.upper()
984     default_logging_level = getattr(logging, logging_level, None)
985     if not isinstance(default_logging_level, int):
986         raise ValueError(f'Invalid level: {config.config["logging_level"]}')
987     logger.setLevel(default_logging_level)
988
989     logging_format = _construct_logging_format()
990     facility_name = None
991     if config.config["logging_syslog"]:
992         if sys.platform not in ("win32", "cygwin"):
993             if config.config["logging_syslog_facility"]:
994                 facility_name = "LOG_" + config.config["logging_syslog_facility"]
995     handlers: List[logging.Handler] = _construct_handlers_list(
996         logging_format, facility_name
997     )
998     _add_logging_handlers_and_filters(logger, handlers)
999
1000     # --logging_captures_prints, if set, will capture and log.info
1001     # anything printed on stdout.
1002     if config.config["logging_captures_prints"]:
1003         import builtins
1004
1005         def print_and_also_log(*arg, **kwarg):
1006             f = kwarg.get("file", None)
1007             if f == sys.stderr:
1008                 logger.warning(*arg)
1009             else:
1010                 logger.info(*arg)
1011             BUILT_IN_PRINT(*arg, **kwarg)
1012
1013         builtins.print = print_and_also_log
1014
1015     # At this point the logger is ready, handlers are set up,
1016     # etc... so log about the logging configuration.
1017     _log_about_logging(
1018         logger,
1019         default_logging_level,
1020         preexisting_handlers_count,
1021         logging_format,
1022         facility_name,
1023     )
1024     return logger
1025
1026
1027 def get_logger(name: str = ""):
1028     """Get the global logger"""
1029     logger = logging.getLogger(name)
1030     return initialize_logging(logger)
1031
1032
1033 class OutputMultiplexer(object):
1034     """A class that broadcasts printed messages to several sinks
1035     (including various logging levels, different files, different file
1036     handles, the house log, etc...).  See also
1037     :class:`OutputMultiplexerContext` for an easy usage pattern.
1038     """
1039
1040     class Destination(enum.IntEnum):
1041         """Bits in the destination_bitv bitvector.  Used to indicate the
1042         output destination."""
1043
1044         # fmt: off
1045         LOG_DEBUG = 0x01     #  ⎫
1046         LOG_INFO = 0x02      #  ⎪
1047         LOG_WARNING = 0x04   #  ⎬ Must provide logger to the c'tor.
1048         LOG_ERROR = 0x08     #  ⎪
1049         LOG_CRITICAL = 0x10  #  ⎭
1050         FILENAMES = 0x20     # Must provide a filename to the c'tor.
1051         FILEHANDLES = 0x40   # Must provide a handle to the c'tor.
1052         HLOG = 0x80
1053         ALL_LOG_DESTINATIONS = (
1054             LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
1055         )
1056         ALL_OUTPUT_DESTINATIONS = 0x8F
1057         # fmt: on
1058
1059     def __init__(
1060         self,
1061         destination_bitv: int,
1062         *,
1063         logger=None,
1064         filenames: Optional[Iterable[str]] = None,
1065         handles: Optional[Iterable[io.TextIOWrapper]] = None,
1066     ):
1067         """
1068         Constructs the OutputMultiplexer instance.
1069
1070         Args:
1071             destination_bitv: a bitvector where each bit represents an
1072                 output destination.  Multiple bits may be set.
1073             logger: if LOG_* bits are set, you must pass a logger here.
1074             filenames: if FILENAMES bit is set, this should be a list of
1075                 files you'd like to output into.  This code handles opening
1076                 and closing said files.
1077             handles: if FILEHANDLES bit is set, this should be a list of
1078                 already opened filehandles you'd like to output into.  The
1079                 handles will remain open after the scope of the multiplexer.
1080         """
1081         if logger is None:
1082             logger = logging.getLogger(None)
1083         self.logger = logger
1084
1085         self.f: Optional[List[Any]] = None
1086         if filenames is not None:
1087             self.f = [open(filename, "wb", buffering=0) for filename in filenames]
1088         else:
1089             if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
1090                 raise ValueError("Filenames argument is required if bitv & FILENAMES")
1091             self.f = None
1092
1093         self.h: Optional[List[Any]] = None
1094         if handles is not None:
1095             self.h = list(handles)
1096         else:
1097             if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
1098                 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
1099             self.h = None
1100
1101         self.set_destination_bitv(destination_bitv)
1102
1103     def get_destination_bitv(self):
1104         """Where are we outputting?"""
1105         return self.destination_bitv
1106
1107     def set_destination_bitv(self, destination_bitv: int):
1108         """Change the output destination_bitv to the one provided."""
1109         if destination_bitv & self.Destination.FILENAMES and self.f is None:
1110             raise ValueError("Filename argument is required if bitv & FILENAMES")
1111         if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
1112             raise ValueError("Handle argument is required if bitv & FILEHANDLES")
1113         self.destination_bitv = destination_bitv
1114
1115     def print(self, *args, **kwargs):
1116         """Produce some output to all sinks."""
1117         from pyutils.string_utils import _sprintf, strip_escape_sequences
1118
1119         end = kwargs.pop("end", None)
1120         if end is not None:
1121             if not isinstance(end, str):
1122                 raise TypeError("end must be None or a string")
1123         sep = kwargs.pop("sep", None)
1124         if sep is not None:
1125             if not isinstance(sep, str):
1126                 raise TypeError("sep must be None or a string")
1127         if kwargs:
1128             raise TypeError("invalid keyword arguments to print()")
1129         buf = _sprintf(*args, end="", sep=sep)
1130         if sep is None:
1131             sep = " "
1132         if end is None:
1133             end = "\n"
1134         if end == "\n":
1135             buf += "\n"
1136         if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
1137             for _ in self.f:
1138                 _.write(buf.encode("utf-8"))
1139                 _.flush()
1140
1141         if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
1142             for _ in self.h:
1143                 _.write(buf)
1144                 _.flush()
1145
1146         buf = strip_escape_sequences(buf)
1147         if self.logger is not None:
1148             if self.destination_bitv & self.Destination.LOG_DEBUG:
1149                 self.logger.debug(buf)
1150             if self.destination_bitv & self.Destination.LOG_INFO:
1151                 self.logger.info(buf)
1152             if self.destination_bitv & self.Destination.LOG_WARNING:
1153                 self.logger.warning(buf)
1154             if self.destination_bitv & self.Destination.LOG_ERROR:
1155                 self.logger.error(buf)
1156             if self.destination_bitv & self.Destination.LOG_CRITICAL:
1157                 self.logger.critical(buf)
1158         if self.destination_bitv & self.Destination.HLOG:
1159             hlog(buf)
1160
1161     def close(self):
1162         """Close all open files."""
1163         if self.f is not None:
1164             for _ in self.f:
1165                 _.close()
1166
1167
1168 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
1169     """
1170     A context that uses an :class:`OutputMultiplexer`.  e.g.::
1171
1172         with OutputMultiplexerContext(
1173                 OutputMultiplexer.LOG_INFO |
1174                 OutputMultiplexer.LOG_DEBUG |
1175                 OutputMultiplexer.FILENAMES |
1176                 OutputMultiplexer.FILEHANDLES,
1177                 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
1178                 handles = [ f, g ]
1179             ) as mplex:
1180                 mplex.print("This is a log message!")
1181     """
1182
1183     def __init__(
1184         self,
1185         destination_bitv: OutputMultiplexer.Destination,
1186         *,
1187         logger=None,
1188         filenames=None,
1189         handles=None,
1190     ):
1191         """
1192         Args:
1193             destination_bitv: a bitvector that indicates where we should
1194                 send output.  See :class:`OutputMultiplexer` for options.
1195             logger: optional logger to use for log destination messages.
1196             filenames: optional filenames to write for filename destination
1197                 messages.
1198             handles: optional open filehandles to write for filehandle
1199                 destination messages.
1200         """
1201         super().__init__(
1202             destination_bitv,
1203             logger=logger,
1204             filenames=filenames,
1205             handles=handles,
1206         )
1207
1208     def __enter__(self):
1209         return self
1210
1211     def __exit__(self, etype, value, tb) -> bool:
1212         super().close()
1213         if etype is not None:
1214             return False
1215         return True
1216
1217
1218 def _get_systemwide_abnormal_exit_handler(filename: str) -> FileHandler:
1219     handler = FileHandler(filename)
1220     handler.setFormatter(
1221         MillisecondAwareFormatter(
1222             fmt=_construct_logging_format(),
1223             datefmt=config.config["logging_date_format"],
1224         )
1225     )
1226     return handler
1227
1228
1229 def non_zero_return_value(ret: Any) -> bool:
1230     """
1231     Special method hooked from bootstrap.py to optionally keep a system-wide
1232     record of non-zero python program exits.
1233
1234     Args:
1235         ret: the return value
1236     """
1237     try:
1238         record = config.config['logging_non_zero_exits_record_path']
1239         if record:
1240             logger = logging.getLogger()
1241             handler = _get_systemwide_abnormal_exit_handler(record)
1242             program = config.PROGRAM_NAME
1243             args = config.ORIG_ARGV
1244             with LoggingContext(logger, handlers=[handler], level=logging.ERROR) as log:
1245                 log.error('%s (%s) Exit %s', program, args, ret)
1246             return True
1247     except Exception:
1248         pass
1249     return False
1250
1251
1252 def unhandled_top_level_exception(
1253     exc_type: type, exc_value: type, exc_tb: TracebackType
1254 ) -> bool:
1255     """
1256     Special method hooked from bootstrap.py to optionally keep a system-wide
1257     record of unhandled top level exceptions.
1258
1259     Args:
1260         exc_type: the type of the unhandled exception
1261         exc_value: the value passed to the exception's c'tor
1262         exc_tb: the stack from where the exception was raised
1263     """
1264     try:
1265         record = config.config['logging_unhandled_top_level_exceptions_record_path']
1266         if record:
1267             import traceback
1268
1269             logger = logging.getLogger()
1270             handler = _get_systemwide_abnormal_exit_handler(record)
1271             program = config.PROGRAM_NAME
1272             args = config.ORIG_ARGV
1273             tb = traceback.extract_tb(exc_tb)
1274             original_frame = tb[-1]
1275             raise_site_file = original_frame.filename
1276             raise_site_lineno = original_frame.lineno
1277             with LoggingContext(logger, handlers=[handler], level=logging.ERROR) as log:
1278                 log.error(
1279                     '%s (%s) unhandled top-level exception (type=%s(%s)) at %s:%s',
1280                     program,
1281                     args,
1282                     exc_type.__name__,
1283                     str(exc_value),
1284                     raise_site_file,
1285                     raise_site_lineno,
1286                 )
1287             return True
1288     except Exception:
1289         pass
1290     return False
1291
1292
1293 def hlog(message: str) -> None:
1294     """Write a message to the house log (syslog facility local7 priority
1295     info) by calling `/usr/bin/logger`.  This is pretty hacky but used
1296     by a bunch of (my) code.  Another way to do this would be to use
1297     :code:`--logging_syslog` and :code:`--logging_syslog_facility` but
1298     I can't actually say that's easier.
1299
1300     TODO: this needs to move.
1301     """
1302     message = message.replace("'", "'\"'\"'")
1303     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
1304
1305
1306 if __name__ == "__main__":
1307     import doctest
1308
1309     doctest.testmod()