Results file failure with 1.3.0rc1 (MapNode)

[effigies]

Summary

An example of the results file issue, again involving MapNodes. Using FitLins installed in a conda environment with poldracklab/fitlins#195.

191031-15:49:32,977 nipype.workflow WARNING:
	 Storing result file without outputs
191031-15:49:32,982 nipype.workflow WARNING:
	 [Node] Error on "_l2_model0" (/System/Volumes/Data/data/scratch/ds003-fitlins/fitlins_wf/l2_model/mapflow/_l2_model0)
191031-15:49:32,994 nipype.workflow WARNING:
	 [Node] Error on "fitlins_wf.l2_model" (/System/Volumes/Data/data/scratch/ds003-fitlins/fitlins_wf/l2_model)
exception calling callback for <Future at 0x11b18e850 state=finished raised FileNotFoundError>
concurrent.futures.process._RemoteTraceback: 
"""
Traceback (most recent call last):
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 69, in run_node
    result['result'] = node.run(updatehash=updatehash)
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 479, in run
    result = self._run_interface(execute=True)
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 1282, in _run_interface
    self.config['execution']['stop_on_first_crash'])))
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 1204, in _collate_results
    (self.name, '\n'.join(msg)))
Exception: Subnodes of node: l2_model failed:
Subnode 0 failed
Error: Traceback (most recent call last):

  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/utils.py", line 104, in nodelist_runner
    result = node.run(updatehash=updatehash)

  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 479, in run
    result = self._run_interface(execute=True)

  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 569, in _run_interface
    return self._run_command(execute)

  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 662, in _run_command
    result = self._interface.run(cwd=outdir)

  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/interfaces/base/core.py", line 382, in run
    runtime = self._run_interface(runtime)

  File "/Users/markiewicz/Projects/crn/fitlins/fitlins/interfaces/nistats.py", line 212, in _run_interface
    output_type='all')

TypeError: compute_contrast() got an unexpected keyword argument 'con_val'


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/concurrent/futures/process.py", line 239, in _process_worker
    r = call_item.fn(*call_item.args, **call_item.kwargs)
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 72, in run_node
    result['result'] = node.result
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 198, in result
    op.join(self.output_dir(), 'result_%s.pklz' % self.name))
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/engine/utils.py", line 294, in load_resultfile
    raise FileNotFoundError(results_file)
FileNotFoundError: /System/Volumes/Data/data/scratch/ds003-fitlins/fitlins_wf/l2_model/result_l2_model.pklz
"""

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 149, in _async_callback
    result = args.result()
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
FileNotFoundError: /System/Volumes/Data/data/scratch/ds003-fitlins/fitlins_wf/l2_model/result_l2_model.pklz

It also causes the whole workflow to hang.

Platform details:

{'commit_hash': '%h',
 'commit_source': 'archive substitution',
 'networkx_version': '2.4',
 'nibabel_version': '2.5.1',
 'nipype_version': '1.3.0-rc1',
 'numpy_version': '1.17.3',
 'pkg_path': '/System/Volumes/Data/anaconda3/envs/fitlins/lib/python3.7/site-packages/nipype',
 'scipy_version': '1.3.1',
 'sys_executable': '/System/Volumes/Data/anaconda3/envs/fitlins/bin/python',
 'sys_platform': 'darwin',
 'sys_version': '3.7.5 (default, Oct 25 2019, 10:52:18) \n'
                '[Clang 4.0.1 (tags/RELEASE_401/final)]',
 'traits_version': '5.1.2'}

Execution environment

Choose one

• My python environment outside container

name: fitlins
channels:
  - conda-forge
  - defaults
