pytest 🚀 - Proposal: disable "live logging" by default and write to terminal writer instead

I would introduce a logcapture (or log-capture) property instead, similar to the existing capture property. In the course of changing the property(ies) of the logging plugin I would also rename the log-cli-* properties (maybe to log-capture-*).

If we use the TerminalWriter for outputting the logs, we could hopefully write a newline character before the first log message s.t. loglines do not appear on the same lines as the testname. This is how it looks when capturing is turned off:

...
collected 1 item                                                                                                                                                                                                              

test_logging_in_pytest.py::test test_logging_in_pytest.py   27 WARNING  Some warning
PASSED                                                                                                                                                                                  [100%]

thisch on 8 Dec 2017

I would introduce a logcapture (or log-capture) property instead, similar to the existing capture property.

You mean a command-line option? I ask because the "capture" configuration that exists today is --capture=X on the command-line. If so I agree, I think we should add an option to disable logging capture completely as well (similar to -s or --capture=no).

Having said that, I still would like a separate option for "live logs": seems useful to be able to be able to capture logs and only having them appear on the captured output section if a test fails.

How about:

--capture-log
- yes (default): capture plugin is active; captured logs are displayed next to stderr and stdout sections if a test fails.
- no: capture plugin is not active
--live_logs:
- no (default): nothing special.
- yes: captured logs are displayed in the TerminalWriter as soon as they are emitted (in color and in a newline). For this to work --capture-log must be yes.

(Alternatively, all those could be ini options instead given that it is easy to set/override them on the command line using -o)

nicoddemus on 8 Dec 2017

Yes I mean a command line --capture-log option, which should be orthogonal to the --capture option. I also think that the capture-log option can have two possible values: yes (default) and no. --capture-log=no should correspond to the live-log mode and --capture-log=yes should display captured logs if a test fails.

I don't understand why you need an additional --live-logs option, though. I also don't understand why your --live-logs option only works when capturing is enabled (--capture-log=yes)
Isn't --capture-log=no the same as -p no:logging in your proposal?

thisch on 8 Dec 2017

(@thisch sorry for the delay)

Isn't --capture-log=no the same as -p no:logging in your proposal?

At first glance it might seem like it is but disabling the plugin entirely means that the caplog fixture would not be available and tests which use it will break, that's why I feel we need a separate option (I should have written: "log capture is not active" instead of "log capture plugin is not active").

I don't understand why you need an additional --live-logs option, though.

When I wrote the previous proposal, I was considering that --capture-log=yes and --live-logs=yes was a valid use case: logs are displayed during the test run and also displayed when a test fails; this might be useful because at least you have the captured log output for each test (otherwise you can't know which test emitted a certain log message).

But I'm thinking that having --capture-log and --live-logs might be confusing.

Perhaps we can have three values for --capture-log then:

on-failure (default): display captured logs on failure
live: display captured logs as they are emitted, possibly with colors
no: no log capturing at all (3.2 behavior), fixture still available

I'm also curious, do people use the live logs feature frequently?

Also would love to hear other opinions on this.

nicoddemus on 12 Dec 2017

Perhaps we can have three values for --capture-log then:

on-failure (default): display captured logs on failure

live: display captured logs as they are emitted, possibly with colors

no: no log capturing at all (3.2 behavior), fixture still available

I like this, but I'm not sure if on-failure should be the default, given that this might cause a high memory usage (see https://github.com/pytest-dev/pytest/issues/2977#issuecomment-351484515)

thisch on 13 Dec 2017

Write the "live logs" to the TerminalWriter, probably in color according to the level, yellow for WARNING
and red for CRITICAL. This means users won't need to use -s to see live logs anymore.

The output by TerminalWriter is captured if -s is not used, or am I missing sth?

thisch on 13 Dec 2017

I like this, but I'm not sure if on-failure should be the default, given that this might cause a high memory usage

This is happening because of we are setting the log-level of the capture-per-item to NO_SET, which causes it to capture everything... this seems like a bad idea in general.

The output by TerminalWriter is captured if -s is not used, or am I missing sth?

TerminalWriter is responsible for writing pytest's own output, so its output is not captured.

nicoddemus on 13 Dec 2017

This is happening because of we are setting the log-level of the capture-per-item to NO_SET, which causes it to capture everything... this seems like a bad idea in general.

Ok, so if we set the default capture-log-level to a non-zero value, i.e., != NO_SET, on-failure can be set as the default for capture-log.

thisch on 13 Dec 2017

TerminalWriter is responsible for writing pytest's own output, so its output is not captured.

I've tried to experiment a bit with TerminalWriter in https://github.com/thisch/pytest/commit/6e3ddf88be83aa9defaace2292a1276dcd9091ff but I can't get the logs to be shown when --capture-log=live is used to run the tests. Maybe I'm doing sth wrong.

thisch on 13 Dec 2017

Ouch sorry, I meant the TerminalReporter plugin! My bad.

nicoddemus on 13 Dec 2017

As demonstrated in #3035, the logging plugin as it stands now generates a lot of overhead in suites which make heavy use of logging:

import logging
import pytest

def add(a, b):
    logging.info(str(a))
    return a + b

@pytest.mark.parametrize("a", range(1000))
def test_add(a):
    for b in range(1000):
        assert a + b == add(a, b)

The difference between logging and no logging (using -p no:logging) is around 30s vs 2-3s.

I don't think the problem is just the default log level, because I get similar times even when using --log-level=9999 and --log-cli-level=9999... we probably need to figure out what's causing so much overhead.

nicoddemus on 14 Dec 2017

@nicoddemus looking at our codebase where I have spotted the problem, we do not generate a lot of logging by default and we have switch for pytest:

def pytest_configure(config):
    level = logging.DEBUG if config.getoption("--appdebug") else logging.ERROR
    logging.basicConfig(level=level)

It seems that 3.3.0 ignores that and logs everything.

skontar on 14 Dec 2017

@skontar thanks, I think it currently overwrites the global settings in favor of its internal settings; another thing to consider.

nicoddemus on 14 Dec 2017

@nicoddemus also it seems to me that it stores logging of all tests, even the ones which passed, you can see it linearly grows in memory. I thought that you can throw away the log messages generated during passing tests? But it is probably tied to our usecase and would not be acceptable generally.

skontar on 14 Dec 2017

I thought that you can throw away the log messages generated during passing tests?

When using the terminal it makes sense, but I think it is kept there so other plugins can access it and optionally make use of that information.

nicoddemus on 14 Dec 2017

also it seems to me that it stores logging of all tests, even the ones which passed, you can see it linearly grows in memory.

I saw this exact same thing with some stress tests (quite frustrating and confusing).

@nicoddemus @thisch why can't logging capture simply be disabled by default unless test code demands the caplog fixture?

Stress tests are a prime example of where you don't want much logging emitted. Currently I see no way to combine such tests alongside caplog consuming unit tests in a single session.

Also,

I think it currently overwrites the global settings in favor of its internal settings;

IMHO ^ that's super wrong.

goodboy on 14 Dec 2017

@nicoddemus @thisch why can't logging capture simply be disabled by default unless test code demands the caplog fixture?

To show logs when a test fails I assume?

The-Compiler on 14 Dec 2017

@The-Compiler showing or not showing logs imo should be independent of whether they're captured.

It's not even really the logging itself that's the the problem is that the level set by test code isn't properly used when capturing is enabled. Setting a crazy low logging level by default is just super unexpected and as we've seen gives major performance headaches.

goodboy on 14 Dec 2017

@tgoodlet

showing or not showing logs imo should be independent of whether they're captured.

I'm not sure I understand, how will we display the logs (after all tests have run, in the summary section, mind you) without capturing them? Could you elaborate please?

It's not even really the logging itself that's the the problem is that the level set by test code isn't properly used when capturing is enabled.

I agree, we should probably do not touch the root logger's level unless it is explicitly set by the --log-level option, otherwise we leave it alone (this was also brought up in #2977).

nicoddemus on 14 Dec 2017

I'm not sure I understand, how will we display the logs (after all tests have run, in the summary section, mind you) without capturing them? Could you elaborate please?

@nicoddemus afaiu there's 2 toggles:
1. we can print to std streams immediately or not (what you call live streaming: i.e. using a logging.StreamHandler + sys.stderr and not suppressing the output as is without -s)
* this only determines whether logs are displayed immediately when they are emitted
* this is the same basic behaviour that existed before 3.3.0
* whether or not the output sent to streams is stored in memory for 2 is irrelevant
2. we can capture log emissions for assertions by test code
- requires that we collect what could be stream output (or any other handler) in memory
- requires that some logging level be set as required by the user (IMO on a per test basis) so that log message assertions can be accomplished

and 2. are independent: live streaming does not requires capture and capture does not require live streaming.
does requires that log emissions are sent to some handler and possibly printed at the end of a test report summary if there is an error.

What I originally wrote:

@nicoddemus @thisch why can't logging capture simply be disabled by default unless test code demands the caplog fixture?

To which @The-Compiler responded:

To show logs when a test fails I assume?

But there is no need to enable log capture (2 above) if the test does not use caplog. ~I'm guessing likely the confusion around all of this is that pytest is capturing log messages by collecting std streams and using that data for assertions instead of just adding a custom handler that it can use to do assertions on output stored at whatever destination is most appropriate (i.e. file-like object, buffer, or disk) - but I haven't looked at the code so no hard claim here~ - I did and see how it works now.

goodboy on 15 Dec 2017

Ok after reading _pytest.logging this would be my opinion:

don't ever enable live streaming to stderr as part of _pytest.logging (aka LoggingPlugin.live_stream)
don't configure the root logger by default (especially not with a low level) as in catching_logs() and allow test code to pass in the logger (whether it's the root or some other) that should be captured
if the user wants a standard (root or other) logging configuration with some prior level set, make that a separate dependency (fixture) that can be explicitly depended upon

