From 2a709c122162d26397672ad90880554b335aca8f Mon Sep 17 00:00:00 2001 From: Arthur Goldberg Date: Wed, 25 Dec 2019 12:44:18 -0500 Subject: [PATCH] add unittests to ensure that FastLogger of the default de_sim.debug.file logger at 'debug' level is not active; change names of handlers and loggers in examples & testing to prevent conflicts; BE CAREFUL: loggers AND handlers ARE ALL GLOBAL!; make config/core.py debuggable --- de_sim/config/core.py | 7 +++--- de_sim/config/debug.default.cfg | 8 +++---- de_sim/utilities.py | 6 ++--- examples/config/debug.default.cfg | 12 +++++----- examples/phold.py | 2 +- tests/config/test_core.py | 11 ++++++--- tests/examples/test_random_state_variable.py | 8 +++---- tests/fixtures/config/debug.default.cfg | 24 +++++++++++++++++++ .../perf_results/de_sim_performance_log.txt | 9 +++++++ tests/test_simulation_engine.py | 1 + tests/test_utilities.py | 21 ++++++++++++++++ 11 files changed, 85 insertions(+), 24 deletions(-) create mode 100644 tests/fixtures/config/debug.default.cfg diff --git a/de_sim/config/core.py b/de_sim/config/core.py index 03e9abf..43f4403 100644 --- a/de_sim/config/core.py +++ b/de_sim/config/core.py @@ -35,18 +35,19 @@ def get_config(extra=None): return wc_utils.config.core.ConfigManager(paths).get_config(extra=extra) -def get_debug_logs_config(extra=None): +def get_debug_logs_config(extra=None, cfg_path=('de_sim', 'config/debug.default.cfg')): """ Get debug logs configuration Args: extra (:obj:`dict`, optional): additional configuration to override + cfg_path (:obj:`str`, optional): path to the debug logs config file Returns: :obj:`configobj.ConfigObj`: nested dictionary with the configuration settings loaded from the - configuration source(s). + configuration source(s). """ paths = wc_utils.debug_logs.config.paths.deepcopy() - paths.default = pkg_resources.resource_filename('de_sim', 'config/debug.default.cfg') + paths.default = pkg_resources.resource_filename(*cfg_path) paths.user = ( 'de_sim.debug.cfg', # todo: fix: this cfg file doesn't alter the log level: diff --git a/de_sim/config/debug.default.cfg b/de_sim/config/debug.default.cfg index 2a92c22..78c6459 100644 --- a/de_sim/config/debug.default.cfg +++ b/de_sim/config/debug.default.cfg @@ -6,15 +6,15 @@ filename = ~/.wc/log/de_sim.debug.log level = info + [[[debug.console]]] + class = StdOutHandler + level = info + [[[plot.file]]] class = FileHandler filename = ~/.wc/log/de_sim.plot.log level = info - [[[debug.console]]] - class = StdOutHandler - level = info - [[loggers]] [[[de_sim.debug.file]]] template = {timestamp}; {name:s}; {level:s}; {source}:{function:s}:{line:d}; {sim_time:f}; {message:s} diff --git a/de_sim/utilities.py b/de_sim/utilities.py index 1c57598..c6ecfa6 100644 --- a/de_sim/utilities.py +++ b/de_sim/utilities.py @@ -6,9 +6,9 @@ :License: MIT """ from abc import ABCMeta, abstractmethod -from progressbar.bar import ProgressBar -from progressbar import widgets from logging2 import LogLevel +from progressbar import widgets +from progressbar.bar import ProgressBar class ConcreteABCMeta(ABCMeta): @@ -111,10 +111,10 @@ def active_logger(logger, level_used): Returns: :obj:`bool`: return `True` if the `logger` is active, `False` otherwise """ - active = False if level_used not in FastLogger.LOG_LEVELS: raise ValueError("bad level '{}'".format(level_used)) log_level = LogLevel[level_used] + active = False for handler in logger.handlers: if handler.min_level <= log_level: active = True diff --git a/examples/config/debug.default.cfg b/examples/config/debug.default.cfg index 0f51e64..ebe34ee 100644 --- a/examples/config/debug.default.cfg +++ b/examples/config/debug.default.cfg @@ -1,20 +1,20 @@ # log config for the wc simulator examples [debug_logs] [[handlers]] - [[[debug.file]]] + [[[debug.example.file]]] class = FileHandler filename = ~/.wc/log/de_sim.debug.log level = debug - [[[debug.console]]] + [[[debug.example.console]]] class = StdOutHandler level = info [[loggers]] - [[[de_sim.debug.file]]] + [[[de_sim.debug.example.file]]] template = {timestamp}; {name:s}; {level:s}; {source}:{function:s}:{line:d}; {message:s} - handler = debug.file + handler = debug.example.file - [[[de_sim.debug.console]]] + [[[de_sim.debug.example.console]]] template = {timestamp}; {name:s}; {level:s}; {source}:{function:s}:{line:d}; {message:s} - handler = debug.console + handler = debug.example.console diff --git a/examples/phold.py b/examples/phold.py index 48772e2..f34c922 100755 --- a/examples/phold.py +++ b/examples/phold.py @@ -84,7 +84,7 @@ def get_state(self): return str(self.args) def log_debug_msg(self, msg): - log = debug_logs.get_log('de_sim.debug.console') + log = debug_logs.get_log('de_sim.debug.example.console') log.debug(msg, sim_time=self.time, local_call_depth=1) event_handlers = [(sim_msg_type, 'handle_simulation_event') for sim_msg_type in MESSAGE_TYPES] diff --git a/tests/config/test_core.py b/tests/config/test_core.py index 8bed7db..8bdfd0e 100644 --- a/tests/config/test_core.py +++ b/tests/config/test_core.py @@ -12,6 +12,7 @@ from de_sim.config import core from wc_utils.debug_logs.core import DebugLogsManager + class TestCore(unittest.TestCase): def test_get_config(self): @@ -22,11 +23,15 @@ def test_get_config(self): def test_get_debug_logs(self): # test conf hierarchy from debug.default.cfg - c = core.get_debug_logs_config() + config = core.get_debug_logs_config() for key in ['debug_logs', 'handlers', 'debug.console', 'level']: - self.assertTrue(key in c) - c = c[key] + self.assertTrue(key in config) + config = config[key] debug_log_manager = core.get_debug_logs() self.assertTrue(isinstance(debug_log_manager, DebugLogsManager)) self.assertTrue(isinstance(debug_log_manager.get_log('de_sim.debug.file'), logging2.loggers.Logger)) + debug_config = core.get_debug_logs_config(cfg_path=('tests', 'fixtures/config/debug.default.cfg')) + debug_logs = debug_config['debug_logs'] + self.assertEqual(set(debug_logs['loggers']), set(['de_sim.debug.testing.file', 'de_sim.debug.testing.console'])) + self.assertEqual(set(debug_logs['handlers']), set(['debug.testing.file', 'debug.testing.console'])) diff --git a/tests/examples/test_random_state_variable.py b/tests/examples/test_random_state_variable.py index e860668..e4f28c0 100644 --- a/tests/examples/test_random_state_variable.py +++ b/tests/examples/test_random_state_variable.py @@ -11,7 +11,7 @@ from argparse import Namespace from examples.random_state_variable import RunRandomStateVariableSimulation -from de_sim.config import core +from examples.config import core class TestRandomStateVariableSimulation(unittest.TestCase): @@ -19,13 +19,13 @@ class TestRandomStateVariableSimulation(unittest.TestCase): def setUp(self): # turn off console logging self.config = core.get_debug_logs_config() - self.console_level = self.config['debug_logs']['handlers']['debug.console']['level'] - self.config['debug_logs']['handlers']['debug.console']['level'] = 'error' + self.console_level = self.config['debug_logs']['handlers']['debug.example.console']['level'] + self.config['debug_logs']['handlers']['debug.example.console']['level'] = 'error' warnings.simplefilter("ignore") def tearDown(self): # restore console logging - self.config['debug_logs']['handlers']['debug.console']['level'] = self.console_level + self.config['debug_logs']['handlers']['debug.example.console']['level'] = self.console_level def test_random_state_variable_simulation(self): with CaptureOutput(relay=False): diff --git a/tests/fixtures/config/debug.default.cfg b/tests/fixtures/config/debug.default.cfg new file mode 100644 index 0000000..b0eabcc --- /dev/null +++ b/tests/fixtures/config/debug.default.cfg @@ -0,0 +1,24 @@ +# log config for the discrete event simulator, de_sim +[debug_logs] + [[handlers]] + [[[debug.testing.file]]] + class = FileHandler + filename = ~/tmp/.wc/log/de_sim.debug.testing.log + level = info + + [[[debug.testing.console]]] + class = StdOutHandler + level = warning + + [[loggers]] + [[[de_sim.debug.testing.file]]] + template = {timestamp}; {name:s}; {level:s}; {source}:{function:s}:{line:d}; {sim_time:f}; {message:s} + handler = debug.testing.file + [[[[additional_context]]]] + sim_time = get_sim_time + + [[[de_sim.debug.testing.console]]] + template = {timestamp}; {name:s}; {level:s}; {source}:{function:s}:{line:d}; {sim_time:f}; {message:s} + handler = debug.testing.console + [[[[additional_context]]]] + sim_time = get_sim_time diff --git a/tests/results/perf_results/de_sim_performance_log.txt b/tests/results/perf_results/de_sim_performance_log.txt index 2a2455b..28e9023 100644 --- a/tests/results/perf_results/de_sim_performance_log.txt +++ b/tests/results/perf_results/de_sim_performance_log.txt @@ -43,3 +43,12 @@ Performance summary on 2019-12-24 1024 102400 8.763 11686 4096 409600 37.809 10833 +Performance summary on 2019-12-25 +#sim obs # events run time (s) events/s +4 400 0.019 21361 +16 1600 0.121 13175 +64 6400 0.520 12306 +256 25600 2.849 8986 +1024 102400 8.728 11733 +4096 409600 39.069 10484 + diff --git a/tests/test_simulation_engine.py b/tests/test_simulation_engine.py index d631853..c19bfcd 100644 --- a/tests/test_simulation_engine.py +++ b/tests/test_simulation_engine.py @@ -382,6 +382,7 @@ def test_suspend_restore_logging(self): fast_logger = FastLogger(debug_logs.get_log(log_name), 'debug') self.assertEqual(fast_logger.get_level(), level_by_logger[log_name]) + # @unittest.skip("takes 3 to 5 min.") def test_performance(self): existing_levels = self.suspend_logging(self.log_names) self.simulator_for_perf_tests = SimulationEngine() diff --git a/tests/test_utilities.py b/tests/test_utilities.py index e68a675..45b1ffb 100644 --- a/tests/test_utilities.py +++ b/tests/test_utilities.py @@ -5,6 +5,7 @@ :Copyright: 2018, Karr Lab :License: MIT """ + from abc import ABCMeta, abstractmethod from capturer import CaptureOutput from logging2 import Logger, LogLevel, StdOutHandler @@ -13,6 +14,7 @@ from de_sim.utilities import ConcreteABCMeta, SimulationProgressBar, FastLogger from de_sim.config import core +from wc_utils.debug_logs.core import DebugLogsManager class AbstractBase(object, metaclass=ABCMeta): @@ -110,3 +112,22 @@ def test_fast_log(self): message = 'hi mom' fast_logger.fast_log(message) self.assertTrue(capturer.get_text().endswith(message)) + + def test_config(self): + debug_config = core.get_debug_logs_config(cfg_path=('tests', 'fixtures/config/debug.default.cfg')) + debug_log_manager = DebugLogsManager().setup_logs(debug_config) + + file_logger = debug_log_manager.logs['de_sim.debug.testing.file'] + self.assertFalse(FastLogger(file_logger, 'debug').active) + self.assertTrue(FastLogger(file_logger, 'info').active) + + console_logger = debug_log_manager.logs['de_sim.debug.testing.console'] + self.assertFalse(FastLogger(console_logger, 'debug').active) + self.assertFalse(FastLogger(console_logger, 'info').active) + self.assertTrue(FastLogger(console_logger, 'warning').active) + + debug_config = core.get_debug_logs_config() + debug_log_manager = DebugLogsManager().setup_logs(debug_config) + + file_logger = debug_log_manager.logs['de_sim.debug.file'] + self.assertFalse(FastLogger(file_logger, 'debug').active)