[issue35530] Counter-intuitive logging API

[Vinay Sajip]

Change by Vinay Sajip :


--
resolution:  -> not a bug
stage:  -> resolved
status: open -> closed

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Vinay Sajip]

Vinay Sajip  added the comment:

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

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Raymond Hettinger]

Change by Raymond Hettinger :


--
assignee:  -> vinay.sajip

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Karthikeyan Singaravelan]

Karthikeyan Singaravelan  added the comment:

> 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  
logger parent handlers  []
logger handler  []
ERROR:root:ZZZ
logger parent after logging  
logger parent handlers after logging  [ (NOTSET)>]
logger handler after logging  []
ERROR:main:XXX

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Emmanuel Arias]

Emmanuel Arias  added the comment:

> 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!

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Mark Dickinson]

Mark Dickinson  added the comment:

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




--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Steven D'Aprano]

Steven D'Aprano  added the comment:

On Wed, Dec 19, 2018 at 10:37:22AM +, Mark Dickinson wrote:
> 
> Mark Dickinson  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.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Steven D'Aprano]

Steven D'Aprano  added the comment:

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

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Mark Dickinson]

Mark Dickinson  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`.

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.

--
nosy: +mark.dickinson

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Karthikeyan Singaravelan]

Karthikeyan Singaravelan  added the comment:

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

--
nosy: +xtreak

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Emmanuel Arias]

Emmanuel Arias  added the comment:

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

--
nosy: +eamanu

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Steven D'Aprano]

Steven D'Aprano  added the comment:

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"

--
nosy: +steven.daprano, vinay.sajip

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue35530] Counter-intuitive logging API

[Victor Porton]

New submission from Victor Porton :

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.

--
components: Library (Lib)
messages: 332103
nosy: porton
priority: normal
severity: normal
status: open
title: Counter-intuitive logging API
type: behavior
versions: Python 3.7

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com