Cleanup logging module.

diff --git a/logging_utils.py b/logging_utils.py
index 005761a5cccf3d5e90bd9ff3020543aed6dcc59c..de69046c30a82914b04e288982fcf93455fcb965 100644 (file)
--- a/logging_utils.py
+++ b/logging_utils.py
@@ -10,12 +10,12 @@ import io
 import logging
 from logging.handlers import RotatingFileHandler, SysLogHandler
 import os
 import logging
 from logging.handlers import RotatingFileHandler, SysLogHandler
 import os

-import pytz

 import random
 import sys
 from typing import Callable, Iterable, Mapping, Optional
 
 from overrides import overrides
 import random
 import sys
 from typing import Callable, Iterable, Mapping, Optional
 
 from overrides import overrides

+import pytz

 
 # This module is commonly used by others in here and should avoid
 # taking any unnecessary dependencies back on them.
 
 # This module is commonly used by others in here and should avoid
 # taking any unnecessary dependencies back on them.


@@ -115,13 +115,13 @@ cfg.add_argument(
     help='logging.info also prints to stdout.'
 )
 cfg.add_argument(
     help='logging.info also prints to stdout.'
 )
 cfg.add_argument(

-    '--logging_squelch_repeats_enabled',
+    '--logging_squelch_repeats',

     action=argparse_utils.ActionNoYes,
     default=True,
     help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?'
 )
 cfg.add_argument(
     action=argparse_utils.ActionNoYes,
     default=True,
     help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?'
 )
 cfg.add_argument(

-    '--logging_probabilistically_enabled',
+    '--logging_probabilistically',

     action=argparse_utils.ActionNoYes,
     default=True,
     help='Do we allow probabilistic logging (for code that wants it) or should we always log?'
     action=argparse_utils.ActionNoYes,
     default=True,
     help='Do we allow probabilistic logging (for code that wants it) or should we always log?'


@@ -144,7 +144,7 @@ cfg.add_argument(
     )
 )
 cfg.add_argument(
     )
 )
 cfg.add_argument(

-    '--logging_clear_spammy_handlers',
+    '--logging_clear_preexisting_handlers',

     action=argparse_utils.ActionNoYes,
     default=False,
     help=(
     action=argparse_utils.ActionNoYes,
     default=False,
     help=(


@@ -155,8 +155,8 @@ cfg.add_argument(
     )
 )
 
     )
 )
 

-

 built_in_print = print
 built_in_print = print

+logging_initialized = False

 
 
 def function_identifier(f: Callable) -> str:
 
 
 def function_identifier(f: Callable) -> str:


@@ -214,7 +214,11 @@ class SquelchRepeatedMessagesFilter(logging.Filter):
 
     This filter only affects logging messages that repeat more than
     a threshold number of times from functions that are tagged with
 
     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.
+    the @logging_utils.squelched_logging_ok decorator; others are
+    ignored.
+
+    This functionality is enabled by default but can be disabled via
+    the --no_logging_squelch_repeats commandline flag.

 
     """
     def __init__(self) -> None:
 
     """
     def __init__(self) -> None:


@@ -234,8 +238,8 @@ class SquelchRepeatedMessagesFilter(logging.Filter):
 
 
 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
 
 
 class DynamicPerScopeLoggingLevelFilter(logging.Filter):

-    """Only interested in seeing logging messages from an allow list of
-    module names or module:function names.  Block others.
+    """This filter only allows logging messages from an allow list of
+    module names or module:function names.  Blocks others.

 
     """
     @staticmethod
 
     """
     @staticmethod


