CODEWITHSUNDEEP
pythonlogging
DeBugR
DeBugR

Reputation: 61

Python logging module raising KeyError exception on "add-on" attributes

I have an issue where I am trying to log some additional attributes (the user ID and connecting host IP) on a Python CGI script. This is running under python 2.6.8 on a RHEL 5 system. I am following the documentation for extending the attributes in the basic logging dictionary as follows:

from __future__ import print_function
import logging
import os
import sys

LOG_DIR = '/apps/log'
LOG_PAGE = re.sub(r'\/(.*)\/.*$', r'\1', os.environ['REQUEST_URI'])
#
# The log format should be 
# <date stamp>  <level>   <remote user> <remote IP>: <message>
#
LOG_FORMAT = '%(asctime)-19s %(levelname)-9s %(user)-7s %(clientip)-15s - %(message)s'
LOG_DATE = '%Y-%m-%d %H:%M:%S'
orig_user = os.environ['REMOTE_USER']
orig_ip = os.environ['REMOTE_ADDR']
xtras = { 'user': orig_user, 'clientip': orig_ip }
#
# Set up logging
#
LOG_FILE = LOG_DIR + '/' + LOG_PAGE
logging.basicConfig(format=LOG_FORMAT, datefmt=LOG_DATE, level=logging.DEBUG, filename=LOG_FILE)
logit = logging.getLogger('groups')

and I am calling it with:

logit.debug('user visited page',extra=xtras)
logit.warn('user has no account under domain %s', myDOM, extra=xtras)

Every time a message is logged, 3 KeyError exceptions are logged in the web servers error logs:

s = self._fmt % record.__dict__, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
KeyError: 'user', referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
Traceback (most recent call last):, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
File "/usr/lib64/python2.6/logging/__init__.py", line 776, in emit, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
msg = self.format(record), referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
File "/usr/lib64/python2.6/logging/__init__.py", line 654, in format, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
return fmt.format(record), referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
File "/usr/lib64/python2.6/logging/__init__.py", line 439, in format, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
s = self._fmt % record.__dict__, referer: https://its-serv-dev.case.edu/googlegroups/index.cgi
KeyError: 'user', referer: https://its-serv-dev.case.edu/googlegroups/index.cgi

What is odd is that the KeyError exceptions are only generated for one of the "extra" dictionary items, and that the information IS being logged into the file correctly. I've tried various combinations of removing the two extra components (the error just shifts to whatever is left) and nothing seems to stop the exception from being thrown unless I completely remove the extra information.

I suppose I could just include the information in a format string as part of the message, but it seems like reinventing the wheel.

Upvotes: 2

Views: 3214

Answers (3)

李际朝
李际朝

Reputation: 16

by call logging.basicConfig, you actually change the formatter of RootLogger, which is the ancestor of all Logger. Then it will affect other loggers.

You can get more detail from this github issue.

Upvotes: 0

ConanG
ConanG

Reputation: 759

Faced a similar problem. I guess the error occurs when there are loggers used which do not have filters added (to add the extra attributes on instantiating the loggers) but still passing the records to the formatters using formats corresponding to these attributes.

Link to documentation example using filters

Upvotes: 0

DeBugR
DeBugR

Reputation: 61

I figured out what was happening here:

I am also importing Google's oauth2client.client module which is using the logging module as well. Since the oauth2cleint.client module is considered a "child" of my page, logging was being passed up to my logging object and since the Google module is not including the extra logging dictionary in its calls, the GOOGLE module was the item generating the KeyError exceptions, not my own code. I've worked around the issue for the moment by including the extra items as part of the message, and will need to dig a little more into the the logging module to see if there is a better way to keep the Google oauth2clent.client module logging from conflicting with the page logging.

Upvotes: 4

Related Questions