← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #12338

[Bug 1298640] [NEW] nova network-vif-plugged event fails with 400 from n-api

  Thread Previous • Date Previous • • Thread Next 
Public bug reported:

Running Tempest in our internal CI we hit 3 test failures out of 1,971
tests, one was:

tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTest.test_snapshot_create_with_volume_in_use

This is running x86_64 RHEL 6.5 with the nova libvirt driver and neutron
openvswitch.

We have neutron.conf configured for nova events:

[root@rhel62 ~]# cat /etc/neutron/neutron.conf | grep nova
# being used in conjunction with nova security groups
# allowed_rpc_exception_modules = neutron.openstack.common.exception, nova.exception
nova_url = http://192.168.4.7:8774/v2
nova_region_name = RegionOne
nova_admin_username = nova
nova_admin_tenant_id = 11b12b24a2bd4672b6332c41b654a438
nova_admin_password = nova
nova_admin_auth_url = http://192.168.4.7:5000/v2.0/

For one failure I'm seeing this in the neutron server log:

2014-03-16 05:57:36.619 8462 ERROR neutron.notifiers.nova [-] Failed to notify nova on events: [{'status': 'completed', 'tag': u'7ecd451e-2f14-4155-a237-3231f3770f1d', 'name': 'network-vif-plugged', 'server_uuid': u'2c368278-e9f4-4458-abdc-b158c5a079ea'}]
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova Traceback (most recent call last):
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/neutron/notifiers/nova.py", line 186, in send_events
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     batched_events)
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/v1_1/contrib/server_external_events.py", line 39, in create
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     return_raw=True)
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/base.py", line 152, in _create
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     _resp, body = self.api.client.post(url, body=body)
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/client.py", line 286, in post
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     return self._cs_request(url, 'POST', **kwargs)
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/client.py", line 260, in _cs_request
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     **kwargs)
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/client.py", line 242, in _time_request
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     resp, body = self.request(url, method, **kwargs)
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/client.py", line 236, in request
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     raise exceptions.from_response(resp, body, url, method)
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova BadRequest: The server could not comply with the request since it is either malformed or otherwise incorrect. (HTTP 400)
2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova

I correlated that server uuid to the nova-api log error here:

2014-03-16 05:57:27.770 12207 INFO nova.osapi_compute.wsgi.server [req-56dabfa1-9abe-4301-91bc-8093ded6c29c cc61e644b9224dc6918241663551996b 2a33892b41b34180ab23151dfe610990] 192.168.4.9 "GET /v2/2a33892b41b34180ab23151dfe610990/servers/2c368278-e9f4-4458-abdc-b158c5a079ea HTTP/1.1" status: 200 len: 2211 time: 0.1646261
2014-03-16 05:57:36.615 12204 ERROR nova.api.openstack.wsgi [-] Exception handling resource: multi() got an unexpected keyword argument 'body'
2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi Traceback (most recent call last):
2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi   File "/usr/lib/python2.6/site-packages/nova/api/openstack/wsgi.py", line 983, in _process_stack
2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi     action_result = self.dispatch(meth, request, action_args)
2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi   File "/usr/lib/python2.6/site-packages/nova/api/openstack/wsgi.py", line 1070, in dispatch
2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi     return method(req=request, **action_args)
2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi TypeError: multi() got an unexpected keyword argument 'body'
2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi 
2014-03-16 05:57:36.616 12204 INFO nova.osapi_compute.wsgi.server [-] 127.0.0.1 "POST /None/os-server-external-events HTTP/1.1" status: 400 len: 274 time: 0.0410700

Talking with Dan Smith in IRC it sounds like maybe neutron isn't putting
the nova tenant ID into the request for some reason?

(4:15:57 PM) dansmith: mriedem: I think neutron sometimes gets the nova url from the context you pass it, so maybe it's related to that
...
(4:17:20 PM) dansmith: mriedem: right, but arosen did some work to have neutron determine the proper nova endpoint to call back to based on the context, in the case you've got two novas sharing a neutron

This is intermittent, but I do see the neutron server error showing up
in community logstash, but only 7% failures:

http://goo.gl/up9utR

I'm not seeing the same error in logstash in nova-api logs, but that was
only going back the last 48 hours.

** Affects: neutron
     Importance: Undecided
         Status: New

** Affects: nova
     Importance: Undecided
         Status: New


** Tags: network

** Also affects: nova
   Importance: Undecided
       Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1298640

Title:
  nova network-vif-plugged event fails with 400 from n-api

Status in OpenStack Neutron (virtual network service):
  New
