From 55cbe278b9842b7135ac94344ecd2c73704b489b Mon Sep 17 00:00:00 2001 From: dsweber2 Date: Thu, 29 Aug 2024 11:50:14 -0500 Subject: [PATCH] add testing environment indicator to the logger --- _delphi_utils_python/delphi_utils/logger.py | 63 +++++++++------------ 1 file changed, 28 insertions(+), 35 deletions(-) diff --git a/_delphi_utils_python/delphi_utils/logger.py b/_delphi_utils_python/delphi_utils/logger.py index c0e4502a8..120d23bbf 100644 --- a/_delphi_utils_python/delphi_utils/logger.py +++ b/_delphi_utils_python/delphi_utils/logger.py @@ -23,8 +23,7 @@ def handle_exceptions(logger): """Handle exceptions using the provided logger.""" def exception_handler(scope, etype, value, traceback): - logger.exception("Top-level exception occurred", - scope=scope, exc_info=(etype, value, traceback)) + logger.exception("Top-level exception occurred", scope=scope, exc_info=(etype, value, traceback)) def sys_exception_handler(etype, value, traceback): exception_handler("sys", etype, value, traceback) @@ -33,21 +32,19 @@ def threading_exception_handler(args): if args.exc_type == SystemExit and args.exc_value.code == 0: # `sys.exit(0)` is considered "successful termination": # https://docs.python.org/3/library/sys.html#sys.exit - logger.debug("normal thread exit", thread=args.thread, - stack="".join( - format_exception( - args.exc_type, args.exc_value, args.exc_traceback))) + logger.debug( + "normal thread exit", + thread=args.thread, + stack="".join(format_exception(args.exc_type, args.exc_value, args.exc_traceback)), + ) else: - exception_handler(f"thread: {args.thread}", - args.exc_type, args.exc_value, args.exc_traceback) + exception_handler(f"thread: {args.thread}", args.exc_type, args.exc_value, args.exc_traceback) sys.excepthook = sys_exception_handler threading.excepthook = threading_exception_handler -def get_structured_logger(name=__name__, - filename=None, - log_exceptions=True): +def get_structured_logger(name=__name__, filename=None, log_exceptions=True, is_real=True): """Create a new structlog logger. Use the logger returned from this in indicator code using the standard @@ -66,6 +63,9 @@ def get_structured_logger(name=__name__, name: Name to use for logger (included in log lines), __name__ from caller is a good choice. filename: An (optional) file to write log output. + log_exceptions: should we log exceptions? + is_real: is this logger *not* in a testing environment? Used to avoid + setting features that interfere with testing the logging output """ # Set the underlying logging configuration if "LOG_DEBUG" in os.environ: @@ -73,10 +73,7 @@ def get_structured_logger(name=__name__, else: log_level = logging.INFO - logging.basicConfig( - format="%(message)s", - level=log_level, - handlers=[logging.StreamHandler()]) + logging.basicConfig(format="%(message)s", level=log_level, handlers=[logging.StreamHandler()]) def add_pid(_logger, _method_name, event_dict): """Add current PID to the event dict.""" @@ -115,7 +112,7 @@ def add_pid(_logger, _method_name, event_dict): # Use a standard wrapper class for utilities like log.warning() wrapper_class=structlog.stdlib.BoundLogger, # Cache the logger - cache_logger_on_first_use=True, + cache_logger_on_first_use=not_testing, ) # Create the underlying python logger and wrap it with structlog @@ -131,7 +128,7 @@ def add_pid(_logger, _method_name, event_dict): return logger -class LoggerThread(): +class LoggerThread: """ A construct to use a logger from multiprocessing workers/jobs. @@ -149,7 +146,7 @@ class LoggerThread(): docs.python.org/3/howto/logging-cookbook.html#logging-to-a-single-file-from-multiple-processes """ - class SubLogger(): + class SubLogger: """MP-safe logger-like interface to convey log messages to a listening LoggerThread.""" def __init__(self, queue): @@ -157,7 +154,7 @@ def __init__(self, queue): self.queue = queue def _log(self, level, *args, **kwargs): - kwargs_plus = {'sub_pid': multiprocessing.current_process().pid} + kwargs_plus = {"sub_pid": multiprocessing.current_process().pid} kwargs_plus.update(kwargs) self.queue.put([level, args, kwargs_plus]) @@ -181,7 +178,6 @@ def critical(self, *args, **kwargs): """Log a CRITICAL level message.""" self._log(logging.CRITICAL, *args, **kwargs) - def get_sublogger(self): """Retrieve SubLogger for this LoggerThread.""" return self.sublogger @@ -195,25 +191,22 @@ def __init__(self, logger, q=None): self.msg_queue = multiprocessing.Queue() def logger_thread_worker(): - logger.info('thread started') + logger.info("thread started") while True: msg = self.msg_queue.get() - if msg == 'STOP': - logger.debug('received stop signal') + if msg == "STOP": + logger.debug("received stop signal") break level, args, kwargs = msg - if level in [logging.DEBUG, logging.INFO, logging.WARNING, - logging.ERROR, logging.CRITICAL]: + if level in [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL]: logger.log(level, *args, **kwargs) else: - logger.error('received unknown logging level! exiting...', - level=level, args_kwargs=(args, kwargs)) + logger.error("received unknown logging level! exiting...", level=level, args_kwargs=(args, kwargs)) break - logger.debug('stopping thread') + logger.debug("stopping thread") - self.thread = threading.Thread(target=logger_thread_worker, - name="LoggerThread__"+logger.name) - logger.debug('starting thread') + self.thread = threading.Thread(target=logger_thread_worker, name="LoggerThread__" + logger.name) + logger.debug("starting thread") self.thread.start() self.sublogger = LoggerThread.SubLogger(self.msg_queue) @@ -222,13 +215,13 @@ def logger_thread_worker(): def stop(self): """Terminate this LoggerThread.""" if not self.running: - self.logger.warning('thread already stopped') + self.logger.warning("thread already stopped") return - self.logger.debug('sending stop signal') - self.msg_queue.put('STOP') + self.logger.debug("sending stop signal") + self.msg_queue.put("STOP") self.thread.join() self.running = False - self.logger.info('thread stopped') + self.logger.info("thread stopped") @contextlib.contextmanager