add unittests to ensure that FastLogger of the default de_sim.debug.f…

…ile 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
KarrLab · Dec 25, 2019 · 2a709c1 · 2a709c1
1 parent a24c3d5
commit 2a709c1
Show file tree

Hide file tree

Showing 11 changed files with 85 additions and 24 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -11,21 +11,21 @@
 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):
 
     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
@@ -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
@@ -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
@@ -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
@@ -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)