os-server-external-events responses 500 to neutron

[Attila Fazekas]

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=

[Salvatore Orlando (salvatore-orlando)]

Bug 1333654 is related to this.
I am a bit surprised this traceback still shows up, especially as it hardly results in an error for the build.

The bug has been filed before the fix for the above bug merged but I still see the tracebacks, and that's what surprises me.

Anyway, the relevant patches which are connected to this bug are:

https://review.openstack.org/#/c/103865/
https://review.openstack.org/#/c/109952/

[Christopher Yeoh (cyeoh-0)]

Yep its still definitely occurring post merge of https://review.openstack.org/#/c/103865

which is rather odd given it implies that instance.host is valid and then instance['host'] is not just a little bit later.

[Christopher Yeoh (cyeoh-0)]

Turns out the errors were only happening on icehouse-stable. Patch has been backported to icehouse master so is not occurring there anymore or in juno master.