tempest.api.network.test_dhcp_ipv6.NetworksTestDHCPv6.* tempest tests are failing repeatedly in the gate for networking-ovn

[Numan Siddique]

We are seeing a lot of tempest failures for the tests tempest.api.network.test_dhcp_ipv6.NetworksTestDHCPv6.*
with the below error.

Either we should fix the error or at least disable these tests temporarily.

t156.9: tempest.api.network.test_dhcp_ipv6.NetworksTestDHCPv6.test_dhcpv6_stateless_no_ra[id-ae2f4a5d-03ff-4c42-a3b0-ce2fcb7ea832]_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
2016-02-26 07:29:46,168 4673 INFO [tempest.lib.common.rest_client] Request (NetworksTestDHCPv6:test_dhcpv6_stateless_no_ra): 404 POST http://127.0.0.1:9696/v2.0/subnets 0.370s
2016-02-26 07:29:46,169 4673 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"subnet": {"cidr": "2003::/64", "ip_version": 6, "network_id": "4c7de56a-b059-4239-a5a0-94a53ba4929c", "gateway_ip": "2003::1", "ipv6_address_mode": "slaac"}}
    Response - Headers: {'content-length': '132', 'status': '404', 'date': 'Fri, 26 Feb 2016 07:29:46 GMT', 'connection': 'close', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-e21f771f-1a16-452a-9429-8a01f0409ae3'}
        Body: {"NeutronError": {"message": "Port 598c23eb-1ae4-4010-a263-39f86240fd86 could not be found.", "type": "PortNotFound", "detail": ""}}
2016-02-26 07:29:46,196 4673 INFO [tempest.lib.common.rest_client] Request (NetworksTestDHCPv6:tearDown): 200 GET http://127.0.0.1:9696/v2.0/ports 0.024s
2016-02-26 07:29:46,197 4673 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'content-location': 'http://127.0.0.1:9696/v2.0/ports', 'content-length': '13', 'status': '200', 'date': 'Fri, 26 Feb 2016 07:29:46 GMT', 'connection': 'close', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-f0966c23-c72f-4a6f-b113-5d88a6dd5912'}
        Body: {"ports": []}
2016-02-26 07:29:46,250 4673 INFO [tempest.lib.common.rest_client] Request (NetworksTestDHCPv6:tearDown): 200 GET http://127.0.0.1:9696/v2.0/subnets 0.052s
2016-02-26 07:29:46,251 4673 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'content-location': 'http://127.0.0.1:9696/v2.0/subnets', 'content-length': '457', 'status': '200', 'date': 'Fri, 26 Feb 2016 07:29:46 GMT', 'connection': 'close', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-3b29ba53-9ae0-4c0f-8c18-ec12db7a6bde'}
        Body: {"subnets": [{"name": "", "enable_dhcp": true, "network_id": "4c7de56a-b059-4239-a5a0-94a53ba4929c", "tenant_id": "631f9cb1391d41b6aba109afe06bc51b", "dns_nameservers": [], "gateway_ip": "2003::1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "2003::2", "end": "2003::ffff:ffff:ffff:ffff"}], "host_routes": [], "ip_version": 6, "ipv6_address_mode": "slaac", "cidr": "2003::/64", "id": "6bc2602c-2584-44cc-a6cd-b8af444f6403", "subnetpool_id": null}]}
2016-02-26 07:29:46,293 4673 INFO [tempest.lib.common.rest_client] Request (NetworksTestDHCPv6:tearDown): 200 GET http://127.0.0.1:9696/v2.0/routers 0.041s
2016-02-26 07:29:46,293 4673 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'content-location': 'http://127.0.0.1:9696/v2.0/routers', 'content-length': '15', 'status': '200', 'date': 'Fri, 26 Feb 2016 07:29:46 GMT', 'connection': 'close', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-2b883ce9-b10f-4a49-a854-450c341f9cd9'}
        Body: {"routers": []}
}}}

Traceback (most recent call last):
  File "tempest/api/network/test_dhcp_ipv6.py", line 129, in test_dhcpv6_stateless_no_ra
    real_ip, eui_ip = self._get_ips_from_subnet(**kwargs)
  File "tempest/api/network/test_dhcp_ipv6.py", line 91, in _get_ips_from_subnet
    subnet = self.create_subnet(self.network, **kwargs)
  File "tempest/api/network/base.py", line 196, in create_subnet
    **kwargs)
  File "tempest/lib/services/network/subnets_client.py", line 21, in create_subnet
    return self.create_resource(uri, post_data)
  File "tempest/lib/services/network/base.py", line 60, in create_resource
    resp, body = self.post(req_uri, req_post_data)
  File "tempest/lib/common/rest_client.py", line 259, in post
    return self.request('POST', url, extra_headers, headers, body)
  File "tempest/lib/common/rest_client.py", line 642, in request
    resp, resp_body)
  File "tempest/lib/common/rest_client.py", line 695, in _error_checker
    raise exceptions.NotFound(resp_body, resp=resp)