Why:

It should be up to the user how logging messages are displayed in the console. Removing this removes the problem of ever having too many logging messages written to std streams that the user isn't expecting (and has the added bonus that pytest won't capture stderr output when -s is not provided which is likely part of the unexpected memory problem).
I bet you 99% of test suites already have logging setup (likely with the StreamHandler) fixture(s) for debugging purposes on the console. No one needs their hand held on how logging messages look for debugging.
All caplog depedent assertions do not need a StreamHandler that writes to std streams and instead should use some performance sensitive handler (seems like this is already true with our internal LogCaptureHandler subtype that uses a StringIO as the stream?).
There is no reason to specially print mismatched log messages to std streams outside what the user has configured on their own - the rest can be handled by an appropriate exception message.

goodboy on 15 Dec 2017

Hi @tgoodlet, thanks for the comments.

don't ever enable live streaming to stderr as part of _pytest.logging (aka LoggingPlugin.live_stream)

I agree it should not write to stderr (that's why since my first post I advocate writing using the TerminalReporter plugin instead), but we can't just throw that feature out of the window now that has been released I'm afraid. It should be disabled by default though.

don't configure the root logger by default (especially not with a low level) as in catching_logs()

I agree, we should only touch the root loggers level if the user explicitly sets --log-level.

allow test code to pass in the logger (whether it's the root or some other) that should be captured

This could be done by a mark, but by default it should capture the root logger I think: the idea is that you get useful log messages when a test fail without the need to preemptively marks the tests where that information could be useful.

There is no reason to specially print mismatched log messages to std streams outside what the user has configured on their own - the rest can be handled by an appropriate exception message.

I'm not sure what you mean by "mismatched log messages" or "the rest can be handled by an appropriate exception message"... could you clarify please?

I think all this discussion is nicely converging to the same set of required changes. 👍

nicoddemus on 15 Dec 2017

This could be done by a mark, but by default it should capture the root logger I think:

Sure but make it opt-in. Don't enforce log capture unless a user calls for caplog. I think I've made a pretty good case for not doing unexpected things behind the scenes. You have to remember that often you can have test code which is testing some project which sets up it's own logger and that project relies on some dep that does its own thing with logging. If the goal of caplog is to verify log messages in the immediate tested project then we don't want to be configuring the underlying dependency's logging to do things if we don't care / it isn't necessary (i.e. the root logger should be something managed explicitly by the user if they desire). Also we're not even considering the case where a project is using pytest as a dep for some higher level testing system/project and independent logging management is desired.

I'll say it again, in pytest enabling the root logger by default is just plain wrong. A user should have to explicitly request that behaviour if desired.

I'm not sure what you mean by "mismatched log messages" or "the rest can be handled by an appropriate exception message"... could you clarify please?

@nicoddemus it seemed to me that @The-Compiler was implying that console printing of the log message (i.e. to a std stream) was necessary to demonstrate which log message was mismatched (i.e. different then what a test asserts using caplog). To me this is unnecessary: there is no need to print anything to the console when there is an exception reporting the log message that didn't match. If a user wants to also print the message to the console it's entirely up to them.

goodboy on 15 Dec 2017

@tgoodlet I now realize we might be talking about different things...

When I say "log capture" I don't mean the caplog fixture, I'm talking about the feature were log messages are automatically captured and displayed when a test fails (similarly to how stdout and stderr are captured, regardless if capsys or capfd fixtures are active on a given test). This is one of the main purposes of the logging module I think.

nicoddemus on 15 Dec 2017

I'm talking about the feature were log messages are automatically captured and displayed when a test fails

Afaik this was already there in < 3.3.0 (has been for a long while) and not what I would call log capture since it's actually file/streams capture? Log capture is when you capture logging records which is the feature added in 3.3.0 right?

pytest already captures std streams so you don't need yet another additional log capture way of collecting stderr as is done with LoggingPlugin.live_stream. Whether or not logs are turned on (sent to the stderr destination) should be up to the user not some default setting in pytest.

This is one of the main purposes of the logging module I think.

Not following. What is?

The main problem IMHO with this new plugin is a complete disregard for separation of concerns. Just because it's conventional for logging to be sent to stderr doesn't mean it should be enabled as a destination by default or used to check expected logging records emitted by the tested project.

goodboy on 15 Dec 2017

Nope, the configuring of logging and automatically capturing it was added in 3.3 only. In <3.3, unless you explicitly configure logging to output to stdout/stderr, you won't see any logging messages at all.

I think I see now why this is so confusing: I think your suites always configure logging to output to stderr, hence you always saw captured messages due to standard stdout/stderr capturing.

nicoddemus on 15 Dec 2017

When I say "log capture" I don't mean the caplog fixture, I'm talking about the feature were log messages are automatically captured and displayed when a test fails

Why are you calling this log capture? It's even in the docs as std streams capture?
It's capsys/capfd not logging. Why is logging getting conflated with output sent to std streams fds? The whole point of logging is to decouple from the handler's destination and add abstractions not available through print?

Nope, the configuring of logging and automatically capturing it was added in 3.3 only. In <3.3, unless you explicitly configure logging to output to stdout/stderr, you won't see any logging messages at all.

This is exactly what I asserted and the way it should stay.

I think I see now why this is so confusing: I think your suites always configure logging to output to stderr, hence you always saw captured messages due to standard stdout/stderr capturing.

For any project whether a library, app, whatever it's expected that logging is handled by the end user of that code.

The 2 common examples:

if you're an app you configure your own internal logging settings for output to your user
if you're a library or framework you expect consuming code to configure logging settings based on whatever output is expected to be delivered to its user for debugging/monitoring purposes

No one starts up pytest thinking oh yeah I bet pytest sets up root logging for my project - and especially not with a DEBUG level?

pytest itself is not the end user and is not an app - the user of pytest (who uses pytest to test the underlying project) is the user and should configure what logging they expect according to the code consuming pytest i.e. the test code.

Again my opinion is pytest should not be configuring any logging implicitly, period, except for what is demanded by the user as part of using caplog.
Having a helper to do some standard setup is fine but pytest should not require that you disable this to get the normal behaviour you'd expect from literally all non-app python projects. If you want to have implicit logging setup due to use of caplog - cool.

A final example to emphasize this:

If pytest itself actually properly used logging internally (which it could by using a non-root logger with a high log level and a handler that sent to stdout) this new 3.3.0 feature would have created a massive mess on the console by first generating DEBUG level logging from pytest to stdout and secondly capturing those records for use by caplog and including it with the same records that the underlying tested project's logging would have generated.

goodboy on 15 Dec 2017

@tgoodlet again I think we are talking about different things. I want to apologize if my tone seemed dismissive before, I was in a rush to get to the office's Christmas party. 😁

Why are you calling this log capture? It's even in the docs as std streams capture?

I'm talking about log capturing, not streams capturing. For example:

import logging

def test():
    logging.info('logging output')
    print('stdout output')
    assert 0

Here's the output:

F                                                    [100%]
======================== FAILURES =========================
__________________________ test ___________________________

    def test():
        logging.info('logging output')
        print('stdout output')
>       assert 0
E       assert 0

.tmp\test_log.py:6: AssertionError
------------------ Captured stdout call -------------------
stdout output
-------------------- Captured log call --------------------
test_log.py                  4 INFO     logging output
1 failed in 0.03 seconds

They are different things: there's the captured log (that's what I've been meaning about log capturing) and stream capturing.

Again my opinion is pytest should not be configuring any logging implicitly, period, except for what is demanded by the user as part of using caplog.

Capturing logging automatically and displaying it for the user is the whole point of pytest-catchlog and its incorporation into the core. You might be arguing as well that pytest should not capture std streams at all; it would be your opinion of course and you are welcome to disable that functionality if you want to. pytest-catchlog is a very popular plugin and people who use it extensively think it is useful.

Of course the current defaults and settings need tweaking, that's what this thread is all about.

No one starts up pytest thinking oh yeah I bet pytest sets up root logging for my project - and especially not with a DEBUG level?

About DEBUG level, it has been said already on this thread already that we probably should fallback to using WARNING as default instead (actually, not configuring level at all unless --log-level is set).

if you're an app you configure your own internal logging settings for output to your user
if you're a library or framework you expect consuming code to configure logging settings based on whatever output is expected to be delivered to its user for debugging/monitoring purposes

Indeed, but I believe the point of logging capturing is that library authors now see their own logging without having to explicitly configure it on their test suites.

Having said all that, I rarely use the logging module so the use cases I mention are mostly from hearing how other people use it, so it should be taken with a grain of salt.

I would love to hear the opinion of other people who do use logging extensively on their projects (@The-Compiler I know does and he's a prominent contributor of pytest-catchlog).

nicoddemus on 16 Dec 2017

I want to apologize if my tone seemed dismissive before

No no not at all - my apologies if I'm seeming cranky 😄
I'm just concerned that the introduction of this plugin in its current form might have been a bit hasty but
I'm probably just overthinking it.

I'm talking about log capturing, not streams capturing... there's the captured log (that's what I've been meaning about log capturing) and stream capturing.

Yes totally agree. So none of my criticism has to do with the necessary logging config to accomplish this - the log capture part (i.e. plugging into logging to capture records). I see now that the printing of them at the end in the report what I think you're referring to. I'm saying that should should be no LoggingPlugin.live_stream going to stderr by default and definitely not with a level that wasn't set by the user - so unless --log-cli-level was passed. I'm saying live streaming should be something that's explicitly requested.

Your example is now confusing me because I don't see the logging.info('logging output') like I expected it to on the stderr capture?

What am I missing?

goodboy on 17 Dec 2017

I'm really pleased that there is a live discussion going on here. Sry
for chiming in so late.

I agree that we need to be a bit more careful when merging such a plugin in
the future. I didn't expect that merging this plugin into pytest core causes
so much trouble. However, a big benefit of this merge is that due to the
feedback we've received from the community so far, we will probably have a
much better logging plugin in pytest 3.4 ;)

In the last couple of days I've played a bit with the logging plugin (see my
earlier comments in this thread) and especially with the example provided in
https://github.com/pytest-dev/pytest/issues/3013#issuecomment-351734223.
I'll give you an update on this in the following days.

I agree that

the live logging stream should not be output to stderr. TerminalWriter/TerminalReporter should be used instead.
root logger must not be used (by default) for setting up live logging/log capturing.

Furthermore I think that

log levels for live logging/log capturing need to be explicitly requested. (using WARNING as a default for log capturing doesn't make sense to me)
log capturing and normal stream capturing (capsys, capfd) should be decoupled. (ATM you need to specify -s, when you want to see the live logs in the terminal)

WDYT if we introduce a (required) config variable with the names of the
loggers that are configured for live-logging and log-capturing? If you want
the same behavior as now, you can pass the name of the root logger to this
config variable, but you can also pass a list of logger names.

thisch on 17 Dec 2017

I agree that we need to be a bit more careful when merging such a plugin in the future.

No, the issue was that the pytest-catchlog plugin had multiple issues that weren't fixed because it was a third-party plugin. Now that it's been merged into core, these issues are being dealt with.

ghost on 18 Dec 2017

In the last couple of days I've played a bit with the logging plugin (see my
earlier comments in this thread) and especially with the example provided in

3013 (comment).

For the record, the example and the issue https://github.com/pytest-dev/pytest/issues/3035 are result of changing the logging level in the tested application by pytest without user intervention. We actually expect the speed and memory requirements when logging is set to DEBUG. We just did not expect it to be enabled by default by pytest - it took me a few hours to actually find out why it suddenly become 4x slower in our CI.

That is IMHO the biggest problem.

skontar on 18 Dec 2017

Thanks @thisch for chiming in, apologies on my part for the delay, I was partially out for the holidays.

I agree that we need to be a bit more careful when merging such a plugin in
the future.

TBH I'm not sure how else we could have been more careful... we've merged a popular and mature plugin into the core, which been in use for many years (even under the name pytest-capturelog).

I suppose we might have asked to people to "please install pytest-catchlog because it will be part of the core in the next release" and see the feedback, but I doubt too many people accompany the mailing list or posts, and how many would have the time to actually do it.

Perhaps we can start doing beta releases to gather feedback?

I would love to hear ideas on how to prevent this kind of thing in the future though.

I didn't expect that merging this plugin into pytest core causes
so much trouble. However, a big benefit of this merge is that due to the
feedback we've received from the community so far, we will probably have a
much better logging plugin in pytest 3.4 ;)

