Merge pull request #2595 from effigies/fix/debug_mode

 FIX: Update logging levels in enable_debug_mode

Author: effigies

doc/users/config_file.rst

@@ -237,16 +237,23 @@ Debug configuration
 
 To enable debug mode, one can insert the following lines::
 
-  from nipype import config, logging
+  from nipype import config
   config.enable_debug_mode()
-  logging.update_logging(config)
 
 In this mode the following variables are set::
 
   config.set('execution', 'stop_on_first_crash', 'true')
   config.set('execution', 'remove_unnecessary_outputs', 'false')
+  config.set('execution', 'keep_inputs', 'true')
   config.set('logging', 'workflow_level', 'DEBUG')
   config.set('logging', 'interface_level', 'DEBUG')
+  config.set('logging', 'utils_level', 'DEBUG')
+
+The primary loggers (``workflow``, ``interface`` and ``utils``) are also reset
+to level ``DEBUG``.
+You may wish to adjust these manually using::
 
+  from nipype import logging
+  logging.getLogger(<logger>).setLevel(<level>)
 
 .. include:: ../links_names.txt

doc/users/debug.rst

@@ -20,15 +20,17 @@ performance issues.
       from nipype import config
       config.enable_debug_mode()
 
-   as the first import of your nipype script. To enable debug logging use::
-
-       from nipype import logging
-       logging.update_logging(config)
+   as the first import of your nipype script.
 
    .. note::
 
-     Turning on debug will rerun your workflows and will rerun them after debugging
-     is turned off.
+     Turning on debug will rerun your workflows and will rerun them after
+     debugging is turned off.
+
+     Turning on debug mode will also override log levels specified elsewhere,
+     such as in the nipype configuration.
+     ``workflow``, ``interface`` and ``utils`` loggers will all be set to
+     level ```DEBUG``.
 
 #. There are several configuration options that can help with debugging. See
    :ref:`config_file` for more details::

nipype/utils/config.py

@@ -147,11 +147,14 @@ def set_default_config(self):
 
     def enable_debug_mode(self):
         """Enables debug configuration"""
+        from .. import logging
         self._config.set('execution', 'stop_on_first_crash', 'true')
         self._config.set('execution', 'remove_unnecessary_outputs', 'false')
         self._config.set('execution', 'keep_inputs', 'true')
         self._config.set('logging', 'workflow_level', 'DEBUG')
         self._config.set('logging', 'interface_level', 'DEBUG')
+        self._config.set('logging', 'utils_level', 'DEBUG')
+        logging.update_logging(self._config)
 
     def set_log_dir(self, log_dir):
         """Sets logging directory

nipype/utils/tests/test_config.py

@@ -241,3 +241,52 @@ def test_cwd_cached(tmpdir):
     oldcwd = config.cwd
     tmpdir.chdir()
     assert config.cwd == oldcwd
+
+
+def test_debug_mode():
+    from ... import logging
+
+    sofc_config = config.get('execution', 'stop_on_first_crash')
+    ruo_config = config.get('execution', 'remove_unnecessary_outputs')
+    ki_config = config.get('execution', 'keep_inputs')
+    wf_config = config.get('logging', 'workflow_level')
+    if_config = config.get('logging', 'interface_level')
+    ut_config = config.get('logging', 'utils_level')
+
+    wf_level = logging.getLogger('workflow').level
+    if_level = logging.getLogger('interface').level
+    ut_level = logging.getLogger('utils').level
+
+    config.enable_debug_mode()
+
+    # Check config is updated and logging levels, too
+    assert config.get('execution', 'stop_on_first_crash') == 'true'
+    assert config.get('execution', 'remove_unnecessary_outputs') == 'false'
+    assert config.get('execution', 'keep_inputs') == 'true'
+    assert config.get('logging', 'workflow_level') == 'DEBUG'
+    assert config.get('logging', 'interface_level') == 'DEBUG'
+    assert config.get('logging', 'utils_level') == 'DEBUG'
+
+    assert logging.getLogger('workflow').level == 10
+    assert logging.getLogger('interface').level == 10
+    assert logging.getLogger('utils').level == 10
+
+    # Restore config and levels
+    config.set('execution', 'stop_on_first_crash', sofc_config)
+    config.set('execution', 'remove_unnecessary_outputs', ruo_config)
+    config.set('execution', 'keep_inputs', ki_config)
+    config.set('logging', 'workflow_level', wf_config)
+    config.set('logging', 'interface_level', if_config)
+    config.set('logging', 'utils_level', ut_config)
+    logging.update_logging(config)
+
+    assert config.get('execution', 'stop_on_first_crash') == sofc_config
+    assert config.get('execution', 'remove_unnecessary_outputs') == ruo_config
+    assert config.get('execution', 'keep_inputs') == ki_config
+    assert config.get('logging', 'workflow_level') == wf_config
+    assert config.get('logging', 'interface_level') == if_config
+    assert config.get('logging', 'utils_level') == ut_config
+
+    assert logging.getLogger('workflow').level == wf_level
+    assert logging.getLogger('interface').level == if_level
+    assert logging.getLogger('utils').level == ut_level