OpenStack Compute (nova)

Nova exception "DBDuplicateEntry" error in n-cond.log

Bug #1608593 reported by Michael Johnson
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Expired
Undecided
Unassigned

Bug Description

I'm running current master nova under devstack on ubuntu 14.04

nova git log:
commit eab62c0d8a3280c559d974d0f31d51a3f06e1048
Merge: dd9af27 b790332
Author: Jenkins <email address hidden>
Date: Mon Aug 1 00:24:20 2016 +0000

    Merge "Option Consistency for availability_zone.py"

Steps to reproduce:
1. Boot up an instance with a network port.
2. Update the port with "device_id" blank.
3. Delete the nova instance.
4. Attempt to boot a new instance with the port.
5. Update the port with "device_id" blank.
6. Delete the nova instance.
7. Attempt to boot a new instance with the port.

This is a multi-failover scenario.

Error from n-cond.log:
/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2137, in _flush
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api transaction.rollback(_capture_exception=True)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api compat.reraise(exc_type, exc_value, exc_tb)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2101, in _flush
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api flush_context.execute()
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api rec.execute(self)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api uow
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 174, in save_obj
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api mapper, table, insert)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 800, in _emit_insert_statements
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api execute(statement, params)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 914, in execute
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api return meth(self, multiparams, params)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api return connection._execute_clauseelement(self, multiparams, params)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api compiled_sql, distilled_params
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api context)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api util.raise_from_cause(newraise, exc_info)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 202, in raise_from_cause
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api reraise(type(exception), exception, tb=exc_tb, cause=cause)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api context)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api cursor.execute(statement, parameters)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 167, in execute
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api result = self._query(query)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 323, in _query
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api conn.query(q)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 836, in query
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1020, in _read_query_result
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api result.read()
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1303, in read
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api first_packet = self.connection._read_packet()
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 982, in _read_packet
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api packet.check_error()
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api err.raise_mysql_exception(self._data)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api _check_mysql_exception(errinfo)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 112, in _check_mysql_exception
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api raise errorclass(errno, errorvalue)
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api DBDuplicateEntry: (pymysql.err.IntegrityError) (1062, u"Duplicate entry 'fa:16:3e:f3:85:c0/58220635-8b9f-44fd-bbdc-7148777500f1-0' for key 'uniq_virtual_interfaces0address0deleted'") [SQL: u'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: {'instance_uuid': '7ab65f46-0044-4098-a74e-9a28b8b20882', 'uuid': '58220635-8b9f-44fd-bbdc-7148777500f1', 'deleted': 0, 'created_at': datetime.datetime(2016, 8, 1, 15, 44, 12, 979629), 'updated_at': None, 'network_id': None, 'tag': None, 'address': u'fa:16:3e:f3:85:c0/58220635-8b9f-44fd-bbdc-7148777500f1', 'deleted_at': None}]
2016-08-01 15:44:12.981 TRACE nova.db.sqlalchemy.api

n-cpu.log:
2016-08-01 15:44:14.075 ERROR nova.compute.manager [req-3296ed1c-0ca0-43aa-9b57-bd89412d92cc admin admin] [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] Failed to allocate network(s)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] Traceback (most recent call last):
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/compute/manager.py", line 1911, in _build_and_run_instance
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] block_device_info=block_device_info)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2664, in spawn
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] write_to_disk=True)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4663, in _get_guest_xml
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] network_info_str = str(network_info)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/network/model.py", line 524, in __str__
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return self._sync_wrapper(fn, *args, **kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/network/model.py", line 507, in _sync_wrapper
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] self.wait()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/network/model.py", line 539, in wait
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] self[:] = self._gt.wait()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 175, in wait
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return self._exit_event.wait()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return hubs.get_hub().switch()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 294, in switch
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return self.greenlet.switch()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 214, in main
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] result = function(*args, **kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/utils.py", line 1052, in context_wrapper
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return func(*args, **kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/compute/manager.py", line 1406, in _allocate_network_async
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] six.reraise(*exc_info)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/compute/manager.py", line 1389, in _allocate_network_async
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] bind_host_id=bind_host_id)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/network/neutronv2/api.py", line 795, in allocate_for_instance
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] bind_host_id, dhcp_opts, available_macs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/network/neutronv2/api.py", line 914, in _update_ports_for_instance
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] vif.destroy()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] self.force_reraise()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] six.reraise(self.type_, self.value, self.tb)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/network/neutronv2/api.py", line 897, in _update_ports_for_instance
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] vifobj.create()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 210, in wrapper
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] ctxt, self, fn.__name__, args, kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/conductor/rpcapi.py", line 241, in object_action
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] objmethod=objmethod, args=args, kwargs=kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] retry=self.retry)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 96, in _send
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] timeout=timeout, retry=retry)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 464, in send
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] retry=retry)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 455, in _send
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] raise result
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] VirtualInterfaceCreateException_Remote: Virtual Interface creation failed
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] Traceback (most recent call last):
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/conductor/manager.py", line 86, in _object_dispatch
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return getattr(target, method)(*args, **kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 226, in wrapper
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return fn(self, *args, **kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/objects/virtual_interface.py", line 97, in create
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] db_vif = db.virtual_interface_create(self._context, updates)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/db/api.py", line 649, in virtual_interface_create
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return IMPL.virtual_interface_create(context, values)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 169, in wrapper
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return f(*args, **kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 240, in wrapped
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] return f(context, *args, **kwargs)
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 1540, in virtual_interface_create
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] raise exception.VirtualInterfaceCreateException()
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] VirtualInterfaceCreateException: Virtual Interface creation failed
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.075 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]
2016-08-01 15:44:14.079 DEBUG nova.compute.utils [req-3296ed1c-0ca0-43aa-9b57-bd89412d92cc admin admin] [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] Virtual Interface creation failed from (pid=6197) notify_about_instance_usage /opt/stack/nova/nova/compute/utils.py:313
2016-08-01 15:44:14.079 ERROR nova.compute.manager [req-3296ed1c-0ca0-43aa-9b57-bd89412d92cc admin admin] [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] Build of instance 7ab65f46-0044-4098-a74e-9a28b8b20882 aborted: Failed to allocate the network(s), not rescheduling.
2016-08-01 15:44:14.079 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] Traceback (most recent call last):
2016-08-01 15:44:14.079 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/compute/manager.py", line 1770, in _do_build_and_run_instance
2016-08-01 15:44:14.079 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] filter_properties)
2016-08-01 15:44:14.079 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] File "/opt/stack/nova/nova/compute/manager.py", line 1950, in _build_and_run_instance
2016-08-01 15:44:14.079 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] reason=msg)
2016-08-01 15:44:14.079 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882] BuildAbortException: Build of instance 7ab65f46-0044-4098-a74e-9a28b8b20882 aborted: Failed to allocate the network(s), not rescheduling.
2016-08-01 15:44:14.079 TRACE nova.compute.manager [instance: 7ab65f46-0044-4098-a74e-9a28b8b20882]

