logging.py: Don't change log level of the root logger to bigger numeric value #3307

KKoukiou · 2018-03-14T08:51:59Z

When doing log capturing we need to temporary change the level of the root logger to be at least
of the log level that the handler used for log capturing has (log_level), so that we 'll be able to capture such logs.

If root logger level has smaller numeric value than log_level parameter we should not enforce root logger level to log_level because we might miss important logs from root logger gathered by other handlers.

KKoukiou · 2018-03-14T09:01:24Z

USE CASE

Our use case is the following:

We have the root logger with log level == DEBUG and using for root logger some FileHandler with DEBUG level as well sending the logs to some files.
Then we need logs with level >= INFO from root logger to be captured by pytest, so that we have use them with junixml plugin.

This constraint is quite important for us, because DEBUG logs are quite a lot, and if we allow logging plugin to capture DEBUG logs we get memory issues in Jenkins, where the tests run.
On the other hand, we really need to have the DEBUG logs in the files, as specified in the logging configuration for python.

RonnyPfannschmidt · 2018-03-14T09:11:35Z

in order to see if we could get by with just correct handler setup i ventured into the python logging package
i am now wishing for a python 4.0 without it

can you please add a test and a change-log entry? i'm also pondering if we should target master or features, since its a slight behaviour change to get this right

RonnyPfannschmidt · 2018-03-14T09:13:16Z

_pytest/logging.py

@@ -153,7 +153,7 @@ def catching_logs(handler, formatter=None, level=None):
        root_logger.addHandler(handler)
    if level is not None:
        orig_level = root_logger.level
-        root_logger.setLevel(level)
+        root_logger.setLevel(min(orig_level, level))


i believe we need to ensure the level of the handler is saved/restored as well, but set to the exact level given,
so the handling will happen at the expected level for the designated handler, even if other handlers work with the original level

I believe setting the log capturing handlers level here

pytest/_pytest/logging.py

Line 146 in b2b629f

handler.setLevel(level)

is enough, or correct me if I am wrong.

correct, that's more than sufficient, thanks for looking that up 👍

coveralls · 2018-03-14T09:18:00Z

Coverage increased (+0.06%) to 92.865% when pulling 6cfed00 on KKoukiou:rhv-qe-fix into ed118d7 on pytest-dev:features.

KKoukiou · 2018-03-14T09:33:18Z

@RonnyPfannschmidt thanks for quick reply, I 'll add tests and entry in changelog.
And I guess feature branch is more appropriate you 're right.

KKoukiou · 2018-03-14T12:50:30Z

doc/en/logging.rst

@@ -224,6 +224,8 @@ made in ``3.4`` after community feedback:

 * Log levels are no longer changed unless explicitly requested by the :confval:`log_level` configuration
  or ``--log-level`` command-line options. This allows users to configure logger objects themselves.
+  When this parameter is used and user requests log level of smaller numeric value than the log level of the root
+  logger then the root logger will be adjusted to have level equal to the requested logging level.


In case this doesn't make sense please suggest rephrase!

I think we don't need to document it in logging.rst. I think having a reasonably descriptive msg in the changelog is enough.

nicoddemus · 2018-03-14T20:53:42Z

Thanks @KKoukiou for the PR!

Then we need logs with level >= INFO from root logger to be captured by pytest, so that we have use them with junixml plugin.

Your use case makes sense, but isn't a little confusing that --log-level=INFO may set root's level to INFO or not, depending of what level is already set? I'm just bringing this up in case adding another option might be better (although we have tons of options already related to logging, heh).

@Thisch couldyou please weigh on this?

twmr · 2018-03-14T21:31:26Z

For those of you, who don't know what this PR is fixing:

Imagine you want to log to a file with a certain log-file-level (e.g. INFO) but don't want to pollute the live-log output (e.g. log-level ERROR) with too many log-messages. Then you can do the following

pytest test_rootlog.py -o log_cli=True --log-level=ERROR --log-file abc.log --log-file-level=INFO

