Fixing logging threshold issue for execution tests.

It turns out that the root logger needed to have its level set, as the
root logger's level was propagating to the others.  This is now present
in the context manager, and log messages are being captured as expected
in the tests. RE:#651
This commit is contained in:
James Douglass 2021-09-23 10:31:54 -07:00
parent 4a9400b724
commit 344a8caf91
1 changed files with 26 additions and 15 deletions

View File

@ -1620,30 +1620,42 @@ class OpenWorkspaceTest(_QtTest):
@contextlib.contextmanager @contextlib.contextmanager
def _capture_logging_messages(logger, records): def _capture_logging_messages(logger):
"""Capture logging messages and return them as a list. """Capture logging messages and return them as a list.
This context manager also sets the root logger's level to
``logging.NOTSET`` and restores the former log level on completion of the
context being managed.
Args: Args:
logger (logging.Logger): A logger instance from python's logging system logger (logging.Logger): A logger instance from python's logging system
to which log records should be captured. from which log records should be captured.
records (list): A list to which log records should be appended.
Returns: Returns:
``None``.""" ``None``."""
# The root logger has a default level of WARNING, but for tests we
# want to capture everything.
root_logger = logging.getLogger()
root_logger_prior_level = root_logger.level
root_logger.setLevel(logging.NOTSET)
log_queue = queue.Queue() log_queue = queue.Queue()
log_queue_handler = logging.handlers.QueueHandler(log_queue) log_queue_handler = logging.handlers.QueueHandler(log_queue)
log_queue_handler.setLevel(logging.NOTSET) # capture all logging log_queue_handler.setLevel(logging.NOTSET) # capture all logging
logger.addHandler(log_queue_handler) logger.addHandler(log_queue_handler)
yield
log_queue_handler.flush() records = []
log_records = [] try:
yield records
finally:
# No matter what happens, always restore root logger level.
root_logger.setLevel(root_logger_prior_level)
try: try:
while True: while True:
records.append(log_queue.get_nowait()) records.append(log_queue.get_nowait())
except queue.Empty: except queue.Empty:
logger.removeHandler(log_queue_handler) logger.removeHandler(log_queue_handler)
pass
class ExecutionTest(_QtTest): class ExecutionTest(_QtTest):
@ -1674,16 +1686,17 @@ class ExecutionTest(_QtTest):
# register the callback with the finished signal. # register the callback with the finished signal.
executor.finished.connect(callback) executor.finished.connect(callback)
log_records = [] with _capture_logging_messages(execution_logger) as log_records:
with _capture_logging_messages(execution_logger, log_records):
executor.start() executor.start()
thread_event.set() thread_event.set()
executor.join() executor.join()
if self.qt_app.hasPendingEvents(): if self.qt_app.hasPendingEvents():
self.qt_app.processEvents() self.qt_app.processEvents()
callback.assert_called_once() callback.assert_called_once()
target.assert_called_once() target.assert_called_once()
target.assert_called_with(*args, **kwargs) target.assert_called_with(*args, **kwargs)
self.assertEqual(len(log_records), 0) self.assertEqual(len(log_records), 0)
def test_executor_exception(self): def test_executor_exception(self):
@ -1713,13 +1726,13 @@ class ExecutionTest(_QtTest):
# register the callback with the finished signal. # register the callback with the finished signal.
executor.finished.connect(callback) executor.finished.connect(callback)
log_records = [] with _capture_logging_messages(execution_logger) as log_records:
with _capture_logging_messages(execution_logger, log_records):
executor.start() executor.start()
thread_event.set() thread_event.set()
executor.join() executor.join()
if self.qt_app.hasPendingEvents(): if self.qt_app.hasPendingEvents():
self.qt_app.processEvents() self.qt_app.processEvents()
callback.assert_called_once() callback.assert_called_once()
target.assert_called_once() target.assert_called_once()
target.assert_called_with(*args, **kwargs) target.assert_called_with(*args, **kwargs)
@ -1729,11 +1742,9 @@ class ExecutionTest(_QtTest):
'Some demo exception') 'Some demo exception')
self.assertTrue(isinstance(executor.traceback, basestring)) self.assertTrue(isinstance(executor.traceback, basestring))
print(log_records) self.assertEqual(len(log_records), 2)
self.assertEqual(len(log_records), 1)
self.assertIn('failed with exception', log_records[0].msg) self.assertIn('failed with exception', log_records[0].msg)
# There is supposed to be a second logger message here, but I can't self.assertIn('Execution finished', log_records[1].msg)
# figure out why it isn't being added to the queue.
def test_default_args(self): def test_default_args(self):
from natcap.invest.ui.execution import Executor from natcap.invest.ui.execution import Executor