Easier and more self documenting patterns for loading/saving Persistent
[python_utils.git] / logging_utils.py
index 7b70d759879e5f537f0a60d60d4692c2bd1536be..f7e3be62ccd0adf8a472e5126e2c5d3f76692faa 100644 (file)
@@ -1,7 +1,31 @@
 #!/usr/bin/env python3
 # -*- coding: utf-8 -*-
 
-"""Utilities related to logging."""
+# © Copyright 2021-2022, Scott Gasch
+
+"""Utilities related to logging.  To use it you must invoke
+:meth:`initialize_logging`.  If you use the
+:meth:`bootstrap.initialize` decorator on your program's entry point,
+it will call this for you.  See :meth:`python_modules.bootstrap.initialize`
+for more details.  If you use this you get:
+
+* Ability to set logging level,
+* ability to define the logging format,
+* ability to tee all logging on stderr,
+* ability to tee all logging into a file,
+* ability to rotate said file as it grows,
+* ability to tee all logging into the system log (syslog) and
+  define the facility and level used to do so,
+* easy automatic pid/tid stamp on logging for debugging threads,
+* ability to squelch repeated log messages,
+* ability to log probabilistically in code,
+* ability to only see log messages from a particular module or
+  function,
+* ability to clear logging handlers added by earlier loaded modules.
+
+All of these are controlled via commandline arguments to your program,
+see the code below for details.
+"""
 
 import collections
 import contextlib
@@ -189,11 +213,13 @@ def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
     messages that it produces be squelched (ignored) after it logs the
     same message more than N times.
 
-    Note: this decorator affects *ALL* logging messages produced
-    within the decorated function.  That said, messages must be
-    identical in order to be squelched.  For example, if the same line
-    of code produces different messages (because of, e.g., a format
-    string), the messages are considered to be different.
+    .. note::
+
+        This decorator affects *ALL* logging messages produced
+        within the decorated function.  That said, messages must be
+        identical in order to be squelched.  For example, if the same line
+        of code produces different messages (because of, e.g., a format
+        string), the messages are considered to be different.
 
     """
 
@@ -208,19 +234,17 @@ def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
 
 
 class SquelchRepeatedMessagesFilter(logging.Filter):
-    """
-    A filter that only logs messages from a given site with the same
+    """A filter that only logs messages from a given site with the same
     (exact) message at the same logging level N times and ignores
     subsequent attempts to log.
 
-    This filter only affects logging messages that repeat more than
-    a threshold number of times from functions that are tagged with
-    the @logging_utils.squelched_logging_ok decorator; others are
-    ignored.
+    This filter only affects logging messages that repeat more than a
+    threshold number of times from functions that are tagged with the
+    @logging_utils.squelched_logging_ok decorator (see above); others
+    are ignored.
 
     This functionality is enabled by default but can be disabled via
-    the --no_logging_squelch_repeats commandline flag.
-
+    the :code:`--no_logging_squelch_repeats` commandline flag.
     """
 
     def __init__(self) -> None:
@@ -241,8 +265,7 @@ class SquelchRepeatedMessagesFilter(logging.Filter):
 
 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
     """This filter only allows logging messages from an allow list of
-    module names or module:function names.  Blocks others.
-
+    module names or module:function names.  Blocks all others.
     """
 
     @staticmethod
@@ -291,6 +314,8 @@ class DynamicPerScopeLoggingLevelFilter(logging.Filter):
 
     @overrides
     def filter(self, record: logging.LogRecord) -> bool:
+        """Decides whether or not to log based on an allow list."""
+
         # First try to find a logging level by scope (--lmodule)
         if len(self.level_by_scope) > 0:
             min_level = None
@@ -317,18 +342,17 @@ probabilistic_logging_levels: Dict[str, float] = {}
 
 
 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
-    """
-    A decorator that indicates that all logging statements within the
+    """A decorator that indicates that all logging statements within the
     scope of a particular (marked) function are not deterministic
     (i.e. they do not always unconditionally log) but rather are