tempest.lib.exceptions.NotFound: Object not found
Details: {u'message': u'Port 598c23eb-1ae4-4010-a263-39f86240fd86 could not be found.', u'detail': u'', u'type': u'PortNotFound'}

[Numan Siddique (numansiddique)]

The reason for port not found is because, dhcp agent calls rpc api "release_dhcp_port" and the port is deleted. And then when the tempest test calls create_subnet, db_base_plugin_v2.NeutronDbPluginV2._create_subnet, tries to update this port (https://github.com/openstack/neutron/blob/master/neutron/db/db_base_plugin_v2.py#L595).
I am failing to understand why _create_subnet is updating the port if the subnet is auto address subnet.

This is a timing issue.

[Numan Siddique (numansiddique)]

I think neutron should handle PortNotFound exception in db_base_plugin_v2.NeutronDbPluginV2._create_subnet when it calls update_port.

[Russell Bryant (russellb)]

It may be useful to look at the ML2 plugin to see how it avoids this issue. It wouldn't be the first time we've come across a race condition in the db base plugin that was worked around at the ML2 layer. We can do our own similar workarounds (like https://review.openstack.org/#/c/276786/), but fixing it in the db base plugin is even better if there's a clear enough fix there.

Yet another option is to 1) create a workaround in networking-ovn that we can merge quickly, 2) post a neutron fix, 3) Post a networking-ovn patch that has a "Depends-on: " header for the Neutron patch in #2 that removes the workaround in networking-ovn.

[OpenStack Infra (hudson-openstack)]

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

[Numan Siddique (numansiddique)]

@Russel - I think there is a workaround for this in ovn plugin. I will submit the patch shortly

[OpenStack Infra (hudson-openstack)]

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

[Armando Migliaccio (armando-migliaccio)]

Do you have a trace from other gate jobs?

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/285420
Committed: https://git.openstack.org/cgit/openstack/networking-ovn/commit/?id=b19527fb3427c43e23f500963c15d750d5301d71
Submitter: Jenkins
Branch: master

commit b19527fb3427c43e23f500963c15d750d5301d71
Author: Numan Siddique <email address hidden>
Date: Fri Feb 26 21:57:56 2016 +0530

    Resolve auto addr subnet create failure due to race condition

    tempest.api.network.test_dhcp_ipv6.NetworksTestDHCPv6.* test cases
    are failing intermittently because of dhcp agent
    deleting the dhcp port at the same time as
    db_base_plugin_v2.NeutronDbPluginV2._create_subnet updating
    the same port while creating an auto addr subnet.

    This patch catches PortNotFound exception in port_update
    and ignores it if port_update seems to be called by
    '_create_subnet'. Else it raises the exception again.

    This is a temporary fix for this issue.

    Change-Id: I7f854ae95abda6944b9fe8e1d8ac0e0dd58ea4a5
    Partial-bug: #1550278

[OpenStack Infra (hudson-openstack)]