However, with pytest 3.4 only log messages with log-level>=ERROR are written to the log-file abc.log. With this PR you see log-messages with level>=ERROR on the cli and message (>=INFO) in the log-file.

I'll take a closer look at the implementation in the following days.

nicoddemus · 2018-03-14T21:37:34Z

@Thisch I see, thanks for the explanation! 👍

KKoukiou · 2018-03-15T07:43:55Z

@nicoddemus thanks for raising this up and @Thisch thanks for the explanation.
To be honest, I don't like as well that I have to make this extra complication in the logging plugin.

On the other hand, what I didn't like from first place is that when we use --log-level=LOG_LEVEL parameter, thus creating in logging plugin the relevant handler with level == LOG_LEVEL we also affect the root loggers log level.

What I consider as more normal behavior, is that all these "--log-level-*" options in pytest will actually only affect the levels of the handlers they are internally creating and nothing else. If the root logger that they are actually applied on, has root_logger_level > handlers_x_level then it's expected to lose some levels of the logs in that handler, and in this case users have to take care of their configuration of the root logger to have level at least as small as the level the want to have in either log-level, log-level-cli etc options.

Wouldn't it be more clear if all these options where clearly creating only relevant handlers for the root logger and nothing else?

I bet there was some reason behind this decision, but I really don't see it now.

RonnyPfannschmidt · 2018-03-20T17:28:54Z

@Thisch gentle ping, we'd like to include this in 3.5 which is due next week

RonnyPfannschmidt

i believe its fine, but i'D like the additional input of @Thisch

twmr · 2018-03-20T19:28:15Z

Thx @KKoukiou for your suggestion

What I consider as more normal behavior, is that all these "--log-level-*" options in pytest will actually only affect the levels of the handlers they are internally creating and nothing else.

Why do you think that this should be more normal behavior?

If the root logger that they are actually applied on, has
root_logger_level > handlers_x_level then it's expected to lose some levels
of the logs in that handler,

This is clear.

and in this case users have to take care of their configuration of the root logger to have level at least as small as the level the want to have in either log-level, log-level-cli etc options.

Why should the users modify the configuration of the root logger at all in
the test code? In the current design the user doesn't need to care about the
root logger configuration, is that bad in your opinion?

Can you come up with an example, which exposes the weaknesses of the
current design?

I bet there was some reason behind this decision, but I really don't see
it now.

Unfortunately, I can't comment on that.

twmr · 2018-03-20T20:15:04Z

testing/logging/test_reporting.py

+        assert all(x in contents for x in ["warning text going to logger",
+                                           "error text going to logger"])
+
+


I've extended your test a bit:

def test_root_logger_affected(testdir): testdir.makepyfile(''' import logging logger = logging.getLogger() logger.addHandler(logging.FileHandler('pytest.log')) def test_foo(): logger.info('info text ' + 'going to logger') logger.warning('warning text ' + 'going to logger') logger.error('error text ' + 'going to logger') assert 0 ''') log_file = testdir.tmpdir.join('pytest.log').strpath result = testdir.runpytest('--log-level=ERROR') assert result.ret == 1 # the capture log calls in the stdout section only contain the # logger.error msg, because --log-level=ERROR result.stdout.fnmatch_lines(['*error text going to logger*',]) with pytest.raises(pytest.fail.Exception): result.stdout.fnmatch_lines(['*warning text going to logger*',]) with pytest.raises(pytest.fail.Exception): result.stdout.fnmatch_lines(['*info text going to logger*',]) # the log file should contain the warning and the error log messages and # not the info one, because the default level of the root logger is # WARNING. assert os.path.isfile(log_file) with open(log_file) as rfh: contents = rfh.read() assert "info text going to logger" not in contents assert "warning text going to logger" in contents assert "error text going to logger" in contents

Can you use that instead, if your a satisfied with it?

Sure. Thanks for extending it.

twmr · 2018-03-20T20:16:53Z

changelog/3307.feature.rst

@@ -0,0 +1,3 @@
+pytest should not change the log level of the root logger
+when the ``log-level`` parameter is set with value
+``LOG_LEVEL>root_logger_level``.


