yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1347833] [NEW] os-server-external-events responses 500 to neutron

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Attila Fazekas <afazekas@xxxxxxxxxx>
Date: Wed, 23 Jul 2014 17:29:23 -0000
Reply-to: Bug 1347833 <1347833@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

The issue usually not fatal, but nova MUST not return 500 on these
requests.

http://logs.openstack.org/73/104673/6/check/check-tempest-dsvm-neutron-full/a1ee0ee/logs/screen-n-api.txt.gz#_2014-07-22_17_15_25_548
2014-07-22 17:15:25.547 AUDIT nova.api.openstack.compute.contrib.server_external_events [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] Create event network-vif-plugged:52f5dc11-1e59-48fe-867c-e059b5c652c6 for instance f918bf3f-2fca-45fe-bf3c-d52dd98b90b3
2014-07-22 17:15:25.548 ERROR nova.api.openstack [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] Caught error: Unable to find host for Instance f918bf3f-2fca-45fe-bf3c-d52dd98b90b3
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack Traceback (most recent call last):
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/__init__.py", line 121, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return req.get_response(self.application)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     application, catch_exc_info=False)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return resp(environ, start_response)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 559, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return self._app(env, start_response)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return resp(environ, start_response)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return resp(environ, start_response)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     response = self.app(environ, start_response)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return resp(environ, start_response)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 906, in __call__
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     content_type, body, accept)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 972, in _process_stack
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 1056, in dispatch
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return method(req=request, **action_args)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/compute/contrib/server_external_events.py", line 128, in create
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     accepted)
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/compute/api.py", line 3141, in external_instance_event
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     context, instances_by_host[host], events_by_host[host])
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/compute/rpcapi.py", line 1025, in external_instance_event
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     server=_compute_host(None, instances[0]),
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/compute/rpcapi.py", line 61, in _compute_host
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     'Instance %s') % instance['uuid'])
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack NovaException: Unable to find host for Instance f918bf3f-2fca-45fe-bf3c-d52dd98b90b3
2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack 
2014-07-22 17:15:25.552 INFO nova.api.openstack [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] http://127.0.0.1:8774/v2/d87904e2444e48bc9632f3087e45b14e/os-server-external-events returned with HTTP 500
2014-07-22 17:15:25.552 DEBUG nova.api.openstack.wsgi [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] Returning 500 to user: The server has either erred or is incapable of performing the requested operation. __call__ /opt/stack/new/nova/nova/api/openstack/wsgi.py:1198
2014-07-22 17:15:25.553 INFO nova.osapi_compute.wsgi.server [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] 127.0.0.1 "POST /v2/d87904e2444e48bc9632f3087e45b14e/os-server-external-events HTTP/1.1" status: 500 len: 335 time: 0.0841761

The error on the q-svc side:
http://logs.openstack.org/73/104673/6/check/check-tempest-dsvm-neutron-full/a1ee0ee/logs/screen-q-svc.txt.gz#_2014-07-22_17_15_25_578

2014-07-22 17:15:25.577 26518 DEBUG urllib3.connectionpool [-] "POST /v2/d87904e2444e48bc9632f3087e45b14e/os-server-external-events HTTP/1.1" 500 128 _make_request /usr/lib/python2.7/dist-packages/urllib3/connectionpool.py:415
2014-07-22 17:15:25.578 26518 ERROR neutron.notifiers.nova [-] Failed to notify nova on events: [{'status': 'completed', 'tag': u'52f5dc11-1e59-48fe-867c-e059b5c652c6', 'name': 'network-vif-plugged', 'server_uuid': u'f918bf3f-2fca-45fe-bf3c-d52dd98b90b3'}]
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova Traceback (most recent call last):
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/neutron/neutron/notifiers/nova.py", line 223, in send_events
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     batched_events)
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/v1_1/contrib/server_external_events.py", line 39, in create
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     return_raw=True)
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/base.py", line 100, in _create
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     _resp, body = self.api.client.post(url, body=body)
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/client.py", line 485, in post
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     return self._cs_request(url, 'POST', **kwargs)
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/client.py", line 459, in _cs_request
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     **kwargs)
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/client.py", line 441, in _time_request
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     resp, body = self.request(url, method, **kwargs)
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/client.py", line 435, in request
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     raise exceptions.from_response(resp, body, url, method)
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209)
2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova 
2014-07-22 17:15:25.651 26518 INFO neutron.wsgi [-] (26518) accepted ('127.0.0.1', 58973)

logstash query:
message: "Caught error: Unable to find host for Instance"  AND filename:"logs/screen-n-api.txt"
http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOiBcIkNhdWdodCBlcnJvcjogVW5hYmxlIHRvIGZpbmQgaG9zdCBmb3IgSW5zdGFuY2VcIiAgQU5EIGZpbGVuYW1lOlwibG9ncy9zY3JlZW4tbi1hcGkudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MDYxMzU3NjY4MzIsIm1vZGUiOiIiLCJhbmFseXplX2ZpZWxkIjoiIn0=

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1347833

Title:
  os-server-external-events responses 500 to neutron

Status in OpenStack Compute (Nova):
  New

