Skip to content

Duplicate Calls to log_handler in log-handler-script #2797

New issue
New issue
Closed
Closed
Duplicate Calls to log_handler in log-handler-script#2797
Labels
bugSomething isn't working
@Ash1One

Description

@Ash1One
Ash1One
opened on Apr 6, 2024

Snakemake version

v8.10.6

Describe the bug

The log_handler function of the log-handler-script parameter is repeatedly added to snakemake.logging.Logger.log_handler, causing the log_handler function to be called twice for every logging message.

Possible Reason

The log_handler function seems to be added to snakemake.logging.Logger.log_handler twice; once here:

snakemake/snakemake/api.py

Line 141 in b3c1dd4

self.setup_logger(mode=workflow_settings.exec_mode)

and once here:

snakemake/snakemake/api.py

Lines 526 to 530 in b3c1dd4

self.snakemake_api.setup_logger(
stdout=executor_plugin.common_settings.dryrun_exec,
mode=self.workflow_api.workflow_settings.exec_mode,
dryrun=executor_plugin.common_settings.dryrun_exec,
)

Minimal example

The problem presents itself when I run the following command with the Snakefile and log_job.py files given below. Note that every message, except the first one, is printed twice.

  • Snakefile:

    rule all:
    input:
        "b.txt"


rule test:
    output:
        touch("b.txt")

  • log_job.py:

    def log_handler(msg):
    print(msg)

  • command:

    snakemake --snakefile Snakefile -c 1 --log-handler-script log_job.py

Output:

Assuming unrestricted shared filesystem usage.
{'level': 'info', 'msg': 'Assuming unrestricted shared filesystem usage.', 'indent': False, 'timestamp': 1712385654.750852}
Building DAG of jobs...
{'level': 'info', 'msg': 'Building DAG of jobs...', 'indent': False, 'timestamp': 1712385654.7939415}
{'level': 'info', 'msg': 'Building DAG of jobs...', 'indent': False, 'timestamp': 1712385654.7939415}
{'level': 'dag_debug', 'status': 'candidate', 'job': all, 'timestamp': 1712385654.795178}
{'level': 'dag_debug', 'status': 'candidate', 'job': all, 'timestamp': 1712385654.795178}
{'level': 'dag_debug', 'status': 'candidate', 'job': test, 'timestamp': 1712385654.7959971}
{'level': 'dag_debug', 'status': 'candidate', 'job': test, 'timestamp': 1712385654.7959971}
{'level': 'dag_debug', 'status': 'selected', 'job': test, 'timestamp': 1712385654.796126}
{'level': 'dag_debug', 'status': 'selected', 'job': test, 'timestamp': 1712385654.796126}
{'level': 'dag_debug', 'status': 'selected', 'job': all, 'timestamp': 1712385654.7962246}
{'level': 'dag_debug', 'status': 'selected', 'job': all, 'timestamp': 1712385654.7962246}
{'level': 'debug', 'msg': 'shared_storage_local_copies: True', 'timestamp': 1712385654.848134}
{'level': 'debug', 'msg': 'shared_storage_local_copies: True', 'timestamp': 1712385654.848134}
{'level': 'debug', 'msg': 'remote_exec: False', 'timestamp': 1712385654.8483002}
{'level': 'debug', 'msg': 'remote_exec: False', 'timestamp': 1712385654.8483002}
Using shell: /usr/bin/bash
{'level': 'info', 'msg': 'Using shell: /usr/bin/bash', 'indent': False, 'timestamp': 1712385654.8494494}
{'level': 'info', 'msg': 'Using shell: /usr/bin/bash', 'indent': False, 'timestamp': 1712385654.8494494}
Provided cores: 1 (use --cores to define parallelism)
{'level': 'resources_info', 'msg': 'Provided cores: 1 (use --cores to define parallelism)', 'timestamp': 1712385654.8498905}
{'level': 'resources_info', 'msg': 'Provided cores: 1 (use --cores to define parallelism)', 'timestamp': 1712385654.8498905}
Rules claiming more threads will be scaled down.
{'level': 'resources_info', 'msg': 'Rules claiming more threads will be scaled down.', 'timestamp': 1712385654.85023}
{'level': 'resources_info', 'msg': 'Rules claiming more threads will be scaled down.', 'timestamp': 1712385654.85023}
Job stats:
job      count
-----  -------
all          1
test         1
total        2

