Counter-intuitive logging API

[vporton]

BPO	35530
Nosy	@vsajip, @mdickinson, @stevendaprano, @vporton, @eamanu, @tirkarthi

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vsajip'
closed_at = <Date 2019-01-07.03:37:42.923>
created_at = <Date 2018-12-19.00:09:09.897>
labels = ['3.7', 'invalid', 'type-bug', 'library']
title = 'Counter-intuitive logging API'
updated_at = <Date 2019-01-07.03:37:42.923>
user = 'https://github.com/vporton'

bugs.python.org fields:

activity = <Date 2019-01-07.03:37:42.923>
actor = 'vinay.sajip'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2019-01-07.03:37:42.923>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2018-12-19.00:09:09.897>
creator = 'porton'
dependencies = []
files = []
hgrepos = []
issue_num = 35530
keywords = []
message_count = 11.0
messages = ['332103', '332115', '332117', '332120', '332121', '332122', '332125', '332126', '332127', '332132', '332322']
nosy_count = 6.0
nosy_names = ['vinay.sajip', 'mark.dickinson', 'steven.daprano', 'porton', 'eamanu', 'xtreak']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue35530'
versions = ['Python 3.7']

[vporton]

The following script:

#/usr/bin/env python3
import logging
logger = logging.getLogger(name='main')
logger.setLevel(logging.INFO)
logger.error('XXX')
logging.error('ZZZ')
logger.error('XXX')

outputs

XXX
ERROR:root:ZZZ
ERROR:main:XXX

That is counter-intuitive: two logger.error('XXX') operators should output the same string, not two different strings "XXX" and "ERROR:main:XXX".

Please discuss how to make Python behave as a user could expect.

[stevendaprano]

The call to logging.error() is irrelevant, since there's no expectation that the module-level function will necessarily output the same as a method of a specific instance logger.error().

I agree that is it quite curious that the first call to logger.error outputs something different from the second.

The documentation says:

The default format set by basicConfig() for messages is:
severity:logger name:message

