Nova docker virt driver triggers - AttributeError: 'Message' object has no attribute 'format'

[Boden R]

Using the nova virt docker driver and when I try to deploy an instance I get:

2013-10-21 12:18:39.229 20636 ERROR nova.compute.manager [req-270deff8-b0dc-4a05-9923-417dc5b662db c99d13095fbd4605b36a802fd9539a4a a03677565e97495fa798fe6cd2628180] [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] Error: 'Message' object has no attribute 'format'
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] Traceback (most recent call last):
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1045, in _build_instance
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] set_access_ip=set_access_ip)
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1444, in _spawn
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] LOG.exception(_('Instance failed to spawn'), instance=instance)
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1430, in _spawn
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] block_device_info)
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] File "/usr/lib/python2.6/site-packages/nova/virt/docker/driver.py", line 297, in spawn
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] LOG.info(msg.format(image_name))
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] File "/usr/lib/python2.6/site-packages/nova/openstack/common/gettextutils.py", line 255, in __getattribute__
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] return UserString.UserString.__getattribute__(self, name)
2013-10-21 12:18:39.229 20636 TRACE nova.compute.manager [instance: 206bb110-4fa5-4999-be87-9b10951ad5dd] AttributeError: 'Message' object has no attribute 'format'

On a boot VM flow.

Based on a tiny bit of poking it appears there is a common gettextutils method to wrapper message/string access which does not account for the use of Message.format() as used in the docker virt driver.

Honestly based on the code I'm running I'm not sure how spawn worked at all for docker as the use of Message.format() is in the boot codepath:

296 msg = _('Image name "{0}" does not exist, fetching it...')
297 LOG.info(msg.format(image_name))

This always triggers the no attr message.

I'm not up to speed on the gettextutils wrapper, but I hacked around this by adding 'format' to the list of ops in gettextutils.py:

     def __getattribute__(self, name):
243 # NOTE(mrodden): handle lossy operations that we can't deal with yet
244 # These override the UserString implementation, since UserString
245 # uses our __class__ attribute to try and build a new message
246 # after running the inner data string through the operation.
247 # At that point, we have lost the gettext message id and can just
248 # safely resolve to a string instead.
249 ops = ['capitalize', 'center', 'decode', 'encode',
250 'expandtabs', 'ljust', 'lstrip', 'replace', 'rjust', 'rstrip',
251 'strip', 'swapcase', 'title', 'translate', 'upper', 'zfill', 'format']
252 if name in ops:
253 return getattr(self.data, name)
254 else:
255 return UserString.UserString.__getattribute__(self, name)

[Doug Hellmann (doug-hellmann)]

It would be better to change the log call to

    msg = _('Image name "%s" does not exist, fetching it...')
    LOG.info(msg, image_name)

because that delays both the translation and the string interpolation until the log message is actually going to be emitted.

[Joe Gordon (jogo)]

nova doesn't have a docker driver currently.

[Ben Nemec (bnemec)]

I suspect we omitted this on purpose because we didn't want to have to support multiple methods of formatting strings, which is a little tricky to do for lazy translation because you have to store all of the parameters too so they can be lazily translated if necessary. Also, as Doug noted the code that originally triggered this doesn't follow logging best practices anyway and should be changed.

I'm going to close as won't-fix for the reasons above, but if anyone disagrees or finds a situation where this is absolutely needed then please feel free to reopen (or ping an Oslo person to reopen).

[Davanum Srinivas (DIMS) (dims-v)]

Duh, looks like current code looks like this

        msg = 'Image name "%s" does not exist, fetching it...'
        LOG.debug(msg % image_meta['name'])

So marking as fixed.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/128376
Committed: https://git.openstack.org/cgit/stackforge/nova-docker/commit/?id=7c2f3c9ebb56974a453a6d7c34f0a2f0c98f4658
Submitter: Jenkins
Branch: master

commit 7c2f3c9ebb56974a453a6d7c34f0a2f0c98f4658
Author: Davanum Srinivas <email address hidden>
Date: Thu Oct 23 08:43:48 2014 -0400

    Fix LOG formatting and defer until emit

    Formatting could and should be deferred until logs are emitted.
    Boden Russell found a bug where bad formatting practice resulted in
    a developer calling format() on the output of a gettextutils call.

    Here, we standardize the debugging output in a saner, cleaner way as
    recommended by Doug Hellmann.

    Closes-Bug: #1242820

    Change-Id: I259a435466d394c7d009f8ba2e976713f3fb4343