TestServerBasicOps: Test fails when deleting server and floating ip almost at the same time

[Monica Tian]

In tempest.scenario.test_server_basic_ops.TestServerBasicOps.test_server_basic_ops, after last step: self.servers_client.delete_server(self.instance['id']) it doesn't wait for the server to be deleted, and then deletes the floating ip immediately in the clean up, this will cause faiure:

Here is the partial log:
2016-05-29 21:51:29.499 29791 INFO tempest.lib.common.rest_client [req-c3588ac4-21ca-47c3-bdb1-62088efd7a8b ] Request (TestServerBasicOps:test_server_basic_ops): 204 DELETE https://<url>:8774/v2/159886ce087a4f8fbfbcab14947d96b1/servers/6d44763b-ea79-4b5b-b57e-714191802c7c 0.465s
2016-05-29 21:51:29.499 29791 DEBUG tempest.lib.common.rest_client [req-c3588ac4-21ca-47c3-bdb1-62088efd7a8b ] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'status': '204', 'content-length': '0', 'content-location': 'https://<url>:8774/v2/159886ce087a4f8fbfbcab14947d96b1/servers/6d44763b-ea79-4b5b-b57e-714191802c7c', 'date': 'Mon, 30 May 2016 02:51:29 GMT', 'x-compute-request-id': 'req-c3588ac4-21ca-47c3-bdb1-62088efd7a8b', 'content-type': 'application/json', 'connection': 'close'}
        Body: _log_request_full tempest/lib/common/rest_client.py:422
2016-05-29 21:51:30.410 29791 INFO tempest.lib.common.rest_client [req-db2323f5-3d58-4fd7-ae51-44f5525c6689 ] Request (TestServerBasicOps:_run_cleanups): 500 DELETE https://<url>:8774/v2/159886ce087a4f8fbfbcab14947d96b1/os-floating-ips/948912f6-ce03-4856-922b-59c4f16d3740 0.910s
2016-05-29 21:51:30.410 29791 DEBUG tempest.lib.common.rest_client [req-db2323f5-3d58-4fd7-ae51-44f5525c6689 ] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'status': '500', 'content-length': '224', 'content-location': 'https://<url>:8774/v2/159886ce087a4f8fbfbcab14947d96b1/os-floating-ips/948912f6-ce03-4856-922b-59c4f16d3740', 'date': 'Mon, 30 May 2016 02:51:30 GMT', 'x-compute-request-id': 'req-db2323f5-3d58-4fd7-ae51-44f5525c6689', 'content-type': 'application/json; charset=UTF-8', 'connection': 'close'}
        Body: {"computeFault": {"message": "Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.\n<class 'neutronclient.common.exceptions.PortNotFoundClient'>", "code": 500}}

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/322731

[Ken'ichi Ohmichi (oomichi)]

This seems a problem of nova side because any internal errors should not happen on nova side even if any requests are gotten from client side(tempest in this case)

[Takashi Natsume (natsume-takashi)]

Need the version of Nova.
Please tell it.

[Rossella Sblendido (rossella-o)]

I hit this. I can reproduce it almost every time on my env using linuxbrige+vxlan. The nova trace is:

2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions [req-bf41dac1-8fc0-4fd6-9a35-d754cea79057 9a0be6e4b8bf4cadb4a43401696fec19 48935f9a5ed84703973c70dd70859b7f - - -] Unexpected exception in API method
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/extensions.py", line 478, in wrapped
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/floating_ips.py", line 173, in delete
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions context, instance, floating_ip)
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 1527, in disassociate_and_release_floating_ip
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions raise_if_associated=False)
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 1536, in _release_floating_ip
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions client.delete_floatingip(fip['id'])
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 102, in with_params
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions ret = self.function(instance, *args, **kwargs)
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 751, in delete_floatingip
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions return self.delete(self.floatingip_path % (floatingip))
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 289, in delete
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions headers=headers, params=params)
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 270, in retry_request
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions headers=headers, params=params)
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 211, in do_request
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions self._handle_fault_response(status_code, replybody)
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 185, in _handle_fault_response
2016-07-02 16:20:52.670 9993 ERROR nova.api.openstack.extensions exception_handler_v20(status_code, des_error_body)
2016-07-02 16:20:52.6...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/336842