Status in OpenStack Compute (Nova):
  New

Bug description:
  Running Tempest in our internal CI we hit 3 test failures out of 1,971
  tests, one was:

  tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTest.test_snapshot_create_with_volume_in_use

  This is running x86_64 RHEL 6.5 with the nova libvirt driver and
  neutron openvswitch.

  We have neutron.conf configured for nova events:

  [root@rhel62 ~]# cat /etc/neutron/neutron.conf | grep nova
  # being used in conjunction with nova security groups
  # allowed_rpc_exception_modules = neutron.openstack.common.exception, nova.exception
  nova_url = http://192.168.4.7:8774/v2
  nova_region_name = RegionOne
  nova_admin_username = nova
  nova_admin_tenant_id = 11b12b24a2bd4672b6332c41b654a438
  nova_admin_password = nova
  nova_admin_auth_url = http://192.168.4.7:5000/v2.0/

  For one failure I'm seeing this in the neutron server log:

  2014-03-16 05:57:36.619 8462 ERROR neutron.notifiers.nova [-] Failed to notify nova on events: [{'status': 'completed', 'tag': u'7ecd451e-2f14-4155-a237-3231f3770f1d', 'name': 'network-vif-plugged', 'server_uuid': u'2c368278-e9f4-4458-abdc-b158c5a079ea'}]
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova Traceback (most recent call last):
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/neutron/notifiers/nova.py", line 186, in send_events
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     batched_events)
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/v1_1/contrib/server_external_events.py", line 39, in create
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     return_raw=True)
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/base.py", line 152, in _create
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     _resp, body = self.api.client.post(url, body=body)
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/client.py", line 286, in post
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     return self._cs_request(url, 'POST', **kwargs)
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/client.py", line 260, in _cs_request
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     **kwargs)
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/client.py", line 242, in _time_request
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     resp, body = self.request(url, method, **kwargs)
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova   File "/usr/lib/python2.6/site-packages/novaclient/client.py", line 236, in request
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova     raise exceptions.from_response(resp, body, url, method)
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova BadRequest: The server could not comply with the request since it is either malformed or otherwise incorrect. (HTTP 400)
  2014-03-16 05:57:36.619 8462 TRACE neutron.notifiers.nova

  I correlated that server uuid to the nova-api log error here:

  2014-03-16 05:57:27.770 12207 INFO nova.osapi_compute.wsgi.server [req-56dabfa1-9abe-4301-91bc-8093ded6c29c cc61e644b9224dc6918241663551996b 2a33892b41b34180ab23151dfe610990] 192.168.4.9 "GET /v2/2a33892b41b34180ab23151dfe610990/servers/2c368278-e9f4-4458-abdc-b158c5a079ea HTTP/1.1" status: 200 len: 2211 time: 0.1646261
  2014-03-16 05:57:36.615 12204 ERROR nova.api.openstack.wsgi [-] Exception handling resource: multi() got an unexpected keyword argument 'body'
  2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi Traceback (most recent call last):
  2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi   File "/usr/lib/python2.6/site-packages/nova/api/openstack/wsgi.py", line 983, in _process_stack
  2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi     action_result = self.dispatch(meth, request, action_args)
  2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi   File "/usr/lib/python2.6/site-packages/nova/api/openstack/wsgi.py", line 1070, in dispatch
  2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi     return method(req=request, **action_args)
  2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi TypeError: multi() got an unexpected keyword argument 'body'
  2014-03-16 05:57:36.615 12204 TRACE nova.api.openstack.wsgi 
  2014-03-16 05:57:36.616 12204 INFO nova.osapi_compute.wsgi.server [-] 127.0.0.1 "POST /None/os-server-external-events HTTP/1.1" status: 400 len: 274 time: 0.0410700

  Talking with Dan Smith in IRC it sounds like maybe neutron isn't
  putting the nova tenant ID into the request for some reason?

  (4:15:57 PM) dansmith: mriedem: I think neutron sometimes gets the nova url from the context you pass it, so maybe it's related to that
  ...
  (4:17:20 PM) dansmith: mriedem: right, but arosen did some work to have neutron determine the proper nova endpoint to call back to based on the context, in the case you've got two novas sharing a neutron

  This is intermittent, but I do see the neutron server error showing up
  in community logstash, but only 7% failures:

  http://goo.gl/up9utR

  I'm not seeing the same error in logstash in nova-api logs, but that
  was only going back the last 48 hours.

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1298640/+subscriptions

Follow ups

References

  Thread Previous • Date Previous • • Thread Next