-> when the log-level parameter has greater numeric value than that of the level of the root logger.

twmr · 2018-03-20T20:21:13Z

doc/en/logging.rst

@@ -224,6 +224,8 @@ made in ``3.4`` after community feedback:

 * Log levels are no longer changed unless explicitly requested by the :confval:`log_level` configuration
  or ``--log-level`` command-line options. This allows users to configure logger objects themselves.
+  When this parameter is used and user requests log level of smaller numeric value than the log level of the root
+  logger then the root logger will be adjusted to have level equal to the requested logging level.


I think we don't need to document it in logging.rst. I think having a reasonably descriptive msg in the changelog is enough.

twmr · 2018-03-20T20:40:15Z

Here is another example which is fixed by this PR:

import logging
logger = logging.getLogger()

def test_foo():
    logger.info('info text ' + 'going to logger')
    logger.warning('warning text ' + 'going to logger')
    logger.error('error text ' + 'going to logger')

    assert 0

Without this fix the following testrun does not show the info and the warning log message in the live log output

$> pytest --log-cli-level=INFO --log-level=ERROR test1.py
...
------------------------------------------------------------- live log call -------------------------------------------------------------
test1.py     7 ERROR    error text going to logger
FAILED                                                                                                                            [100%]

=============================================================== FAILURES ================================================================
_______________________________________________________________ test_foo ________________________________________________________________

    def test_foo():
        logger.info('info text ' + 'going to logger')
        logger.warning('warning text ' + 'going to logger')
        logger.error('error text ' + 'going to logger')
    
>       assert 0
E       assert 0

test1.py:9: AssertionError
----------------------------------------------------------- Captured log call -----------------------------------------------------------
test1.py     7 ERROR    error text going to logger

@KKoukiou please add this test also to the unittests

twmr · 2018-03-21T08:28:47Z

testing/logging/test_reporting.py

+        import logging
+
+        logger = logging.getLogger()
+        logger.addHandler(logging.FileHandler('pytest.log'))


I would prefer to not add the FileHandler manually but use the --log-file cmd line option instead. I'm fine with testing both cases

Replaced with --log-file.

KKoukiou · 2018-03-21T09:41:51Z

@Thisch thanks for being open to this discussion. See answer inline.

Thx @KKoukiou for your suggestion

    What I consider as more normal behavior, is that all these "--log-level-*"
    options in pytest will actually only affect the levels of the handlers they
    are internally creating and nothing else.

Why do you think that this should be more normal behavior?

See answer bellow.

    If the root logger that they are actually applied on, has
    root_logger_level > handlers_x_level then it's expected to lose some levels
    of the logs in that handler,

This is clear.

    and in this case users have to take care of their configuration of the root
    logger to have level at least as small as the level the want to have in
    either log-level, log-level-cli etc options.

Why should the users modify the configuration of the root logger at all in
the test code? In the current design the user doesn't need to care about the
root logger configuration, is that bad in your opinion?

Overwritting the root logger configuration from pytest, according to some
parameters, might at first look handy to the user, who doesn't need to
touch his tests code for getting some extra/less logs but it leads to unessesary
complexity in pytest logging plugin, which I personally took some time to
understand how to use, and I bet it's not clear for more users.

Additionally, when we in pytest overwrite the logger values and invalidate the
loggers configuration it's somehow bad IMO. See example bellow.

Can you come up with an example, which exposes the weaknesses of the
current design?

Lets say your tests use the following logging configuration file.

handlers:
  file:
    class : logging.FileHandler
    level: DEBUG
    filename: logconfig.log
loggers:
   randomlogger:
     level: DEBUG
     handlers:
       - file
   propagate: 0
root:
  level: INFO
  handlers:
    - file

logconfig.log file will have DEBUG logs from randomlogger
and INFO logs from root logger.

If you 'll pass --log-level=DEBUG because someone decided that
he wants to capture logs of DEBUG you will flood the logconfig.log
with DEBUG logs from root logger which were not supposed to be there.
But you don't want to restrict the file handlers to level == INFO
because you need the DEBUG logs from randomlogger.

