Bug 1128112 - Metadata service is returning HTTP/500 errors to instances when booting [NEEDINFO]
Summary: Metadata service is returning HTTP/500 errors to instances when booting
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-neutron
Version: 4.0
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: 5.0 (RHEL 7)
Assignee: Jakub Libosvar
QA Contact: Ofer Blaut
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-08-08 10:20 UTC by Eduard Barrera
Modified: 2018-12-09 18:18 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-10-15 14:39:19 UTC
jlibosva: needinfo? (ebarrera)


Attachments (Terms of Use)
api (24.91 KB, application/x-bzip)
2014-08-11 06:49 UTC, Eduard Barrera
no flags Details
metadata (74.32 KB, application/x-bzip)
2014-08-11 06:49 UTC, Eduard Barrera
no flags Details
server_log (3.91 MB, application/x-bzip)
2014-08-11 12:08 UTC, Eduard Barrera
no flags Details

Description Eduard Barrera 2014-08-08 10:20:56 UTC
Description of problem:


OpenStack metadata service is unstable. From time to time, it stops behaving properly, which translates into HTTP/500 errors seen by instances when booting:

cloud-init[845]: 2014-08-08 04:13:38,554 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [77/120s]: bad status code [500]

I've traced this to the following errors in /var/log/nova/api.log:

2014-08-08 10:13:10.184 4198 WARNING keystoneclient.middleware.auth_token [-] Unable to find authentication token in headers
2014-08-08 10:13:10.795 4199 ERROR nova.api.metadata.handler [-] Failed to get metadata for instance id: 810ff4bd-245d-44b9-96af-439618e0484a
2014-08-08 10:13:10.795 4199 ERROR nova.api.ec2 [-] FaultWrapper: 'NoneType' object has no attribute 'instance'
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2 Traceback (most recent call last):
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/nova/api/ec2/__init__.py", line 87, in __call__
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     return req.get_response(self.application)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/WebOb-1.2.3-py2.6.egg/webob/request.py", line 1296, in send
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     application, catch_exc_info=False)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/WebOb-1.2.3-py2.6.egg/webob/request.py", line 1260, in call_application
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     app_iter = application(self.environ, start_response)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/WebOb-1.2.3-py2.6.egg/webob/dec.py", line 130, in __call__
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     resp = self.call_func(req, *args, **self.kwargs)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/WebOb-1.2.3-py2.6.egg/webob/dec.py", line 195, in call_func
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     return self.func(req, *args, **kwargs)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/nova/api/ec2/__init__.py", line 99, in __call__
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     rv = req.get_response(self.application)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/WebOb-1.2.3-py2.6.egg/webob/request.py", line 1296, in send
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     application, catch_exc_info=False)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/WebOb-1.2.3-py2.6.egg/webob/request.py", line 1260, in call_application
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     app_iter = application(self.environ, start_response)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/WebOb-1.2.3-py2.6.egg/webob/dec.py", line 130, in __call__
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     resp = self.call_func(req, *args, **self.kwargs)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/WebOb-1.2.3-py2.6.egg/webob/dec.py", line 195, in call_func
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     return self.func(req, *args, **kwargs)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/nova/api/metadata/handler.py", line 107, in __call__
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     meta_data = self._handle_instance_id_request(req)
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2   File "/usr/lib/python2.6/site-packages/nova/api/metadata/handler.py", line 203, in _handle_instance_id_request
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2     if meta_data.instance['project_id'] != tenant_id:
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2 AttributeError: 'NoneType' object has no attribute 'instance'
2014-08-08 10:13:10.795 4199 TRACE nova.api.ec2 


We also found the following errors in /var/log/neutron/metadata-agent.log:

