[Bug 1821088] Re: Virtual Interface creation failed due to duplicate entry

[Trent Lloyd]

I found another cause for this issue not so far discussed, noting it
here for future travellers that may find this bug on the off chance you
happen to have a workflow that re-uses a neutron port on another
instance.

We had a workflow like this:
- Create a static neutron port that is re-used
- Create an instance using that port
- Delete the instance
- Loop waiting for neutron to show the port's device_id has been cleared to know we can re-use it
- Create another instance using the same port

The problem is that the neutron.ports table entry is updated with
device_id='', status='DOWN' before the entry in nova.virtual_interfaces
is marked deleted.

So there is a small window of time, a few seconds or more, where you can
create an virtual machines and use an unassigned neutron port, but the
nova.virtual_interfaces will have a conflicting entry that hasn't yet
been cleared and will cause the server creation to fail.

It seems that the nova.instances vm_state='deleted' and
deleted=instances.id set after the virtual_interfaces entry is deleted,
so as a workaround you can wait for deletion of the previous instance in
such an exact workflow, but this is probably still a bug in that the
virtual_interfaces entry should probably be getting cleared before the
neutron port is released.

I haven't delved into the code to figure out how possible that is. The
same behaviour exists on ussuri and antelope.


For reference, the order of MySQL queries in my focal-ussuri test environment (some of this may possibly be asynchronous and may vary depending on the worker count, load, size of database, etc):

2024-03-15T06:47:07 # start: openstack server create --wait
2024-03-15T06:47:12.2 INSERT INTO nova.instances
2024-03-15T06:47:16.0 UPDATE neutron.ports SET device_id
2024-03-15T06:47:18.1 INSERT INTO nova.virtual_interfaces
2024-03-15T06:47:21.9 UPDATE neutron.ports SET status='ACTIVE'
2024-03-15T06:47:27 # finish: openstack server create --wait

2024-03-15T06:47:45 # openstack server delete
2024-03-15T06:47:45.1 UPDATE nova.instances SET task_state='deleting'
2024-03-15T06:47:46.1 UPDATE neutron.ports SET status='DOWN'
2024-03-15T06:47:47.1 UPDATE neutron.ports SET device_id=''
2024-03-15T06:47:48.3 UPDATE nova.virtual_interfaces SET deleted=id
2024-03-15T06:47:48.4 UPDATE nova.instances SET vm_state='deleted'
2024-03-15T06:47:48.9 UPDATE nova.instances SET deleted=instances.id

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to Ubuntu Cloud Archive.
https://bugs.launchpad.net/bugs/1821088

Title:
  Virtual Interface creation failed due to duplicate entry

Status in Ubuntu Cloud Archive:
  New
Status in Ubuntu Cloud Archive ussuri series:
  New
Status in Ubuntu Cloud Archive victoria series:
  New
Status in Ubuntu Cloud Archive wallaby series:
  New
Status in Ubuntu Cloud Archive xena series:
  New
Status in Ubuntu Cloud Archive yoga series:
  New
Status in OpenStack Compute (nova):
  Fix Released
Status in OpenStack Compute (nova) train series:
  Won't Fix
Status in OpenStack Compute (nova) ussuri series:
  Won't Fix
Status in OpenStack Compute (nova) victoria series:
  Won't Fix
Status in OpenStack Compute (nova) wallaby series:
  Won't Fix
Status in OpenStack Compute (nova) xena series:
  Fix Released

Bug description:
  Seen once in a test on stable/rocky:

  http://logs.openstack.org/48/638348/1/gate/heat-functional-convg-
  mysql-lbaasv2-py35/9d70590/logs/screen-n-api.txt.gz?level=ERROR

  The traceback appears to be similar to the one reported in bug 1602357
  (which raises the possibility that
  https://bugs.launchpad.net/nova/+bug/1602357/comments/8 is relevant
  here):

  ERROR nova.api.openstack.wsgi [None req-e05ce059-71c4-437d-91e0-e4bc896acca6 demo demo] Unexpected exception in API method: nova.exception_Remote.VirtualInterfaceCreateException_Remote: Virtual Interface creation failed
  pymysql.err.IntegrityError: (1062, "Duplicate entry 'fa:16:3e:9d:18:a6/aac0ca83-b3d2-4b28-ab15-de2d3a3e6e16-0' for key 'uniq_virtual_interfaces0address0deleted'")
  oslo_db.exception.DBDuplicateEntry: (pymysql.err.IntegrityError) (1062, "Duplicate entry 'fa:16:3e:9d:18:a6/aac0ca83-b3d2-4b28-ab15-de2d3a3e6e16-0' for key 'uniq_virtual_interfaces0address0deleted'") [SQL: 'INSERT INTO virtual_interfaces (created_at, updated_at, deleted_at, deleted, address, network_id, instance_uuid, uuid, tag) VALUES (%(created_at)s, %(updated_at)s, %(deleted_at)s, %(deleted)s, %(address)s, %(network_id)s, %(instance_uuid)s, %(uuid)s, %(tag)s)'] [parameters: {'created_at': datetime.datetime(2019, 3, 20, 16, 11, 27, 753079), 'tag': None, 'uuid': 'aac0ca83-b3d2-4b28-ab15-de2d3a3e6e16', 'deleted_at': None, 'deleted': 0, 'address': 'fa:16:3e:9d:18:a6/aac0ca83-b3d2-4b28-ab15-de2d3a3e6e16', 'network_id': None, 'instance_uuid': '890675f9-3a1e-4a07-8bed-8648cea9fbb9', 'updated_at': None}] (Background on this error at: http://sqlalche.me/e/gkpj)

  (This sequence of exceptions occurs 3 times, I assume because retrying
  is normally sufficient to fix a duplicate entry problem.)

  The test was
  heat_integrationtests.functional.test_cancel_update.CancelUpdateTest.test_cancel_update_server_with_port

To manage notifications about this bug go to:
https://bugs.launchpad.net/cloud-archive/+bug/1821088/+subscriptions