ICA-AROMA attempted to run on several echoes: not enough values to unpack

[Shotgunosine]

Version: 20.1.0
What was I trying to do:
Run fMRIPrep on nodes on our cluster with 64GB ram and 12 physical cores hyperthreaded to 24. The dataset includes single echo task fmri and multi-echo rest data and I'm asking for aroma to be run.

What did I expect to happen:
See fMRIPrep complete without errors.

What actually happened:
fMRIPrep completed, but reports an error in AROMA. The report contains AROMA output for sub-23613_ses-01_task-rest_run-1 and it appears that all of the expected output files are created and of about the correct size.

I've attached the error log.
20200528-165544_3854c182-41ad-4620-b4c1-abf281cb0956.zip

As well as the complete standard out and standard error with debug turned on:
sub-23613_output.zip

Here is the contents of the func directory for a subject that did not produce the error:

-rw-r--r-- 1 nielsond MBDU   68 May 29 09:06 sub-23927_ses-01_task-mid_run-1_AROMAnoiseICs.csv
-rw-r--r-- 1 nielsond MBDU 201K May 29 09:07 sub-23927_ses-01_task-mid_run-1_desc-confounds_regressors.json
-rw-r--r-- 1 nielsond MBDU 1.5M May 29 09:06 sub-23927_ses-01_task-mid_run-1_desc-confounds_regressors.tsv
-rw-r--r-- 1 nielsond MBDU 620K May 29 09:06 sub-23927_ses-01_task-mid_run-1_desc-MELODIC_mixing.tsv
-rw-r--r-- 1 nielsond MBDU 228M May 29 02:30 sub-23927_ses-01_task-mid_run-1_space-fsaverage_hemi-L_bold.func.gii
-rw-r--r-- 1 nielsond MBDU 228M May 29 02:30 sub-23927_ses-01_task-mid_run-1_space-fsaverage_hemi-R_bold.func.gii
-rw-r--r-- 1 nielsond MBDU 1.2M May 29 05:03 sub-23927_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_boldref.nii.gz
-rw-r--r-- 1 nielsond MBDU 100K May 29 05:05 sub-23927_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-aparcaseg_dseg.nii.gz
-rw-r--r-- 1 nielsond MBDU  88K May 29 05:05 sub-23927_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-aseg_dseg.nii.gz
-rw-r--r-- 1 nielsond MBDU   97 May 29 05:03 sub-23927_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-brain_mask.json
-rw-r--r-- 1 nielsond MBDU  27K May 29 05:03 sub-23927_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-brain_mask.nii.gz
-rw-r--r-- 1 nielsond MBDU   93 May 29 05:05 sub-23927_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-preproc_bold.json
-rw-r--r-- 1 nielsond MBDU 524M May 29 05:05 sub-23927_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-preproc_bold.nii.gz
-rw-r--r-- 1 nielsond MBDU 337M May 29 09:08 sub-23927_ses-01_task-mid_run-1_space-MNI152NLin6Asym_desc-smoothAROMAnonaggr_bold.nii.gz
-rw-r--r-- 1 nielsond MBDU   33 May 29 09:06 sub-23927_ses-01_task-rest_run-1_AROMAnoiseICs.csv
-rw-r--r-- 1 nielsond MBDU 113K May 29 09:07 sub-23927_ses-01_task-rest_run-1_desc-confounds_regressors.json
-rw-r--r-- 1 nielsond MBDU 269K May 29 09:06 sub-23927_ses-01_task-rest_run-1_desc-confounds_regressors.tsv
-rw-r--r-- 1 nielsond MBDU 161K May 29 09:06 sub-23927_ses-01_task-rest_run-1_desc-MELODIC_mixing.tsv
-rw-r--r-- 1 nielsond MBDU 123M May 29 02:28 sub-23927_ses-01_task-rest_run-1_space-fsaverage_hemi-L_bold.func.gii
-rw-r--r-- 1 nielsond MBDU 122M May 29 02:28 sub-23927_ses-01_task-rest_run-1_space-fsaverage_hemi-R_bold.func.gii
-rw-r--r-- 1 nielsond MBDU 1.5M May 29 04:46 sub-23927_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_boldref.nii.gz
-rw-r--r-- 1 nielsond MBDU 100K May 29 04:46 sub-23927_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-aparcaseg_dseg.nii.gz
-rw-r--r-- 1 nielsond MBDU  88K May 29 04:46 sub-23927_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-aseg_dseg.nii.gz
-rw-r--r-- 1 nielsond MBDU   98 May 29 04:46 sub-23927_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-brain_mask.json
-rw-r--r-- 1 nielsond MBDU  28K May 29 04:46 sub-23927_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-brain_mask.nii.gz
-rw-r--r-- 1 nielsond MBDU   75 May 29 05:02 sub-23927_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-preproc_bold.json
-rw-r--r-- 1 nielsond MBDU 382M May 29 05:02 sub-23927_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-preproc_bold.nii.gz
-rw-r--r-- 1 nielsond MBDU 507M May 29 09:30 sub-23927_ses-01_task-rest_run-1_space-MNI152NLin6Asym_desc-smoothAROMAnonaggr_bold.nii.gz