2014-08-08 06:01:47.493 21793 TRACE neutron.agent.metadata.agent
2014-08-08 06:01:48.504 21793 DEBUG neutron.agent.metadata.agent [-] Request: GET /2009-04-04/meta-data/instance-id HTTP/1.0^M
Accept-Encoding: gzip, deflate^M
Content-Type: text/plain^M
Host: 169.254.169.254^M
User-Agent: Python-httplib2/0.7.2 (gzip)^M
X-Forwarded-For: 192.168.203.7^M
X-Neutron-Router-Id: b61f1285-d307-48be-95b6-b21ddc08d37a __call__ /usr/lib/python2.6/site-packages/neutron/agent/metadata/agent.py:116
2014-08-08 06:01:48.505 21793 DEBUG neutron.openstack.common.lockutils [-] Got semaphore "('neutron.agent.metadata.agent.MetadataProxyHandler._get_router_networks', 'b61f1285-d307-48be-95b6-b21ddc08d37a')" lock /usr/lib/python2.6/site-packages/neutron/openstack/common/lockutils.py:168
2014-08-08 06:01:48.505 21793 DEBUG neutron.openstack.common.lockutils [-] Got semaphore "('neutron.agent.metadata.agent.MetadataProxyHandler._get_ports_for_remote_address', '192.168.203.7', (u'cd7e5f8d-9ba6-4b2e-b83f-3da366a2e4c2',))" lock /usr/lib/python2.6/site-packages/neutron/openstack/common/lockutils.py:168
2014-08-08 06:01:48.565 21793 ERROR neutron.agent.metadata.agent [-] Unexpected error.
2014-08-08 06:01:48.565 21793 TRACE neutron.agent.metadata.agent Traceback (most recent call last):
2014-08-08 06:01:48.565 21793 TRACE neutron.agent.metadata.agent   File "/usr/lib/python2.6/site-packages/neutron/agent/metadata/agent.py", line 120, in __call__
2014-08-08 06:01:48.565 21793 TRACE neutron.agent.metadata.agent     return self._proxy_request(instance_id, tenant_id, req)
2014-08-08 06:01:48.565 21793 TRACE neutron.agent.metadata.agent   File "/usr/lib/python2.6/site-packages/neutron/agent/metadata/agent.py", line 227, in _proxy_request
2014-08-08 06:01:48.565 21793 TRACE neutron.agent.metadata.agent     raise Exception(_('Unexpected response code: %s') % resp.status)
2014-08-08 06:01:48.565 21793 TRACE neutron.agent.metadata.agent Exception: Unexpected response code: 400


After spending quite some time trying to figure out why 'NoneType' was being returned for meta_data, couldn't figure out anything. I decided to restart Neutron metadata agent service:

# service neutron-metadata-agent restart


This solved the issue, and metadata requests were working again. However, I find this workaround not acceptable in a production environment. Could we please look into this issue and figure out why it is happening?

Comment 5 Eduard Barrera 2014-08-11 06:47:40 UTC
At this moment I have api.log and metadata.log. I already asked for the rest

attaching files

Comment 6 Eduard Barrera 2014-08-11 06:49:01 UTC
Created attachment 925625 [details]
api

Comment 7 Eduard Barrera 2014-08-11 06:49:31 UTC
Created attachment 925626 [details]
metadata

Comment 8 Eduard Barrera 2014-08-11 12:08:02 UTC
Created attachment 925716 [details]
server_log

Comment 9 Eduard Barrera 2014-08-18 12:12:14 UTC
# rpm -qa | grep python-neutron
python-neutron-2013.2.2-5.el6ost.noarch
python-neutronclient-2.3.1-3.el6ost.noarch

Comment 10 Ihar Hrachyshka 2014-08-18 12:40:00 UTC
So the used versions of both neutron and neutronclient lack multiple significant patches both for performance and stability of metadata agent. I would try to upgrade to latest package versions first before proceeding with debugging.

Comment 12 haichuan 2015-07-13 03:39:48 UTC
I also encountered this problem, is there any solution?

Comment 13 Lars Kellogg-Stedman 2015-07-31 13:49:26 UTC
haichuan: this bug was opened against RHEL-OSP 4.0.  More recent versions (5.0, 6.0) include newer packages which in theory address the comments Ihar made in #10.  

If you are experiencing this bug in a more recent release of RHEL-OSP, please open a new bug against that version, and attach log files from nova-api and neutron-metadata-agent.

Comment 15 Assaf Muller 2015-10-15 14:39:19 UTC
OSP 4 is EOL, customer upgraded to OSP 5 and issue was resolved.


Note You need to log in before you can comment on or make changes to this bug.