{'level': 'run_info', 'msg': 'Job stats:\njob      count\n-----  -------\nall          1\ntest         1\ntotal        2\n', 'timestamp': 1712385654.865111}
{'level': 'run_info', 'msg': 'Job stats:\njob      count\n-----  -------\nall          1\ntest         1\ntotal        2\n', 'timestamp': 1712385654.865111}
{'level': 'debug', 'msg': "Resources before job selection: {'_cores': 1, '_nodes': 9223372036854775807}", 'timestamp': 1712385654.8659875}
{'level': 'debug', 'msg': "Resources before job selection: {'_cores': 1, '_nodes': 9223372036854775807}", 'timestamp': 1712385654.8659875}
{'level': 'debug', 'msg': 'Ready jobs (1)', 'timestamp': 1712385654.8660717}
{'level': 'debug', 'msg': 'Ready jobs (1)', 'timestamp': 1712385654.8660717}
Select jobs to execute...
{'level': 'info', 'msg': 'Select jobs to execute...', 'indent': False, 'timestamp': 1712385654.8661244}
{'level': 'info', 'msg': 'Select jobs to execute...', 'indent': False, 'timestamp': 1712385654.8661244}
{'level': 'debug', 'msg': 'Using greedy selector because only single job has to be scheduled.', 'timestamp': 1712385655.4708471}
{'level': 'debug', 'msg': 'Using greedy selector because only single job has to be scheduled.', 'timestamp': 1712385655.4708471}
{'level': 'debug', 'msg': 'Selected jobs (1)', 'timestamp': 1712385655.4719083}
{'level': 'debug', 'msg': 'Selected jobs (1)', 'timestamp': 1712385655.4719083}
{'level': 'debug', 'msg': "Resources after job selection: {'_cores': 0, '_nodes': 9223372036854775806}", 'timestamp': 1712385655.4719808}
{'level': 'debug', 'msg': "Resources after job selection: {'_cores': 0, '_nodes': 9223372036854775806}", 'timestamp': 1712385655.4719808}
Execute 1 jobs...
{'level': 'info', 'msg': 'Execute 1 jobs...', 'indent': False, 'timestamp': 1712385655.4720397}
{'level': 'info', 'msg': 'Execute 1 jobs...', 'indent': False, 'timestamp': 1712385655.4720397}

[Sat Apr  6 14:40:55 2024]
localrule test:
    output: b.txt
    jobid: 1
    reason: Missing output files: b.txt; Set of input files has changed since last execution; Code has changed since last execution; Software environment definition has changed since last execution
    resources: tmpdir=/tmp

{'jobid': 1, 'msg': None, 'name': 'test', 'local': True, 'input': [], 'output': ['b.txt'], 'log': [], 'benchmark': None, 'wildcards': {}, 'reason': 'Missing output files: b.txt; Set of input files has changed since last execution; Code has changed since last execution; Software environment definition has changed since last execution', 'resources': [1, 1, '/tmp'], 'priority': 0, 'threads': 1, 'indent': False, 'is_checkpoint': False, 'printshellcmd': True, 'is_handover': False, 'level': 'job_info', 'timestamp': 1712385655.472389}
{'jobid': 1, 'msg': None, 'name': 'test', 'local': True, 'input': [], 'output': ['b.txt'], 'log': [], 'benchmark': None, 'wildcards': {}, 'reason': 'Missing output files: b.txt; Set of input files has changed since last execution; Code has changed since last execution; Software environment definition has changed since last execution', 'resources': [1, 1, '/tmp'], 'priority': 0, 'threads': 1, 'indent': False, 'is_checkpoint': False, 'printshellcmd': True, 'is_handover': False, 'level': 'job_info', 'timestamp': 1712385655.472389}
{'level': 'debug', 'msg': "Completion of job ['test'] reported to scheduler.", 'timestamp': 1712385655.4739897}
{'level': 'debug', 'msg': "Completion of job ['test'] reported to scheduler.", 'timestamp': 1712385655.4739897}
Touching output file b.txt.
{'level': 'info', 'msg': 'Touching output file b.txt.', 'indent': False, 'timestamp': 1712385655.4761367}
{'level': 'info', 'msg': 'Touching output file b.txt.', 'indent': False, 'timestamp': 1712385655.4761367}
{'level': 'debug', 'msg': 'jobs registered as running before removal {test}', 'timestamp': 1712385655.479458}
{'level': 'debug', 'msg': 'jobs registered as running before removal {test}', 'timestamp': 1712385655.479458}
[Sat Apr  6 14:40:55 2024]
Finished job 1.
{'jobid': 1, 'level': 'job_finished', 'timestamp': 1712385655.4795644}
{'jobid': 1, 'level': 'job_finished', 'timestamp': 1712385655.4795644}
1 of 2 steps (50%) done
{'level': 'progress', 'done': 1, 'total': 2, 'timestamp': 1712385655.4799452}
{'level': 'progress', 'done': 1, 'total': 2, 'timestamp': 1712385655.4799452}
{'level': 'debug', 'msg': "Resources before job selection: {'_cores': 1, '_nodes': 9223372036854775807}", 'timestamp': 1712385655.4804513}
{'level': 'debug', 'msg': "Resources before job selection: {'_cores': 1, '_nodes': 9223372036854775807}", 'timestamp': 1712385655.4804513}
{'level': 'debug', 'msg': 'Ready jobs (1)', 'timestamp': 1712385655.4805186}
{'level': 'debug', 'msg': 'Ready jobs (1)', 'timestamp': 1712385655.4805186}
Select jobs to execute...
{'level': 'info', 'msg': 'Select jobs to execute...', 'indent': False, 'timestamp': 1712385655.4805582}
{'level': 'info', 'msg': 'Select jobs to execute...', 'indent': False, 'timestamp': 1712385655.4805582}
{'level': 'debug', 'msg': 'Using greedy selector because only single job has to be scheduled.', 'timestamp': 1712385655.480737}
{'level': 'debug', 'msg': 'Using greedy selector because only single job has to be scheduled.', 'timestamp': 1712385655.480737}
{'level': 'debug', 'msg': 'Selected jobs (1)', 'timestamp': 1712385655.4815145}
{'level': 'debug', 'msg': 'Selected jobs (1)', 'timestamp': 1712385655.4815145}
{'level': 'debug', 'msg': "Resources after job selection: {'_cores': 0, '_nodes': 9223372036854775806}", 'timestamp': 1712385655.481586}
{'level': 'debug', 'msg': "Resources after job selection: {'_cores': 0, '_nodes': 9223372036854775806}", 'timestamp': 1712385655.481586}
Execute 1 jobs...
{'level': 'info', 'msg': 'Execute 1 jobs...', 'indent': False, 'timestamp': 1712385655.481647}
{'level': 'info', 'msg': 'Execute 1 jobs...', 'indent': False, 'timestamp': 1712385655.481647}