Change abandoned by Numan Siddique (<email address hidden>) on branch: master
Review: https://review.openstack.org/285388

[Numan Siddique (numansiddique)]

We are getting below errors now

2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource [req-2b1db0d1-83b2-4415-9bc5-384136c24a77 tempest-NetworksTestDHCPv6-2041417291 -] create failed
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource Traceback (most recent call last):
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/resource.py", line 84, in resource
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource result = method(request=request, **args)
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 410, in create
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource return self._create(request, body, **kwargs)
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_db/api.py", line 148, in wrapper
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource ectxt.value = e.inner_exc
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource self.force_reraise()
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_db/api.py", line 138, in wrapper
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource return f(*args, **kwargs)
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 521, in _create
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource obj = do_create(body)
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 503, in do_create
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource request.context, reservation.reservation_id)
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource self.force_reraise()
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 496, in do_create
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource return obj_creator(request.context, **kwargs)
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 703, in create_subnet
2016-03-22 11:21:26.485 10117 ERROR neutron.api.v2.resource retu...

[Richard Theis (rtheis)]

These tests have been consistently passing for https://review.openstack.org/#/c/312705/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/318095
Committed: https://git.openstack.org/cgit/openstack/networking-ovn/commit/?id=d6c544c4490ffc23bc47465845b9605111382dad
Submitter: Jenkins
Branch: master

commit d6c544c4490ffc23bc47465845b9605111382dad
Author: Richard Theis <email address hidden>
Date: Wed May 18 08:39:37 2016 -0500

    Convert core plugin to ML2 mechanism driver

    This patch set converts networking-ovn from a core
    plugin to an ML2 mechanism driver.

    This patch set completes the following conversion work:
    - DevStack and Vagrant deployment updates for ML2
    - Documentation and release note updates for ML2
    - Removes core plugin code and refactors remaining code
      over to ML2 mechanism driver

    The conversion work remains:
    - Resolve the ML2 unit test TODOs
    - Resolve concerns about ML2 mechanism driver _ovn
      property raised in [1].

    [1] https://review.openstack.org/#/c/323460/

    Co-Authored-By: Richard Theis <email address hidden>
    Co-Authored-By: John Kasperski <email address hidden>

    Change-Id: Iffa596baa5c7520c1ca5ecddaab790c52e761460
    Closes-Bug: #1578198
    Closes-Bug: #1550278

[Isaku Yamahata (yamahata)]

This happends repeatedly to networking-odl too.
The issue is that update_port on dhcp port raises PortNotFound.
But the dhcp port isn't created by agent yet.

[Isaku Yamahata (yamahata)]

Recent stack trace is at http://logs.openstack.org/41/398041/5/gate/gate-tempest-dsvm-networking-odl-boron-snapshot/0b64e05/logs/testr_results.html.gz

ft163.8: tempest.api.network.test_dhcp_ipv6.NetworksTestDHCPv6.test_dhcpv6_stateless_eui64[id-e5517e62-6f16-430d-a672-f80875493d4c]_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
2016-11-23 21:06:35,941 8388 INFO [tempest.lib.common.rest_client] Request (NetworksTestDHCPv6:test_dhcpv6_stateless_eui64): 201 POST http://127.0.0.1:9696/v2.0/subnets 0.266s
2016-11-23 21:06:35,942 8388 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'X-Auth-Token': '<omitted>', 'Accept': 'application/json'}
        Body: {"subnet": {"ipv6_address_mode": "slaac", "ip_version": 6, "gateway_ip": "2003::1", "ipv6_ra_mode": "slaac", "cidr": "2003::/64", "network_id": "da812a27-75db-48d3-ad8a-ffa3180de680"}}
    Response - Headers: {'x-openstack-request-id': 'req-cffa5f02-54b0-4cd3-9e99-36fe8bdb0ed0', 'content-type': 'application/json', 'content-length': '645', 'date': 'Wed, 23 Nov 2016 21:06:35 GMT', 'connection': 'close', 'content-location': 'http://127.0.0.1:9696/v2.0/subnets', 'status': '201'}
        Body: {"subnet": {"service_types": [], "description": "", "enable_dhcp": true, "network_id": "da812a27-75db-48d3-ad8a-ffa3180de680", "tenant_id": "6c38c86ba0c741f88f487aeaa0210f9d", "created_at": "2016-11-23T21:06:35Z", "dns_nameservers": [], "updated_at": "2016-11-23T21:06:35Z", "gateway_ip": "2003::1", "ipv6_ra_mode": "slaac", "allocation_pools": [{"start": "2003::2", "end": "2003::ffff:ffff:ffff:ffff"}], "host_routes": [], "revision_number": 2, "ip_version": 6, "ipv6_address_mode": "slaac", "cidr": "2003::/64", "project_id": "6c38c86ba0c741f88f487aeaa0210f9d", "id": "83bc1fd7-53f0-4f1b-91ec-4faeac670df5", "subnetpool_id": null, "name": ""}}
