Error checking MapNode hash with fMRIPrep

[oesteban]

Summary

190904-01:20:18,695 nipype.workflow ERROR:
	 Node t1_conform failed to run on host 890949213e2e.
190904-01:20:18,696 nipype.workflow ERROR:
	 Saving crash info to /tmp/ds054/derivatives/smriprep/sub-100185/log/20190904-011955_7143d03c-6f71-442e-b03b-868465d5d7f5/crash-20190904-012018-UID1001-t1_conform-79d9866d-bc88-4848-9512-c54ff701db1b.txt
Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 269, in _send_procs_to_workers
    num_subnodes = self.procs[jobid].num_subnodes()
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 1204, in num_subnodes
    self._get_inputs()
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 1219, in _get_inputs
    super(MapNode, self)._get_inputs()
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 521, in _get_inputs
    outputs = _load_resultfile(results_file)[0].outputs
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/utils.py", line 311, in load_resultfile
    if resolve and result.outputs:
AttributeError: 'NoneType' object has no attribute 'outputs'

https://circleci.com/gh/oesteban/smriprep/502

Related to #3009 (in that case, it occurred for a regular Node).

[oesteban]

Cleaning up the cache solved the problem.

@satra - I believe this (and #3009) are an artifact of working directory degradation, but I'm worried that they could have some other source since they happen while _get_inputs is run. Gathering inputs from previous nodes should work, since their result file has been already checked (and should exist, for the case of #3009. In this case of MapNodes, I think that the outputs of the prior node got aggregated for some obscure reason.

Before I go ahead and start some refactor that can end up being a rats' nest, we wanted to touch base with you. Do you want to allocate some time to chat (cc/ @effigies )?

[satra]

let's chat. i would like to understand if this is something that is a new bug that was created by a commit, or is because of mixing versions of caches.

[effigies]

I wonder if this is the same problem as #2694. IIRC, that was also impossible to reproduce because a clean working directory didn't exhibit the problem, and there was no clear path toward intentionally producing a broken one.

[oesteban]

I believe that last month's refactor should have addressed that, precisely.

My impression is that nipype is overly noisy: it seems that the first time the cache is checked -early in checking it there is a call to _get_inputs()- in the master thread, the result file of some preceding node is not yet found. In the second pass of the cache check (when the node has been already submitted to the executor, so this is done, e.g., by the child process or a new cluster node), it seems that _get_inputs() actually finds the result file.

This synchronization issue worries me a little, as I would think the result file of preceding nodes should be available already in the first call to _get_inputs().

#2694 is related to the interpretation of the result file of the current node (vs. prior nodes, which is this case).

[satra]

@oesteban - this really depends on the file system and the executor.

1. should never be an issue using multiproc/concurrentfuture, since the filesystem is local and any filesystem cache does not have to be written out to a server. if the issue is happening with local executors, it is likely a different reason.

2. this is often the case in many job schedulers with NFS clients/servers, which is why there is a timeout configuration in nipype to explicitly deal with delayed dirty cache writes across compute nodes. a user can change this config option for such scenarios.

[oesteban]

Right, that's why I believe this is mostly noise and things aren't looking bad. However, not being able to come up with a clear explanation for what is happening has me a bit bugged (mostly because of 1 in your comment).

[oesteban]

Please note that the errors happen within _get_inputs(), which means that the failing cache is not the results file of the current node, but some prior node. We will need to improve the cache checking logic so that _get_inputs() is not called this early, and first check whether the hashfile and the result file are present. Right now, the cache check is as follows:

1. Does current node's folder exist?
2. Run _get_inputs() which propagates results from prior nodes connected to the inputs.
3. Check the hashfile (requires the actual inputs to calculate hash)

A useful optimization that I'm sure will minimize some of these issues is a new step between 1-2 to check whether the result file exists and a hashfile-looking file exists. However, that optimization should happen after we clear up this weirdness because in local filesystems _get_inputs() should not fail.