[Sat Apr  6 14:40:55 2024]
localrule all:
    input: b.txt
    jobid: 0
    reason: Input files updated by another job: b.txt
    resources: tmpdir=/tmp

{'jobid': 0, 'msg': None, 'name': 'all', 'local': True, 'input': ['b.txt'], 'output': [], 'log': [], 'benchmark': None, 'wildcards': {}, 'reason': 'Input files updated by another job: b.txt', 'resources': [1, 1, '/tmp'], 'priority': 0, 'threads': 1, 'indent': False, 'is_checkpoint': False, 'printshellcmd': True, 'is_handover': False, 'level': 'job_info', 'timestamp': 1712385655.4818804}
{'jobid': 0, 'msg': None, 'name': 'all', 'local': True, 'input': ['b.txt'], 'output': [], 'log': [], 'benchmark': None, 'wildcards': {}, 'reason': 'Input files updated by another job: b.txt', 'resources': [1, 1, '/tmp'], 'priority': 0, 'threads': 1, 'indent': False, 'is_checkpoint': False, 'printshellcmd': True, 'is_handover': False, 'level': 'job_info', 'timestamp': 1712385655.4818804}
{'level': 'debug', 'msg': "Completion of job ['all'] reported to scheduler.", 'timestamp': 1712385655.4829967}
{'level': 'debug', 'msg': "Completion of job ['all'] reported to scheduler.", 'timestamp': 1712385655.4829967}
{'level': 'debug', 'msg': 'jobs registered as running before removal {all}', 'timestamp': 1712385655.4834087}
{'level': 'debug', 'msg': 'jobs registered as running before removal {all}', 'timestamp': 1712385655.4834087}
[Sat Apr  6 14:40:55 2024]
Finished job 0.
{'jobid': 0, 'level': 'job_finished', 'timestamp': 1712385655.4834876}
{'jobid': 0, 'level': 'job_finished', 'timestamp': 1712385655.4834876}
2 of 2 steps (100%) done
{'level': 'progress', 'done': 2, 'total': 2, 'timestamp': 1712385655.483759}
{'level': 'progress', 'done': 2, 'total': 2, 'timestamp': 1712385655.483759}
Complete log: .snakemake/log/2024-04-06T144054.752622.snakemake.log
{'level': 'info', 'msg': 'Complete log: .snakemake/log/2024-04-06T144054.752622.snakemake.log', 'indent': False, 'timestamp': 1712385655.4846082}
{'level': 'info', 'msg': 'Complete log: .snakemake/log/2024-04-06T144054.752622.snakemake.log', 'indent': False, 'timestamp': 1712385655.4846082}
{'level': 'debug', 'msg': 'unlocking', 'timestamp': 1712385655.4847965}
{'level': 'debug', 'msg': 'unlocking', 'timestamp': 1712385655.4847965}
{'level': 'debug', 'msg': 'removing lock', 'timestamp': 1712385655.4848487}
{'level': 'debug', 'msg': 'removing lock', 'timestamp': 1712385655.4848487}
{'level': 'debug', 'msg': 'removing lock', 'timestamp': 1712385655.4852245}
{'level': 'debug', 'msg': 'removing lock', 'timestamp': 1712385655.4852245}
{'level': 'debug', 'msg': 'removed all locks', 'timestamp': 1712385655.4855657}
{'level': 'debug', 'msg': 'removed all locks', 'timestamp': 1712385655.4855657}

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions