Snakemake: RuntimeError stack trace missing when using Python fileConfig()

Question

I have a snakefile with one rule which imports a local Python script and then raises a RuntimeError. When I run the snakefile, the stack trace for the RuntimeError is not shown. The code and snakemake output are shown below.

// test.snakefile
rule test_rule:
    run:
        from test import hello
        print(hello)
        raise RuntimeError('raising error')

// test.py
import logging
import os
from logging.config import fileConfig

log_file_path = os.path.join(os.path.dirname(os.path.abspath(__file__)), 'logging_config.ini')
fileConfig(log_file_path)

hello = 'hello'

snakemake output:

...
[Mon Jan 13 14:45:54 2020]
rule test_rule:
    jobid: 0

Job counts:
    count   jobs
    1   test_rule
    1
hello
Shutting down, this might take some time.
Exiting because a job execution failed. Look above for error message

However, if I comment out the line fileConfig(log_file_path) in test.py and run snakemake, the RuntimeError stack trace is printed as expected:

Error in rule test_rule:
    jobid: 0

RuleException:
RuntimeError in line 5 of /my-dir/test.snakefile:
raising error
  File "/my-dir/test.snakefile", line 5, in __rule_test_rule
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
Exiting because a job execution failed. Look above for error message

Anyone know why this occurs?

EDIT: logging_config.ini

[loggers]
keys=root

[handlers]
keys=stream_handler

[formatters]
keys=formatter

[logger_root]
level=INFO
handlers=stream_handler

[handler_stream_handler]
class=handlers.TimedRotatingFileHandler
level=DEBUG
formatter=formatter
args=('/tmp/experiments.log', 'midnight')

[formatter_formatter]
format=%(asctime)s %(name)-12s %(levelname)-8s %(message)s

Can you show the contents of logging_config.ini? Wondering if stderr gets redirected to some file specified in the config. — Manavalan Gajapathy
@Maarten-vd-Sande Yes, hello is printed above the stack trace, I just didn't copy it in the post. — mmy227
@ManavalanGajapathy Edited the post to include logging_config.ini! — mmy227
Looks like this error is due to logging setup and not snakemake's. I think if you executed the code in run section as a separate python script, you would have the same problem. Did you check /tmp/experiments.log to see if error messages get redirected there? Also, you may need to add logger=logging.getLogger() after fileConfig(). — Manavalan Gajapathy

Manavalan Gajapathy Manavalan Gajapathy · Accepted Answer · 2020-01-23T04:26:01

This issue has to do with how logging module was defined in test.py and how they were imported in Snakefile. Following setup should work. Please note comments inside code block for description of modifications.

test.py

import logging
import os
from logging.config import fileConfig

fileConfig('logging_config.ini')
logger = logging.getLogger(__name__)   # assigns to "logger", through which logs are passed. 
logger.info('test.py debug msg')   # example log message

hello = 'yo yo yo'

Snakefile

rule test_rule:
    run:
        from test import hello, logger.   # imports both hello and logger
        print(hello)
        print (logger)

        logger.exception("Exception occurred")   # error log that would capture stack traces, if any. No stack trace in this example.
        raise SystemExit(1)     # exits with non-zero error

logging_config.ini - same as posted in questions.

In this setup, variable hello and class logger get imported into rule test_rule, and their logging output gets written into file /tmp/experiments.log, as configured in logging_config.ini.

Snakemake: RuntimeError stack trace missing when using Python fileConfig()

1 Answers