Control loggers in GPF tests

For long time when you run GPF tests (dae or wdae) by default the logging level was set to DEBUG. Unfortunately this makes logging not helpfull in figuring out any problems because the size of the generated logs.

So we switched the default logging level to ERROR.

For example, if you run dae/effect_annotation/tests/test_splice_site_tests.py::test_insertion_3_prime_side with enabled output:

py.test -vs \
    dae/effect_annotation/tests/test_splice_site_tests.py::test_insertion_3_prime_side

the test will produce almost no output:

========================================================================================================================= test session starts =
platform linux -- Python 3.9.7, pytest-6.2.4, py-1.11.0, pluggy-0.13.1 -- .../anaconda3/envs/gpf2/bin/python
cachedir: .pytest_cache
rootdir: .../gpf/dae, configfile: pytest.ini
plugins: typeguard-2.13.3, xdist-2.3.0, mock-3.6.1, cov-2.12.1, django-4.4.0, forked-1.3.0, doctestplus-0.12.0, dae-conftests-0.1.0
collected 1 item

dae/effect_annotation/tests/test_splice_site_tests.py::test_insertion_3_prime_side PASSED

========================================================================================================================= 1 passed in 0.01s =

This document describes the options for controlling logging level for loggers in GPF tests.

Control default logging level

When you run tests you can pass an option --logger-default that controls default logging level for all loggers.

Let say that you want to run above mentioned test enabling all loggers. If you pass --logger-default=DEBUG, then the default logging level for all loggers will become DEBUG

py.test -vs --logger-default=DEBUG \
    dae/effect_annotation/tests/test_splice_site_tests.py::test_insertion_3_prime_side

and the output is going to be much more detailed including all messages from all loggers:

============================================================================================================================= test session starts =
platform linux -- Python 3.9.7, pytest-6.2.4, py-1.11.0, pluggy-0.13.1 -- /home/lubo/Local/anaconda3/envs/gpf2/bin/python
cachedir: .pytest_cache
rootdir: /home/lubo/Work/seq-pipeline/gpf/dae, configfile: pytest.ini
plugins: typeguard-2.13.3, xdist-2.3.0, mock-3.6.1, cov-2.12.1, django-4.4.0, forked-1.3.0, doctestplus-0.12.0, dae-conftests-0.1.0
collected 1 item

dae/effect_annotation/tests/test_splice_site_tests.py::test_insertion_3_prime_side 2022-03-28 15:41:42,959 - dae.effect_annotation.effect_checkers.splice_site - DEBUG - pos: 80-80 checking intronic region 70-80 90
2022-03-28 15:41:42,959 - dae.effect_annotation.effect_checkers.splice_site - DEBUG - pos: 80-80 checking intronic region 90-100 110
2022-03-28 15:41:42,959 - dae.effect_annotation.effect_checkers.splice_site - DEBUG - pos: 79-79 checking intronic region 70-80 90
2022-03-28 15:41:42,959 - dae.effect_annotation.annotation_request - DEBUG - start len 6 65-70
2022-03-28 15:41:42,959 - dae.effect_annotation.annotation_request - DEBUG - total 17 + len 11 90-79
2022-03-28 15:41:42,959 - dae.effect_annotation.annotation_request - DEBUG - total 28 + len 11 110-99
2022-03-28 15:41:42,959 - dae.effect_annotation.annotation_request - DEBUG - total 27 - len 1 110-109
2022-03-28 15:41:42,959 - dae.effect_annotation.annotation_request - DEBUG - start len 6 65-70
2022-03-28 15:41:42,959 - dae.effect_annotation.annotation_request - DEBUG - total 17 + len 11 90-79
2022-03-28 15:41:42,959 - dae.effect_annotation.annotation_request - DEBUG - total 28 + len 11 110-99
2022-03-28 15:41:42,959 - dae.effect_annotation.annotation_request - DEBUG - get_coding_nucleotide_position pos=2000 len=28
2022-03-28 15:41:42,960 - dae.effect_annotation.annotation_request - DEBUG - get_coding_nucleotide_position pos=80 len=6
2022-03-28 15:41:42,960 - dae.effect_annotation.effect_checkers.splice_site - DEBUG - pos: 78-78 checking intronic region 70-80 90
2022-03-28 15:41:42,960 - dae.effect_annotation.effect_checkers.splice_site - DEBUG - pos: 78-78 checking intronic region 90-100 110
PASSED

============================================================================================================================= 1 passed in 0.01s =

Control logging level for specific loggers

Let say we want to conroll logging level for specific logger. Let’s say you want to run the above mentioned test with enabling debug logging only for dae.effect_annotation.annotation_request logger. Then you can run the test as follows:

py.test -vs --logger-debug \
    dae.effect_annotation.annotation_request \
    -- \
    dae/effect_annotation/tests/test_splice_site_tests.py::test_insertion_3_prime_side

then only the specified logger will have logging level DEBUG:

=============================================================================================================================== test session starts =
platform linux -- Python 3.9.7, pytest-6.2.4, py-1.11.0, pluggy-0.13.1 -- /home/lubo/Local/anaconda3/envs/gpf2/bin/python
cachedir: .pytest_cache
rootdir: /home/lubo/Work/seq-pipeline/gpf/dae, configfile: pytest.ini
plugins: typeguard-2.13.3, xdist-2.3.0, mock-3.6.1, cov-2.12.1, django-4.4.0, forked-1.3.0, doctestplus-0.12.0, dae-conftests-0.1.0
collected 1 item

dae/effect_annotation/tests/test_splice_site_tests.py::test_insertion_3_prime_side 2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - start len 6 65-70
2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - total 17 + len 11 90-79
2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - total 28 + len 11 110-99
2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - total 27 - len 1 110-109
2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - start len 6 65-70
2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - total 17 + len 11 90-79
2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - total 28 + len 11 110-99
2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - get_coding_nucleotide_position pos=2000 len=28
2022-03-28 15:51:14,917 - dae.effect_annotation.annotation_request - DEBUG - get_coding_nucleotide_position pos=80 len=6
PASSED

=============================================================================================================================== 1 passed in 0.01s ===

The option –logger-debug is accepting list loggers. So you can use:

py.test -vs --logger-debug \
        dae.effect_annotation.annotation_request \
        dae.effect_annotation.effect_checkers \
        -- \
    dae/effect_annotation/tests/test_splice_site_tests.py::test_insertion_3_prime_side

Note

Note the usage of -- to finish the list of parameters passed to --logger-debug.

Parameters to control logging in GPF tests

GPF tests will accept following parameters that control the logging:

Parameter

Description

--logger-default

specifies default logging level for all loggers. If parameter is not passed, the default logging level is set to ERROR

--logger-debug

list of loggers whose logging level will be set to DEBUG

--logger-info

list of loggers whose logging level will be set to INFO

--logger-warning

list of loggers whose logging level will be set to WARNING

--logger-error

list of loggers whose logging level will be set to ERROR