Bug description:
  The issue usually not fatal, but nova MUST not return 500 on these
  requests.

  http://logs.openstack.org/73/104673/6/check/check-tempest-dsvm-neutron-full/a1ee0ee/logs/screen-n-api.txt.gz#_2014-07-22_17_15_25_548
  2014-07-22 17:15:25.547 AUDIT nova.api.openstack.compute.contrib.server_external_events [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] Create event network-vif-plugged:52f5dc11-1e59-48fe-867c-e059b5c652c6 for instance f918bf3f-2fca-45fe-bf3c-d52dd98b90b3
  2014-07-22 17:15:25.548 ERROR nova.api.openstack [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] Caught error: Unable to find host for Instance f918bf3f-2fca-45fe-bf3c-d52dd98b90b3
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack Traceback (most recent call last):
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/__init__.py", line 121, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return req.get_response(self.application)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     application, catch_exc_info=False)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return resp(environ, start_response)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 559, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return self._app(env, start_response)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return resp(environ, start_response)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return resp(environ, start_response)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     response = self.app(environ, start_response)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return resp(environ, start_response)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 906, in __call__
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     content_type, body, accept)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 972, in _process_stack
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 1056, in dispatch
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     return method(req=request, **action_args)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/api/openstack/compute/contrib/server_external_events.py", line 128, in create
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     accepted)
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/compute/api.py", line 3141, in external_instance_event
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     context, instances_by_host[host], events_by_host[host])
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/compute/rpcapi.py", line 1025, in external_instance_event
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     server=_compute_host(None, instances[0]),
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack   File "/opt/stack/new/nova/nova/compute/rpcapi.py", line 61, in _compute_host
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack     'Instance %s') % instance['uuid'])
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack NovaException: Unable to find host for Instance f918bf3f-2fca-45fe-bf3c-d52dd98b90b3
  2014-07-22 17:15:25.548 26476 TRACE nova.api.openstack 
  2014-07-22 17:15:25.552 INFO nova.api.openstack [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] http://127.0.0.1:8774/v2/d87904e2444e48bc9632f3087e45b14e/os-server-external-events returned with HTTP 500
  2014-07-22 17:15:25.552 DEBUG nova.api.openstack.wsgi [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] Returning 500 to user: The server has either erred or is incapable of performing the requested operation. __call__ /opt/stack/new/nova/nova/api/openstack/wsgi.py:1198
  2014-07-22 17:15:25.553 INFO nova.osapi_compute.wsgi.server [req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209 nova service] 127.0.0.1 "POST /v2/d87904e2444e48bc9632f3087e45b14e/os-server-external-events HTTP/1.1" status: 500 len: 335 time: 0.0841761

  The error on the q-svc side:
  http://logs.openstack.org/73/104673/6/check/check-tempest-dsvm-neutron-full/a1ee0ee/logs/screen-q-svc.txt.gz#_2014-07-22_17_15_25_578

  2014-07-22 17:15:25.577 26518 DEBUG urllib3.connectionpool [-] "POST /v2/d87904e2444e48bc9632f3087e45b14e/os-server-external-events HTTP/1.1" 500 128 _make_request /usr/lib/python2.7/dist-packages/urllib3/connectionpool.py:415
  2014-07-22 17:15:25.578 26518 ERROR neutron.notifiers.nova [-] Failed to notify nova on events: [{'status': 'completed', 'tag': u'52f5dc11-1e59-48fe-867c-e059b5c652c6', 'name': 'network-vif-plugged', 'server_uuid': u'f918bf3f-2fca-45fe-bf3c-d52dd98b90b3'}]
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova Traceback (most recent call last):
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/neutron/neutron/notifiers/nova.py", line 223, in send_events
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     batched_events)
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/v1_1/contrib/server_external_events.py", line 39, in create
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     return_raw=True)
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/base.py", line 100, in _create
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     _resp, body = self.api.client.post(url, body=body)
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/client.py", line 485, in post
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     return self._cs_request(url, 'POST', **kwargs)
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/client.py", line 459, in _cs_request
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     **kwargs)
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/client.py", line 441, in _time_request
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     resp, body = self.request(url, method, **kwargs)
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova   File "/opt/stack/new/python-novaclient/novaclient/client.py", line 435, in request
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova     raise exceptions.from_response(resp, body, url, method)
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-82b210ca-21a9-4b40-b26a-ff0a4b1a3209)
  2014-07-22 17:15:25.578 26518 TRACE neutron.notifiers.nova 
  2014-07-22 17:15:25.651 26518 INFO neutron.wsgi [-] (26518) accepted ('127.0.0.1', 58973)

  logstash query:
  message: "Caught error: Unable to find host for Instance"  AND filename:"logs/screen-n-api.txt"
  http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOiBcIkNhdWdodCBlcnJvcjogVW5hYmxlIHRvIGZpbmQgaG9zdCBmb3IgSW5zdGFuY2VcIiAgQU5EIGZpbGVuYW1lOlwibG9ncy9zY3JlZW4tbi1hcGkudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MDYxMzU3NjY4MzIsIm1vZGUiOiIiLCJhbmFseXplX2ZpZWxkIjoiIn0=

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1347833/+subscriptions
Follow ups

[Bug 1347833] Re: os-server-external-events responses 500 to neutron
From: Thierry Carrez, 2014-09-05
[Bug 1347833] [NEW] os-server-external-events responses 500 to neutron
From: Attila Fazekas, 2014-07-23
References

[Bug 1347833] [NEW] os-server-external-events responses 500 to neutron
From: Attila Fazekas, 2014-07-23