dependencies:
  - appnope=0.1.0=py37_1000
  - asn1crypto=1.2.0=py37_0
  - attrs=19.3.0=py_0
  - backcall=0.1.0=py_0
  - bleach=3.1.0=py_0
  - bz2file=0.98=py_0
  - ca-certificates=2019.10.16=0
  - certifi=2019.9.11=py37_0
  - cffi=1.13.1=py37h33e799b_0
  - chardet=3.0.4=py37_1003
  - click=7.0=py_0
  - cryptography=2.8=py37ha12b0ac_0
  - cycler=0.10.0=py_2
  - decorator=4.4.1=py_0
  - defusedxml=0.6.0=py_0
  - entrypoints=0.3=py37_1000
  - etelemetry=0.1.2=py_1
  - filelock=3.0.12=py_0
  - freetype=2.10.0=h24853df_1
  - funcsigs=1.0.2=py_3
  - future=0.18.1=py37_0
  - graphviz=2.40.1=h69955ae_1
  - h5py=2.10.0=nompi_py37h6248fd5_100
  - hdf5=1.10.5=nompi_h3e39495_1104
  - html5lib=1.0.1=py_0
  - icu=64.2=h6de7cb9_1
  - idna=2.8=py37_1000
  - importlib_metadata=0.23=py37_0
  - ipykernel=5.1.3=py37h5ca1d4c_0
  - ipython=7.9.0=py37h5ca1d4c_0
  - ipython_genutils=0.2.0=py_1
  - isodate=0.6.0=py_1
  - jedi=0.15.1=py37_0
  - jinja2=2.10.3=py_0
  - jpeg=9c=h1de35cc_1001
  - json5=0.8.5=py_0
  - jsonschema=3.1.1=py37_0
  - jupyter_client=5.3.4=py37_0
  - jupyter_core=4.6.0=py37_0
  - jupyterlab=1.2.0=py_0
  - jupyterlab_server=1.0.6=py_0
  - keepalive=0.5=py_1
  - kiwisolver=1.1.0=py37h770b8ee_0
  - libblas=3.8.0=14_openblas
  - libcblas=3.8.0=14_openblas
  - libcxx=9.0.0=h89e68fa_1
  - libedit=3.1.20181209=hb402a30_0
  - libffi=3.2.1=h6de7cb9_1006
  - libgfortran=4.0.0=2
  - libiconv=1.15=h01d97ff_1005
  - liblapack=3.8.0=14_openblas
  - libopenblas=0.3.7=h4bb4525_2
  - libpng=1.6.37=h2573ce8_0
  - libsodium=1.0.17=h01d97ff_0
  - libtiff=4.0.10=h3527a1b_1004
  - libxml2=2.9.10=h53d96d6_0
  - libxslt=1.1.33=h320ff13_0
  - llvm-openmp=9.0.0=h40edb58_0
  - lxml=4.4.1=py37h08abf6f_0
  - lz4-c=1.8.3=h6de7cb9_1001
  - markupsafe=1.1.1=py37h1de35cc_0
  - matplotlib=3.1.1=py37_1
  - matplotlib-base=3.1.1=py37h3a684a6_1
  - mistune=0.8.4=py37h1de35cc_1000
  - more-itertools=7.2.0=py_0
  - nbconvert=5.6.1=py37_0
  - nbformat=4.4.0=py_1
  - ncurses=6.1=h0a44026_1002
  - networkx=2.4=py_0
  - neurdflib=5.0.0.post1=py_0
  - nibabel=2.5.1=py_0
  - nipype=1.3.0rc1=py37_0
  - notebook=6.0.1=py37_0
  - numpy=1.17.3=py37hde6bac1_0
  - openssl=1.1.1d=h1de35cc_3
  - packaging=19.2=py_0
  - pandoc=2.7.3=0
  - pandocfilters=1.4.2=py_1
  - parso=0.5.1=py_0
  - pexpect=4.7.0=py37_0
  - pickleshare=0.7.5=py37_1000
  - pip=19.3.1=py37_0
  - prometheus_client=0.7.1=py_0
  - prompt_toolkit=2.0.10=py_0
  - prov=1.5.3=py_1
  - psutil=5.6.3=py37h01d97ff_0
  - ptyprocess=0.6.0=py_1001
  - pycparser=2.19=py37_1
  - pydicom=1.3.0=py_0
  - pydot=1.4.1=py37_1001
  - pydotplus=2.0.2=pyhd1c1de3_3
  - pygments=2.4.2=py_0
  - pyopenssl=19.0.0=py37_0
  - pyparsing=2.4.2=py_0
  - pyrsistent=0.15.5=py37h0b31af3_0
  - pysocks=1.7.1=py37_0
  - python=3.7.5=h359304d_0
  - python-dateutil=2.8.0=py_0
  - pyzmq=18.1.0=py37hee98d25_0
  - rdflib=4.2.2=py37_1000
  - readline=7.0=hcfe32e1_1001
  - requests=2.22.0=py37_1
  - scipy=1.3.1=py37h7e0e109_2
  - send2trash=1.5.0=py_0
  - setuptools=41.6.0=py37_0
  - simplejson=3.16.0=py37h1de35cc_1002
  - six=1.12.0=py37_1000
  - sparqlwrapper=1.8.2=py37_1000
  - sqlite=3.30.1=ha441bb4_0
  - terminado=0.8.2=py37_0
  - testpath=0.4.2=py_1001
  - tk=8.6.9=h2573ce8_1003
  - tornado=6.0.3=py37h01d97ff_0
  - traitlets=4.3.3=py37_0
  - traits=5.1.2=py37h01d97ff_0
  - urllib3=1.25.6=py37_0
  - wcwidth=0.1.7=py_1
  - webencodings=0.5.1=py_1
  - wheel=0.33.6=py37_0
  - xvfbwrapper=0.2.9=py37_1000
  - xz=5.2.4=h1de35cc_1001
  - zeromq=4.3.2=h6de7cb9_2
  - zipp=0.6.0=py_0
  - zlib=1.2.11=h0b31af3_1006
  - zstd=1.4.3=he7fca8b_0
  - pip:
    - alabaster==0.7.12
    - babel==2.7.0
    - bids-validator==1.2.4
    - citeproc-py==0.4.0
    - coverage==4.5.4
    - docopt==0.6.2
    - docutils==0.15.2
    - duecredit==0.7.0
    - flake8==3.7.9
    - imagesize==1.1.0
    - joblib==0.14.0
    - m2r==0.2.1
    - mccabe==0.6.1
    - nilearn==0.5.2
    - nistats==0.0.1b1
    - num2words==0.5.10
    - numexpr==2.7.0
    - pandas==0.25.2
    - patsy==0.5.1
    - pbr==5.4.3
    - pillow==6.2.1
    - pybids==0.9.4
    - pycodestyle==2.5.0
    - pyflakes==2.1.1
    - pytz==2019.3
    - scikit-learn==0.21.3
    - seaborn==0.9.0
    - snowballstemmer==2.0.0
    - sphinx==2.2.1
    - sphinx-argparse==0.2.5
    - sphinx-nbexamples==0.4.0
    - sphinxcontrib-apidoc==0.3.0
    - sphinxcontrib-applehelp==1.0.1
    - sphinxcontrib-devhelp==1.0.1
    - sphinxcontrib-htmlhelp==1.0.2
    - sphinxcontrib-jsmath==1.0.1
    - sphinxcontrib-qthelp==1.0.2
    - sphinxcontrib-serializinghtml==1.1.3
    - sqlalchemy==1.3.10
    - tables==3.6.1
    - texext==0.6.1
