Missing input tmp files when running with --cluster (SLURM)

[visze]

7.3.0 7.3.1, 7.3.2, 7.3.2

Describe the bug
When running snakemake on --cluster mode (using SLURM) I get (on a few rules) a missing input file error. Basically snakemake seems to require a tmp file directory which is not there. The bug is introduced in 7.3.0. With 7.2.1 I do not face the issue. I also do not get the error when running snakemake locally.

Logs

Waiting at most 5 seconds for missing files.
Missing files after 5 seconds:
['/fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/.snakemake/tmp.r2c0dyx_', 'results/experiments/run1-3counts/stats/counts/293T_1_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_1_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_2_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_2_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_3_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_3_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_1_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_1_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_2_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_2_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_3_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_3_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_1_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_1_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_2_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_2_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_3_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_3_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_1_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_1_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_2_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_2_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_3_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_3_RNA_filtered_counts.tsv.gz', '/fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/.snakemake/conda/4f84cfa510afb6fc4f7548b77e604269']

Additional context
From the changelog I see that in 7.3.0 there was a change in group tmp handling (#1487). Maybe this introduced the bug here?

From the log above. All files are there except: /fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/.snakemake/tmp.r2c0dyx

[johanneskoester]

Hi, thanks for reporting! I think this might be just a latency issue. Can you try to increase --latency-wait? I have made a PR for improving the error message in such cases: #1528

[visze]

thanks johannes. I will try that out and post an update of it resolved the issue.

[visze]

@johanneskoester increasing --latency-wait to --latency-wait 60 did not resolve the issue. The required tmp folder in .snakemake was not generated. I also tried 120 seconds. This did not work either. When downgrading to 7.2.1 everything works fine...

Waiting at most 120 seconds for missing files.
Missing files after 120 seconds:
['/fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/.snakemake/tmp.qooux3z9', 'results/experiments/run1-3counts/stats/counts/293T_1_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_1_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_2_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_2_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_3_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/293T_3_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_1_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_1_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_2_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_2_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_3_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/HepG2_3_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_1_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_1_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_2_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_2_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_3_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/K562_3_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_1_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_1_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_2_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_2_RNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_3_DNA_filtered_counts.tsv.gz', 'results/experiments/run1-3counts/stats/counts/WTC_3_RNA_filtered_counts.tsv.gz', '/fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/.snakemake/conda/1c2964349c5d67bd75dff367585d952d']

[nick-youngblut]

I seem to be getting the same issue (SGE cluster), but only for some jobs in the pipeline.

Apparently, snakemake cannot find any of the required input files (including the conda env) for the job. This only happens for only some rules (cluster jobs), so it shouldn't be an issue with the cluster or NFS.

I tried deleting the existing .snakemake directory, but that didn't help.

I'm using snakemake 7.3.2.

Downgrading to 7.2.1 resolves the issue.

[leachim]

Same here, on a slurm cluster. The issue occurred after upgrading snakemake to 7.3.3. Downgrading to 7.2 solved the issue for me.

[johanneskoester]

Can you run with --verbose and post the full stack trace here?

[johanneskoester]

Never mind, I am pretty sure I found the bug! Fix incoming!

[johanneskoester]

Fixed, thanks a lot!

[johanneskoester]

I've also modified a test case to prevent us from such errors in the future.

[visze]

just for completeness (with 7.3.4)

nakemake --verbose --latency-wait 120 --use-conda -p  --configfile config.yaml --snakefile /data/gpfs-1/users/schubacm_c/work/projects/MP
RAsnakeflow/workflow/Snakefile --conda-frontend mamba --keep-going --cluster-config /data/gpfs-1/users/schubacm_c/work/projects/MPRAsnakeflow/config/cluster.yml --cluster-cancel scancel
 --cluster-status status.py --cluster "sbatch --parsable --nodes=1 --ntasks={cluster.threads} --mem={cluster.mem} -t {cluster.time} -p {cluster.queue} -o {cluster.output} "  --jobs 100 
results/experiments/run1-3counts/stats/counts/count_filtered.tsv
Building DAG of jobs...
Using shell: /usr/bin/bash
Provided cluster nodes: 100
Job stats:
job                            count    min threads    max threads
---------------------------  -------  -------------  -------------
statistic_count_stats_merge        1              1              1
total                              1              1              1
  
Resources before job selection: {'_cores': 9223372036854775807, '_nodes': 100}
Ready jobs (1):
        statistic_count_stats_merge
Select jobs to execute...
Using greedy selector because only single job has to be scheduled.
Selected jobs (1):
        statistic_count_stats_merge
Resources after job selection: {'_cores': 9223372036854775806, '_nodes': 99}
  
[Thu Mar 31 13:40:58 2022]
rule statistic_count_stats_merge:
    input: results/experiments/run1-3counts/stats/counts/293T_1_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/293T_1_RNA_filtered_counts.tsv.gz, results/expe
riments/run1-3counts/stats/counts/293T_2_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/293T_2_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/st
ats/counts/293T_3_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/293T_3_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/HepG2_1_DNA_
filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/HepG2_1_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/HepG2_2_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/HepG2_2_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/HepG2_3_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/HepG2_3_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/K562_1_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/K562_1_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/K562_2_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/K562_2_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/K562_3_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/K562_3_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/WTC_1_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/WTC_1_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/WTC_2_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/WTC_2_RNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/WTC_3_DNA_filtered_counts.tsv.gz, results/experiments/run1-3counts/stats/counts/WTC_3_RNA_filtered_counts.tsv.gz
    output: results/experiments/run1-3counts/stats/counts/count_filtered.tsv
    log: logs/experiments/run1-3counts/stats/counts/statistic_count_stats_merge.filtered.log
    jobid: 0
    wildcards: project=run1-3counts, countType=filtered
    resources: mem_mb=1000, disk_mb=1000, tmpdir=/data/gpfs-1/scratch/users/schubacm_c/tmp

cat results/experiments/run1-3counts/stats/counts/293T_1_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_1_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_2_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_2_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_3_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_3_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_1_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_1_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_2_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_2_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_3_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_3_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_1_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_1_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_2_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_2_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_3_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_3_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_1_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_1_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_2_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_2_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_3_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_3_RNA_filtered_counts.tsv.gz | sort -k1,1 -k3,3 -k2,2 > results/experiments/run1-3counts/stats/counts/count_filtered.tsv 2> logs/experiments/run1-3counts/stats/counts/statistic_count_stats_merge.filtered.log
        
Jobscript:
#!/bin/sh
# properties = {"type": "single", "rule": "statistic_count_stats_merge", "local": false, "input": ["results/experiments/run1-3counts/stats/counts/293T_1_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/293T_1_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/293T_2_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/293T_2_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/293T_3_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/293T_3_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/HepG2_1_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/HepG2_1_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/HepG2_2_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/HepG2_2_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/HepG2_3_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/HepG2_3_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/K562_1_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/K562_1_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/K562_2_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/K562_2_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/K562_3_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/K562_3_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/WTC_1_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/WTC_1_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/WTC_2_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/WTC_2_RNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/WTC_3_DNA_filtered_counts.tsv.gz", "results/experiments/run1-3counts/stats/counts/WTC_3_RNA_filtered_counts.tsv.gz"], "output": ["results/experiments/run1-3counts/stats/counts/count_filtered.tsv"], "wildcards": {"project": "run1-3counts", "countType": "filtered"}, "params": {}, "log": ["logs/experiments/run1-3counts/stats/counts/statistic_count_stats_merge.filtered.log"], "threads": 1, "resources": {"mem_mb": 1000, "disk_mb": 1000, "tmpdir": "/data/gpfs-1/scratch/users/schubacm_c/tmp"}, "jobid": 0, "cluster": {"time": "0-01:00", "threads": 1, "mem": "2G", "queue": "debug", "error": "logs/%x_%j_%N.err", "output": "logs/%x_%j_%N.log"}}
cd /fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design && /fast/users/schubacm_c/work/miniconda3/bin/python3.7 -m snakemake --snakefile '/data/gpfs-1/users/schubacm_c/work/projects/MPRAsnakeflow/workflow/Snakefile' 'results/experiments/run1-3counts/stats/counts/count_filtered.tsv' --allowed-rules 'statistic_count_stats_merge' --cores 'all' --attempt 1 --force-use-threads  --wait-for-files-file '/fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/.snakemake/tmp.830t0f99/snakejob.statistic_count_stats_merge.0.sh.waitforfilesfile.txt' --force --keep-target-files --keep-remote --max-inventory-time 0 --nocolor --notemp --no-hooks --nolock --ignore-incomplete --skip-script-cleanup  --use-conda  --conda-frontend 'mamba' --conda-base-path '/fast/users/schubacm_c/work/miniconda3' --wrapper-prefix 'https://github.com/snakemake/snakemake-wrappers/raw/' --configfiles '/fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/config.yaml' --printshellcmds  --latency-wait 120 --scheduler 'ilp' --scheduler-solver-path '/fast/users/schubacm_c/work/miniconda3/bin' --default-resources 'mem_mb=max(2*input.size_mb, 1000)' 'disk_mb=max(2*input.size_mb, 1000)' 'tmpdir=system_tmpdir' --mode 2 && exit 0 || exit 1
  
Submitted job 0 with external jobid '1317357'.

[Thu Mar 31 13:43:32 2022]
Error in rule statistic_count_stats_merge:
    jobid: 0
    output: results/experiments/run1-3counts/stats/counts/count_filtered.tsv
    log: logs/experiments/run1-3counts/stats/counts/statistic_count_stats_merge.filtered.log (check log file(s) for error message)
    conda-env: /fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/.snakemake/conda/1c2964349c5d67bd75dff367585d952d
    shell:
        
        zcat results/experiments/run1-3counts/stats/counts/293T_1_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_1_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_2_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_2_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_3_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/293T_3_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_1_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_1_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_2_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_2_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_3_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/HepG2_3_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_1_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_1_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_2_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_2_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_3_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/K562_3_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_1_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_1_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_2_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_2_RNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_3_DNA_filtered_counts.tsv.gz results/experiments/run1-3counts/stats/counts/WTC_3_RNA_filtered_counts.tsv.gz | sort -k1,1 -k3,3 -k2,2 > results/experiments/run1-3counts/stats/counts/count_filtered.tsv 2> logs/experiments/run1-3counts/stats/counts/statistic_count_stats_merge.filtered.log
        
        (one of the commands exited with non-zero exit code; note that snakemake uses bash strict mode!)
    cluster_jobid: 1317357

Error executing rule statistic_count_stats_merge on cluster (jobid: 0, external: 1317357, jobscript: /fast/work/groups/ag_kircher/MPRA/MPRAsnakeflow_projects/MPRA_ML_design/.snakemake/tmp.830t0f99/snakejob.statistic_count_stats_merge.0.sh). For error details see the cluster log and the log files of the involved rule(s).
Cleanup job metadata.
Cleanup failed jobs output files.
Job failed, going on with independent jobs.
Exiting because a job execution failed. Look above for error message
BUG: Out of jobs ready to be started, but not all files built yet. Please check https://github.com/snakemake/snakemake/issues/823 for more information.
Remaining jobs:
 - statistic_count_stats_merge: results/experiments/run1-3counts/stats/counts/count_filtered.tsv
Complete log: .snakemake/log/2022-03-31T134055.809545.snakemake.log
unlocking
removing lock
removing lock
removed all locks