-    probabilistic (i.e. they log N% of the time randomly).
-
-    Note that this functionality can be disabled (forcing all logged
-    messages to produce output) via the --no_logging_probabilistically
-    cmdline argument.
+    probabilistic (i.e. they log N% of the time, randomly).
 
-    This affects *ALL* logging statements within the marked function.
+    .. note::
+        This affects *ALL* logging statements within the marked function.
 
+    That this functionality can be disabled (forcing all logged
+    messages to produce output) via the
+    :code:`--no_logging_probabilistically` cmdline argument.
     """
 
     def probabilistic_logging_wrapper(f: Callable):
@@ -348,7 +372,6 @@ class ProbabilisticFilter(logging.Filter):
 
     This filter only affects logging messages from functions that have
     been tagged with the @logging_utils.probabilistic_logging decorator.
-
     """
 
     @overrides
@@ -361,12 +384,10 @@ class ProbabilisticFilter(logging.Filter):
 
 
 class OnlyInfoFilter(logging.Filter):
-    """
-    A filter that only logs messages produced at the INFO logging
-    level.  This is used by the logging_info_is_print commandline
-    option to select a subset of the logging stream to send to a
-    stdout handler.
-
+    """A filter that only logs messages produced at the INFO logging
+    level.  This is used by the ::code`--logging_info_is_print`
+    commandline option to select a subset of the logging stream to
+    send to a stdout handler.
     """
 
     @overrides
@@ -378,7 +399,6 @@ class MillisecondAwareFormatter(logging.Formatter):
     """
     A formatter for adding milliseconds to log messages which, for
     whatever reason, the default python logger doesn't do.
-
     """
 
     converter = datetime.datetime.fromtimestamp  # type: ignore
@@ -401,10 +421,13 @@ def log_about_logging(
     fmt,
     facility_name,
 ):
+    """Some of the initial messages in the debug log are about how we
+    have set up logging itself."""
+
     level_name = logging._levelToName.get(default_logging_level, str(default_logging_level))
     logger.debug('Initialized global logging; default logging level is %s.', level_name)
     if config.config['logging_clear_preexisting_handlers'] and preexisting_handlers_count > 0:
-        logger.warning(
+        logger.debug(
             'Logging cleared %d global handlers (--logging_clear_preexisting_handlers)',
             preexisting_handlers_count,
         )
@@ -465,6 +488,31 @@ def log_about_logging(
 
 
 def initialize_logging(logger=None) -> logging.Logger:
+    """Initialize logging for the program.  This must be called if you want
+    to use any of the functionality provided by this module such as:
+
+    * Ability to set logging level,
+    * ability to define the logging format,
+    * ability to tee all logging on stderr,
+    * ability to tee all logging into a file,
+    * ability to rotate said file as it grows,
+    * ability to tee all logging into the system log (syslog) and
+      define the facility and level used to do so,
+    * easy automatic pid/tid stamp on logging for debugging threads,
+    * ability to squelch repeated log messages,
+    * ability to log probabilistically in code,
+    * ability to only see log messages from a particular module or
+      function,
+    * ability to clear logging handlers added by earlier loaded modules.
+
+    All of these are controlled via commandline arguments to your program,
+    see the code below for details.
+
+    If you use the
+    :meth:`bootstrap.initialize` decorator on your program's entry point,
+    it will call this for you.  See :meth:`python_modules.bootstrap.initialize`
+    for more details.
+    """
     global LOGGING_INITIALIZED
     if LOGGING_INITIALIZED:
         return logging.getLogger()
@@ -633,6 +681,7 @@ def initialize_logging(logger=None) -> logging.Logger:
 
 
 def get_logger(name: str = ""):
+    """Get the global logger"""
     logger = logging.getLogger(name)
     return initialize_logging(logger)
 
@@ -641,7 +690,6 @@ def tprint(*args, **kwargs) -> None:
     """Legacy function for printing a message augmented with thread id
     still needed by some code.  Please use --logging_debug_threads in
     new code.