And here is one that did produce the error:

-rw-r--r-- 1 nielsond MBDU  112 May 29 04:09 sub-23613_ses-01_task-mid_run-1_AROMAnoiseICs.csv                                                                           
-rw-r--r-- 1 nielsond MBDU 199K May 29 04:09 sub-23613_ses-01_task-mid_run-1_desc-confounds_regressors.json                                                              
-rw-r--r-- 1 nielsond MBDU 1.4M May 29 04:09 sub-23613_ses-01_task-mid_run-1_desc-confounds_regressors.tsv                                                               
-rw-r--r-- 1 nielsond MBDU 720K May 29 04:09 sub-23613_ses-01_task-mid_run-1_desc-MELODIC_mixing.tsv                                                                     
-rw-r--r-- 1 nielsond MBDU 229M May 29 00:32 sub-23613_ses-01_task-mid_run-1_space-fsaverage_hemi-L_bold.func.gii                                                        
-rw-r--r-- 1 nielsond MBDU 230M May 29 00:32 sub-23613_ses-01_task-mid_run-1_space-fsaverage_hemi-R_bold.func.gii                                                        
-rw-r--r-- 1 nielsond MBDU 1.2M May 29 02:39 sub-23613_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_boldref.nii.gz                                              
-rw-r--r-- 1 nielsond MBDU 101K May 29 02:40 sub-23613_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-aparcaseg_dseg.nii.gz                                  
-rw-r--r-- 1 nielsond MBDU  88K May 29 02:40 sub-23613_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-aseg_dseg.nii.gz                                       
-rw-r--r-- 1 nielsond MBDU   97 May 29 02:39 sub-23613_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-brain_mask.json                                        
-rw-r--r-- 1 nielsond MBDU  29K May 29 02:39 sub-23613_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-brain_mask.nii.gz                                      
-rw-r--r-- 1 nielsond MBDU   93 May 29 02:40 sub-23613_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-preproc_bold.json                                      
-rw-r--r-- 1 nielsond MBDU 541M May 29 02:40 sub-23613_ses-01_task-mid_run-1_space-MNI152NLin2009cAsym_res-2_desc-preproc_bold.nii.gz                                    
-rw-r--r-- 1 nielsond MBDU 350M May 29 04:11 sub-23613_ses-01_task-mid_run-1_space-MNI152NLin6Asym_desc-smoothAROMAnonaggr_bold.nii.gz                                   
-rw-r--r-- 1 nielsond MBDU   57 May 29 03:43 sub-23613_ses-01_task-rest_run-1_AROMAnoiseICs.csv                                                                          
-rw-r--r-- 1 nielsond MBDU 119K May 29 03:43 sub-23613_ses-01_task-rest_run-1_desc-confounds_regressors.json                                                             
-rw-r--r-- 1 nielsond MBDU 423K May 29 03:43 sub-23613_ses-01_task-rest_run-1_desc-confounds_regressors.tsv                                                              
-rw-r--r-- 1 nielsond MBDU 269K May 29 03:43 sub-23613_ses-01_task-rest_run-1_desc-MELODIC_mixing.tsv                                                                    
-rw-r--r-- 1 nielsond MBDU 124M May 29 00:30 sub-23613_ses-01_task-rest_run-1_space-fsaverage_hemi-L_bold.func.gii                                                       
-rw-r--r-- 1 nielsond MBDU 125M May 29 00:30 sub-23613_ses-01_task-rest_run-1_space-fsaverage_hemi-R_bold.func.gii                                                       
-rw-r--r-- 1 nielsond MBDU 1.4M May 29 02:23 sub-23613_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_boldref.nii.gz                                             
-rw-r--r-- 1 nielsond MBDU 101K May 29 02:23 sub-23613_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-aparcaseg_dseg.nii.gz                                 
-rw-r--r-- 1 nielsond MBDU  88K May 29 02:23 sub-23613_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-aseg_dseg.nii.gz                                      
-rw-r--r-- 1 nielsond MBDU   98 May 29 02:23 sub-23613_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-brain_mask.json                                       
-rw-r--r-- 1 nielsond MBDU  29K May 29 02:23 sub-23613_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-brain_mask.nii.gz                                     
-rw-r--r-- 1 nielsond MBDU   75 May 29 02:38 sub-23613_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-preproc_bold.json                                     
-rw-r--r-- 1 nielsond MBDU 369M May 29 02:38 sub-23613_ses-01_task-rest_run-1_space-MNI152NLin2009cAsym_res-2_desc-preproc_bold.nii.gz                                   
-rw-r--r-- 1 nielsond MBDU 471M May 29 04:02 sub-23613_ses-01_task-rest_run-1_space-MNI152NLin6Asym_desc-smoothAROMAnonaggr_bold.nii.gz    

I'm at a bit of a loss about how to debug this further, but I've got the working directory for one of the subjects that produced the error if that's needed.

[Shotgunosine]

In terms of replicability, I've got one subject where I ran it twice and once produced the error and once did not. It looks like the number of CPUs differs, so this may be another manifestation of the nthreads issue #2151. I'll parse through the runs that produced errors and see if they're consistently on 72 CPU nodes.

[mgxd]

i'm almost positive this is a result of the memory failure - can you rerun using the --nprocs flag and see if you still run into this?

[Shotgunosine]

Yep, I've kicked off a new batch of runs. Will let you know tomorrow if that's resolved it.

I'm not 100% certain it will though. I grouped runs by completion status, number of CPUs on the compute node, and the label of the nipype node that generated the first error message and found all 5 jobs on 32 CPU nodes failed, as did a bunch on the 56 CPU nodes. There are several cases where it ran out of memory and did not write any Error messages to standard out. You can see the first failure was always in the aroma workflow for the first rest echo from the first rest run.

In case it's relevant to the error, all of the rest scans and field maps are LAS+

[Shotgunosine]

@mgxd I could be wrong, but I don't think nprocs is going to fix it. Here's the command I ran:

singularity run --cleanenv /data/MBDU/singularity_images/fmriprep_20.1.0.simg /data/MBDU/midla/data/bids      $TMPDIR/out participant     --participant_label 20900     -w $TMPDIR/wrk     --nprocs $SLURM_CPUS_PER_TASK     --mem_mb $SLURM_MEM_PER_NODE     --fs-license-file /data/MBDU/singularity_images/license.txt     --output-spaces MNI152NLin2009cAsym:res-2 fsaverage     --dummy-scans 4 --bids-filter-file /data/MBDU/midla/data/derivatives/fmriprep/fmriprepv20.1.0_20200528_2mm_nprocs/bids_filter --longitudinal --use-aroma --error-on-aroma-warnings -vvv

And nprocs is set:

                [nipype]
                crashfile_format = "txt"
                get_linked_libs = false
                memory_gb = 65.536
                nprocs = 24
                omp_nthreads = 8
                plugin = "MultiProc"
                resource_monitor = false
                stop_on_first_crash = false

However, it looks like it's still using 56 threads:

200529-16:14:59,986 nipype.workflow INFO:
         [MultiProc] Running 0 tasks, and 41 jobs ready. Free memory (GB): 65.54/65.54, Free processors: 56/56.