mysql after the error:
mysql> select * from virtual_interfaces;
+---------------------+------------+---------------------+----+--------------------------------------------------------+------------+--------------------------------------+--------------------------------------+---------+------+
| created_at | updated_at | deleted_at | id | address | network_id | uuid | instance_uuid | deleted | tag |
+---------------------+------------+---------------------+----+--------------------------------------------------------+------------+--------------------------------------+--------------------------------------+---------+------+
| 2016-08-01 04:51:13 | NULL | NULL | 1 | fa:16:3e:94:0e:d9/a2dab54d-6fb7-458f-baa4-a4615c7a01c0 | NULL | a2dab54d-6fb7-458f-baa4-a4615c7a01c0 | 83d7950b-2a46-4441-98f9-8b39ccd5ad13 | 0 | NULL |
| 2016-08-01 04:51:14 | NULL | NULL | 2 | fa:16:3e:d2:3f:cc/c217cb17-9bb0-4520-a776-7f291027507a | NULL | c217cb17-9bb0-4520-a776-7f291027507a | 75453188-c0a7-4943-a6e9-4d71b5816d19 | 0 | NULL |
| 2016-08-01 04:52:37 | NULL | 2016-08-01 04:57:57 | 3 | fa:16:3e:a2:48:c9/5a276860-903b-4a25-8688-40f03d375f4f | NULL | 5a276860-903b-4a25-8688-40f03d375f4f | d223d120-7e46-45d5-b233-8d8719de5a29 | 3 | NULL |
| 2016-08-01 04:52:58 | NULL | 2016-08-01 04:57:57 | 4 | fa:16:3e:55:1f:f1/52f28060-9014-48c7-b94e-6847e336727c | NULL | 52f28060-9014-48c7-b94e-6847e336727c | d223d120-7e46-45d5-b233-8d8719de5a29 | 4 | NULL |
| 2016-08-01 04:54:09 | NULL | 2016-08-01 04:57:57 | 5 | fa:16:3e:b9:bc:26/2f1fad78-451f-4e91-a164-e8c925933d72 | NULL | 2f1fad78-451f-4e91-a164-e8c925933d72 | d223d120-7e46-45d5-b233-8d8719de5a29 | 5 | NULL |
| 2016-08-01 04:54:43 | NULL | 2016-08-01 04:57:57 | 6 | fa:16:3e:01:89:22/b3add585-c06c-47c7-b081-24c2120fa7c7 | NULL | b3add585-c06c-47c7-b081-24c2120fa7c7 | d223d120-7e46-45d5-b233-8d8719de5a29 | 6 | NULL |
| 2016-08-01 04:57:57 | NULL | 2016-08-01 04:57:57 | 7 | fa:16:3e:62:4f:38/71b6d508-fc59-4386-8b5f-b09432cab419 | NULL | 71b6d508-fc59-4386-8b5f-b09432cab419 | 95142ff6-ec33-408b-8f11-2c86f332bbf8 | 7 | NULL |
| 2016-08-01 15:26:03 | NULL | 2016-08-01 15:38:45 | 9 | fa:16:3e:60:f3:f3/775de30a-c39a-46ea-81ef-f7f94d1c40d3 | NULL | 775de30a-c39a-46ea-81ef-f7f94d1c40d3 | 77e4184c-f3ec-4b01-aa14-191583673ea4 | 9 | NULL |
| 2016-08-01 15:26:11 | NULL | 2016-08-01 15:38:45 | 10 | fa:16:3e:02:04:92/f5e8d9c3-832a-4f49-86b3-974dfef6cd38 | NULL | f5e8d9c3-832a-4f49-86b3-974dfef6cd38 | 77e4184c-f3ec-4b01-aa14-191583673ea4 | 10 | NULL |
| 2016-08-01 15:27:23 | NULL | 2016-08-01 15:38:45 | 11 | fa:16:3e:f3:85:c0/58220635-8b9f-44fd-bbdc-7148777500f1 | NULL | 58220635-8b9f-44fd-bbdc-7148777500f1 | 77e4184c-f3ec-4b01-aa14-191583673ea4 | 11 | NULL |
| 2016-08-01 15:27:57 | NULL | 2016-08-01 15:38:45 | 12 | fa:16:3e:21:5b:85/e66a8ddd-8398-427b-a0fd-403bdcbe9fae | NULL | e66a8ddd-8398-427b-a0fd-403bdcbe9fae | 77e4184c-f3ec-4b01-aa14-191583673ea4 | 12 | NULL |
| 2016-08-01 15:38:45 | NULL | 2016-08-01 15:44:13 | 13 | fa:16:3e:44:8a:e7/45ec8e98-722e-46e3-abc9-73578e4766d5 | NULL | 45ec8e98-722e-46e3-abc9-73578e4766d5 | 5cdb6bb1-bc10-4879-85b9-321f54bf3e80 | 13 | NULL |
| 2016-08-01 15:38:45 | NULL | 2016-08-01 15:44:13 | 14 | fa:16:3e:f3:85:c0/58220635-8b9f-44fd-bbdc-7148777500f1 | NULL | 58220635-8b9f-44fd-bbdc-7148777500f1 | 5cdb6bb1-bc10-4879-85b9-321f54bf3e80 | 14 | NULL |
| 2016-08-01 15:38:45 | NULL | 2016-08-01 15:44:13 | 15 | fa:16:3e:21:5b:85/e66a8ddd-8398-427b-a0fd-403bdcbe9fae | NULL | e66a8ddd-8398-427b-a0fd-403bdcbe9fae | 5cdb6bb1-bc10-4879-85b9-321f54bf3e80 | 15 | NULL |
| 2016-08-01 15:38:46 | NULL | 2016-08-01 15:44:13 | 16 | fa:16:3e:02:04:92/f5e8d9c3-832a-4f49-86b3-974dfef6cd38 | NULL | f5e8d9c3-832a-4f49-86b3-974dfef6cd38 | 5cdb6bb1-bc10-4879-85b9-321f54bf3e80 | 16 | NULL |
| 2016-08-01 15:44:12 | NULL | 2016-08-01 15:44:13 | 17 | fa:16:3e:0f:f7:7c/eeda7841-9c60-49b7-b0f9-09103b6a9b91 | NULL | eeda7841-9c60-49b7-b0f9-09103b6a9b91 | 7ab65f46-0044-4098-a74e-9a28b8b20882 | 17 | NULL |
+---------------------+------------+---------------------+----+--------------------------------------------------------+------------+--------------------------------------+--------------------------------------+---------+------+
16 rows in set (0.00 sec)

