logging KeyError: '<key>'

[sicklife]

Actually, I reproduce an error in the same with this one, which I think maybe a bug of urllib3.

[sethmlarson]

Thanks for submitting this, do you think you'd be able to submit a patch to fix the issue?

[sicklife]

I traceback this bug today, and find it a little tricky.

1. It's not a fatal error. It can be handled by the logging.Handler.handleError of logging module.

2. when you do logger = logging.getLogger(); logStdOut = logging.StreamHandler(); LOGFORMATCNSL=logging.Formatter("%(asctime)s %(message)s %(aVar)s %(bVar)s"); logStdOut.setFormatter(LOGFORMATCNSL); logger.addHandler(logStdOut) this actually changed the formatter of the RootLogger, which is the ancestor of all logger. So when you make a log Record that inherit the RootLogger, while without the required extra info, an error will raise.

The possible solution might be:

1. Just ingore this, for it's not fatal;
2. Check the RootLogger formatter, if it contains extra keys, set current logger with a new formatter without extra key explicitly.

which do you prefer? Or is there other solution?

[sethmlarson]

I'm wondering if this is actually a bug or if we should recommend users not use the RootLogger? Using the RootLogger while expecting non-standard keys within the handler you attach seems like a risky idea, unless I'm reading that wrong?

[sicklife]

No, you understand what I means exactly. I'm not a native english speaker, forgive me, if there is any odd expression.

Infact, if you don't use RootLogger, by passing a name to the logging.getLogger() function, which will create a child of the RootLogger, and leave the RootLogger untouched, will avoid this trouble.

the code is as follow

import requests
import logging

# code with out bug
logger = logging.getLogger("__abc__")
# code will trigger the keyError bug
# logger = logging.getLogger()

logStdOut = logging.StreamHandler()
print(isinstance(logger, logging.RootLogger))
LOGFORMATCNSL=logging.Formatter("%(asctime)s %(message)s %(aVar)s %(bVar)s")
logStdOut.setFormatter(LOGFORMATCNSL)
logStdOut.setLevel(logging.DEBUG)
logger.setLevel(logging.NOTSET)
logger.addHandler(logStdOut)


def tryThis():
    logger.error("deneme", extra={"aVar": "aVal", "bVar": "bVal"})
    conn = requests.get("http://www.baidu.com")
    conn.close()

tryThis()

[sethmlarson]

So I don't think this is a urllib3 issue because I can reproduce it without urllib3:

import logging

root_logger = logging.getLogger()
sub_logger = logging.getLogger('test')

handler = logging.StreamHandler()
handler.addFormatter(logging.Formatter('%(aVar)'))
root_logger.addHandler(handler)
root_logger.setLevel(logging.NOTSET)

sub_logger.info('testme', extra={})
"""
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/__init__.py", line 987, in emit
    msg = self.format(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 833, in format
    return fmt.format(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 573, in format
    s = self.formatMessage(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 542, in formatMessage
    return self._style.format(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 386, in format
    return self._fmt % record.__dict__
KeyError: 'aVar'
Call stack:
  File "<stdin>", line 1, in <module>
Message: 'testme'
Arguments: ()
"""

[sicklife]

OK. Then I'll close the issue.