remove hashfiles on error situations, improve logging the diff of hashvalues

Author: oesteban

nipype/pipeline/engine/nodes.py

@@ -30,7 +30,7 @@
 from future import standard_library
 
 from ... import config, logging
-from ...utils.misc import (flatten, unflatten, str2bool)
+from ...utils.misc import flatten, unflatten, str2bool, dict_diff
 from ...utils.filemanip import (
     md5, FileNotFoundError, filename_to_list, list_to_filename,
     copyfiles, fnames_presuffix, loadpkl, split_filename, load_json, makedirs,
@@ -292,38 +292,46 @@ def hash_exists(self, updatehash=False):
             # Find previous hashfiles
             hashfiles = glob(op.join(outdir, '_0x*.json'))
             if len(hashfiles) > 1:
+                for rmfile in hashfiles:
+                    os.remove(rmfile)
+
                 raise RuntimeError(
-                    '[Node] Cache ERROR - Found %d previous hashfiles that indicate '
+                    '[Node] Cache ERROR - Found %d previous hashfiles indicating '
                     'that the ``base_dir`` for this node went stale. Please re-run the '
                     'workflow.' % len(hashfiles))
 
             # Find unfinished hashfiles and error if any
             unfinished = glob(op.join(outdir, '_0x*_unfinished.json'))
 
+            # This should not happen, but clean up and break if so.
             if unfinished and updatehash:
+                for rmfile in unfinished:
+                    os.remove(rmfile)
+
                 raise RuntimeError(
-                    '[Node] Cache ERROR - Found unfinished hashfiles (%d) that indicate '
+                    '[Node] Cache ERROR - Found unfinished hashfiles (%d) indicating '
                     'that the ``base_dir`` for this node went stale. Please re-run the '
                     'workflow.' % len(unfinished))
 
             # Remove outdated hashfile
             if hashfiles and hashfiles[0] != hashfile:
                 logger.info('[Node] Outdated hashfile found for "%s", removing and forcing node '
-                            'to rerun', self.fullname)
+                            'to rerun.', self.fullname)
 
                 # If logging is more verbose than INFO (20), print diff between hashes
-                if logger.getEffectiveLevel() < 20 and hash_exists:  # Lazy logging: only < INFO
+                loglevel = logger.getEffectiveLevel()
+                if loglevel < 20:  # Lazy logging: only < INFO
                     split_out = split_filename(hashfiles[0])
                     exp_hash_file_base = split_out[1]
                     exp_hash = exp_hash_file_base[len('_0x'):]
-                    logger.debug("Previous node hash = %s", exp_hash)
+                    logger.log(loglevel, "[Node] Old/new hashes = %s/%s", exp_hash, hashvalue)
                     try:
                         prev_inputs = load_json(hashfiles[0])
                     except Exception:
                         pass
                     else:
-                        logging.logdebug_dict_differences(
-                            prev_inputs, hashed_inputs)
+                        logger.log(loglevel, dict_diff(prev_inputs, hashed_inputs, 10))
+
                 os.remove(hashfiles[0])
 
         # Update only possible if it exists

nipype/utils/logger.py

@@ -97,42 +97,7 @@ def logdebug_dict_differences(self, dold, dnew, prefix=""):
 
         typical use -- log difference for hashed_inputs
         """
-        # First check inputs, since they usually are lists of tuples
-        # and dicts are required.
-        if isinstance(dnew, list):
-            dnew = dict(dnew)
-        if isinstance(dold, list):
-            dold = dict(dold)
-
-        # Compare against hashed_inputs
-        # Keys: should rarely differ
-        new_keys = set(dnew.keys())
-        old_keys = set(dold.keys())
-        if len(new_keys - old_keys):
-            self._logger.debug("%s not previously seen: %s"
-                               % (prefix, new_keys - old_keys))
-        if len(old_keys - new_keys):
-            self._logger.debug("%s not presently seen: %s"
-                               % (prefix, old_keys - new_keys))
-
-        # Values in common keys would differ quite often,
-        # so we need to join the messages together
-        msgs = []
-        for k in new_keys.intersection(old_keys):
-            same = False
-            try:
-                new, old = dnew[k], dold[k]
-                same = new == old
-                if not same:
-                    # Since JSON does not discriminate between lists and
-                    # tuples, we might need to cast them into the same type
-                    # as the last resort.  And lets try to be more generic
-                    same = old.__class__(new) == old
-            except Exception as e:
-                same = False
-            if not same:
-                msgs += ["%s: %r != %r"
-                         % (k, dnew[k], dold[k])]
-        if len(msgs):
-            self._logger.debug("%s values differ in fields: %s" % (prefix,
-                                                                   ", ".join(msgs)))
+        from .misc import dict_diff
+        self._logger.warning("logdebug_dict_differences has been deprecated, please use "
+                             "nipype.utils.misc.dict_diff.")
+        self._logger.debug(dict_diff(dold, dnew))

nipype/utils/misc.py

@@ -15,7 +15,7 @@
 import inspect
 
 from distutils.version import LooseVersion
-from textwrap import dedent
+from textwrap import dedent, indent as textwrap_indent
 import numpy as np
 
 def human_order_sorted(l):
@@ -229,3 +229,57 @@ def normalize_mc_params(params, source):
         params[-1:2:-1] = aff2euler(matrix)
 
     return params
+
+
+def dict_diff(dold, dnew, indent=0):
+    """Helper to log what actually changed from old to new values of
+    dictionaries.
+
+    typical use -- log difference for hashed_inputs
+    """
+    # First check inputs, since they usually are lists of tuples
+    # and dicts are required.
+    if isinstance(dnew, list):
+        dnew = dict(dnew)
+    if isinstance(dold, list):
+        dold = dict(dold)
+
+    # Compare against hashed_inputs
+    # Keys: should rarely differ
+    new_keys = set(dnew.keys())
+    old_keys = set(dold.keys())
+
+    diff = []
+    if new_keys - old_keys:
+        diff += ["  * keys not previously seen: %s" % (new_keys - old_keys)]
+
+    if old_keys - new_keys:
+        diff += ["  * keys not presently seen: %s" % (old_keys - new_keys)]
+
+    # Add topical message
+    if diff:
+        diff.insert(0, "Dictionaries had differing keys:")
+
+    diffkeys = len(diff)
+
+    # Values in common keys would differ quite often,
+    # so we need to join the messages together
+    for k in new_keys.intersection(old_keys):
+        same = False
+        try:
+            new, old = dnew[k], dold[k]
+            same = new == old
+            if not same:
+                # Since JSON does not discriminate between lists and
+                # tuples, we might need to cast them into the same type
+                # as the last resort.  And lets try to be more generic
+                same = old.__class__(new) == old
+        except Exception:
+            same = False
+        if not same:
+            diff += ["%s: %r != %r" % (k, dnew[k], dold[k])]
+
+    if len(diff) > diffkeys:
+        diff.insert(diffkeys, "Some dictionary entries had differing values:")
+
+    return textwrap_indent('\n'.join(diff), ' ' * indent)