Non obvious logging handler behaviour

[oneofthose]

BPO	34350
Nosy	@vsajip, @mdickinson

^{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 = None
closed_at = <Date 2018-08-08.22:14:19.795>
created_at = <Date 2018-08-06.20:41:27.527>
labels = ['3.7', 'invalid', 'type-bug', 'library']
title = 'Non obvious logging handler behaviour'
updated_at = <Date 2018-08-08.22:14:19.794>
user = 'https://bugs.python.org/oneofthose'

bugs.python.org fields:

activity = <Date 2018-08-08.22:14:19.794>
actor = 'vinay.sajip'
assignee = 'none'
closed = True
closed_date = <Date 2018-08-08.22:14:19.795>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2018-08-06.20:41:27.527>
creator = 'oneofthose'
dependencies = []
files = []
hgrepos = []
issue_num = 34350
keywords = []
message_count = 3.0
messages = ['323224', '323227', '323306']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'mark.dickinson', 'oneofthose']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue34350'
versions = ['Python 3.6', 'Python 3.7']

[oneofthose]

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.

[mdickinson]

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.

[vsajip]

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