This may be related to https://bugs.launchpad.net/nova/+bug/1602357

Revision history for this message
Matt Riedemann (mriedem) wrote :

You don't need to update the port.device_id to be '', nova will do that for ports it didn't create. By wiping those out before deleting the instance, nova can't find the ports to unbind/delete here:

https://github.com/openstack/nova/blob/b790332f227411a16049f841c68292a7b0b88d81/nova/network/neutronv2/api.py#L1064

But nova should still be deleting the virtual interface records for the given instance here:

https://github.com/openstack/nova/blob/b790332f227411a16049f841c68292a7b0b88d81/nova/network/neutronv2/api.py#L1091

Changed in nova:
status: New → Invalid
status: Invalid → New
Revision history for this message
Matt Riedemann (mriedem) wrote :

Are you waiting for the nova instance to be deleted before trying to spawn a new instance with the port?

Revision history for this message
Matt Riedemann (mriedem) wrote :

To expand on comment 2, I'm wondering if you're just issuing the delete request which is a cast to the compute and asynchronous and before the vifs are deleted from the nova db you're already trying to boot a new instance with the port, and that's why you hit the unique constraint.

Ideally what you should be doing is deleting the instance and polling the port.device_id to be unbound, that's what the tempest test "test_reassign_port_between_servers" does.

Matt Riedemann (mriedem)
Changed in nova:
status: New → Incomplete
Revision history for this message
Michael Johnson (johnsom) wrote :

I am going to do additional testing on this today. It may be that we are assigning the port too quickly, in which case polling is probably the right answer.

Revision history for this message
Michael Johnson (johnsom) wrote :

Matt,
I have done additional testing. If I don't clear that device_id before the nova delete call the port ends up getting deleted.

This is a port_show before the nova delete of a port that gets deleted:

port: {'status': u'ACTIVE', 'name': u'', 'admin_state_up': True, 'network_id': u'6708b678-eac3-4334-8404-d9b729b43eaf', 'device_owner': u'compute:None', 'device_id': u'93aec306-ba5b-48ff-a668-d2f4e18be215', 'mac_address': u'fa:16:3e:d6:f4:a5', 'project_id': u'4ab023de954e443b93d1163c0e729485', 'fixed_ips': None, 'id': u'38d10b1d-c06d-4316-b3b9-cb311f8cb690', 'network': None}

I am puzzled as to why a nova delete of the instance would cause this port to get deleted. Do you see something in the above port details that tips you off as to why it would get flagged for deletion?

Thank you for your help here,
Michael

Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]

Changed in nova:
status: Incomplete → Expired
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.