This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: logging.basicConfig creates phantom handler
Type: Stage:
Components: Library (Lib) Versions:
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: logistix, techtonik, vinay.sajip
Priority: normal Keywords:

Created on 2005-03-17 02:38 by logistix, last changed 2022-04-11 14:56 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
logging_fix.diff logistix, 2005-03-17 02:39 Trivial Fix
Messages (8)
msg24667 - (view) Author: Grant Olson (logistix) Date: 2005-03-17 02:38
calling logging.basicConfig() creates a phantom handler 
that doesn't operate in an intuitive way.  A reproducable 
follows.

My actual use case:  I started off using the logging 
module on a project with the builting logging.info(), 
logging.debug(), logging.error() functions.  As my needs 
got more sophisticated, I started creating some loggers 
via logging.getLogger('a.b.c')  I setup a custom handler 
to do formatting without printing "INFO:a.b.c" headers.  
One of my import statements triggered a call to 
logging.basicConfig.  Halfway through the running 
program, my logging messages started showing up 
twice.  Once without the header and once with.  I 
eventually tracked this down to usage of a logging.info() 
statement.  I tried explicitly calling logging.basicConfig
(level=logging.ERROR) to disable the duplicate errors, 
but that didn't work.

A trivial patch is attached.  It fixes the problem if you 
explicitly call logging.basicConfig.  I don't know if it will 
fix the implicit calls by logging.info(), etc.

C:\Python24>python
Python 2.4 (#60, Nov 30 2004, 11:49:19) [MSC v.1310 
32 bit (Intel)] on win32
Type "help", "copyright", "credits" or "license" for more 
information.
>>> import logging
>>>
>>> logger = logging.getLogger('foo')
>>> logger.setLevel(logging.INFO)
>>> logger.info('bar') # no output yet
No handlers could be found for logger "foo"
>>>
>>> console = logging.StreamHandler()
>>> console.setLevel(logging.INFO)
>>> console.setFormatter(logging.Formatter("%
(message)s")
... )
>>> logger.addHandler(console)
>>>
>>> logger.info('foo')
foo
>>>
>>> logger.warning('foo')
foo
>>>
>>> logger.debug('foo')
>>>
>>> logger.info('foo')
foo
>>>
>>> logging.basicConfig(level=logging.ERROR)
>>>
>>> logger.info('foo')
foo
INFO:foo:foo
>>> ^Z


C:\Python24>
msg24668 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2005-03-17 10:52
Logged In: YES 
user_id=308438

Thanks for the feedback, but it's not a bug. Check the 
docstring for basicConfig: "This function does nothing if the 
root logger already has handlers configured. It is a 
convenience method intended for use by simple scripts to do 
one-shot configuration of the logging package. The default 
behaviour is to create a StreamHandler which writes to 
sys.stderr, set a formatter using the BASIC_FORMAT format 
string, and add the handler to the root logger."

The logging.debug(), etc. methods are for simple use of the 
logging package. If you are using named loggers, then don't 
use basicConfig() except to configure a handler at the root 
level - and do this early in your application. Thereafter you 
can log to the root logger (using logging.debug() and its 
brethren) or to a named logger which has no handlers set (the 
root's handlers will be used).

If you add a console handler manually to logger "foo" and 
then add another one to the root handler via basicConfig(), 
then both handlers will be called (correctly). This is what you 
are seeing.

Your fix (add the level to the handler as well) does not fit the 
contract of basicConfig(). Users working in simple mode will 
just use the logger's level. Setting levels in the handler is for 
more sophisticated use of the logging package than implied 
by use of basicConfig() and logging.debug(), etc.
msg145060 - (view) Author: anatoly techtonik (techtonik) Date: 2011-10-07 07:55
Can basicConfig() report its failure with DEBUG level when called twice?
msg145069 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-10-07 10:05
@anatoly: What failure do you mean? The behaviour that logistix described is not a failure, it's by design. See my closing comment.
msg145072 - (view) Author: anatoly techtonik (techtonik) Date: 2011-10-07 12:41
I know that it is by design, but from all logging users you may be the only one who keeps this behaviour in mind. The message why basicConfig() failed will be more user-friendly.
msg145079 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-10-07 14:31
> anatoly techtonik <techtonik@gmail.com> added the comment:
> 
> I know that it is by design, but from all logging users you may be the only one 
> who keeps this behaviour in mind. The message why basicConfig() failed will be 
> more user-friendly.

You're not likely to be aware of all the feedback I get from other users of the logging package, so I'm not sure what your inference "you may be the only one" is based on. Since basicConfig() didn't "fail" (behaviour is as designed), I'm not planning any changes in this area. Also note: this issue was raised and closed in March 2005, and there have been no requests since then to change the existing behaviour (nor would it be possible to accommodate such requests without compromising backward compatibility).
msg145080 - (view) Author: anatoly techtonik (techtonik) Date: 2011-10-07 14:40
There were no request to change the behaviour, because there is already this closed issue where it is clearly said that this won't be fixed.

However, this doesn't cancel the fact that logging package needs enhancements to be more pythonic (i.e. intuitive and user-friendly). Even though they can not be included in Python, it can make sense to keep that in mind (or split a branch) for Python4.

http://code.google.com/p/rainforce/wiki/WartsOfPython#Logging_%282.x_tested,_3.x_unknown%29
msg145089 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-10-07 15:18
> There were no request to change the behaviour, because there is already this 
> closed issue where it is clearly said that this won't be fixed.

Sure, but this issue seldom comes up as a point of confusion on comp.lang.python. If you think the documentation is confusing or not sufficiently explicit, you can propose a patch. Since configuration preferences and styles tend to be very much a matter of personal taste, I'm pretty sure that any change in this area which will be liked by some people won't be liked by others. So, it's best if people roll their own or publish on PyPI or elsewhere some code [to configure logging "optimally"] which others can use: if a widely-used pattern emerges as a no-brainer from actual usage out there, we can revisit this discussion.
History
Date User Action Args
2022-04-11 14:56:10adminsetgithub: 41710
2011-10-07 15:18:50vinay.sajipsetmessages: + msg145089
2011-10-07 14:40:50techtoniksetmessages: + msg145080
2011-10-07 14:31:58vinay.sajipsetmessages: + msg145079
2011-10-07 12:41:42techtoniksetmessages: + msg145072
2011-10-07 10:05:56vinay.sajipsetmessages: + msg145069
2011-10-07 07:55:06techtoniksetnosy: + techtonik
messages: + msg145060
2005-03-17 02:38:17logistixcreate