Log lines originating in keystone.common.wsgi are doubled in log files

[Jay Pipes]

Log lines appear to be doubled up after a certain point in the keystone log output:

http://paste.openstack.org/show/28966/

which makes debugging quite difficult :)

There's nothing particularly strange about my keystone.conf:

[DEFAULT]
public_port = 5000
admin_port = 35357
admin_token = 999888777666
bind_host = 192.168.128.11
compute_port = 8774
verbose = False
debug = true
log_config = /etc/keystone/logging.conf

# ================= Syslog Options ============================
# Send logs to syslog (/dev/log) instead of to file specified
# by `log-file`
use_syslog = false

# Facility to use. If unset defaults to LOG_LOCAL2
syslog_log_facility = LOG_LOCAL3

and in keystone/logging.conf:

[loggers]
keys=root,keystone,combined

[formatters]
keys=normal,normal_with_name,debug

[handlers]
keys=production,file,devel

[logger_root]
level=NOTSET
handlers=file

[logger_keystone]
level=DEBUG
handlers=file
qualname=keystone

[logger_combined]
level=DEBUG
handlers=file
qualname=keystone-combined

[handler_production]
class=handlers.SysLogHandler
level=ERROR
formatter=normal_with_name
args=(('localhost', handlers.SYSLOG_UDP_PORT), handlers.SysLogHandler.LOG_USER)

[handler_file]
class=FileHandler
level=DEBUG
formatter=normal_with_name
args=('/var/log/keystone/keystone.log', 'w')

[handler_devel]
class=StreamHandler
level=NOTSET
formatter=debug
args=(sys.stdout,)

[formatter_normal]
format=%(asctime)s %(levelname)s %(message)s

[formatter_normal_with_name]
format=(%(name)s): %(asctime)s %(levelname)s %(message)s

[formatter_debug]
format=(%(name)s): %(asctime)s %(levelname)s %(module)s %(funcName)s %(message)s

Any ideas on why this might be happening?

[gordon chung (chungg)]

i believe the issue is that both root logger and keystone loggers use the file handler

from python docs (http://docs.python.org/2/library/logging.html), you shouldn't need to attach handler to more than one logger:

Note: If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger - if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

[Jay Pipes (jaypipes)]

This worked:

<dolphm> jaypipes: change the first line in your config "keys=root,keystone,combined" to just "keys=keystone"

[Jay Pipes (jaypipes)]

Dolph's solution actually didn't work...

<email address hidden> 01:03:49:~# exec su -s /bin/sh -c "exec keystone-all" keystone
Traceback (most recent call last):
  File "/usr/bin/keystone-all", line 83, in <module>
    config.setup_logging(CONF)
  File "/usr/lib/python2.7/dist-packages/keystone/config.py", line 41, in setup_logging
    logging.config.fileConfig(conf.log_config)
  File "/usr/lib/python2.7/logging/config.py", line 79, in fileConfig
    _install_loggers(cp, handlers, disable_existing_loggers)
  File "/usr/lib/python2.7/logging/config.py", line 183, in _install_loggers
    llist.remove("root")
ValueError: list.remove(x): x not in list

[Jay Pipes (jaypipes)]

What DID work was to keep the root logger in the keys then set logger_root section's handler to devel which uses StreamHandler instead of File...