-
     """
     if config.config['logging_debug_threads']:
         from thread_utils import current_thread_id
@@ -656,18 +704,15 @@ def dprint(*args, **kwargs) -> None:
     """Legacy function used to print to stderr still needed by some code.
     Please just use normal logging with --logging_console which
     accomplishes the same thing in new code.
-
     """
     print(*args, file=sys.stderr, **kwargs)
 
 
 class OutputMultiplexer(object):
-    """
-    A class that broadcasts printed messages to several sinks (including
-    various logging levels, different files, different file handles,
-    the house log, etc...).  See also OutputMultiplexerContext for an
-    easy usage pattern.
-
+    """A class that broadcasts printed messages to several sinks
+    (including various logging levels, different files, different file
+    handles, the house log, etc...).  See also
+    :class:`OutputMultiplexerContext` for an easy usage pattern.
     """
 
     class Destination(enum.IntEnum):
@@ -697,6 +742,20 @@ class OutputMultiplexer(object):
         filenames: Optional[Iterable[str]] = None,
         handles: Optional[Iterable[io.TextIOWrapper]] = None,
     ):
+        """
+        Constructs the OutputMultiplexer instance.
+
+        Args:
+            destination_bitv: a bitvector where each bit represents an
+                output destination.  Multiple bits may be set.
+            logger: if LOG_* bits are set, you must pass a logger here.
+            filenames: if FILENAMES bit is set, this should be a list of
+                files you'd like to output into.  This code handles opening
+                and closing said files.
+            handles: if FILEHANDLES bit is set, this should be a list of
+                already opened filehandles you'd like to output into.  The
+                handles will remain open after the scope of the multiplexer.
+        """
         if logger is None:
             logger = logging.getLogger(None)
         self.logger = logger
@@ -720,9 +779,11 @@ class OutputMultiplexer(object):
         self.set_destination_bitv(destination_bitv)
 
     def get_destination_bitv(self):
+        """Where are we outputting?"""
         return self.destination_bitv
 
     def set_destination_bitv(self, destination_bitv: int):
+        """Change the output destination_bitv to the one provided."""
         if destination_bitv & self.Destination.FILENAMES and self.f is None:
             raise ValueError("Filename argument is required if bitv & FILENAMES")
         if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
@@ -730,6 +791,7 @@ class OutputMultiplexer(object):
         self.destination_bitv = destination_bitv
 
     def print(self, *args, **kwargs):
+        """Produce some output to all sinks."""
         from string_utils import sprintf, strip_escape_sequences
 
         end = kwargs.pop("end", None)
@@ -775,6 +837,7 @@ class OutputMultiplexer(object):
             hlog(buf)
 
     def close(self):
+        """Close all open files."""
         if self.f is not None:
             for _ in self.f:
                 _.close()
@@ -782,7 +845,7 @@ class OutputMultiplexer(object):
 
 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
     """
-    A context that uses an OutputMultiplexer.  e.g.
+    A context that uses an :class:`OutputMultiplexer`.  e.g.::
 
         with OutputMultiplexerContext(
                 OutputMultiplexer.LOG_INFO |
@@ -793,7 +856,6 @@ class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
                 handles = [ f, g ]
             ) as mplex:
                 mplex.print("This is a log message!")
-
     """
 
     def __init__(
@@ -825,9 +887,8 @@ def hlog(message: str) -> None:
     """Write a message to the house log (syslog facility local7 priority
     info) by calling /usr/bin/logger.  This is pretty hacky but used
     by a bunch of code.  Another way to do this would be to use
-    --logging_syslog and --logging_syslog_facility but I can't
-    actually say that's easier.
-
+    :code:`--logging_syslog` and :code:`--logging_syslog_facility` but
+    I can't actually say that's easier.
     """
     message = message.replace("'", "'\"'\"'")
     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")