requests to EC2 metadata's '/2009-04-04/meta-data/security-groups' failing

[Adam Gandelman]

Just did a distro upgrade to juno rc2.. Running an old nova-network cloud with mult-host, nova-api running on compute host. Noticed ubuntu instances cloud-init is failing:

Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/boto/utils.py", line 177, in retry_url
    resp = urllib2.urlopen(req)
  File "/usr/lib/python2.7/urllib2.py", line 126, in urlopen
    return _opener.open(url, data, timeout)
  File "/usr/lib/python2.7/urllib2.py", line 406, in open
    response = meth(req, response)
  File "/usr/lib/python2.7/urllib2.py", line 519, in http_response
    'http', request, response, code, msg, hdrs)
  File "/usr/lib/python2.7/urllib2.py", line 444, in error
    return self._call_chain(*args)
  File "/usr/lib/python2.7/urllib2.py", line 378, in _call_chain
    result = func(*args)
  File "/usr/lib/python2.7/urllib2.py", line 527, in http_error_default
    raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)

Looking at nova-api.log on compute, webob is throwing an exception:

2014-10-13 13:47:37.468 9183 INFO nova.metadata.wsgi.server [req-e133f95b-5f99-41e5-89dc-8e35b41f7cd6 None] 10.0.0.6 "GET /2009-04-04/meta-data/security-groups HTTP/1.1" status: 400 len: 265 time: 0.2675409
2014-10-13 13:48:41.947 9182 ERROR nova.api.ec2 [req-47b84883-a48c-4004-914b-c983895a33be None] FaultWrapper: You cannot set Response.body to a text object (use Response.text)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 Traceback (most recent call last):
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/nova/api/ec2/__init__.py", line 87, in __call__
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 return req.get_response(self.application)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 application, catch_exc_info=False)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 app_iter = application(self.environ, start_response)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 resp = self.call_func(req, *args, **self.kwargs)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 return self.func(req, *args, **kwargs)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/nova/api/ec2/__init__.py", line 99, in __call__
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 rv = req.get_response(self.application)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 application, catch_exc_info=False)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 app_iter = application(self.environ, start_response)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 resp = self.call_func(req, *args, **self.kwargs)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 return self.func(req, *args, **kwargs)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/nova/api/metadata/handler.py", line 136, in __call__
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 req.response.body = resp
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/response.py", line 373, in _body__set
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 raise TypeError(msg)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2 TypeError: You cannot set Response.body to a text object (use Response.text)
2014-10-13 13:48:41.947 9182 TRACE nova.api.ec2

A bit of poking shows that nova.api.metadata.base.ec2_md_print() is converting the secgroup list to string:

    elif isinstance(data, list):
        return '\n'.join(data)

.. but in this case data=[u'default'], and the exception is being raised when resp.body = u'default'. ec2_md_print() needs to ensure its returning non-unicode string here.

[Matt Riedemann (mriedem)]

Which versions of webob and boto are you using?

[Matt Riedemann (mriedem)]

This is bad:

http://git.openstack.org/cgit/openstack/nova/tree/nova/api/ec2/__init__.py?id=2014.2.rc2#n89

We aren't supposed to cast exceptions to unicode, <email address hidden> had a patch to fix these in nova I thought as part of the i18n work.

However, adam_g pointed out he's using boto 2.20.1 and the min version required for nova rc2 is >= 2.32.1:

http://git.openstack.org/cgit/openstack/nova/tree/requirements.txt?id=2014.2.rc2#n9

So try using a newer boto and see if the problem goes away.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/128100

[Adam Gandelman (gandelman-a)]

Tested with the boto described in requirements (2.33.0) and the issue still exists. It's not boto related, its a webob excpetion raised when attempting to set:

req.response.body = u'foo'
*** TypeError: You cannot set Response.body to a text object (use Response.text)

[Adam Gandelman (gandelman-a)]

It looks like security groups metadata always exists internally as a list of unicode names, however nova's unit test coverage doesn't stress fetching any metadata that would trigger this. AFAICS 'security_groups' is the only bit of ec2 metadata that would contain a list, adding a simple unit test to fetch that path triggers the bug. I can't find anything in Tempest that would hit this, either.

[Adam Gandelman (gandelman-a)]

Proposed a failing test to tempest that triggers the issue: https://review.openstack.org/#/c/128422/

http://logs.openstack.org/22/128422/1/check/check-tempest-dsvm-full/3734c9e/logs/screen-n-api.txt.gz#_2014-10-14_20_21_58_603

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/128100
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=f0f07fdb6702f89f3800a5054e9365c3abc90f7a
Submitter: Jenkins
Branch: master

commit f0f07fdb6702f89f3800a5054e9365c3abc90f7a
Author: Adam Gandelman <email address hidden>
Date: Mon Oct 13 17:42:42 2014 -0700

    Use response.text for returning unicode EC2 metadata

    When serving meta-data that contains unicode, use the webob Response.text
    instead of Response.body. This also adds a test that triggers the bug in
    addition to testing that all meta-data offered by the server can be served.

    Closes-bug: #1380792

    Change-Id: If2ddaa97bbc89cf574205c0327e3caa02dd503fc

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/juno
Review: https://review.openstack.org/130342

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/130342
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=c159f9107b2184f1d8af546eae5a985a3627e7d9
Submitter: Jenkins
Branch: stable/juno

commit c159f9107b2184f1d8af546eae5a985a3627e7d9
Author: Adam Gandelman <email address hidden>
Date: Mon Oct 13 17:42:42 2014 -0700

    Use response.text for returning unicode EC2 metadata

    When serving meta-data that contains unicode, use the webob Response.text
    instead of Response.body. This also adds a test that triggers the bug in
    addition to testing that all meta-data offered by the server can be served.

    Closes-bug: #1380792

    Change-Id: If2ddaa97bbc89cf574205c0327e3caa02dd503fc
    (cherry picked from commit f0f07fdb6702f89f3800a5054e9365c3abc90f7a)