Changes in the logging plugin for 3.4 #3124
Conversation
nicoddemus
force-pushed
the
logging-3013
branch
from
dbeaaf1 to
f64a084
Compare
There was a problem hiding this comment.
IMO there are still some usability issues that can be improved, but this can probably be done in a different PR:
- turn on --verbose output automatically when log_cli is set to True. Otherwise log message and the test progress indicator (the dots in the cli output) are mixed.
- when log_cli is true add a newline before the first log message in each test. Otherwise the first log message is shown on the same line as the testname, provided that
-vis specified on the command line.
_pytest/logging.py
Outdated
| logger = logging.getLogger(logger) | ||
| logger_name = logger | ||
| logger = logging.getLogger(logger_name) | ||
| self._initial_log_levels.setdefault(logger_name, logger.level) |
There was a problem hiding this comment.
Nice usage of setdefault! However, a comment describing what this line does would be nice.
| return LogCaptureFixture(request.node) | ||
| result = LogCaptureFixture(request.node) | ||
| yield result | ||
| result._finalize() |
There was a problem hiding this comment.
I guess that a try finally block is needed here around yield result. Otherwise result._finalize() is not called if an exception is raised in the code called after yield result.
There was a problem hiding this comment.
Your suggestion is true for @contextmanager, but it is not needed for pytest fixtures: the code after the yield is always executed regardless if an exception has been raised in the test or not. 😉
|
|
||
| def test1(caplog): | ||
| caplog.set_level(logging.INFO) | ||
| # using + operator here so fnmatch_lines doesn't match the code in the traceback |
testing/logging/test_reporting.py
Outdated
| [pytest] | ||
| log_cli=true | ||
| ''') | ||
| result = testdir.runpytest('-s') |
There was a problem hiding this comment.
The capture=no pararmeter should not be needed here (at least not for enable=True), right? You probably want to explicitly test that the log message is not shown in the console output when enabled=False. Nice!
There was a problem hiding this comment.
Indeed good points, will do!
testing/logging/test_reporting.py
Outdated
| result.stderr.fnmatch_lines([ | ||
| "* This log message will be shown" | ||
| result.stdout.fnmatch_lines([ | ||
| '*WARNING message will be shown*', |
There was a problem hiding this comment.
you can merge the two result.stdout.fnmatch_lines calls.
BTW there seems to be an issue with the indentation of the progress indicator (100%).
(pytest_venv) thomas-XPS-13-9360 :: ~gr/pytest_logging_tests » pytest test.py -v --log-cli-format '%(message)s'
================================================================= test session starts ==================================================================
platform linux2 -- Python 2.7.12, pytest-3.3.3.dev51+gf64a084, py-1.5.2, pluggy-0.6.0 -- /home/thomas/gitrepos/pytest_venv/bin/python
cachedir: .cache
rootdir: /home/thomas/gitrepos/pytest_logging_tests, inifile: pytest.ini
plugins: xdist-1.20.1, sphinx-0.2, forked-0.2, cov-2.5.1, hypothesis-3.40.1
collected 1 item
test.py::test_log_cli PASSED [100%]
=============================================================== 1 passed in 0.00 seconds ===============================================================
(pytest_venv) thomas-XPS-13-9360 :: ~gr/pytest_logging_tests » pytest test.py
================================================================= test session starts ==================================================================
platform linux2 -- Python 2.7.12, pytest-3.3.3.dev51+gf64a084, py-1.5.2, pluggy-0.6.0
rootdir: /home/thomas/gitrepos/pytest_logging_tests, inifile: pytest.ini
plugins: xdist-1.20.1, sphinx-0.2, forked-0.2, cov-2.5.1, hypothesis-3.40.1
collected 1 item
test.py . [100%]
=============================================================== 1 passed in 0.00 seconds ================
The output of the progress indicator is automatically disabled when -s is specified on the command line but not when log_cli is set to True.
There was a problem hiding this comment.
Indeed, this test was written before log_cli would write to stdout and I forgot to update the test, thanks.
I will also take a look at the progress indicator issue, thanks for pointing it out.
doc/en/logging.rst
Outdated
| * 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. | ||
| * :ref:`Live Logs <live_logs>` is now disabled by default and can be enabled setting the | ||
| :confval:`log_cli` configuration option to ``true``. |
There was a problem hiding this comment.
why didn't you add a command line flag for log_cli? When writing tests or debugging problems I want to temporarily turn on cli logging using a command line flag and not by editing pytest.ini.
There was a problem hiding this comment.
Nowadays (after pytest 3.0) we should avoid adding duplicate command-line flags and options because you can use the new -o option to change ini options in the command line:
pytest -o log_cli=true
There was a problem hiding this comment.
Ahh I forgot that this is possible nowadays. For me it seems that the live logging feature is put in second place compared to the -s command line flag for --capture=no. I agree that it does not make sense to add duplicate command-line flags for every option but at least for the log_cli option an short command line parameter (similar to -s) would be nice.
There was a problem hiding this comment.
Let's add a short option in another PR if we see demand for it.
|
And I forgot to mention: Thank you very much for working on this!!! 👍 |
|
Thx for the quick response. I've already implemented a fix for the missing-newline-for-first-log-message issue. However, I can't find the commit atm. The fix is easy: Subclass from logging.StreamHandler and add an |
Ahh I was wondering how to implement that, thanks for this. 👍 😁 |
|
Once this PR is merged I'll work on improving the visual appearance of the live logging output: Colored log levels, tabular output (all columns (message, timestamp, loglevel,..) should be aligned) |
|
I've found a bug when live logging is enabled: warning messages are shown both in the |
|
I've implemented your suggestions, thanks!
Hmm I can't reproduce this, can you try again with the latest version of this branch? |
|
No it doesn't make a difference. BTW, the live log output is only shown if I turn capturing off using -s. |
|
Hmm I still can't reproduce the problem you posted before. Here's my test file: import logging
LOGGER = logging.getLogger(__name__)
def test_captured_log_report():
LOGGER.info("INFO message won't be shown")
LOGGER.warning("WARNING message will be shown")
print('PASSED')
assert 0And here is the output I'm getting: Can you please try my example and see if you get the same results? |
|
With the same input file and the latest pytest (from you feature branch) I get the following output: and I don't understand why we get different outputs. I installed pytest into a fresh virtualenv before to rule out that it has to do with other packages installed in the virtualenv. |
|
Oh OK I got it, using Python 2.7 I also get the same output as you, including the problem with the progress indicator. 😅 I will take a look at this tomorrow. 👍 |
|
@nicoddemus as you asked me in #3126 I tested your PR for my use-case and I have some issues. Please see bellow dummy example: Tests file(.art) [kkoukiou@katerina workdir]$ cat test_template.py
import logging.config
import yaml
import pytest
conf_file="logger_conf.yaml"
with open(conf_file, 'r') as stream:
conf_data = yaml.load(stream)
logging.config.dictConfig(conf_data)
flow = logging.getLogger('art.flow')
@pytest.fixture
def setup_1():
flow.info("Hi with info from test 1 setup")
def test_function_1(setup_1):
# Logs from this test with level > INFO are expected to be in console
flow.debug("Hi with debug from test 1")
flow.info("Hi with info from test 1")
flow.error("Hi with error from test 1")Logging configuration file(.art) [kkoukiou@katerina workdir]$ cat logger_conf.yaml
---
version: 1
handlers:
consoleHandler:
class: logging.StreamHandler
level: INFO
stream: ext://sys.stdout
simpleFileHandler:
class: logging.FileHandler
filename: logs.txt
loggers:
art.flow:
level: INFO
handlers:
- consoleHandler
propagate: 0
root:
level: DEBUG
handlers:
- simpleFileHandler
disable_existing_loggers: FalseRunning with #1st Run(.art) [kkoukiou@katerina workdir]$ py.test test_template.py -s
==================================================================================== test session starts =====================================================================================
platform linux2 -- Python 2.7.13, pytest-3.2.3.dev491+gf64a084a, py-1.5.2, pluggy-0.6.0
rootdir: /home/kkoukiou/workdir, inifile:
plugins: xdist-1.20.0, ordering-0.5, marker-bugzilla-0.7, logger-0.3.0, jira-0.3.5, forked-0.2, art-0.0.0
collected 1 item
test_template.py Hi with info from test 1 setup
Hi with info from test 1
Hi with error from test 1
.
================================================================================== 1 passed in 0.01 seconds =================================================================================#2nd Run (Let's try log_cli option)(.art) [kkoukiou@katerina workdir]$ py.test test_template.py -o log_cli=true --junit-xml=xunit_output.xml
==================================================================================== test session starts =====================================================================================
platform linux2 -- Python 2.7.13, pytest-3.2.3.dev491+gf64a084a, py-1.5.2, pluggy-0.6.0
rootdir: /home/kkoukiou/workdir, inifile:
plugins: xdist-1.20.0, ordering-0.5, marker-bugzilla-0.7, logger-0.3.0, jira-0.3.5, forked-0.2, art-0.0.0
collected 1 item
test_template.py . [100%]
---------------------------------------------------------------- generated xml file: /home/kkoukiou/workdir/xunit_output.xml -----------------------------------------------------------------
================================================================================== 1 passed in 0.01 seconds ==================================================================================(.art) [kkoukiou@katerina workdir]$ cat xunit_output.xml
<?xml version="1.0" encoding="utf-8"?><testsuite errors="0" failures="0" name="pytest" skips="0" tests="1" time="0.011"><properties><property name="polarion-custom-isautomated" value="True"/><property name="polarion-response-myproduct" value="None"/><property name="polarion-testrun-id" value="None"/><property name="polarion-custom-plannedin" value="None"/><property name="polarion-user-id" value="None"/><property name="polarion-project-id" value="None"/><property name="polarion-custom-arch" value="None"/></properties><testcase classname="test_template" file="test_template.py" line="19" name="test_function_1" time="0.00116491317749"><system-out>Hi with info from test 1 setup
Hi with info from test 1
Hi with error from test 1
</system-out></testcase></testsuite>So, here since So, is log_cli supposed to support such use case, or maybe there is other WA that I can use? @update: Now that I am seeing closer, I think this PR maybe not be even relevant in my needs. What I need, is some way, to be able to see the console output like when using |
|
@nicoddemus I'll try this branch out shortly and give you my feedback. |
|
@nicoddemus, I get the same output as in my python2.7 env using your example when running pytest in a python3.6 env. Something is fishy here. |
|
Hi @KKoukiou, thanks for trying it out so quickly and providing the means for me to reproduce it. You don't see any logging when using loggers:
art.flow:
level: INFO
handlers:
- consoleHandler
propagate: 0Because propagation is disabled when you log something the handler installed by pytest never receives the logging records, which explains why you don't see any output in the terminal. Commenting the <?xml version="1.0" encoding="utf-8"?><testsuite errors="0" failures="0" name="pytest" skips="0" tests="1" time="0.040"><testcase classname="test_template" file="test_template.py" line="18" name="test_function_1" time="0.009990692138671875"><system-out>Hi with info from test 1 setup
Hi with info from test 1
Hi with error from test 1
</system-out></testcase></testsuite>But note that I get this output with Python 3.6; with Python 2.7 things don't go so well: I'm investigating this issue, which @Thisch has already noticed and reported. |
|
@Thisch I figured out what's happening. It was working on my machine in Python 3.6 because there's a workaround specifically for Python 3.6 on Windows which caused things to work for me. It also explains why you couldn't reproduce my results even on Python 3.6. 😅 In order for the live logging feature to work we have to explicitly suspend capture when emitting log messages. I've pushed a new commit which fixes this, it would be great if @Thisch and @KKoukiou could give the branch another go. |
|
@nicoddemus I tried again with the new commit included, but I still can't get in console what you posted before. As you suggested I commented out the propagate: true, and this is what I see: (.art) [kkoukiou@katerina nicoddemus-pytest]$ py.test test_template.py -o log_cli=true --junit-xml=xunit_output.xml
==================================================================================== test session starts =====================================================================================
platform linux2 -- Python 2.7.13, pytest-3.2.3.dev491+gf64a084a, py-1.5.2, pluggy-0.6.0
rootdir: /home/kkoukiou/repos/nicoddemus-pytest, inifile: pytest.ini
plugins: xdist-1.20.0, ordering-0.5, marker-bugzilla-0.7, logger-0.3.0, jira-0.3.5, forked-0.2, art-0.0.0
collected 1 item
test_template.py . [100%]
-------------------------------------------------------- generated xml file: /home/kkoukiou/repos/nicoddemus-pytest/xunit_output.xml ---------------------------------------------------------
================================================================================== 1 passed in 0.01 seconds ==================================================================================Same result with: |
doc/en/logging.rst
Outdated
| [pytest] | ||
| addopts=-p no:logging | ||
| .. versionadded:: 3.3 | ||
| .. versionchanged:: 3.4 | ||
|
|
||
| Log messages are captured by default and for each failed test will be shown in |
There was a problem hiding this comment.
Note to self: should update this phrasing to mention that pytest will capture WARNING and above only by default.
|
Great @nicoddemus! Now pytest works as expected. So far I've only tested your example from #3124 (comment) in a py2.7 venv. |
As commented in review, this makes it consistent with the headers shown
by stdout/stderr capturing ("Captured log call")
_pytest/logging.py
Outdated
| @@ -368,12 +371,33 @@ class _LiveLoggingStreamHandler(logging.StreamHandler): | |||
| """ | |||
| Custom StreamHandler used by the live logging feature: it will write a newline before the first log message | |||
| in each test. | |||
|
|
|||
| During live logging we must also explicitly disable stdout/stderr capturing otherwise it will get captured | |||
There was a problem hiding this comment.
I guess this is the reason that when I enabled log_cli I can't get any logs into the junitxml file. Junitxml plugin AFAIK gets all captured logs sections and puts them inside the xml file. If you don't capture logs here, when the log_cli is enabled, we will never be able to see logs in console and in the xml file.
There was a problem hiding this comment.
Good point @KKoukiou.
Looking at your configuration:
version: 1
handlers:
consoleHandler:
class: logging.StreamHandler
level: INFO
stream: ext://sys.stdout
simpleFileHandler:
class: logging.FileHandler
filename: logs.txt
loggers:
art.flow:
level: INFO
handlers:
- consoleHandler
propagate: 0
root:
level: DEBUG
handlers:
- simpleFileHandler
disable_existing_loggers: FalseI believe if you configure the root logger to also write to stdout:
root:
level: DEBUG
handlers:
- simpleFileHandler
- consoleHandlerYou will then see the output written to junitxml (that's one of the things I planned on trying later today).
There was a problem hiding this comment.
It doesn't work but I didn't expect since all logs are captured from art.flow logger which is not propagating the logs to root logger, thus don't see why this change would affect it.
Maybe is would be better for you to provide me with a working minimal example where logs appear in console and the same logs appear in the xmlfile?
Maybe it would be nice test addition to the existing ones as well.
Again, thanks for the help.
There was a problem hiding this comment.
I will get to this later when I get home and let you know.
There was a problem hiding this comment.
@KKoukiou out of the box your requirements (showing captured log in the terminal while tests are running and capture it so it appears in the junit xml) are not possible, I'm afraid.
But I managed to make things work like you expect by writing a fixture which manually adds the captured log information to the item's sections:
@pytest.fixture(autouse=True)
def append_captured_log_to_item_stdout(request, caplog):
yield
for when in ('setup', 'call', 'teardown'):
records = caplog.get_handler(when).records
for record in records:
request.node.add_report_section(when, 'stdout', record.message + '\n')With this fixture in the root conftest.py file, I get the live logging output:
test_template.py::test_function_1
--------------------------------------------------- live log setup ----------------------------------------------------
test_template.py 30 INFO Hi with info from test 1 setup
---------------------------------------------------- live log call ----------------------------------------------------
test_template.py 35 INFO Hi with info from test 1
test_template.py 36 ERROR Hi with error from test 1
PASSED [100%]
And the log messages also appear in the xml file:
<?xml version="1.0" encoding="utf-8"?><testsuite errors="0" failures="0" name="pytest" skips="0" tests="1" time="0.079"><testcase classname="test_template" file="test_template.py" line="31" name="test_function_1" time="0.011009693145751953"><system-out>Hi with info from test 1 setup
Hi with info from test 1
Hi with error from test 1
</system-out></testcase></testsuite>(This is obtained with your original logging configuration, except for the propagate: 0 configuration which needs to be removed as commented before).
IMHO this is an acceptable workaround. What do you think?
There was a problem hiding this comment.
You 're super! I can definitely WA my use case! Thanks :)
There was a problem hiding this comment.
@KKoukiou can you try the following patch and test it (without the conftest.py fixture)?
diff --git a/_pytest/junitxml.py b/_pytest/junitxml.py
index 7fb40dc..0cbec7a 100644
--- a/_pytest/junitxml.py
+++ b/_pytest/junitxml.py
@@ -125,11 +125,14 @@ class _NodeReporter(object):
self.append(node)
def write_captured_output(self, report):
- for capname in ('out', 'err'):
- content = getattr(report, 'capstd' + capname)
- if content:
- tag = getattr(Junit, 'system-' + capname)
- self.append(tag(bin_xml_escape(content)))
+ content = report.caplog # TODO merge with report.capstdout or add a junit flag to switch between stdout and caplog
+ if content:
+ tag = getattr(Junit, 'system-out')
+ self.append(tag(bin_xml_escape(content)))
+ content = report.capstderr
+ if content:
+ tag = getattr(Junit, 'system-err')
+ self.append(tag(bin_xml_escape(content)))
def append_pass(self, report):
self.add_stats('passed')
diff --git a/_pytest/runner.py b/_pytest/runner.py
index 13abee3..b475be9 100644
--- a/_pytest/runner.py
+++ b/_pytest/runner.py
@@ -257,6 +257,14 @@ class BaseReport(object):
return exc.strip()
@property
+ def caplog(self):
+ """Return captured log lines, if log capturing is enabled
+
+ .. versionadded:: 3.4
+ """
+ return '\n'.join(content for (prefix, content) in self.get_sections('Captured log'))
+
+ @property
def capstdout(self):
"""Return captured text from stdout, if capturing is enabled@nicoddemus Do you have interest in integrating a fix for junitxml into pytest?
There was a problem hiding this comment.
@Thisch @nicoddemus I confirm that with this patch I get the expected output in console and junitxml file as with the conftest.py adjustment.
There was a problem hiding this comment.
@Thisch I'm not sure, TBH I would like to avoid to add more to this PR, it is quite big as it is already. Also I think merging capout and caplog needs more detailed discussion.
There was a problem hiding this comment.
Thx for the confirmation @KKoukiou. I totally agree that this PR is already quite large @nicoddemus. Let's create a new ticket for this issue.
|
@nicoddemus just running the relevant project's CI with your changes. If that runs clean I'll review asap! |
|
@nicoddemus looks like we're in the green!. |
Thanks to the adjustments in pytest-dev/pytest#3124 we don't need to worry about live logging with a low logging level being enabled by default in `pytest` any more. Go back to using the default plugin set.
|
@tgoodlet that's great news, thanks for trying it out! |
_pytest/logging.py
Outdated
| if self.log_file_handler is not None: | ||
| with closing(self.log_file_handler): | ||
| with catching_logs(self.log_file_handler, | ||
| level=self.log_file_level): | ||
| yield # run all the tests | ||
| else: | ||
| yield # run all the tests | ||
|
|
||
| def _setup_cli_logging(self): | ||
| """Setups the handler and logger for the Live Logs feature, if enabled. |
doc/en/logging.rst
Outdated
| @@ -146,12 +135,31 @@ You can call ``caplog.clear()`` to reset the captured log records in a test:: | |||
| your_test_method() | |||
| assert ['Foo'] == [rec.message for rec in caplog.records] | |||
|
|
|||
|
|
|||
| Accessing logs from other test stages | |||
There was a problem hiding this comment.
@nicoddemus amazing job 👍
I'm so glad this was resolved and I'm stoked to finally get a chance to use these new features!
|
@Thisch anything else still missing? I ask because your review is still marked as "requested changes". |
While updating the docs I noticed that caplog.get_handler() exposes the underlying Handler object, which I think it is a bit too much detail at this stage. Update to return the records directly instead.
nicoddemus
force-pushed
the
logging-3013
branch
from
cdc1f34 to
15cbd61
Compare
|
@boxed while reviewing the docs I realized that |
|
Sounds good to me!
… On 24 Jan 2018, at 22:09, Bruno Oliveira ***@***.***> wrote:
@boxed while reviewing the docs I realized that caplog.get_handler(when) exposes
the underlying Handler object, which I think is exposing too much of the internal implementation. Because it is easier to add functionality later than removing it, I decided to change the method to caplog.get_records(when) which returns the records directly. Please take a look at commit 15cbd61 when you have the time, would love to hear your thoughts.
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.
|
|
Thanks for this everyone! You're doing a great job! I had an issue where I This PR solved that issue. Can't wait for 3.4 to be out. |
|
@RonnyPfannschmidt would you like some time to review this as well? |
|
nope, i havent found the time to work into it and by the discussion it looks like everything went into a good direction |
Thanks @RonnyPfannschmidt, I'm merging this then! Let's aim to have 3.4 release next week to have some time to finish the other PRs that are open now. 👍 |
This contains the changes discussed in #3013, except that I did not deprecate any of the configuration variables because I realized it would basically duplicate the number of options which would probably result in more confusion than benefits; we might decide to change/deprecate the options at a later time.
Summary:
WARNINGmessages or above are captured (instead of all messages).sys.stderr, which no longer requires users to pass-sto see live logging;