classification
Title: Non obvious logging handler behaviour
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.7, Python 3.6
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: mark.dickinson, oneofthose, vinay.sajip
Priority: normal Keywords:

Created on 2018-08-06 20:41 by oneofthose, last changed 2018-08-08 22:14 by vinay.sajip. This issue is now closed.

Messages (3)
msg323224 - (view) Author: Sebastian (oneofthose) Date: 2018-08-06 20:41
In Python 3.6.3 I can do:

import logging
logger = logging.getLogger()
logger.setLevel(logging.INFO)
logger.info("this does not work")
logging.info("PARTY")
logger.info("this works")

And it outputs:

INFO:root:PARTY
INFO:root:this works


The line 
logging.info("PARTY") 
seems to add a handler which makes the last line work. This is very confusing behavior as it is not obvious that a call to "logging.info" mutates the state of the logging subsystem and affects subsequent logging calls.
msg323227 - (view) Author: Mark Dickinson (mark.dickinson) * (Python committer) Date: 2018-08-06 21:03
The behaviour is long-standing and documented, in the note just under this entry: https://docs.python.org/3/library/logging.html?highlight=logging#logging.log

But I do agree that it's surprising and (at least for me) undesirable behaviour, in that it makes it way too easy to accidentally configure logging in library code, which is a no-no according to most logging "best practices" advice. (Applications do logging configuration; libraries should usually confine themselves to creating loggers and emitting log messages.)

But I suspect it would be rather hard to change now.
msg323306 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-08-08 22:14
The logging module-level convenience functions are specifically there for the use of casual, short scripts where users don't want to be concerned with the details of loggers and handlers.

Even if you accidentally configure logging in library code because you typed logging.XXX() instead of logger.XXX(), that's just like any other bug introduced because of a typo. It would presumably get caught in testing.

Obviously, this behaviour can't be changed because of the need to maintain backward compatibility (and IMO there is no reason to change this behaviour, as it is like this by design).
History
Date User Action Args
2018-08-08 22:14:19vinay.sajipsetstatus: open -> closed
type: behavior
messages: + msg323306

resolution: not a bug
stage: resolved
2018-08-08 17:01:47mark.dickinsonsetnosy: + vinay.sajip
2018-08-06 21:03:42mark.dickinsonsetnosy: + mark.dickinson
messages: + msg323227
2018-08-06 20:41:27oneofthosecreate