yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1608593] [NEW] Nova exception "DBDuplicateEntry" error in n-cond.log

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Michael Johnson <johnsomor@xxxxxxxxx>
Date: Mon, 01 Aug 2016 16:03:04 -0000
Reply-to: Bug 1608593 <1608593@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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

nova git log:
commit eab62c0d8a3280c559d974d0f31d51a3f06e1048
Merge: dd9af27 b790332
Author: Jenkins <jenkins@xxxxxxxxxxxxxxxxxxxx>
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

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1608593

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

Status in OpenStack Compute (nova):
  New

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

  nova git log:
  commit eab62c0d8a3280c559d974d0f31d51a3f06e1048
  Merge: dd9af27 b790332
  Author: Jenkins <jenkins@xxxxxxxxxxxxxxxxxxxx>
  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

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1608593/+subscriptions
Follow ups

[Bug 1608593] Re: Nova exception "DBDuplicateEntry" error in n-cond.log
From: Launchpad Bug Tracker, 2016-10-10