Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

add testing environment indicator to the logger #2042

Closed
wants to merge 2 commits into from
Closed

add testing environment indicator to the logger #2042

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
51f0814
formatting
dsweber2 Aug 29, 2024
8ee933e
add testing environment indicator to the logger
dsweber2 Aug 29, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
63 changes: 28 additions & 35 deletions _delphi_utils_python/delphi_utils/logger.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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):
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
def get_structured_logger(name=__name__, filename=None, log_exceptions=True, is_real=True):
def get_structured_logger(name=__name__, filename=None, log_exceptions=True, *, test_mode=False):

and then below:

cache_logger_on_first_use=not(test_mode),

This name (and inverted truth value) makes the purpose of the argument clearer, and the * in the arguments list ensures its only ever triggered explicitly.

"""Create a new structlog logger.

Use the logger returned from this in indicator code using the standard
Expand All @@ -66,17 +63,17 @@ 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:
log_level = logging.DEBUG
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."""
Expand Down Expand Up @@ -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=is_real,
dshemetov marked this conversation as resolved.
Show resolved Hide resolved
)

# Create the underlying python logger and wrap it with structlog
Expand All @@ -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.

Expand All @@ -149,15 +146,15 @@ 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):
"""Create SubLogger with a bound 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])

Expand All @@ -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
Expand All @@ -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)
Expand All @@ -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
Expand Down