( Paragraph just above this:
https://docs.python.org/3.5/howto/logging.html#logging-flow )

but you don't call basicConfig. I'm not sure that it is mandatory though.

It looks like a bug to *me*, but I'm not a logging expert. I'm seeing the same behaviour in 3.5 and 3.7, but in 2.7.1 the first call to logger.error prints an error message:

No handlers could be found for logger "main"

[eamanu]

The call to logging.error() is irrelevant, since there's no expectation that the module-level function will necessarily output the same as a method of a specific instance logger.error().

That's true. Maybe and warning or Exception can be raise?

It looks like a bug to *me*, but I'm not a logging expert. I'm seeing the same behaviour in 3.5 and 3.7, but in 2.7.1 the first call to logger.error prints an error message:

and 3.8?

[tirkarthi]

The output is the same in 3.8. I think this is due to propagation to the root logger after logging.error call. When logger.error is called with no handler attached to it then root logger handler is called and root handler's format is used. The fix would be to do logger.propagate = False after logger initialization. In your code in first call for logger.error just prints the message, root handler is initialized during logging.error and thus the earlier call works fine but the next call to logger calls the root logger's handler.

The fix in the reported case would be to add logger.propagate = False after calling logging.error. I think logging.error has does something to define root logger handler?

Hopefully Vinay has a better explanation of this behavior.

Sample code :

import logging

logging.basicConfig(format="root logger handler: %(message)s")

logger = logging.getLogger(name='main')
logger.setLevel(logging.INFO)

logger1 = logging.getLogger(name='main1')
logger1.setLevel(logging.INFO)
ch = logging.StreamHandler()
logger1_formatter = logging.Formatter('logger 1 handler : %(message)s')
ch.setFormatter(logger1_formatter)
logger1.addHandler(ch)

logger.error('logger XXX') # calls root logger's handler
logging.error('root logger XXX') # calls root logger's handler
logger1.error('logger 1 XXX') # Calls ch and then root logger's handler

logger1.propagate = False
logger1.error('logger 1 XXX') # Calls only ch since propagation is set to False and root handler is not called

Output on 3.8 :

root logger handler: logger XXX
root logger handler: root logger XXX
logger 1 handler : logger 1 XXX
root logger handler: logger 1 XXX
logger 1 handler : logger 1 XXX

[mdickinson]

The call to logging.error is not irrelevant here. It's causing an implicit, and surprising (albeit documented), call to logging.basicConfig.

https://bugs.python.org/issue34350 is essentially the same issue. That issue was closed as "not a bug", though I think a more appropriate resolution would have been "won't fix". In my mind, this is a design flaw in logging, and it's one that's caused my colleagues and me real-world pain on multiple occasions.

There may be backwards compatibility constraints that make it impossible to fix this. I haven't looked into what would be needed.

[stevendaprano]

That's true. Maybe and warning or Exception can be raise?

Why would we raise a warning or exception for expected behaviour?
logging.error() and some_instance.error() don't necessarily produce the
same output. What would the exception say?

FatalError: no error occurred

*wink*

and 3.8?

If you have 3.8 installed, feel free to test the code yourself and
report what happens.

[stevendaprano]

On Wed, Dec 19, 2018 at 10:37:22AM +0000, Mark Dickinson wrote:

Mark Dickinson dickinsm@gmail.com added the comment:

The call to logging.error is not irrelevant here. It's causing an
implicit, and surprising (albeit documented), call to
logging.basicConfig.

Ah, thanks.

And of course the documentation you refer to is right there in the
paragraph above the one I linked to earlier, and I completely missed it.
Ouch.

[mdickinson]

I completely missed it.

You're not alone. Authors of many of the libraries that we work with on a day-to-day basis missed it, too. And that results in logging being accidentally configured as a side-effect halfway through a long test run, when one of those libraries happens to be imported. That it turn leads to heisenbug-like test failures (e.g., tests that fail locally but pass on Travis CI or Appveyor, or vice versa, just because one test accidentally configures logging, another test checks for particular logged messages, and unittest happened to run the tests in different orders in different setups).

This is a real problem for Enthought, where we write large, well-tested (our test suites commonly include thousands of tests) applications. In those circumstances, test interactions (tests that fail after some other test has been run, but don't fail when run standalone) are one of the biggest sources of pain.

Vinay claims in the bpo-34350 discussion that:

that's just like any other bug introduced because of a typo. It would presumably get caught in testing.

This isn't true in practice. The "bug" here is accidental configuration of logging by a library (possibly by one's own code, possibly by a third-party library that's being sued directly or indirectly). And unless you know about this possibility in advance, you're not going to test for it. If it does get caught in testing, it's in the form of the unpleasant test interactions described above. I've witnessed various third-party libraries configuring logging accidentally and not realising it; it doesn't tend to cause problems for the library directly - it causes problems for the downstream users of those libraries.

If this behaviour can't be changed for backwards compatibility reasons, then so be it. But I think it would be disingenuous to claim it's not a design flaw.

</rant>

[eamanu]

What would the exception say?

FatalError: no error occurred

haha, I mean a message that tell you something to avoid have some weird behave (like here). :-)

If you have 3.8 installed, feel free to test the code yourself and report what happens.

Ok!

[tirkarthi]

If you have 3.8 installed, feel free to test the code yourself and report what happens.

I tested it on master and it's the same as per the original report.

➜  cpython git:(master) cat ../backups/bpo35530_1.py
import logging
logger = logging.getLogger(name='main')
logger.setLevel(logging.INFO)
logger.error('XXX')
logging.error('ZZZ')
logger.error('XXX')
➜  cpython git:(master) ./python.exe
Python 3.8.0a0 (heads/master:1dd035954b, Dec 18 2018, 10:12:34)
[Clang 7.0.2 (clang-700.1.81)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> ^D
➜  cpython git:(master) ./python.exe ../backups/bpo35530_1.py
XXX
ERROR:root:ZZZ
ERROR:main:XXX

root is parent for all logger objects created down the inheritance chain. When there is no root handler for logger then it resorts to lastResort handler (As per name called on last resort when there is no handler even for root) whose format is "%(message)s". Calling logging.error sets the root's handler (like doing logging.basicConfig). When there is a root with handler then subsequent logger calls the root's handler but lastResort is not called since it has found the root handler. I agree with Mark that this could affect downstream and is very hard to debug when libraries have wrong configuration.

import logging
logger = logging.getLogger(name='main')
logger.setLevel(logging.INFO)
logger.error('XXX')
print("logger parent ", logger.parent) # Root is always the parent by default
print("logger parent handlers ", logger.parent.handlers) # No root handler since root is not configured which logging error does below
print("logger handler ", logger.handlers) # Empty and no parent (root) handler so calls lastResort
logging.error('ZZZ') # Sets the root handler
print("logger parent after logging ", logger.parent) # Root is parent
print("logger parent handlers after logging ", logger.parent.handlers) # Root handler is set
print("logger handler after logging ", logger.handlers) # Empty but has parent (root) handler so lastResort is not called
logger.error('XXX')

Output :

XXX
logger parent <RootLogger root (WARNING)>
logger parent handlers []
logger handler []
ERROR:root:ZZZ
logger parent after logging <RootLogger root (WARNING)>
logger parent handlers after logging [<StreamHandler <stderr> (NOTSET)>]
logger handler after logging []
ERROR:main:XXX

[vsajip]

If this behaviour can't be changed for backwards compatibility reasons, then so be it.

It can't be changed for this reason.

But I think it would be disingenuous to claim it's not a design flaw.

Do you think *I'm* being disingenuous, Mark? I don't mean to be. As well as developers from Enthought, who write large, well-tested libraries, logging also has to satisfy the newbie who writes a one-off script that probably won't even be tested via a test runner. For that use case, logging.debug() and friends call basicConfig() under the hood so that simple usage is as easy as possible. So the "accidental" configuring of logging only occurs if nothing has previously been configured and logging.debug() or similar is called. This is documented, as has been mentioned.

Libraries are not supposed to configure logging except using a NullHandler, and this is also documented, but there are numerous authors of libraries that ignore that advice. If this causes problems to users of those libraries, that is down to the authors of those libraries rather than logging itself, and issues should be logged against those libraries. I maintain that calling basicConfig() in logging.XXX() is not accidental or a design flaw that crept in somehow, but was considered specifically in the context of logging in simple cases. This is documented in the PEP:

https://www.python.org/dev/peps/pep-0282/#id30

This PEP was the basis for discussion on python-dev before the logging package was accepted into Python.

What guidelines does Enthought provide to its developers for configuring Python logging and its usage in libraries and unit tests? If this is public, I would be interested to see it. Are there any specific third-party libraries you have come across which Enthought uses regularly/repeatedly, which misconfigure logging in the way you describe? I would also be curious to know about those.