200529-16:15:00,350 nipype.workflow DEBUG:
         Allocating fmriprep_wf.single_subject_20900_wf.func_preproc_ses_01_task_mid_run_1_wf.func_derivatives_wf.spacesource ID=0 (0.20GB, 1 threads). Free: 65.34GB, 55 threads.

I can let these continue running if you really think it's made a difference, but as far as I can tell, --nprocs is not a solution.

In the mean time I'm also testing a small batch of jobs specifying the 56 core nodes and requesting 247 GB of ram.

[mgxd]

nope - you are totally right, it won't affect anything... we're not setting the correct nipype config value 😅

• 20.0.x
  https://github.com/poldracklab/fmriprep/blob/bcfd9eb22b29b2a14d2c818bf0e45fca9fd7b003/fmriprep/cli/run.py#L590

• 20.1.0
  https://github.com/poldracklab/fmriprep/blob/ea351101a53a037038b7df63a85a18a288a6ff7f/fmriprep/config.py#L275

[Shotgunosine]

Alright, I'm using singularity build to build from dockerhub images in order to run things on our HPC. Easiest way for me to test it would be if I could pull an image with that fix from dockerhub. Is there a relatively painless way for that to happen tonight so that I can check results tomorrow?

[mgxd]

your best bet would probably be to:

• download https://github.com/mgxd/fmriprep/archive/fix/cli-parser.zip locally and unzip
• bind the fmriprep/ source folder to fmriprep's location within the container: /usr/local/miniconda/lib/python3.7/site-packages/fmriprep

[Shotgunosine]

Thanks for the prompt response late on a Friday! That seems to be running with the bindpath set:

-------------------------------
(   export TMPDIR=/lscratch/$SLURM_JOB_ID &&     export SINGULARITY_BINDPATH="/gs4,/gs5,/gs6,/gs7,/gs8,/gs9,/gs10,/gs11,/spin1,/scratch,/fdb,/data,/lscratch" &&    mkdir
 -p $TMPDIR/out &&     mkdir -p $TMPDIR/wrk &&     singularity run --cleanenv --bind /data/MBDU/nielsond/fmriprep-fix-cli-parser/fmriprep/:/usr/local/miniconda/lib/pytho
n3.7/site-packages/fmriprep /data/MBDU/singularity_images/fmriprep_20.1.0.simg /data/MBDU/midla/data/bids      $TMPDIR/out participant     --participant_label 20900     
-w $TMPDIR/wrk     --nprocs $SLURM_CPUS_PER_TASK     --mem_mb $SLURM_MEM_PER_NODE     --fs-license-file /data/MBDU/singularity_images/license.txt     --output-spaces MNI
152NLin2009cAsym:res-2 fsaverage     --dummy-scans 4 --bids-filter-file /data/MBDU/midla/data/derivatives/fmriprep/fmriprepv20.1.0_20200528_2mm_clifix_test/bids_filter -
-longitudinal --use-aroma --error-on-aroma-warnings -vvv ;

I'll check it in 3 hours and see if the number of threads is being constrained properly.

[Shotgunosine]

Number of threads looks good now, running the rest of my subjects.

[Shotgunosine]

Looks like it still had errors with aroma on many of the subjects.

[oesteban]

Looks like it still had errors with aroma on many of the subjects.

Same errors as above?

[Shotgunosine]

No memory errors this time, but still failures in Aroma.

Since it wasn't getting memory errors, it looks like the more sessions were run, which produced more errors for each subject. I think for the analysis I'm using this data for at OHBM, I'm going to just have to forgo AROMA. Processing without aroma, only the DVARs error persisted. I'm happy to add some of the failing sessions to this OpenNeuro dataset (https://openneuro.org/datasets/ds002156/versions/1.0.0) if that would be helpful. I can also pull out more log files or error messages if needed.

[oesteban]

I can also pull out more log files or error messages if needed.

That'd be helpful if you want to give aroma another opportunity.

I'm happy to add some of the failing sessions to this OpenNeuro dataset (https://openneuro.org/datasets/ds002156/versions/1.0.0) if that would be helpful.

This would be very helpful, but I can't promise anything immediate. Particularly useful to test whether upgrading aroma will help (which I believe it will)