[Jean-Philippe Evrard (jean-philippe-evrard)]

I'd be happy if this bug fix is backported to mitaka.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/338184

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/338200

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/336842
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=6e275e38575981386508718bf31e6f88b5a0887d
Submitter: Jenkins
Branch: master

commit 6e275e38575981386508718bf31e6f88b5a0887d
Author: rossella <email address hidden>
Date: Sat Jul 2 18:15:32 2016 +0000

    When deleting floating IP catch PortNotFound

    If we try to delete a VM and to delete the floating IP
    associated with the VM at the same time, depending
    on the order according to which these requests are processed
    Neutron might fail in the deletion of the floating IP,
    raising a PortNotFound error. This happens because Neutron
    notifies Nova of the network change event and it tries to get
    the port to which the FIP is associated. If the port is not there,
    Neutron shouldn't raise, it shouldn't send any notification.

    Change-Id: Ic72313ad1f787b3cb528e806c843f1fd01eb12f2
    Closes-bug: #1586931

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/338200
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=d39d45ab4b9e7f8974e6018ad40def0d79a9909f
Submitter: Jenkins
Branch: stable/liberty

commit d39d45ab4b9e7f8974e6018ad40def0d79a9909f
Author: rossella <email address hidden>
Date: Sat Jul 2 18:15:32 2016 +0000

    When deleting floating IP catch PortNotFound

    If we try to delete a VM and to delete the floating IP
    associated with the VM at the same time, depending
    on the order according to which these requests are processed
    Neutron might fail in the deletion of the floating IP,
    raising a PortNotFound error. This happens because Neutron
    notifies Nova of the network change event and it tries to get
    the port to which the FIP is associated. If the port is not there,
    Neutron shouldn't raise, it shouldn't send any notification.

    Conflicts:
     neutron/notifiers/nova.py
     neutron/tests/unit/notifiers/test_nova.py

    Closes-bug: #1586931
    Change-Id: Ic72313ad1f787b3cb528e806c843f1fd01eb12f2
    (cherry picked from commit 6e275e38575981386508718bf31e6f88b5a0887d)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/338184
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=9e403b18f03362872571c1b595df9567a7c39e29
Submitter: Jenkins
Branch: stable/mitaka

commit 9e403b18f03362872571c1b595df9567a7c39e29
Author: rossella <email address hidden>
Date: Sat Jul 2 18:15:32 2016 +0000

    When deleting floating IP catch PortNotFound

    If we try to delete a VM and to delete the floating IP
    associated with the VM at the same time, depending
    on the order according to which these requests are processed
    Neutron might fail in the deletion of the floating IP,
    raising a PortNotFound error. This happens because Neutron
    notifies Nova of the network change event and it tries to get
    the port to which the FIP is associated. If the port is not there,
    Neutron shouldn't raise, it shouldn't send any notification.

    Conflicts:
     neutron/notifiers/nova.py
     neutron/tests/unit/notifiers/test_nova.py

    Closes-bug: #1586931
    Change-Id: Ic72313ad1f787b3cb528e806c843f1fd01eb12f2
    (cherry picked from commit 6e275e38575981386508718bf31e6f88b5a0887d)

[Markus Zoeller (markus_z) (mzoeller)]

> comment #3
tempest is always executed against master, IIUC. This means it's Nova master (Newton).

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/neutron 9.0.0.0b2 development milestone.

[Michael Gugino (gugino-michael)]

We are seeing the 500 DELETE error from tempest as well.

As you can see here: http://logs.openstack.org/06/350806/4/check/gate-openstack-ansible-os_tempest-ansible-func-ubuntu-trusty/6a2c7cc/console.html#_2016-08-04_15_54_20_044407

We are deploying neutron from master.

