Error in snakemake wrapper goes not to log file

[SilasK]

Snakemake version
Note the Snakemake and snakemake-wrappers version for which you experience the bug.
Always make sure to try out the latest version of both before creating a new bug report.

7.15

Describe the bug

Error in snakemake wrapper goes not to log file

Logs

rule mapping_stats_genomes:
    input: genomes/alignments/bams/sample1.bam
    output: genomes/alignments/stats/sample1.stats
    log: logs/genomes/alignments/sample1_stats.log
    jobid: 0
    reason: Forced execution
    wildcards: sample=sample1
    resources: mem_mb=10000, disk_mb=1000, tmpdir=/tmp, mem=10, time=1, time_min=60

python -c "import sys; print('.'.join(map(str, sys.version_info[:2])))"
Activating conda environment: ../../../../gpfs/nihs/microbiome/Software/anaconda/Anaconda3-ATLAS/ATLAS_DATABASES/conda_envs/559a96fc72675fbc18f6663be49b4d36_
python /scratch/rdkiesersi1/Debug_atlas/WD/.snakemake/scripts/tmphrhrjlo3.wrapper.py
Activating conda environment: ../../../../gpfs/nihs/microbiome/Software/anaconda/Anaconda3-ATLAS/ATLAS_DATABASES/conda_envs/559a96fc72675fbc18f6663be49b4d36_
Traceback (most recent call last):
  File "/scratch/rdkiesersi1/Debug_atlas/WD/.snakemake/scripts/tmphrhrjlo3.wrapper.py", line 31, in <module>
    shell(
  File "/gpfs/home/rdkiesersi1/miniconda3/envs/atlas-dev/lib/python3.10/site-packages/snakemake/shell.py", line 139, in __new__
    cmd = format(cmd, *args, stepout=2, **kwargs)
  File "/gpfs/home/rdkiesersi1/miniconda3/envs/atlas-dev/lib/python3.10/site-packages/snakemake/utils.py", line 431, in format
    return fmt.format(_pattern, *args, **variables)
  File "/gpfs/nihs/microbiome/Software/anaconda/Anaconda3-ATLAS/ATLAS_DATABASES/conda_envs/559a96fc72675fbc18f6663be49b4d36_/lib/python3.10/string.py", line 161, in format
    return self.vformat(format_string, args, kwargs)
  File "/gpfs/nihs/microbiome/Software/anaconda/Anaconda3-ATLAS/ATLAS_DATABASES/conda_envs/559a96fc72675fbc18f6663be49b4d36_/lib/python3.10/string.py", line 165, in vformat
    result, _ = self._vformat(format_string, args, kwargs, used_args, 2)
  File "/gpfs/nihs/microbiome/Software/anaconda/Anaconda3-ATLAS/ATLAS_DATABASES/conda_envs/559a96fc72675fbc18f6663be49b4d36_/lib/python3.10/string.py", line 205, in _vformat
    obj, arg_used = self.get_field(field_name, args, kwargs)
  File "/gpfs/nihs/microbiome/Software/anaconda/Anaconda3-ATLAS/ATLAS_DATABASES/conda_envs/559a96fc72675fbc18f6663be49b4d36_/lib/python3.10/string.py", line 276, in get_field
    obj = getattr(obj, i)
AttributeError: 'InputFiles' object has no attribute 'bam'
Not cleaning up /scratch/rdkiesersi1/Debug_atlas/WD/.snakemake/scripts/tmphrhrjlo3.wrapper.py
[Thu Nov 17 11:22:10 2022]
Error in rule mapping_stats_genomes:
    jobid: 0
    output: genomes/alignments/stats/sample1.stats
    log: logs/genomes/alignments/sample1_stats.log (check log file(s) for error message)
    conda-env: /gpfs/nihs/microbiome/Software/anaconda/Anaconda3-ATLAS/ATLAS_DATABASES/conda_envs/559a96fc72675fbc18f6663be49b4d36_

Minimal example
see log

Additional context
cluster execution

[fgvieira]

which wrapper are you using?

[SilasK]

samtools / stats

[fgvieira]

I think that is because that is not a wrapper error, but rather a snakemake error.
The wrapper requires the input file to be names as bam. Can you include the rule you are trying to run?

[SilasK]

I see. Then this is more of a feature request. If there is such an error in a normal rule. It gets detected by the main snakemake instance at the very beginning. Here the rule gets submitted and only there is it caught.

Also if there is anything else in the wrapper that doesn't work the error will just be printed to the stderr or stdout. Which will likely be missed.

[fgvieira]

But those errors should be caught if you do a dry run of your workflow, no?

[jeffhsu3]

Snakemake version: 7.32.3
Snakemake wrapper: 2.6.0

I am getting a similar issue where logs for rules that use snakemake wrappers aren't getting written to logs if they error out. Running the jobs locally, correctly writes the errors. Will snakemake still upload the logs to remote storage if that rule errors out?

[fgvieira]

Can you provide an example of the logs you expect to be written?

[jeffhsu3]

The rule:

rule STAR_multi:
    input:
        fq1 = input_reads,
        fq2 = input_reads_2,
        idx = config["star_index"],
    output:
        aln = f"{bp}STAR/{{sample}}/{{sample}}.bam",
        log = f"{bp}STAR/{{sample}}/{{sample}}.log",
        log_final = f"{bp}STAR/{{sample}}/Log.final.out",
        sj = f"{bp}STAR/{{sample}}/SJ.out.tab"
    log:
        f"{bp}logs/STAR/{{sample}}.log"
    resources:
        mem_mb = 54000
    params:
        extra = "--outSAMtype BAM SortedByCoordinate",
    threads:
        8
    wrapper:
        "v2.9.0/bio/star/align"

And the written log on local:
/home/jeff/mambaforge/envs/8c6cfff4a79e638bd42875ab09a0331d_/bin/STAR: line 8: 353419 Killed "${cmd}" "$@"

[fgvieira]

If you run locally, you say that it "correctly writes the errors"; what do you mean? Does it write them to the screen? To the rule log file? To the snakemake log?

And when is the message not printed? When you run it in a cluster? Are you using slurm?

[jeffhsu3]

The error is written to the log file specified in the snakemake rule. The cluster is a google kubernetes cluster. No log file is created. Completed rules do write the log file.

[fgvieira]

And do you see the same behavior with rules that do not use wrappers? Or is it only when using wrappers?

[SilasK]

@johanneskoester I would like to add logging to each wrapper. I think we can do this more or less automated.

E.g. I would like to add something like the following code at the beginning of each wrapper.
Before making a PR I would discuss if this is ok, or needs adaption.

### loging all exceptiuon to log file if available
import sys
import logging, traceback
import warnings

if len(snakemake.log)>0:
    logfile =  snakemake.log[0]
else:
    logfile =None

logging.basicConfig(
    filename=logfile,
    level=logging.INFO,
    format="%(asctime)s %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)

logger = logging.getLogger(__file__) # Or simply "wrapper"

def handle_exception(exc_type, exc_value, exc_traceback):
    if issubclass(exc_type, KeyboardInterrupt):
        sys.__excepthook__(exc_type, exc_value, exc_traceback)
        return

    logger.error(
        "".join(
            [
                "Uncaught exception: ",
                *traceback.format_exception(exc_type, exc_value, exc_traceback),
            ]
        )
    )


# Install exception handler
sys.excepthook = handle_exception


###################################### Beginning of wrapper ######################################

Eventually, the logfile should be determined by _infer_stdout_and_stderr snakemake/snakemake#2474 to allow logging to stderr file if there are multiple log files.

[jeffhsu3]

And do you see the same behavior with rules that do not use wrappers? Or is it only when using wrappers?

Yeah, my python scripts without the sys.excethook = handle_exception that @SilasK posted have the same problem.