exception tracebacks in run: blocks are sent to /dev/null, making rules hard to debug

[grahamgower]

Snakemake version

7.8.1

Describe the bug

When calling python code in a run: block, an uncaught exception will cause the job to fail. As it should. However, the stack trace isn't captured so its not possible to track down the cause of the exception!

Minimal example

$ cat Snakefile
rule all:
    input:
        "test-output"

rule test:
    output:
        "test-output"
    run:
        raise Exception("Hello? Is anybody out there?")

$ snakemake -c1
Building DAG of jobs...
Using shell: /usr/bin/bash
Provided cores: 1 (use --cores to define parallelism)
Rules claiming more threads will be scaled down.
Job stats:
job      count    min threads    max threads
-----  -------  -------------  -------------
all          1              1              1
test         1              1              1
total        2              1              1

Select jobs to execute...

[Fri Jun  3 15:40:47 2022]
rule test:
    output: test-output
    jobid: 1
    reason: Missing output files: test-output
    resources: tmpdir=/tmp

Shutting down, this might take some time.
Exiting because a job execution failed. Look above for error message
Complete log: .snakemake/log/2022-06-03T154046.915828.snakemake.log

$ cat .snakemake/log/2022-06-03T154046.915828.snakemake.log
Building DAG of jobs...
Using shell: /usr/bin/bash
Provided cores: 1 (use --cores to define parallelism)
Rules claiming more threads will be scaled down.
Job stats:
job      count    min threads    max threads
-----  -------  -------------  -------------
all          1              1              1
test         1              1              1
total        2              1              1

Select jobs to execute...

[Fri Jun  3 15:40:47 2022]
rule test:
    output: test-output
    jobid: 1
    reason: Missing output files: test-output
    resources: tmpdir=/tmp

Shutting down, this might take some time.
Exiting because a job execution failed. Look above for error message
Complete log: .snakemake/log/2022-06-03T154046.915828.snakemake.log

[achennu]

Thanks for reporting this. I've also been bitten by this bug, and can confirm that it also affects v7.7.

When I installed with snakemake-minimal <7.6 using the bioconda channel, I got v7.3.8 installed. This version behaved as expected and displayed the traceback.

[dweindl]

The problem is the all here

snakemake/snakemake/executors/__init__.py

Line 469 in c8d81d0

return f"{super().get_job_args(job, **kwargs)} --quiet all"

in combination with the early return in

snakemake/snakemake/logging.py

Lines 433 to 435 in c8d81d0

	if self.is_quiet_about("all"):
	# do not log anything
	return

This was introduced in c8d81d0#diff-438f3317205fd7130727d0589d2fc1a6c2e1f6fc48c2c04d354a8a09b91ba2f4

Last unaffected version is v7.6.2.

[sverchkov]

in combination with the early return in

snakemake/snakemake/logging.py

Lines 433 to 435 in c8d81d0

	if self.is_quiet_about("all"):
	# do not log anything
	return

Am I missing something or would simply removing the early return fix this?

[grzanka]

I suffer the same issue, is there any hope for a fix?

[cademirch]

Still an issue on 7.12.

[VukanJ]

Still an issue with 7.14.0

[cclienti]

Hello,

The regression is due to the commit:

feat: new directive "retries" for annotating the number of times a job shall be restarted after a failure (#1649)
c8d81d0

If I revert the following in snakemake/executors/__init__.py, the exceptions are correctly printed:

     def get_job_args(self, job, **kwargs):
-        return f"{super().get_job_args(job, **kwargs)} --quiet"
+        return f"{super().get_job_args(job, **kwargs)} --quiet all"

I think that the "quiet" behavior has changed, and the executor subprocess does not have the correct command line option. IMO, the solution would be to correctly configure the "quiet" option in the subprocess.

I agree with @dweindl

[SilasK]

Is there a way to transfer the error and trace back to a log file? One can do that by mounting a whole logging structure but this is probably too much for a simple run directive.

Ideally, errors should go directly to a log if one is provided.

[sverchkov]

Is there a way to transfer the error and trace back to a log file? One can do that by mounting a whole logging structure but this is probably too much for a simple run directive.

Ideally, errors should go directly to a log if one is provided.

All error printing and logging (both to standard output/error and snakemake's default log files) is already being done with a logging structure. The problem here is that the subprocess for the run block is being run with --quiet all which configures the logger to log nothing.

[SilasK]

The new version snakemake 7.15.1 fixes this issue. However now all the snakemake log from the executor is printed out. I wonder if there would be a better solution.

[SilasK]

In addition the log is printed to the stdout but not in the main snakemake logfile

[SilasK]

In addition the log is printed to the stdout but not in the main snakemake logfile

Can we reopen this issue?