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

Question

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.

DeBugR · Accepted Answer · 2014-04-14 18:13:26Z

4

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.

answered Apr 14, 2014 at 18:13

DeBugR

611 silver badge4 bronze badges

Sign up to request clarification or add additional context in comments.

2 Comments

fangzhzh Over a year ago

Hi, any update about your question. Please share your answer if you find solution :)

Ruben Flam-Shepherd Over a year ago

Eight year later and this is still an issue...

ConanG · Accepted Answer · 2017-07-12 12:47:06Z

0

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

answered Jul 12, 2017 at 12:47

ConanG

7791 gold badge7 silver badges18 bronze badges

Comments

李际朝 · Accepted Answer · 2018-08-01 13:52:33Z

0

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.

answered Aug 1, 2018 at 13:52

李际朝

163 bronze badges

Collectives™ on Stack Overflow

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

3 Answers 3

2 Comments

Comments

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

3 Answers 3

2 Comments

Comments

Comments

Your Answer

Sign up or log in

Post as a guest

Related