prefix: /System/Volumes/Data/anaconda3/envs/fitlins

[satra]

@effigies - can you check this with #3089 ?

[effigies]

I checked. It didn't make a difference.

[satra]

that's weird. a few questions/comments:

1. so there seems to be an actual error in there related to an interface, was that fixed:
   TypeError: compute_contrast() got an unexpected keyword argument 'con_val'

2. i'm assuming you reran this from scratch, rather than reusing an existing cache-dir. the gzip change i made was specific to an end of stream error.

3. does this file actually exist: /System/Volumes/Data/data/scratch/ds003-fitlins/fitlins_wf/l2_model/result_l2_model.pklz and if so, can you load it?

[effigies]

1. Yes. I expect nipype to handle crashes, though...
2. I did reuse, but removing the specific node directory in the scratch directory. I can start from scratch if you prefer, but I expect the same.
3. It does not exist.

[satra]

1. Yes. I expect nipype to handle crashes, though...

i would expect it to as well. that's why it's weird what other thing is causing it not to. it's almost as if something in the crashfile generation function is crashing.

3. It does not exist.
   this seems to be a different issue. the issues that were being caused that initiated the wait were all cases, where the file actually existed, but not available to the loader at the point of load (possibly due to file system issues). the actual missing file case is something different.

if you can start from scratch it would help. also if i can replicate this, i can try to see what else could be triggering this.

[effigies]

Sorry, I was hoping to give instructions for how to set up an environment, but didn't finish. Will do that shortly. Here's a Circle test, which should be pretty reproducible.

[effigies]

Set up a fresh conda environment:

conda create -n fitlinscrash python=3.7 nipype==1.3.1
conda activate fitlinscrash

Install poldracklab/fitlins@c95eea3:

pip install git+https://github.com/poldracklab/fitlins.git@c95eea33477c192d8a49d4957069caeb5ba8c54b

I'll assume you have datalad and some place you like to keep BIDS datasets $BIDS:

