← Back to team overview

yahoo-eng-team team mailing list archive

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

[Bug 1691176] [NEW] test_verify_duplicate_network_nics[id-1678d144-ed74-43f8-8e57-ab10dbf9b3c2] race fails during port deletion on postgresql job

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

Seen here:

http://logs.openstack.org/59/383859/22/experimental/gate-tempest-dsvm-
neutron-pg-full-ubuntu-
xenial/b2f29e9/console.html.gz#_2017-04-21_14_20_13_438646

NOTE: THIS DOES NOT APPEAR TO BE CAUSED BY POSTGRESQL AT ALL, IT'S A
TIMING ISSUE

This test is creating two networks and a subnet on each network, and
then booting a server with those two networks.

The test fails on teardown of the network because the dhcp port is
already gone when the network delete request is being processed, which
is racing with the asynchronous subnet delete on the same network
(tempest cleans up in a LIFO order, so the subnet is created after the
network and deleted before the network).

Notes from debugging the logs:

aee62d13-f5f2-4aec-8fec-abd56c99eda1 - tempest-ServersTestJSON-927337740
- 19.80.0.0/24

a144b4fb-5a53-4f52-baad-07811e528c81 - tempest-
ServersTestJSON-1149271515 - 19.86.0.0/24

create server with these requested networks:

"networks": [{"uuid": "aee62d13-f5f2-4aec-8fec-abd56c99eda1"},
             {"uuid": "a144b4fb-5a53-4f52-baad-07811e528c81"},
             {"uuid": "aee62d13-f5f2-4aec-8fec-abd56c99eda1"}]

server IPs:

{"addresses": {"tempest-ServersTestJSON-927337740": [
			{"version": 4, "addr": "19.80.0.6"},
			{"version": 4, "addr": "19.80.0.3"}],
	       "tempest-ServersTestJSON-1149271515": [
			{"version": 4, "addr": "19.86.0.6"}]}}

delete failure on the first network:

req: 2017-04-21 13:53:59,064 28262 404 DELETE
https://15.184.65.212:9696/v2.0/networks/aee62d13-f5f2-4aec-8fec-
abd56c99eda1

res:

{
   'status':'404',
   u'content-length':'132',
   u'server':'Apache/2.4.18 (Ubuntu)',
   'content-location':'https://15.184.65.212:9696/v2.0/networks/aee62d13-f5f2-4aec-8fec-abd56c99eda1',
   u'date':'Fri, 21 Apr 2017 13:53:59 GMT',
   u'content-type':'application/json',
   u'x-openstack-request-id':'req-8f94b291-ced4-4c88-9783-ceb4b04eb320',
   u'connection':'close'
}

{"NeutronError": {"message": "Port b48cc7a3-d81f-49f4-b87c-97958192897c could not be found.",
                  "type": "PortNotFound", "detail": ""}}


The problem port:

b48cc7a3-d81f-49f4-b87c-97958192897c

The port is created here:

2017-04-21 13:53:14.088 17266 Allocated IP 19.80.0.2 (aee62d13-f5f2
-4aec-8fec-abd56c99eda1/2b0869e7-f15b-4030-a745-6a1782b57878/b48cc7a3
-d81f-49f4-b87c-97958192897c)

[Port(admin_state_up=True,allowed_address_pairs=[],binding=PortBinding,binding_levels=[],
created_at=2017-04-21T13:53:13Z,data_plane_status=<?>,description='',
device_id='dhcpef44eb91-ca69-52e5-a9b5-bb0cff2edb74-aee62d13-f5f2-4aec-8fec-abd56c99eda1',
device_owner='network:dhcp',dhcp_options=[],distributed_binding=None,dns=None,fixed_ips=[IPAllocation],
id=b48cc7a3-d81f-49f4-b87c-97958192897c,mac_address=fa:16:3e:0d:e9:1d,name='',
network_id=aee62d13-f5f2-4aec-8fec-abd56c99eda1,project_id='0ca1e45b37a042b9ba3b88e442526972',
qos_policy_id=None,revision_number=6,security=PortSecurity(b48cc7a3-d81f-49f4-b87c-97958192897c),
security_group_ids=set([]),status='DOWN',updated_at=2017-04-21T13:53:14Z)]

Subnet is being deleted here:

2017-04-21 13:53:57,680 28262 INFO     [tempest.lib.common.rest_client]
Request (ServersTestJSON:_run_cleanups): 204 DELETE
https://15.184.65.212:9696/v2.0/subnets/2b0869e7-f15b-4030-a745-6a1782b57878

