Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
Ash1One opened this issue Apr 6, 2024 · 1 comment
Open

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

Ash1One opened this issue Apr 6, 2024 · 1 comment
Labels
bug Something isn't working

Comments

@Ash1One
Copy link

Ash1One commented 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}
@Ash1One Ash1One added the bug Something isn't working label Apr 6, 2024
@cademirch
Copy link
Contributor

cademirch commented Apr 13, 2024 •
edited

I see this too when testing the wms logger. Printing logger.log_handler shows the wmslogger doubled up:

[<bound method Logger.text_handler of <snakemake.logging.Logger object at 0x10ce3bb30>>, 
<bound method WMSLogger.log_handler of <snakemake.logging.WMSLogger object at 0x10e603470>>, 
<bound method WMSLogger.log_handler of <snakemake.logging.WMSLogger object at 0x10e603470>>]

I guess this might be something that didn't get caught in the transition to the api?

@cademirch cademirch mentioned this issue Apr 13, 2024
Open
2 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Ash1One @cademirch