@@ -322,6 +326,10 @@ def logging_is_probabilistic(probability_of_logging: float) -> Callable:
     (i.e. they do not always unconditionally log) but rather are
     probabilistic (i.e. they log N% of the time randomly).
 
     (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.
+

     This affects *ALL* logging statements within the marked function.
 
     """
     This affects *ALL* logging statements within the marked function.
 
     """


@@ -365,7 +373,8 @@ class OnlyInfoFilter(logging.Filter):
 
 class MillisecondAwareFormatter(logging.Formatter):
     """
 
 class MillisecondAwareFormatter(logging.Formatter):
     """

-    A formatter for adding milliseconds to log messages.
+    A formatter for adding milliseconds to log messages which, for
+    whatever reason, the default python logger doesn't do.

 
     """
     converter = datetime.datetime.fromtimestamp
 
     """
     converter = datetime.datetime.fromtimestamp


@@ -384,15 +393,20 @@ class MillisecondAwareFormatter(logging.Formatter):
 
 
 def initialize_logging(logger=None) -> logging.Logger:
 
 
 def initialize_logging(logger=None) -> logging.Logger:

-    assert config.has_been_parsed()
+    global logging_initialized
+    if logging_initialized:
+        return
+    logging_initialized = True
+

     if logger is None:
     if logger is None:

-        logger = logging.getLogger()       # Root logger
+        logger = logging.getLogger()

 
 

-    spammy_handlers = 0
-    if config.config['logging_clear_spammy_handlers']:
+    preexisting_handlers_count = 0
+    assert config.has_been_parsed()
+    if config.config['logging_clear_preexisting_handlers']:

         while logger.hasHandlers():
             logger.removeHandler(logger.handlers[0])
         while logger.hasHandlers():
             logger.removeHandler(logger.handlers[0])

-            spammy_handlers += 1
+            preexisting_handlers_count += 1

 
     if config.config['logging_config_file'] is not None:
         logging.config.fileConfig('logging.conf')
 
     if config.config['logging_config_file'] is not None:
         logging.config.fileConfig('logging.conf')


@@ -416,7 +430,6 @@ def initialize_logging(logger=None) -> logging.Logger:
             fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
         else:
             fmt = '%(levelname).1s:%(asctime)s: %(message)s'
             fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
         else:
             fmt = '%(levelname).1s:%(asctime)s: %(message)s'

-

     if config.config['logging_debug_threads']:
         fmt = f'%(process)d.%(thread)d|{fmt}'
     if config.config['logging_debug_modules']:
     if config.config['logging_debug_threads']:
         fmt = f'%(process)d.%(thread)d|{fmt}'
     if config.config['logging_debug_modules']:


@@ -471,11 +484,11 @@ def initialize_logging(logger=None) -> logging.Logger:
         handler.addFilter(OnlyInfoFilter())
         logger.addHandler(handler)
 
         handler.addFilter(OnlyInfoFilter())
         logger.addHandler(handler)
 

-    if config.config['logging_squelch_repeats_enabled']:
+    if config.config['logging_squelch_repeats']:

         for handler in handlers:
             handler.addFilter(SquelchRepeatedMessagesFilter())
 
         for handler in handlers:
             handler.addFilter(SquelchRepeatedMessagesFilter())
 

-    if config.config['logging_probabilistically_enabled']:
+    if config.config['logging_probabilistically']:

         for handler in handlers:
             handler.addFilter(ProbabilisticFilter())
 
         for handler in handlers:
             handler.addFilter(ProbabilisticFilter())
 


@@ -502,36 +515,56 @@ def initialize_logging(logger=None) -> logging.Logger:
             built_in_print(*arg, **kwarg)
         builtins.print = print_and_also_log
 
             built_in_print(*arg, **kwarg)
         builtins.print = print_and_also_log
 

-    logger.debug(f'Initialized logger; default logging level is {default_logging_level}.')
-    if config.config['logging_clear_spammy_handlers'] and spammy_handlers > 0:
+    # At this point the logger is ready, handlers are set up,
+    # etc... so log about the logging configuration.
+
+    level_name = logging._levelToName.get(default_logging_level, str(default_logging_level))
+    logger.debug(
+        f'Initialized global logging; default logging level is {level_name}.'
+    )
+    if config.config['logging_clear_preexisting_handlers'] and preexisting_handlers_count > 0:

         logger.warning(
         logger.warning(

-            'Logging cleared {spammy_handlers} global handlers (--logging_clear_spammy_handlers)'
+            'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'

         )
         )

-    logger.debug(f'Logging format is "{fmt}"')
+    logger.debug(f'Logging format specification is "{fmt}"')
+    if config.config['logging_debug_threads']:
+        logger.debug('...Logging format spec captures tid/pid (--logging_debug_threads)')
+    if config.config['logging_debug_modules']:
+        logger.debug('...Logging format spec captures files/functions/lineno (--logging_debug_modules)')

     if config.config['logging_syslog']:
     if config.config['logging_syslog']:

-        logger.debug(f'Logging to syslog as {facility_name} with normal severity mapping')
+        logger.debug(f'Logging to syslog as {facility_name} with priority mapping based on level')

     if config.config['logging_filename']:
     if config.config['logging_filename']:

-        logger.debug(f'Logging to filename {config.config["logging_filename"]} with rotation')
+        logger.debug(f'Logging to filename {config.config["logging_filename"]}')
+        logger.debug(f'...with {config.config["logging_filename_maxsize"]} bytes max file size.')
+        logger.debug(f'...and {config.config["logging_filename_count"]} rotating backup file count.')

     if config.config['logging_console']:
     if config.config['logging_console']:

-        logger.debug(f'Logging to the console.')
+        logger.debug('Logging to the console (stderr).')

     if config.config['logging_info_is_print']:
         logger.debug(
             'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
         )
     if config.config['logging_info_is_print']:
         logger.debug(
             'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
         )

-    if config.config['logging_squelch_repeats_enabled']:
+    if config.config['logging_squelch_repeats']:
+        logger.debug(
+            'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
+        )
+    else:

         logger.debug(
         logger.debug(

-            'Logging code is allowed to request repeated messages be squelched (--logging_squelch_repeats_enabled)'
+            'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'

         )
         )

-    if config.config['logging_probabilistically_enabled']:
+    if config.config['logging_probabilistically']:

         logger.debug(
         logger.debug(

-            'Logging code is allowed to request probabilistic logging (--logging_probabilistically_enabled)'
+            'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
+        )
+    else:
+        logger.debug(
+            'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'

         )
     if config.config['lmodule']:
         logger.debug(
             'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
         )
     if config.config['logging_captures_prints']:
         )
     if config.config['lmodule']:
         logger.debug(
             'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
         )
     if config.config['logging_captures_prints']:

-        logger.debug('Logging will capture printed messages (--logging_captures_prints)')
+        logger.debug('Logging will capture printed data as logger.info messages (--logging_captures_prints)')

     return logger
 
 
     return logger
 
 


@@ -541,8 +574,11 @@ def get_logger(name: str = ""):
 
 
 def tprint(*args, **kwargs) -> None:
 
 
 def tprint(*args, **kwargs) -> None:

-    """Legacy function for printing a message augmented with thread id."""
+    """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
         print(f'{current_thread_id()}', end="")
     if config.config['logging_debug_threads']:
         from thread_utils import current_thread_id
         print(f'{current_thread_id()}', end="")


@@ -552,8 +588,11 @@ def tprint(*args, **kwargs) -> None:
 
 
 def dprint(*args, **kwargs) -> None:
 
 
 def dprint(*args, **kwargs) -> None:

-    """Legacy function used to print to stderr."""
+    """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)
 
 
     print(*args, file=sys.stderr, **kwargs)
 
 


@@ -561,7 +600,8 @@ class OutputMultiplexer(object):
     """
     A class that broadcasts printed messages to several sinks (including
     various logging levels, different files, different file handles,
     """
     A class that broadcasts printed messages to several sinks (including
     various logging levels, different files, different file handles,

-    the house log, etc...)
+    the house log, etc...).  See also OutputMultiplexerContext for an
+    easy usage pattern.

 
     """
     class Destination(enum.IntEnum):
 
     """
     class Destination(enum.IntEnum):


@@ -720,8 +760,13 @@ class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
 
 
 def hlog(message: str) -> None:
 
 
 def hlog(message: str) -> None:

-    """Write a message to the house log."""
+    """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.

 
 

+    """

     message = message.replace("'", "'\"'\"'")
     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
 
     message = message.replace("'", "'\"'\"'")
     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")