Logging: how to suppress default output when adding handlers?

[Chris Shenton]

I am setting up handlers to log DEBUG and above to a rotating file and
ERROR and above to console. But if any of my code calls a logger
(e.g., logging.error("foo")) before I setup my handlers, the logging
system will create a default logger that *also* emits logs, which I
can't seem to get rid of. Is there a way I can suppress the creation
of this default logger, or remove it when I 'm setting up my handlers?
Thanks.

Sample code:

import sys, logging, logging.handlers

if len(sys.argv) > 1:
logging.warning("Logging before setting handlers adds unwanted default logger")

logging.getLogger().setLevel(logging.DEBUG)

console = logging.StreamHandler()
console.setLevel(logging.ERROR)
console.setFormatter(logging.Formatter('%(levelname)-8s %(module)s: %(message)s'))
logging.getLogger().addHandler(console)

filelog = logging.handlers.RotatingFileHandler("/tmp/logtest2.log")
filelog.setFormatter(logging.Formatter('%(asctime)s %(levelname)-8s %(module)s: %(message)s'))
filelog.setLevel(logging.DEBUG) # NOP since default above is DEBUG, but OK
logging.getLogger().addHandler(filelog)

logging.debug("TEST debug")
logging.warning("TEST warning")
logging.error("TEST error")


Sample runs, first without initial log call (good), then with one
showing the default log messages in the mix (bad); I'm showing the
console and tailing the logfile so they're mixed together but the
timestamp indicates the file logs:

chris@Bacalao:/tmp<103> tail -f /tmp/logtest2.log &

chris@Bacalao:/tmp<118> python /tmp/logtest2.py
2007-06-05 09:36:27,234 DEBUG logtest2: TEST debug
2007-06-05 09:36:27,234 WARNING logtest2: TEST warning
ERROR logtest2: TEST error
2007-06-05 09:36:27,239 ERROR logtest2: TEST error

chris@Bacalao:/tmp<119> python /tmp/logtest2.py this gives ugly logger
WARNING:root:Logging before setting handlers adds unwanted default logger
DEBUG:root:TEST debug
2007-06-05 09:36:30,069 DEBUG logtest2: TEST debug
WARNING:root:TEST warning
2007-06-05 09:36:30,072 WARNING logtest2: TEST warning
ERROR:root:TEST error
ERROR logtest2: TEST error
2007-06-05 09:36:30,073 ERROR logtest2: TEST error

 

[Vinay Sajip]

I am setting up handlers to log DEBUG and above to a rotating file and
ERROR and above to console. But if any of my code calls a logger
(e.g.,logging.error("foo")) before I setup my handlers, thelogging
system will create a default logger that *also* emits logs, which I
can't seem to get rid of. Is there a way I can suppress the creation
of this default logger, or remove it when I 'm setting up my handlers?
Thanks.

The default handler is created because you are calling the convenience
functions of the logging package: logging.error, etc. If you don't
want the default handler to be created, either

(a) Configure the logging system yourself before any logging call is
made (I'm not sure why you're not doing this - it could be done in
your main script before anything else happens) - or
(b) Make calls on a specific named logger, e.g.
logging.getLogger("logtest2").error("foo"), rather than
logging.error("foo") which is for casual/unsophisticated use only.

Regards,

Vinay Sajip

 

[Chris Shenton]

The default handler is created because you are calling the convenience
functions of the logging package: logging.error, etc. If you don't
want the default handler to be created, either

(a) Configure the logging system yourself before any logging call is
made (I'm not sure why you're not doing this - it could be done in
your main script before anything else happens) - or

Yeah, I think this is the cause. Unfortunately I'm using a couple
dozen files and a bunch more libraries and if they're doing a
logging.debug() or whatnot they're creating this.

Do you have any ideas how I can trace where the first call is made?
This seems a newbie question but if I have a bunch of other files
which do stuff like "from sqlalchemy import *" they might be invoking
a logging call so I'm not sure how to chase these down.

(b) Make calls on a specific named logger, e.g.
logging.getLogger("logtest2").error("foo"), rather than
logging.error("foo") which is for casual/unsophisticated use only.

I'm dreading having to be so verbose with my (copious) loggers, which
is why I was curious if there was a way to nuke any auto-created
ones. I thought calling logging.shutdown() before configuring my
loggers might do this but it didn't.

Thanks.

 

[Vinay Sajip]

Yeah, I think this is the cause. Unfortunately I'm using a couple
dozen files and a bunch more libraries and if they're doing a logging.debug() or whatnot they're creating this.

I wouldn't have thought that well-written third party libraries (like
SQLAlchemy) would log to the root logger. It's by logging to an
application or library-specific logger that people can see where the
events are being generated - logging to the root logger means a lot of
useful information is lost.

Do you have any ideas how I can trace where the first call is made?
This seems a newbie question but if I have a bunch of other files
which do stuff like "from sqlalchemy import *" they might be invoking
a logging call so I'm not sure how to chase these down.

I presume you are starting the ball rolling using one or more scripts.
As long as you are not making logging calls at import time, then you
can configure logging in your main script, e.g.

if __name__ == "__main__":
logging.basicConfigure(...)

I'm dreading having to be so verbose with my (copious) loggers, which
is why I was curious if there was a way to nuke any auto-created
ones. I thought callinglogging.shutdown() before configuring my
loggers might do this but it didn't.

No need to be particularly verbose. One convention is for each module
to:

# for module foo/bar/baz.py

# Near the top of the module...
import logging

logger = logging.getLogger("foo.bar.baz")

# Then, in the rest of the module...

logger.debug("Test debug output") # No more verbose than
logging.debug("Test debug output")

Even if you have a dozen files, it should be easy to do search/replace
across them without too much trouble.

Regards,

Vinay Sajip