Duplicate entries in the log

[Petr Man]

Dear list,

I have recently run into a problem, when CherryPy starts to write all
of its logging twice. This happens, when I change any logging options
using the standard python logging. For example:

logging.basicConfig(level=logging.DEBUG,
format='%(asctime)s %(levelname)-8s %(message)s',
datefmt='%Y-%m-%d %H:%M:%S')

Then the output looks like this for http requests:
192.168.0.151 - - [06/Feb/2009:16:49:59] "POST /xmlrpc HTTP/1.0" 200
129 "" "xmlrpclib.py/1.0.1 (by www.pythonware.com)"
2009-02-06 16:49:59 INFO 192.168.0.151 - - [06/Feb/2009:16:49:59]
"POST /xmlrpc HTTP/1.0" 200 129 "" "xmlrpclib.py/1.0.1 (by www.pythonware.com)"

and output from the server core:
[06/Feb/2009:16:50:05] ENGINE Bus EXITED
2009-02-06 16:50:05 INFO [06/Feb/2009:16:50:05] ENGINE Bus EXITED

I have read http://www.cherrypy.org/wiki/Logging, but using the
suggested
cherrypy.log(msg, context='', severity=logging.DEBUG, traceback=False)
is definitely not an option, because that would require changing
thousands of lines of code in CherryPy independent libraries.

Is there any way to fix this problem?

Petr

[Robert Brewer]

CherryPy creates two levels of Loggers:

root
|
+- cherrypy
|
+- access # Not usually called
| |
| +- <id(app)> # Logs access for each request
|
+- error # Called for startup/shutdown, e.g.
ENGINE
|
+- <id(app)> # Called for errors during the request

The Loggers "cherrypy.access" [1] and "cherrypy.error" are called
outside of a request. During a request, the Loggers
"cherrypy.access.7856" and "cherrypy.error.7856" are called, where
"7856" is id(cherrypy.request.app). All four of these Loggers may have
their own Handlers, whether file, stream, or other. You add a handler to
the "cherrypy.error" Logger by writing, for example:

[global]
log.stream = True

...and you add a handler to the "cherrypy.error.7856" Logger by writing,
for example:

[/]
log.stream = True

The logging module docs say: "In addition to any handlers directly
associated with a logger, all handlers associated with all ancestors of
the logger are called to dispatch the message." This means that if you
include both of the above config snippets, you're going to get two lines
written to stderr for every log call.

But it also means that if you add handlers to the root Logger, then
*that* Logger's handlers will also be called. This is what a call to
logging.basicConfig does--it adds handlers to the root Logger. CherryPy
doesn't set up the root Logger itself, but if you do, the logging module
is designed to dispatch CP messages to it. To stop having CP's loggers
propagate messages up to the root Logger:

cherrypy.log.error_log.propagate = False
cherrypy.log.access_log.propagate = False

There are other ways to achieve this (like upgrading your "CherryPy
independent libraries" to use their own Loggers instead of the root
Logger, like CherryPy does), but the above should be a quick fix.

Robert Brewer
fuma...@aminus.org

[1] Yeah, I know, an access log doesn't make much sense outside of the
request process. It's mostly there for completeness.