Port is being deleted here:

http://logs.openstack.org/59/383859/22/experimental/gate-tempest-dsvm-
neutron-pg-full-ubuntu-
xenial/b2f29e9/logs/screen-q-svc.txt.gz#_2017-04-21_13_53_57_986

2017-04-21 13:53:57.986 17266 DEBUG neutron.plugins.ml2.plugin [req-
893ff18c-5732-42e6-b7ef-bddf9c42d9e7 - -] Deleting port b48cc7a3-d81f-
49f4-b87c-97958192897c _pre_delete_port
/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:1410

network delete is trying to delete the port here:

http://logs.openstack.org/59/383859/22/experimental/gate-tempest-dsvm-
neutron-pg-full-ubuntu-
xenial/b2f29e9/logs/screen-q-svc.txt.gz#_2017-04-21_13_53_58_412

2017-04-21 13:53:58.412 17264 DEBUG neutron.plugins.ml2.plugin [req-
8f94b291-ced4-4c88-9783-ceb4b04eb320 tempest-ServersTestJSON-1475565165
tempest-ServersTestJSON-1475565165] Deleting port b48cc7a3-d81f-49f4
-b87c-97958192897c _pre_delete_port
/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:1410

2017-04-21 13:53:58.988 17264 DEBUG neutron.plugins.ml2.plugin [req-
8f94b291-ced4-4c88-9783-ceb4b04eb320 tempest-ServersTestJSON-1475565165
tempest-ServersTestJSON-1475565165] Calling delete_port for b48cc7a3
-d81f-49f4-b87c-97958192897c owned by network:dhcp delete_port
/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:1469

2017-04-21 13:53:59.061 17264 INFO neutron.pecan_wsgi.hooks.translation
[req-8f94b291-ced4-4c88-9783-ceb4b04eb320 tempest-
ServersTestJSON-1475565165 tempest-ServersTestJSON-1475565165] DELETE
failed (client error): The resource could not be found.

** Affects: neutron
     Importance: High
         Status: Confirmed

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

Title:
  test_verify_duplicate_network_nics[id-
  1678d144-ed74-43f8-8e57-ab10dbf9b3c2] race fails during port deletion
  on postgresql job

Status in neutron:
  Confirmed