2016-11-23 21:06:36,553 8388 INFO [tempest.lib.common.rest_client] Request (NetworksTestDHCPv6:test_dhcpv6_stateless_eui64): 201 POST http://127.0.0.1:9696/v2.0/ports 0.611s
2016-11-23 21:06:36,553 8388 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'X-Auth-Token': '<omitted>', 'Accept': 'application/json'}
        Body: {"port": {"mac_address": "fa:16:3e:ef:72:30", "network_id": "da812a27-75db-48d3-ad8a-ffa3180de680"}}
    Response - Headers: {'x-openstack-request-id': 'req-d81274a4-a072-4243-b389-c0c63c59bbf8', 'content-type': 'application/json', 'content-length': '741', 'date': 'Wed, 23 Nov 2016 21:06:36 GMT', 'connection': 'close', 'content-location': 'http://127.0.0.1:9696/v2.0/ports', 'status': '201'}
        Body: {"port": {"status": "DOWN", "created_at": "2016-11-23T21:06:36Z", "project_id": "6c38c86ba0c741f88f487aeaa0210f9d", "description": "", "allowed_address_pairs": [], "admin_state_up": true, "network_id": "da812a27-75db-48d3-ad8a-ffa3180de680", "tenant_id": "6c38c86ba0c741f88f487aeaa0210f9d", "extra_dhcp_opts": [], "updated_at": "2016-11-23T21:06:36Z", "name": "", "device_owner": "", "revision_number": 5, "mac_address": "fa:16:3e:ef:72:30", "port_security_enabled": true, "binding:vnic_type": "normal", "fixed_ips": [{"subnet_id": "...

[Isaku Yamahata (yamahata)]

Recently networking-odl doesn't observe this issue.
So marking this imcomplete.

[LIU Yulong (dragon889)]

Neutron:
http://logs.openstack.org/58/453458/13/gate/neutron-tempest-plugin-api/f4f8558/logs/testr_results.html.gz

NetworksTestDHCPv6)
fail

ft1.1: setUpClass (neutron_tempest_plugin.api.test_dhcp_ipv6.NetworksTestDHCPv6)_StringException: Traceback (most recent call last):
  File "tempest/test.py", line 153, in setUpClass
    "skip_checks" % cls.__name__)
RuntimeError: skip_checks for NetworksTestDHCPv6 did not call the super's skip_checks

[Mike Kolesnik (mkolesni)]

Curretly marking Invalid, if this resurfaces please reopen

[Kailun Qin (kailun.qin)]

Neutron tempest.api.network.test_dhcp_ipv6.NetworksTestDHCPv6.test_dhcpv6_stateless_eui64 met the same failure:
http://logs.openstack.org/70/574370/4/check/neutron-tempest-dvr/8fa19ba/job-output.txt.gz

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Neutron bug closed due to lack of activity, please feel free to reopen if needed.

This error is not present anymore in the CI jobs.