Definitely! I'm keen to release 3.4 as soon as we settle this. 😁

the live logging stream should not be output to stderr. TerminalWriter/TerminalReporter should be used instead.

Agreed!

root logger must not be used (by default) for setting up live logging/log capturing.

I kinda disagree here, because I think the problem is not capturing the root logger, but the default level used. Capturing the root logger just seem logical from my POV because that's the logger you get when you call logging.getLogger() without parameters.

log levels for live logging/log capturing need to be explicitly requested. (using WARNING as a default for log capturing doesn't make sense to me)

Can you elaborate why do you think it doesn't make sense in your opinion? Is it because in your vision it will limit the utility of the plugin in the first place?

I think given all the problems that may rise when we capture everything, using the default level for capturing makes sense to me. Actually, just to emphasize, I think we should not set any level in any logger unless the user explicitly requests so using the --log-level option; this will get us WARNING by default because of logging's own default and will prevent us from messing with the level set by users during initialization (as @tgoodlet and @skontar mention).

log capturing and normal stream capturing (capsys, capfd) should be decoupled. (ATM you need to specify -s, when you want to see the live logs in the terminal)

Agreed. This is fixed by writing to TerminalReporter instead of sys.stderr.

WDYT if we introduce a (required) config variable with the names of the
loggers that are configured for live-logging and log-capturing?

I'm not a big fan... this will immediately break every pytest-3.4 user out there because nobody will have their option in this ini file. 😬

Again I don't think the main problem is which logger to capture, but the default level used.

In summary, here's what I think should be done in my vision:

Live Logging

Disabled by default, can be enabled with --live-log; we need a separate option because disabling the entire plugin with -p no:logging will break tests which use the caplog fixture.
--live-log-level sets the log level, default being "default" in which case we don't set anything explicitly and use whatever level is configured (I also thought the value could be "no-set", but I think this will be confusing because logging.NOSET exists);
Writes to TerminalReporter, not sys.stderr; this makes it decoupled from -s
Captures the root logger; if people think necessary, we can add now or in the future an option to configure which loggers should be captured;

Logging capture

--log-capture: defaults to yes, can be disabled with --log-capture=no. This has a nice symmetry with the --capture=sys/fd/no option; we need a separate option for the same reasons stated above.
--log-level sets the log level, default being default in which case we don't set anything explicitly and use whatever level is configured;
Captures the root logger; if people think necessary, we can add now or in the future an option to configure which loggers should be captured;

I think "live logging" is a better term than "cli logging", in which case we should create new options as alias to the old ones, and consider the old ones deprecated:

log_cli_level: deprecated, alias to live_log_level
log_cli_format: deprecated, alias to live_log_format
log_cli_date_format: deprecated, alias to live_log_date_format

nicoddemus on 26 Dec 2017

in addition, --no-print-logs should be default,
for two reasons:

flake8 becomes useless (too cluttered) otherwise: https://github.com/tholo/pytest-flake8/issues/42
For projects that output logging to stderr, the outputs are duplicated otherwise.

This would follow the "path of least surprise" for projects not using log-capture.

ederag on 2 Jan 2018

👍1

@ederag I'm not sure. I see the output you provided a link to, and it is verbose because it is printing DEBUG and INFO messages. The proposal would be to use WARNING as the default level, so all those log messages would not show up.

For projects that output logging to stderr, the outputs are duplicated otherwise.

Indeed this might be a problem. It is my understanding though that those projects output logging to stderr because they were not using pytest-catchlog before, but now that pytest supports this out of the box perhaps it would make sense for those projects to change their logging code instead? Or is this due to a another use case?

I like the fact that logging is automatically captured (using the defaults in the new proposal) without new users having to do anything, similar to how stdout/stderr capture is also done out of the box, but I might be wrong here.

EDIT: on the other hand, logging is not configured by Python by default, perhaps pytest should follow the same logic.

nicoddemus on 3 Jan 2018

@nicoddemus Yes, it is a different use case, not related to pytest.
The application uses the python logger with a basic logging.StreamHandler() that outputs to stderr.
For this app, it is currently the main feedback mechanism to the user.
In this case, --no-print-logs is preferable.

logging is not configured by Python by default, perhaps pytest should follow the same logic

Exactly, the application logger level should not be tampered with during the tests,
unless explicitly requested.
(otherwise, how to check that the default logging level of the app is correct ?)

ederag on 3 Jan 2018

👍1

My 2 cents:

A few major problems we ran into when updating to pytest 3.3:

Logging was now enabled for all libraries we used, not the ones we explicitly enabled logging for. For example, paramiko. Even though we explicitly set logging for our internal library to DEBUG, with the pytest update all logs, everywhere are generated and captured (if capture enabled) or output (if capture disabled -- the -s option).
Related to #1, pytest modifying the root logger behind the scenes also affects any forked/multiprocessing logging (which might or might not be going to file).

As you guys said, anybody that has been using pytest likely has logging setup and configured how they wanted. Merging in capturelog threw that out the window.

And finally, a sample use case for -s. Using pytest for functional testing, sometimes tests have unintended side effects. Verbose logging can help track down those side effects, provided you can see the logging. Having logs only be visible on a failure is profoundly unhelpful in that case, so we use -s and can track terminal output (jenkins console log). Combine that with customizing which libraries are outputting log data to stdout, and you can have a full stream of everything that is done in a test.

astraw38 on 11 Jan 2018

Thanks @astraw38 for sharing your thoughts. Can you take a look at the changes proposed in https://github.com/pytest-dev/pytest/issues/3013#issuecomment-353897902 and see if they are enough to improve the logging support in your POV or is there anything missing?

nicoddemus on 11 Jan 2018

The major concern I have is the default setting of log level, since you'd be modifying the root logger and affecting everything. This is more of a documentation thing, but users should be setting log levels programmatically if they want varying levels across libraries/modules (and setting --log-level could be confusing for newer users)

And a minor feature that I'd like would be capture + livelogging. Full run logging aside, it is really nice to have the captured logs for a given test in junitxml :)

astraw38 on 11 Jan 2018

The major concern I have is the default setting of log level, since you'd be modifying the root logger and affecting everything.

Under the new proposal we wouldn't touch the log level of the root logger at all, unless the user explicitly asks to by passing --log-level in the command line or in the ini file.

And a minor feature that I'd like would be capture + livelogging. Full run logging aside, it is really nice to have the captured logs for a given test in junitxml :)

I see, but that is already possible today and under the new proposal, no?

nicoddemus on 11 Jan 2018

I see, but that is already possible today and under the new proposal, no?

Not logging to stdout, as far as I can tell. You can get output on stdout by disabling capturing, but with capture enabled and setting various --log-cli* options, it won't output to terminal during the test.

astraw38 on 11 Jan 2018

Not logging to stdout, as far as I can tell.

Oh sorry, you are right; that will be fixed when live logging writes directly to the TerminalReporter plugin then. 👍

nicoddemus on 11 Jan 2018

Finally got time to work on this proposal, #3124 is open and all comments are welcome.

nicoddemus on 17 Jan 2018

👍1

Pytest: Proposal: disable "live logging" by default and write to terminal writer instead

All 43 comments

3013 (comment).

Live Logging

Logging capture

Related issues