datalad install -r -s ///labs/poldrack/ds003_fmriprep $BIDS/ds003_fmriprep
datalad get $BIDS/ds003_fmriprep/sub-0{1,2,3}/func/*_space-MNI152NLin2009cAsym_desc-*.nii.gz \\
            $BIDS/ds003_fmriprep/sub-0{1,2,3}/func/*_desc-confounds_*.tsv \
            $BIDS/ds003_fmriprep/dataset_description.json \
            $BIDS/ds003_fmriprep/sub-*/*/*.json

Grab a model:

curl -sSLO https://github.com/poldracklab/fitlins/raw/master/examples/models/ds000003/models/model-001_smdl.json

Reproduce:

fitlins $BIDS/ds003_fmriprep/sourcedata $OUT/ds003-fitlins dataset \
    -d $BIDS/ds003_fmriprep -m $PWD/model-001_smdl.json \
    --participant-label 01 02 03 -w $SCRATCH/ds003-fitlins

[wtriplett]

Hi,

I've seen this issue as well, and it does cause the execution to hang under multiproc and legacy multiproc. It seems that all of the missing files are related to a mapnode's "parent" node's result file. For example:

Workflow
 |- Node_X
     |- result_Node_X.pklz <-- this is being looked for but is missing.
     |- mapflow
         |- _Node_X0
             |- result__Node_X0.pklz

Catching the eventual FileNotFoundException at line 70 below will prevent the execution from hanging, but I'm not sure about why the result file is missing in the first place. Maybe it is looking for it too soon, before all of the mapflows are finished up?

nipype/nipype/pipeline/plugins/multiproc.py

Lines 65 to 70 in 2125c0b

	# Try and execute the node via node.run()
	try:
	result["result"] = node.run(updatehash=updatehash)
	except: # noqa: E722, intendedly catch all here
	result["traceback"] = format_exception(*sys.exc_info())
	result["result"] = node.result

Edit: Possible postponing the raising of this exception here (_collate_results()) until after returning and writing the results file could prevent the FileNotFoundError:

nipype/nipype/pipeline/engine/nodes.py

Lines 1288 to 1300 in 1a86999

	if returncode and any([code is not None for code in returncode]):
	msg = []
	for i, code in enumerate(returncode):
	if code is not None:
	msg += ["Subnode %d failed" % i]
	msg += ["Error: %s" % str(code)]
	raise Exception(
	"Subnodes of node: %s failed:\n%s" % (self.name, "\n".join(msg))
	)
	return finalresult
	def get_subnodes(self):

Allow that to return and check the retvals and after saving the result file:

nipype/nipype/pipeline/engine/nodes.py

Lines 1368 to 1379 in 1a86999

	# Run mapnode
	result = self._collate_results(
	_node_runner(
	self._make_nodes(cwd),
	updatehash=updatehash,
	stop_first=str2bool(self.config["execution"]["stop_on_first_crash"]),
	)
	)
	# And store results
	_save_resultfile(result, cwd, self.name, rebase=False)
	# remove any node directories no longer required
	dirs2remove = []

[satra]

@effigies: got a chance to try this out. i cannot repeat your error with the instructions above. the process completes and the three nodes have crashed

End of the Error log

200104-10:24:12,835 nipype.workflow ERROR:
         Node _l2_model2 failed to run on host node017.
200104-10:24:12,835 nipype.workflow ERROR:
         Saving crash info to /scratch/Mon/satra/fitlins/scratch/ds003-fitlins/crash-20200104-102412-satra-_l2_model2-5d7199c1-e175-4916-97a7-85c380d53b24.txt
Traceback (most recent call last):
  File "/home/satra/miniconda3/envs/fitlinscrash/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 69, in run_node
    result['result'] = node.run(updatehash=updatehash)
  File "/home/satra/miniconda3/envs/fitlinscrash/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 479, in run
    result = self._run_interface(execute=True)
  File "/home/satra/miniconda3/envs/fitlinscrash/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 585, in _run_interface
    return self._run_command(execute)
  File "/home/satra/miniconda3/envs/fitlinscrash/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 678, in _run_command
    result = self._interface.run(cwd=outdir)
  File "/home/satra/miniconda3/envs/fitlinscrash/lib/python3.7/site-packages/nipype/interfaces/base/core.py", line 382, in run
    runtime = self._run_interface(runtime)
  File "/home/satra/miniconda3/envs/fitlinscrash/lib/python3.7/site-packages/fitlins/interfaces/nistats.py", line 212, in _run_interface
    output_type='all')
TypeError: compute_contrast() got an unexpected keyword argument 'con_val'

200104-10:24:22,814 nipype.workflow ERROR:
         could not run node: fitlins_wf.l2_model
200104-10:24:22,814 nipype.workflow ERROR:
         could not run node: fitlins_wf.l2_model
200104-10:24:22,814 nipype.workflow ERROR:
         could not run node: fitlins_wf.l2_model
satra@node017:fitlins$ 

what's weird to me is that i cannot see an unfinished.json file in either of these directories

satra@node017:fitlins$ ls scratch/ds003-fitlins/fitlins_wf/l2_model/mapflow/_l2_model0/
_inputs.pklz  _node.pklz  _report  result__l2_model0.pklz
satra@node017:fitlins$ ls scratch/ds003-fitlins/fitlins_wf/l2_model/
mapflow  _report

[satra]

@wtriplett - the missing result file is something i thought we had taken care of, and from my run it looks like it.

[wtriplett]

@satra : here is a portion of my log in case that is helpful:

https://gist.github.com/wtriplett/75fac896d7ba2ca200675119f1f3c04d

I see this indefinitely at the end as the workflow

200104-11:02:19,736 nipype.workflow WARNING:
	 Storing result file without outputs
200104-11:02:19,740 nipype.workflow WARNING:
	 [Node] Error on "_VoxelPlacementMaker0" (/Users/wtt/Desktop/___/DataProc_py3/TestData.out/11110/__WORK/DataProc_Pipeline_V2/VoxelPlacement_Workflow_axial/6256b158b7995fd02c0950368785107052f15080/VoxelPlacementMaker/mapflow/_VoxelPlacementMaker0)
200104-11:02:19,747 nipype.workflow WARNING:
	 [Node] Error on "DataProc_Pipeline_V2.VoxelPlacement_Workflow_axial.VoxelPlacementMaker" (/Users/wtt/Desktop/___/DataProc_py3/TestData.out/11110/__WORK/DataProc_Pipeline_V2/VoxelPlacement_Workflow_axial/6256b158b7995fd02c0950368785107052f15080/VoxelPlacementMaker)
                     Currently running:
                       * DataProc_Pipeline_V2.VoxelPlacement_Workflow_axial.VoxelPlacementMaker
                       * DataProc_Pipeline_V2.VoxelPlacement_Workflow_axial.VoxelPlacementMaker
	 [MultiProc] Running 2 tasks, and 17 jobs ready. Free memory (GB): 14.00/14.40, Free processors: 0/2.
                     Currently running:
                       * DataProc_Pipeline_V2.VoxelPlacement_Workflow_axial.VoxelPlacementMaker
                       * DataProc_Pipeline_V2.VoxelPlacement_Workflow_axial.VoxelPlacementMaker

as the watcher thread loops endless waiting for the jobs to clean up/finish.

[satra]

thanks @wtriplett - just to confirm - does this hang happen with nipype 1.4.0 on a fresh working dir?

and if so, is it possible to create an example like @effigies ? i cannot repeat the issue currently with @effigies code anymore.

[wtriplett]

@satra: This seems to reproduce the issue with 1.4.0:

conda create -n mapnode_multiproc python=3.7
conda activate mapnode_multiproc
pip install nipype==1.4.0
./crash_example.py linear
./crash_example.py multiproc

crash_example.py: https://gist.github.com/wtriplett/d216a4e9aad146bd0f3b272e22a128a3

I've attached the output of linear and multiproc, where multiproc was run under the timeout command with a time limit of 30 seconds.

linear.txt
multiproc.txt

[satra]

@wtriplett - i think this PR #3143 should fix the problem. thank you very much for your example. i reduced it down to a single MapNode workflow with a Function interface.

[wtriplett]

NP let me know if I can help further.

-B

[satra]

@wtriplett - can you run your code using that branch?

[wtriplett]

@satra : sure...

I ran my original workflow with nipy/master and the nodes crashed as expected, but the workflow hung/locked up as seen previously.

Then ran with satra/fix/mapnode_single and the nodes crashed as expected, and the workflow ran to completion instead of locking up. Also the mapnode "parent" result pklzs were present.

Thanks!
Bill

[satra]

thanks @wtriplett - i'll let @effigies run his workflow, and if all goes well, we can merge it in. and then patch the 1.3.x series.