Bug description:
  Seen here:

  http://logs.openstack.org/59/383859/22/experimental/gate-tempest-dsvm-
  neutron-pg-full-ubuntu-
  xenial/b2f29e9/console.html.gz#_2017-04-21_14_20_13_438646

  NOTE: THIS DOES NOT APPEAR TO BE CAUSED BY POSTGRESQL AT ALL, IT'S A
  TIMING ISSUE

  This test is creating two networks and a subnet on each network, and
  then booting a server with those two networks.

  The test fails on teardown of the network because the dhcp port is
  already gone when the network delete request is being processed, which
  is racing with the asynchronous subnet delete on the same network
  (tempest cleans up in a LIFO order, so the subnet is created after the
  network and deleted before the network).

  Notes from debugging the logs:

  aee62d13-f5f2-4aec-8fec-abd56c99eda1 - tempest-
  ServersTestJSON-927337740 - 19.80.0.0/24

  a144b4fb-5a53-4f52-baad-07811e528c81 - tempest-
  ServersTestJSON-1149271515 - 19.86.0.0/24

  create server with these requested networks:

  "networks": [{"uuid": "aee62d13-f5f2-4aec-8fec-abd56c99eda1"},
               {"uuid": "a144b4fb-5a53-4f52-baad-07811e528c81"},
               {"uuid": "aee62d13-f5f2-4aec-8fec-abd56c99eda1"}]

  server IPs:

  {"addresses": {"tempest-ServersTestJSON-927337740": [
  			{"version": 4, "addr": "19.80.0.6"},
  			{"version": 4, "addr": "19.80.0.3"}],
  	       "tempest-ServersTestJSON-1149271515": [
  			{"version": 4, "addr": "19.86.0.6"}]}}

  delete failure on the first network:

  req: 2017-04-21 13:53:59,064 28262 404 DELETE
  https://15.184.65.212:9696/v2.0/networks/aee62d13-f5f2-4aec-8fec-
  abd56c99eda1

  res:

  {
     'status':'404',
     u'content-length':'132',
     u'server':'Apache/2.4.18 (Ubuntu)',
     'content-location':'https://15.184.65.212:9696/v2.0/networks/aee62d13-f5f2-4aec-8fec-abd56c99eda1',
     u'date':'Fri, 21 Apr 2017 13:53:59 GMT',
     u'content-type':'application/json',
     u'x-openstack-request-id':'req-8f94b291-ced4-4c88-9783-ceb4b04eb320',
     u'connection':'close'
  }

  {"NeutronError": {"message": "Port b48cc7a3-d81f-49f4-b87c-97958192897c could not be found.",
                    "type": "PortNotFound", "detail": ""}}

  
  The problem port:

  b48cc7a3-d81f-49f4-b87c-97958192897c

  The port is created here:

  2017-04-21 13:53:14.088 17266 Allocated IP 19.80.0.2 (aee62d13-f5f2
  -4aec-8fec-abd56c99eda1/2b0869e7-f15b-4030-a745-6a1782b57878/b48cc7a3
  -d81f-49f4-b87c-97958192897c)

  [Port(admin_state_up=True,allowed_address_pairs=[],binding=PortBinding,binding_levels=[],
  created_at=2017-04-21T13:53:13Z,data_plane_status=<?>,description='',
  device_id='dhcpef44eb91-ca69-52e5-a9b5-bb0cff2edb74-aee62d13-f5f2-4aec-8fec-abd56c99eda1',
  device_owner='network:dhcp',dhcp_options=[],distributed_binding=None,dns=None,fixed_ips=[IPAllocation],
  id=b48cc7a3-d81f-49f4-b87c-97958192897c,mac_address=fa:16:3e:0d:e9:1d,name='',
  network_id=aee62d13-f5f2-4aec-8fec-abd56c99eda1,project_id='0ca1e45b37a042b9ba3b88e442526972',
  qos_policy_id=None,revision_number=6,security=PortSecurity(b48cc7a3-d81f-49f4-b87c-97958192897c),
  security_group_ids=set([]),status='DOWN',updated_at=2017-04-21T13:53:14Z)]

  Subnet is being deleted here:

  2017-04-21 13:53:57,680 28262 INFO
  [tempest.lib.common.rest_client] Request
  (ServersTestJSON:_run_cleanups): 204 DELETE
  https://15.184.65.212:9696/v2.0/subnets/2b0869e7-f15b-4030-a745-6a1782b57878

  Port is being deleted here:

  http://logs.openstack.org/59/383859/22/experimental/gate-tempest-dsvm-
  neutron-pg-full-ubuntu-
  xenial/b2f29e9/logs/screen-q-svc.txt.gz#_2017-04-21_13_53_57_986

  2017-04-21 13:53:57.986 17266 DEBUG neutron.plugins.ml2.plugin [req-
  893ff18c-5732-42e6-b7ef-bddf9c42d9e7 - -] Deleting port b48cc7a3-d81f-
  49f4-b87c-97958192897c _pre_delete_port
  /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:1410

  network delete is trying to delete the port here:

  http://logs.openstack.org/59/383859/22/experimental/gate-tempest-dsvm-
  neutron-pg-full-ubuntu-
  xenial/b2f29e9/logs/screen-q-svc.txt.gz#_2017-04-21_13_53_58_412

  2017-04-21 13:53:58.412 17264 DEBUG neutron.plugins.ml2.plugin [req-
  8f94b291-ced4-4c88-9783-ceb4b04eb320 tempest-
  ServersTestJSON-1475565165 tempest-ServersTestJSON-1475565165]
  Deleting port b48cc7a3-d81f-49f4-b87c-97958192897c _pre_delete_port
  /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:1410

  2017-04-21 13:53:58.988 17264 DEBUG neutron.plugins.ml2.plugin [req-
  8f94b291-ced4-4c88-9783-ceb4b04eb320 tempest-
  ServersTestJSON-1475565165 tempest-ServersTestJSON-1475565165] Calling
  delete_port for b48cc7a3-d81f-49f4-b87c-97958192897c owned by
  network:dhcp delete_port
  /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:1469

  2017-04-21 13:53:59.061 17264 INFO
  neutron.pecan_wsgi.hooks.translation [req-
  8f94b291-ced4-4c88-9783-ceb4b04eb320 tempest-
  ServersTestJSON-1475565165 tempest-ServersTestJSON-1475565165] DELETE
  failed (client error): The resource could not be found.

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

Follow ups

  Thread Previous • Date Previous • • Thread Next