Here is the exact error text: http://logs.openstack.org/06/350806/4/check/gate-openstack-ansible-os_tempest-ansible-func-ubuntu-trusty/6a2c7cc/console.html#_2016-08-04_16_06_59_878324

We have been seeing this issue pretty consistently for the last month+

The fix merged into neutron has had no effect.

[Ken'ichi Ohmichi (oomichi)]

This still seems due to Nova side because Nova should not return HTTP500 basically.

We start trying to fix this problem on nova side with the commit https://review.openstack.org/#/c/351960/

[Michael Gugino (gugino-michael)]

Thanks for looking into this. I think that your patch for nova is a good patch, nova should not produce 500 errors, but I think we're likely to just see the HTTPNotFound error in it's place, and that will likely cause a non-zero exit code for the tempest run. Will the HTTPNotFound error be handled by tempest?

[Ken'ichi Ohmichi (oomichi)]

Hi Michael,

Yeah, that is a nice point.
I am thinking this problem is due to the lack of error handling.
In cleanup of Tempest, Tempest checks the deletions of the created resources by receiving HTTP404(NotFound). However, now Nova returns HTTP500 and Tempest considers it as an error.
By handling this case rightly, I am hoping the test can pass.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit e72826123bfd7c1d962b615da3f028b315ba3943
Author: Ken'ichi Ohmichi <email address hidden>
Date: Fri Aug 12 10:15:29 2016 -0700

    Return None in get_instance_id_by_floating_address

    _show_port() can raise a PortNotFound exception, but the method
    get_instance_id_by_floating_address() doesn't handle it. On the
    other hand, the method returns None if fip doesn't contain
    port_id as a normal case.
    On the caller side, "Delete a floating ip" API can use the returned
    value None to disassociate_and_release_floating_ip() and the method
    handles the None as a normal value.

    So this patch makes get_instance_id_by_floating_address return None
    if PortNotFound happens.

    Closes-Bug: #1586931

    Change-Id: I03be8100155d343eb6a4ea9eda3f1498ad3fb4cf

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/358152

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/neutron 7.1.2 release.

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/neutron 8.2.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 14.0.0.0b3 development milestone.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/358153
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=daf281f95fa96aef72933280d873112b5e72807c
Submitter: Jenkins
Branch: stable/mitaka

commit daf281f95fa96aef72933280d873112b5e72807c
Author: Ken'ichi Ohmichi <email address hidden>
Date: Fri Aug 12 10:15:29 2016 -0700

    Return None in get_instance_id_by_floating_address

    _show_port() can raise a PortNotFound exception, but the method
    get_instance_id_by_floating_address() doesn't handle it. On the
    other hand, the method returns None if fip doesn't contain
    port_id as a normal case.
    On the caller side, "Delete a floating ip" API can use the returned
    value None to disassociate_and_release_floating_ip() and the method
    handles the None as a normal value.

    So this patch makes get_instance_id_by_floating_address return None
    if PortNotFound happens.

    Closes-Bug: #1586931

    Change-Id: I03be8100155d343eb6a4ea9eda3f1498ad3fb4cf
    (cherry picked from commit e72826123bfd7c1d962b615da3f028b315ba3943)

[OpenStack Infra (hudson-openstack)]

Change abandoned by Ken'ichi Ohmichi (<email address hidden>) on branch: stable/liberty
Review: https://review.openstack.org/358152
Reason: Now liberty branch is closing to Phase 3(http://docs.openstack.org/project-team-guide/stable-branches.html#support-phases), so this patch is not worth to be backport-ed at this time.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 13.1.2 release.

[chandan kumar (chkumar246)]

Unassigning this bug as there is no activity from last 6 months. If you are still want to work on this bug, feel free to assign yourself.

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Martin Kopec <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/322731
Reason: The associated bug is fixed, for tempest's side it's marked as Won't Fix and the latest comment in this review says the issue is fixed .. seems like this patch is not needed anymore, so i'm gonna abandon, feel free to restore and rebase if it's still needed