This is example might not be the best, but my point is that I believe we should
not invalidate logging configuration from python,
thinking that for users it might be 'easier' to not change their code to see
some logs which where initially NOT supposed to be seen.

PS: I know that we can use here log-file option and avoid this, but imagine root logger
might have logs outside of tests as well, like from plugins etc which will not be captured
in the pytest defined log file.

    I bet there was some reason behind this decision, but I really don't see
    it now.

Unfortunately, I can't comment on that.

twmr

This looks good now, except the few code style issues.

twmr · 2018-03-25T11:05:58Z

testing/logging/test_reporting.py

+
+def test_log_cli_level_log_level_interaction(testdir):
+    testdir.makepyfile('''
+    import logging


This and the following lines should be indented.

twmr · 2018-03-25T11:11:04Z

testing/logging/test_reporting.py

@@ -49,6 +49,66 @@ def test_foo():
                                 'text going to stderr'])


+def test_root_logger_affected(testdir):
+    testdir.makepyfile('''


Use tiple-double-quotes

twmr · 2018-03-25T11:11:13Z

testing/logging/test_reporting.py

+            logger.error('error text ' + 'going to logger')
+
+            assert 0
+        ''')


Unindent this line

twmr · 2018-03-25T11:11:55Z

testing/logging/test_reporting.py

+            '*WARNING*warning text going to logger',
+            '*ERROR*error text going to logger',
+            '=* 1 failed in *=',
+        ])


Lines 103 to 108 should be unindented by one level.

…ic value

nicoddemus · 2018-03-27T21:03:35Z

Thanks @KKoukiou and everyone involved!

This PR updates [pytest](https://pypi.org/project/pytest) from **3.5.1** to **3.6.3**. <details> <summary>Changelog</summary> ### 3.6.2 ``` ========================= Bug Fixes --------- - Fix regression in ``Node.add_marker`` by extracting the mark object of a ``MarkDecorator``. (`3555 <https://github.com/pytest-dev/pytest/issues/3555>`_) - Warnings without ``location`` were reported as ``None``. This is corrected to now report ``<undetermined location>``. (`3563 <https://github.com/pytest-dev/pytest/issues/3563>`_) - Continue to call finalizers in the stack when a finalizer in a former scope raises an exception. (`3569 <https://github.com/pytest-dev/pytest/issues/3569>`_) - Fix encoding error with `print` statements in doctests (`3583 <https://github.com/pytest-dev/pytest/issues/3583>`_) Improved Documentation ---------------------- - Add documentation for the ``--strict`` flag. (`3549 <https://github.com/pytest-dev/pytest/issues/3549>`_) Trivial/Internal Changes ------------------------ - Update old quotation style to parens in fixture.rst documentation. (`3525 <https://github.com/pytest-dev/pytest/issues/3525>`_) - Improve display of hint about ``--fulltrace`` with ``KeyboardInterrupt``. (`3545 <https://github.com/pytest-dev/pytest/issues/3545>`_) - pytest's testsuite is no longer runnable through ``python setup.py test`` -- instead invoke ``pytest`` or ``tox`` directly. (`3552 <https://github.com/pytest-dev/pytest/issues/3552>`_) - Fix typo in documentation (`3567 <https://github.com/pytest-dev/pytest/issues/3567>`_) ``` ### 3.6.1 ``` ========================= Bug Fixes --------- - Fixed a bug where stdout and stderr were logged twice by junitxml when a test was marked xfail. (`3491 <https://github.com/pytest-dev/pytest/issues/3491>`_) - Fix ``usefixtures`` mark applyed to unittest tests by correctly instantiating ``FixtureInfo``. (`3498 <https://github.com/pytest-dev/pytest/issues/3498>`_) - Fix assertion rewriter compatibility with libraries that monkey patch ``file`` objects. (`3503 <https://github.com/pytest-dev/pytest/issues/3503>`_) Improved Documentation ---------------------- - Added a section on how to use fixtures as factories to the fixture documentation. (`3461 <https://github.com/pytest-dev/pytest/issues/3461>`_) Trivial/Internal Changes ------------------------ - Enable caching for pip/pre-commit in order to reduce build time on travis/appveyor. (`3502 <https://github.com/pytest-dev/pytest/issues/3502>`_) - Switch pytest to the src/ layout as we already suggested it for good practice - now we implement it as well. (`3513 <https://github.com/pytest-dev/pytest/issues/3513>`_) - Fix if in tests to support 3.7.0b5, where a docstring handling in AST got reverted. (`3530 <https://github.com/pytest-dev/pytest/issues/3530>`_) - Remove some python2.5 compatibility code. (`3529 <https://github.com/pytest-dev/pytest/issues/3529>`_) ``` ### 3.6.0 ``` ========================= Features -------- - Revamp the internals of the ``pytest.mark`` implementation with correct per node handling which fixes a number of long standing bugs caused by the old design. This introduces new ``Node.iter_markers(name)`` and ``Node.get_closest_mark(name)`` APIs. Users are **strongly encouraged** to read the `reasons for the revamp in the docs <https://docs.pytest.org/en/latest/mark.htmlmarker-revamp-and-iteration>`_, or jump over to details about `updating existing code to use the new APIs <https://docs.pytest.org/en/latest/mark.htmlupdating-code>`_. (`3317 <https://github.com/pytest-dev/pytest/issues/3317>`_) - Now when ``pytest.fixture`` is applied more than once to the same function a ``ValueError`` is raised. This buggy behavior would cause surprising problems and if was working for a test suite it was mostly by accident. (`2334 <https://github.com/pytest-dev/pytest/issues/2334>`_) - Support for Python 3.7's builtin ``breakpoint()`` method, see `Using the builtin breakpoint function <https://docs.pytest.org/en/latest/usage.htmlbreakpoint-builtin>`_ for details. (`3180 <https://github.com/pytest-dev/pytest/issues/3180>`_) - ``monkeypatch`` now supports a ``context()`` function which acts as a context manager which undoes all patching done within the ``with`` block. (`3290 <https://github.com/pytest-dev/pytest/issues/3290>`_) - The ``--pdb`` option now causes KeyboardInterrupt to enter the debugger, instead of stopping the test session. On python 2.7, hitting CTRL+C again exits the debugger. On python 3.2 and higher, use CTRL+D. (`3299 <https://github.com/pytest-dev/pytest/issues/3299>`_) - pytest not longer changes the log level of the root logger when the ``log-level`` parameter has greater numeric value than that of the level of the root logger, which makes it play better with custom logging configuration in user code. (`3307 <https://github.com/pytest-dev/pytest/issues/3307>`_) Bug Fixes --------- - A rare race-condition which might result in corrupted ``.pyc`` files on Windows has been hopefully solved. (`3008 <https://github.com/pytest-dev/pytest/issues/3008>`_) - Also use iter_marker for discovering the marks applying for marker expressions from the cli to avoid the bad data from the legacy mark storage. (`3441 <https://github.com/pytest-dev/pytest/issues/3441>`_) - When showing diffs of failed assertions where the contents contain only whitespace, escape them using ``repr()`` first to make it easy to spot the differences. (`3443 <https://github.com/pytest-dev/pytest/issues/3443>`_) Improved Documentation ---------------------- - Change documentation copyright year to a range which auto-updates itself each time it is published. (`3303 <https://github.com/pytest-dev/pytest/issues/3303>`_) Trivial/Internal Changes ------------------------ - ``pytest`` now depends on the `python-atomicwrites <https://github.com/untitaker/python-atomicwrites>`_ library. (`3008 <https://github.com/pytest-dev/pytest/issues/3008>`_) - Update all pypi.python.org URLs to pypi.org. (`3431 <https://github.com/pytest-dev/pytest/issues/3431>`_) - Detect `pytest_` prefixed hooks using the internal plugin manager since ``pluggy`` is deprecating the ``implprefix`` argument to ``PluginManager``. (`3487 <https://github.com/pytest-dev/pytest/issues/3487>`_) - Import ``Mapping`` and ``Sequence`` from ``_pytest.compat`` instead of directly from ``collections`` in ``python_api.py::approx``. Add ``Mapping`` to ``_pytest.compat``, import it from ``collections`` on python 2, but from ``collections.abc`` on Python 3 to avoid a ``DeprecationWarning`` on Python 3.7 or newer. (`3497 <https://github.com/pytest-dev/pytest/issues/3497>`_) ``` </details> <details> <summary>Links</summary> - PyPI: https://pypi.org/project/pytest - Changelog: https://pyup.io/changelogs/pytest/ - Repo: https://github.com/pytest-dev/pytest/issues - Homepage: http://pytest.org </details>

twmr · 2020-05-02T22:39:50Z

What I consider as more normal behavior, is that all these "--log-level-*" options in pytest will actually only affect the levels of the handlers they are internally creating and nothing else.

@KKoukiou I'm currently having a look at removing the root-logger-level code from the logging plugin, due to a discussion in #7139 (comment).

RonnyPfannschmidt reviewed Mar 14, 2018

View reviewed changes

KKoukiou force-pushed the rhv-qe-fix branch from ec68803 to 229e3cb Compare March 14, 2018 12:47

KKoukiou changed the base branch from master to features March 14, 2018 12:47

KKoukiou force-pushed the rhv-qe-fix branch from 229e3cb to 4df1a1c Compare March 14, 2018 12:49

KKoukiou commented Mar 14, 2018

View reviewed changes

KKoukiou force-pushed the rhv-qe-fix branch 2 times, most recently from a5435ef to 62afe33 Compare March 14, 2018 15:25

nicoddemus requested a review from twmr March 14, 2018 20:38

RonnyPfannschmidt approved these changes Mar 20, 2018

View reviewed changes

twmr suggested changes Mar 20, 2018

View reviewed changes

twmr reviewed Mar 21, 2018

View reviewed changes

KKoukiou force-pushed the rhv-qe-fix branch from 62afe33 to 60cd1eb Compare March 21, 2018 08:59

KKoukiou force-pushed the rhv-qe-fix branch from 60cd1eb to 701b255 Compare March 21, 2018 09:43

twmr suggested changes Mar 25, 2018

View reviewed changes

logging.py: Don't change log level of the root logger to bigger numer…

d895f5d

…ic value

KKoukiou force-pushed the rhv-qe-fix branch from 701b255 to d895f5d Compare March 26, 2018 08:12

Tweak changelog entry

6cfed00

twmr approved these changes Mar 27, 2018

View reviewed changes

nicoddemus merged commit 2962c73 into pytest-dev:features Mar 27, 2018

KKoukiou deleted the rhv-qe-fix branch March 29, 2018 11:11

nicoddemus mentioned this pull request May 4, 2018

Logging gobbled up after pytest.main executed #3450

Open

		assert all(x in contents for x in ["warning text going to logger",
		"error text going to logger"])

logging.py: Don't change log level of the root logger to bigger numeric value #3307

logging.py: Don't change log level of the root logger to bigger numeric value #3307

Conversation

KKoukiou commented Mar 14, 2018

KKoukiou commented Mar 14, 2018

RonnyPfannschmidt commented Mar 14, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Mar 14, 2018 • edited Loading

KKoukiou commented Mar 14, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nicoddemus commented Mar 14, 2018

twmr commented Mar 14, 2018

nicoddemus commented Mar 14, 2018

KKoukiou commented Mar 15, 2018

RonnyPfannschmidt commented Mar 20, 2018

RonnyPfannschmidt left a comment

Choose a reason for hiding this comment

twmr commented Mar 20, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

twmr commented Mar 20, 2018 • edited Loading

twmr Mar 21, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

KKoukiou commented Mar 21, 2018

twmr left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nicoddemus commented Mar 27, 2018

twmr commented May 2, 2020

coveralls commented Mar 14, 2018 •

edited

Loading

twmr commented Mar 20, 2018 •

edited

Loading

twmr commented Mar 20, 2018 •

edited

Loading

twmr Mar 21, 2018 •

edited

Loading