Custom logger fails with KeyError

[kstratis]

I've already posted on StackOverflow but I'm also opening an issue here so this can gain more traction.

I'm having difficulties getting the library to play well with my custom logger:

import logging
from PIL import Image


class TaskAddingFilter(logging.Filter):
    def __init__(self):
        logging.Filter.__init__(self)

    def filter(self, record):
        record.args = record.args + ('task', '')

# Notice the custom task key in format
logging.basicConfig(
    filename='mylog.txt',
    format='%(asctime)-19.19s|%(task)-36s|%(levelname)s:%(name)s:%(lineno)s: %(message)s',
    level=eval('logging.%s' % 'DEBUG'))

# My attempt to "monkey-patch" PIL's logger 
for name, logger in logging.Logger.manager.loggerDict.iteritems():
    logger = logging.getLogger(name)
    if name.startswith('PIL'):
        logger.addFilter(TaskAddingFilter())

logger = logging.getLogger('demo')


def tryThis():
    with open('my_image.png', 'rb') as im:
        logger.debug('Attempting to read image size...', extra={'task': '123'})
        try:
            image = Image.open(im)
            w, h = image.size
            image.save('my_image_out.png', 'PNG')
        except IOError:
            logger.error('Processing failed!', extra={'task': '123'})
            raise Exception()


tryThis()

I get this error back:

Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.12_2/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 861, in emit
    msg = self.format(record)
  File "/usr/local/Cellar/python/2.7.12_2/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 734, in format
    return fmt.format(record)
  File "/usr/local/Cellar/python/2.7.12_2/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 469, in format
    s = self._fmt % record.__dict__
KeyError: 'task'
Logged from file PngImagePlugin.py, line 135

I am running Python 2.7.12 on macOS Sierra. Just copy past my code with an image of your own and you'll be able to quickly reproduce it.

How should I handle this?

Thank you.

[wiredfool]

I think what's happening is that you're customizing the loggers before the logger for PngImagePlugin is set up.

>>> from PIL import Image
>>> import logging
>>> print (logging.Logger.manager.loggerDict)
{'PIL.Image': <logging.Logger object at 0x7fa1db4eec88>, 'PIL': <logging.PlaceHolder object at 0x7fa1db5c5630>}
>>> Image.init()
1
>>> print (logging.Logger.manager.loggerDict)
{'PIL.PcxImagePlugin': <logging.Logger object at 0x7fa1d9a4d898>, 'PIL.Image': <logging.Logger object at 0x7fa1db4eec88>, 'PIL': <logging.PlaceHolder object at 0x7fa1db5c5630>, 'PIL.PngImagePlugin': <logging.Logger object at 0x7fa1d98539e8>}
>>> 

[kstratis]

I'm not sure I follow.

I've put Image.init() just after the import statement but I still get the same error.

Is it my error here?

[wiredfool]

Try running under pdb (python -m pdb script.py) and see what the logger name is, then check to ensure that you're patching it.

[kstratis]

logger = logging.getLogger(name) inside the for loop deals with lazy initialization. Otherwise it would just be logger.

In any case the logger names are:

PIL.Image
PIL

[wiredfool]

You're missing the loggers that are in lazily loaded image plugins. It's not picking up PIL.PcxImagePlugin or PIL.PngImagPlugin.

And, it's also missing PIL.PyAccess, even after init, since that one is conditionally imported if cffi is installed and you're running pypy or specially requested it.

[kstratis]

I see.
It seems you are correct because I inspected the PIL and PIL.Image and they seem to be properly patched.

After the first for loop I put the following lines:

for name, logger in logging.Logger.manager.loggerDict.iteritems():
    logger = logging.getLogger(name)
    print name, logger.filters

and then got this back:

PIL.Image [<__main__.TaskAddingFilter object at 0x106d35d10>]
PIL [<__main__.TaskAddingFilter object at 0x106d35d90>]

which means that they are indeed patched but as you said they are not the right ones. So the question becomes:
How do I expose the lazily loaded image plugins PIL.PcxImagePlugin and PIL.PngImagPlugin and patch them in advance?

[wiredfool]

Image.init() is what loads the extra plugins, as seen in in my first response. If you're only getting the two PIL loggers, then Image.init hasn't been successfully called.

[kstratis]

So for anyone interested, I managed to fix this by rearranging my code such that Image.init() is called right after getting my module's logger but before I set up any custom formatting/filters in such a way that once that latter are run, Pillow's image plugins will be already loaded.

Full code:

import logging
from PIL import Image


class TaskAddingFilter(logging.Filter):
    def __init__(self):
        logging.Filter.__init__(self)

    def filter(self, record):
        record.args = record.args + ('task', '123')


logger = logging.getLogger('THEDEMO')

Image.init()

logging.basicConfig(
    filename='mylog.txt',
    format='%(asctime)-19.19s|%(task)-36s|%(levelname)s:%(name)s:%(lineno)s: %(message)s',
    level=eval('logging.%s' % 'DEBUG'))

for name, elogger in logging.Logger.manager.loggerDict.iteritems():
    elogger = logging.getLogger(name)
    if name.startswith('PIL'):
        elogger.addFilter(TaskAddingFilter())


def tryThis():
    with open('my_image.png', 'rb') as im:
        logger.debug('Attempting to read image size...', extra={'task': '123'})
        try:
            image = Image.open(im)
            w, h = image.size
            image.save('my_image_out.png', 'PNG')
            print 'all ran well'
        except IOError:
            logger.error('Processing failed!', extra={'task': 123})
            raise Exception()


tryThis()

Thanks @wiredfool