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

[nicoddemus]

The Live Logs feature currently is enabled by default and requires the user to pass -s to see the logs.

I see two problems:

1. If the user is interested in the feature, having to pass -s feels clumsy because now all sort of outputs will come through, reducing the actual usefulness of the feature because it will be harder to see the actual logging messages.
2. To solve 1), I believe we will need to write to the TerminalWriter, which by consequence will show up for all users from that point on even if they are not interested in the feature because the default is WARNING.

My proposal:

1. Create a new property, live_logs, defaulting to False.
2. 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.

This feature was originally implemented in eisensheng/pytest-catchlog#33 but was never released to PyPI, so I assume "live logs" has seen little use in the wild.

cc @thisch

[twmr]

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%]

[nicoddemus]

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)

[twmr]

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?

[nicoddemus]

(@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.

[twmr]

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 #2977 (comment))

[twmr]

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?

[nicoddemus]

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.

[twmr]

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.

[twmr]

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 twmr@6e3ddf8 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.

[nicoddemus]

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

[nicoddemus]

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.

[skontar]

@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.

[nicoddemus]

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

[skontar]

@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.

[nicoddemus]

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.

[goodboy]

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.

[The-Compiler]

@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?

[goodboy]

@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.

[nicoddemus]

@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).

[goodboy]

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

1. and 2. are independent: live streaming does not requires capture and capture does not require live streaming.
2. 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]

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.

[nicoddemus]

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. 👍

[goodboy]

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.

[skontar]

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 #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.

[nicoddemus]

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

[ederag]

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

1. flake8 becomes useless (too cluttered) otherwise: This plugin produces very verbose output tholo/pytest-flake8#42
2. 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.

[nicoddemus]

@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.

[ederag]

@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 ?)

[astraw38]

My 2 cents:

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

1. 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).

2. Related to assert reinterpretation fails for some code layouts #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.

[nicoddemus]

Thanks @astraw38 for sharing your thoughts. Can you take a look at the changes proposed in #3013 (comment) and see if they are enough to improve the logging support in your POV or is there anything missing?

[astraw38]

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 :)

[nicoddemus]

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?

[astraw38]

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.

[nicoddemus]

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]

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