When running the test pushing all VMs at the same time instead of sequencial as Aaron suggested I was able to reproduce the bug: 22bdea7f-0215-4810-82e6-1292fbbddadd | vm-54 | ACTIVE | None | Running | private=10.0.0.56, 10.0.0.78 | | 5041f4ce-52d4-40f9-b9cc-0e8eda5bb1bd | vm-55 | ACTIVE | None | Running | private=10.0.0.102 | | 9f105432-a74d-4fe7-acac-8ed423f99ef8 | vm-58 | ACTIVE | None | Running | private=10.0.0.115 | quantum port-list |grep 10.0.0.56 | b39a4766-d8e9-4f86-98a5-41697bed30db | | fa:16:3e:5e:1d:5d | {"subnet_id": "b9ded0f5-faa7-40f8-abde-a1a400b056c7", "ip_address": "10.0.0.56"} | Both Ports have the same device_id: emagana@rock:/opt/stack/logs/screen$ quantum port-show b39a4766-d8e9-4f86-98a5-41697bed30db +-----------------+----------------------------------------------------------------------------------+ | Field | Value | +-----------------+----------------------------------------------------------------------------------+ | admin_state_up | True | | device_id | 22bdea7f-0215-4810-82e6-1292fbbddadd | | device_owner | compute:None | | fixed_ips | {"subnet_id": "b9ded0f5-faa7-40f8-abde-a1a400b056c7", "ip_address": "10.0.0.56"} | | id | b39a4766-d8e9-4f86-98a5-41697bed30db | | mac_address | fa:16:3e:5e:1d:5d | | name | | | network_id | aedb8668-e23a-463b-932a-7e95f0d005b1 | | security_groups | eea80a63-eb12-4d77-bac9-95a5195c98fb | | status | DOWN | | tenant_id | 3bb1aac4f1a547f48af504db0a6d64e2 | +-----------------+----------------------------------------------------------------------------------+ emagana@rock:/opt/stack/logs/screen$ quantum port-show d8aac4ec-e22b-4547-98d5-ce4c0c88ba2c +-----------------+----------------------------------------------------------------------------------+ | Field | Value | +-----------------+----------------------------------------------------------------------------------+ | admin_state_up | True | | device_id | 22bdea7f-0215-4810-82e6-1292fbbddadd | | device_owner | compute:None | | fixed_ips | {"subnet_id": "b9ded0f5-faa7-40f8-abde-a1a400b056c7", "ip_address": "10.0.0.78"} | | id | d8aac4ec-e22b-4547-98d5-ce4c0c88ba2c | | mac_address | fa:16:3e:bb:02:2b | | name | | | network_id | aedb8668-e23a-463b-932a-7e95f0d005b1 | | security_groups | eea80a63-eb12-4d77-bac9-95a5195c98fb | | status | ACTIVE | | tenant_id | 3bb1aac4f1a547f48af504db0a6d64e2 | +-----------------+----------------------------------------------------------------------------------+ It seems that allocate_for_instance() is being called just once: (I did not find another call for this VM with the two ports in the logs) allocate_for_instance() for vm-54 allocate_for_instance /opt/stack/nova/nova/network/quantumv2/api.py:153 I see some ERRORs (Time out) in Quantum: Traceback (most recent call last): File "/opt/stack/quantum/quantum/api/v2/resource.py", line 82, in resource result = method(request=request, **args) File "/opt/stack/quantum/quantum/api/v2/base.py", line 239, in index return self._items(request, True, parent_id) File "/opt/stack/quantum/quantum/api/v2/base.py", line 192, in _items obj_list = obj_getter(request.context, **kwargs) File "/opt/stack/quantum/quantum/plugins/openvswitch/ovs_quantum_plugin.py", line 554, in get_networks limit, marker, page_reverse) File "/opt/stack/quantum/quantum/db/db_base_plugin_v2.py", line 1019, in get_networks page_reverse=page_reverse) File "/opt/stack/quantum/quantum/db/db_base_plugin_v2.py", line 240, in _get_collection items = [dict_func(c, fields) for c in query.all()] File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2115, in all return list(self) File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2227, in __iter__ return self._execute_and_instances(context) File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2240, in _execute_and_instances close_with_result=True) File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2231, in _connection_from_session **kw) File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 777, in connection close_with_result=close_with_result) File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 781, in _connection_for_bind return self.transaction._connection_for_bind(engine) File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 306, in _connection_for_bind conn = bind.contextual_connect() File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2489, in contextual_connect self.pool.connect(), File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 236, in connect return _ConnectionFairy(self).checkout() File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 401, in __init__ rec = self._connection_record = pool._do_get() File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 738, in _do_get (self.size(), self.overflow(), self._timeout)) TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30 2013-05-22 22:28:24 DEBUG [quantum.policy] loading policy file at /etc/quantum/policy.json The logs for nova-cpu related to that device_id (22bdea7f-0215-4810-82e6-1292fbbddadd): emagana@rock:/opt/stack/logs/screen$ grep -r "22bdea7f-0215-4810-82e6-1292fbbddadd" screen-n-cpu.log 2013-05-22 22:26:31.905 26460 DEBUG nova.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'anotherrole', u'Member', u'admin'], u'_context_request_id': u'req-597f6296-0a89-4f67-972c-95d3c60883b0', u'_context_quota_class': None, u'_context_project_name': u'demo', u'_context_service_catalog': [{u'endpoints': [{u'adminURL': u'http://10.1.1.200:8776/v1/3bb1aac4f1a547f48af504db0a6d64e2', u'region': u'RegionOne', u'id': u'12755c1ae8e44155ba0a3865d267b6a4', u'internalURL': u'http://10.1.1.200:8776/v1/3bb1aac4f1a547f48a f504db0a6d64e2', u'publicURL': u'http://10.1.1.200:8776/v1/3bb1aac4f1a547f48af504db0a6d64e2'}], u'endpoints_links': [], u'type': u'volume', u'name': u'cinder'}], u'_context_user_name': u'demo', u'_context_auth_token': '', u'args': {u'node': u'rock.plumg rid.com', u'request_spec': {u'block_device_mapping': [], u'image': {u'status': u'active', u'name': u'tty-quantum', u'deleted': False, u'container_format': u'ami', u'created_at': u'2013-05-23T05:14:40.000000', u'disk_format': u'ami', u'updated_at': u'2013-05-23T05: 14:40.000000', u'id': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'owner': u'f612f4b5a5ff4e129cf18705fa4b9f53', u'min_ram': 0, u'checksum': u'bd0818c1e5bf8267f944f5667692e5fc', u'min_disk': 0, u'is_public': True, u'deleted_at': None, u'properties': {u'kernel_id': u' 6321291c-bad5-4e3f-b8ee-808820bc8c74', u'ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2729'}, u'size': 25165824}, u'instance_type': {u'disabled': False, u'root_gb': 0, u'name': u'm1.nano', u'flavorid': u'42', u'deleted': 0, u'created_at': u'2013-05-23T05:14:44.0 00000', u'ephemeral_gb': 0, u'updated_at': None, u'memory_mb': 64, u'vcpus': 1, u'extra_specs': {}, u'swap': 0, u'rxtx_factor': 1.0, u'is_public': True, u'deleted_at': None, u'vcpu_weight': None, u'id': 6}, u'instance_properties': {u'vm_state': u'building', u'avai lability_zone': None, u'launch_index': 0, u'ephemeral_gb': 0, u'instance_type_id': 6, u'user_data': None, u'vm_mode': None, u'reservation_id': u'r-oj8cm0i0', u'config_drive_id': u'', u'root_device_name': None, u'user_id': u'3b36a6a76935439cbfa18de2417d61e2', u'dis play_description': u'vm-54', u'key_data': None, u'power_state': 0, u'progress': 0, u'project_id': u'3bb1aac4f1a547f48af504db0a6d64e2', u'config_drive': u'', u'ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2729', u'access_ip_v6': None, u'access_ip_v4': None, u'ker nel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'key_name': None, u'display_name': u'vm-54', u'system_metadata': {u'image_kernel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'instance_type_memory_mb': 64, u'instance_type_swap': 0, u'instance_type_vcpu_weight' : None, u'instance_type_root_gb': 0, u'instance_type_name': u'm1.nano', u'image_ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2729', u'instance_type_id': 6, u'instance_type_ephemeral_gb': 0, u'instance_type_rxtx_factor': 1.0, u'instance_type_flavorid': u'42', u'i nstance_type_vcpus': 1, u'image_base_image_ref': u'431b6066-3bc8-4948-b234-6b5455cd4a5b'}, u'root_gb': 0, u'locked': False, u'launch_time': u'2013-05-23T05:26:20Z', u'memory_mb': 64, u'vcpus': 1, u'image_ref': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'architectur e': None, u'auto_disk_config': None, u'os_type': None, u'metadata': {}}, u'security_group': [u'default'], u'instance_uuids': [u'22bdea7f-0215-4810-82e6-1292fbbddadd']}, u'requested_networks': [[u'aedb8668-e23a-463b-932a-7e95f0d005b1', None, None]], u'filter_proper ties': {u'config_options': {}, u'limits': {u'memory_mb': 24036.0}, u'request_spec': {u'block_device_mapping': [], u'image': {u'status': u'active', u'name': u'tty-quantum', u'deleted': False, u'container_format': u'ami', u'created_at': u'2013-05-23T05:14:40.000000' , u'disk_format': u'ami', u'updated_at': u'2013-05-23T05:14:40.000000', u'id': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'owner': u'f612f4b5a5ff4e129cf18705fa4b9f53', u'min_ram': 0, u'checksum': u'bd0818c1e5bf8267f944f5667692e5fc', u'min_disk': 0, u'is_public': Tr ue, u'deleted_at': None, u'properties': {u'kernel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2729'}, u'size': 25165824}, u'instance_type': {u'disabled': False, u'root_gb': 0, u'name': u'm1.nano', u'flavorid': u'4 2', u'deleted': 0, u'created_at': u'2013-05-23T05:14:44.000000', u'ephemeral_gb': 0, u'updated_at': None, u'memory_mb': 64, u'vcpus': 1, u'extra_specs': {}, u'swap': 0, u'rxtx_factor': 1.0, u'is_public': True, u'deleted_at': None, u'vcpu_weight': None, u'id': 6}, u'instance_properties': {u'vm_state': u'building', u'availability_zone': None, u'launch_index': 0, u'ephemeral_gb': 0, u'instance_type_id': 6, u'user_data': None, u'vm_mode': None, u'reservation_id': u'r-oj8cm0i0', u'config_drive_id': u'', u'root_device_name': Non e, u'user_id': u'3b36a6a76935439cbfa18de2417d61e2', u'display_description': u'vm-54', u'key_data': None, u'power_state': 0, u'progress': 0, u'project_id': u'3bb1aac4f1a547f48af504db0a6d64e2', u'config_drive': u'', u'ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2 729', u'access_ip_v6': None, u'access_ip_v4': None, u'kernel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'key_name': None, u'display_name': u'vm-54', u'system_metadata': {u'image_kernel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'instance_type_memory_mb': 6 4, u'instance_type_swap': 0, u'instance_type_vcpu_weight': None, u'instance_type_root_gb': 0, u'instance_type_name': u'm1.nano', u'image_ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2729', u'instance_type_id': 6, u'instance_type_ephemeral_gb': 0, u'instance_type _rxtx_factor': 1.0, u'instance_type_flavorid': u'42', u'instance_type_vcpus': 1, u'image_base_image_ref': u'431b6066-3bc8-4948-b234-6b5455cd4a5b'}, u'root_gb': 0, u'locked': False, u'launch_time': u'2013-05-23T05:26:20Z', u'memory_mb': 64, u'vcpus': 1, u'image_ref ': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'architecture': None, u'auto_disk_config': None, u'os_type': None, u'metadata': {}}, u'security_group': [u'default'], u'instance_uuids': [u'22bdea7f-0215-4810-82e6-1292fbbddadd']}, u'instance_type': {u'disabled': False, u'root_gb': 0, u'name': u'm1.nano', u'flavorid': u'42', u'deleted': 0, u'created_at': u'2013-05-23T05:14:44.000000', u'ephemeral_gb': 0, u'updated_at': None, u'memory_mb': 64, u'vcpus': 1, u'extra_specs': {}, u'swap': 0, u'rxtx_factor': 1.0, u'is_public': True, u 'deleted_at': None, u'vcpu_weight': None, u'id': 6}, u'retry': {u'num_attempts': 1, u'hosts': [[u'rock', u'rock.plumgrid.com']]}, u'os_type': None, u'project_id': u'3bb1aac4f1a547f48af504db0a6d64e2', u'scheduler_hints': {}}, u'instance': {u'vm_state': u'building', u'availability_zone': None, u'terminated_at': None, u'ephemeral_gb': 0, u'instance_type_id': 6, u'user_data': None, u'vm_mode': None, u'deleted_at': None, u'reservation_id': u'r-oj8cm0i0', u'id': 49, u'security_groups': [], u'disable_terminate': False, u'user_id' : u'3b36a6a76935439cbfa18de2417d61e2', u'uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'default_swap_device': None, u'info_cache': {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated _at': None, u'network_info': u'[]', u'deleted_at': None, u'id': 49}, u'hostname': u'vm-54', u'launched_on': None, u'display_description': u'vm-54', u'key_data': None, u'kernel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'power_state': 0, u'default_ephemeral_dev ice': None, u'progress': 0, u'project_id': u'3bb1aac4f1a547f48af504db0a6d64e2', u'launched_at': None, u'scheduled_at': u'2013-05-23T05:26:31.760378', u'node': None, u'ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2729', u'access_ip_v6': None, u'access_ip_v4': Non e, u'deleted': 0, u'key_name': None, u'updated_at': u'2013-05-23T05:26:31.814354', u'host': None, u'architecture': None, u'display_name': u'vm-54', u'system_metadata': [{u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'201 3-05-23T05:26:25.000000', u'updated_at': None, u'value': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'key': u'image_kernel_id', u'deleted_at': None, u'id': 625}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T0 5:26:25.000000', u'updated_at': None, u'value': u'64', u'key': u'instance_type_memory_mb', u'deleted_at': None, u'id': 626}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': Non e, u'value': u'0', u'key': u'instance_type_swap', u'deleted_at': None, u'id': 627}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': None, u'key': u'instance_typ e_vcpu_weight', u'deleted_at': None, u'id': 628}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_root_gb', u'deleted_at': None, u 'id': 629}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'6', u'key': u'instance_type_id', u'deleted_at': None, u'id': 630}, {u'instance_uuid': u'22bdea7f-0 215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'6c283423-2469-4fa5-996e-4b526c2e2729', u'key': u'image_ramdisk_id', u'deleted_at': None, u'id': 631}, {u'instance_uuid': u'22bdea7f-0215-4810 -82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'm1.nano', u'key': u'instance_type_name', u'deleted_at': None, u'id': 632}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_ephemeral_gb', u'deleted_at': None, u'id': 633}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:2 6:25.000000', u'updated_at': None, u'value': u'1', u'key': u'instance_type_rxtx_factor', u'deleted_at': None, u'id': 634}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'42', u'key': u'instance_type_flavorid', u'deleted_at': None, u'id': 635}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'1', u'key': u'instance_ type_vcpus', u'deleted_at': None, u'id': 636}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'key': u'image_base_ima ge_ref', u'deleted_at': None, u'id': 637}], u'task_state': u'scheduling', u'shutdown_terminate': False, u'cell_name': None, u'root_gb': 0, u'locked': False, u'name': u'instance-00000031', u'created_at': u'2013-05-23T05:26:25.000000', u'launch_index': 0, u'metadata ': [], u'memory_mb': 64, u'vcpus': 1, u'image_ref': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'root_device_name': None, u'auto_disk_config': None, u'os_type': None, u'config_drive': u''}, u'admin_password': '', u'injected_files': [], u'is_first_time': T rue}, u'_context_tenant': u'3bb1aac4f1a547f48af504db0a6d64e2', u'_context_instance_lock_checked': False, u'_context_timestamp': u'2013-05-23T05:26:00.440653', u'_context_is_admin': False, u'version': u'2.19', u'_context_project_id': u'3bb1aac4f1a547f48af504db0a6d6 4e2', u'_context_user': u'3b36a6a76935439cbfa18de2417d61e2', u'_unique_id': u'56a64367199640ff8627095c9bfee52c', u'_context_read_deleted': u'no', u'_context_user_id': u'3b36a6a76935439cbfa18de2417d61e2', u'method': u'run_instance', u'_context_remote_address': u'10 .1.1.200'} _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:276 2013-05-22 22:26:32.391 DEBUG nova.openstack.common.lockutils [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] Got semaphore "22bdea7f-0215-4810-82e6-1292fbbddadd" for method "do_run_instance"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:186 2013-05-22 22:26:32.907 AUDIT nova.compute.manager [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Starting instance... 2013-05-22 22:26:51.152 AUDIT nova.compute.claims [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Attempting claim: memory 64 MB, disk 0 GB, VCPUs 1 2013-05-22 22:26:51.152 AUDIT nova.compute.claims [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Total Memory: 16024 MB, used: 3584 MB 2013-05-22 22:26:51.153 AUDIT nova.compute.claims [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Memory limit: 24036 MB, free: 20452 MB 2013-05-22 22:26:51.153 AUDIT nova.compute.claims [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Total Disk: 884 GB, used: 0 GB 2013-05-22 22:26:51.154 AUDIT nova.compute.claims [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Disk limit not specified, defaulting to unlimited 2013-05-22 22:26:51.154 AUDIT nova.compute.claims [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Total CPU: 8 VCPUs, used: 48 VCPUs 2013-05-22 22:26:51.154 AUDIT nova.compute.claims [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] CPU limit not specified, defaulting to unlimited 2013-05-22 22:26:51.155 AUDIT nova.compute.claims [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Claim successful 2013-05-22 22:30:19.153 DEBUG nova.compute.manager [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Instance network_info: |[VIF({'ovs_interfaceid': u'd8aac4ec-e22b-4547-98d5-ce4c0c88ba2c', 'network': Network({' bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.0.0.78'})], 'version': 4, 'meta': {'dhcp_server': u'10.0.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.0.0.0/24', 'gateway': IP({' meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.0.0.1'})})], 'meta': {'injected': False, 'tenant_id': u'3bb1aac4f1a547f48af504db0a6d64e2'}, 'id': u'aedb8668-e23a-463b-932a-7e95f0d005b1', 'label': u'private'}), 'devname': u'tapd8aac4ec-e2', 'qbh_params' : None, 'meta': {}, 'address': u'fa:16:3e:bb:02:2b', 'type': u'ovs', 'id': u'd8aac4ec-e22b-4547-98d5-ce4c0c88ba2c', 'qbg_params': None})]| _allocate_network /opt/stack/nova/nova/compute/manager.py:1078 2013-05-22 22:30:42.928 26460 INFO nova.compute.manager [-] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] During sync_power_state the instance has a pending task. Skip. 2013-05-22 22:31:39.106 INFO nova.virt.libvirt.driver [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Creating image 2013-05-22 22:31:39.112 DEBUG nova.utils [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] Running cmd (subprocess): cp /opt/stack/data/nova/instances/_base/6321291c-bad5-4e3f-b8ee-808820bc8c74 /opt/stack/data/nova/instances/22bdea7f-0215-4810-82e6-1292fbbddadd /kernel execute /opt/stack/nova/nova/utils.py:208 2013-05-22 22:31:39.183 DEBUG nova.utils [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/22bdea7f-0215-4810-82e6-1292fbbddadd/kernel execute /opt/stack/nova/nova/utils. py:208 2013-05-22 22:31:39.248 DEBUG nova.utils [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] Running cmd (subprocess): cp /opt/stack/data/nova/instances/_base/6c283423-2469-4fa5-996e-4b526c2e2729 /opt/stack/data/nova/instances/22bdea7f-0215-4810-82e6-1292fbbddadd /ramdisk execute /opt/stack/nova/nova/utils.py:208 2013-05-22 22:31:39.304 DEBUG nova.utils [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/22bdea7f-0215-4810-82e6-1292fbbddadd/ramdisk execute /opt/stack/nova/nova/utils .py:208 2013-05-22 22:31:39.446 DEBUG nova.utils [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/cfcf361456f6839132c91dac5f2666b8262da3b8 /opt/stack/data/nova/inst ances/22bdea7f-0215-4810-82e6-1292fbbddadd/disk execute /opt/stack/nova/nova/utils.py:208 2013-05-22 22:31:39.789 DEBUG nova.virt.libvirt.driver [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] Start to_xml instance={u'vm_state': u'building', u'availability_zone': None, u'terminated_at': None, u'ephemeral_gb': 0, u'instance_type_id': 6, u'user_data ': None, u'vm_mode': None, u'deleted_at': None, u'reservation_id': u'r-oj8cm0i0', u'id': 49, u'security_groups': [], u'disable_terminate': False, u'root_device_name': None, u'user_id': u'3b36a6a76935439cbfa18de2417d61e2', u'uuid': u'22bdea7f-0215-4810-82e6-1292fbb ddadd', u'default_swap_device': None, u'info_cache': {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': u'2013-05-23T05:30:18.000000', u'network_info': u'[{"ovs_interfaceid": "d8a ac4ec-e22b-4547-98d5-ce4c0c88ba2c", "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.78"}], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}, "dns": [], "routes": [], "cidr": " 10.0.0.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"}}], "meta": {"injected": false, "tenant_id": "3bb1aac4f1a547f48af504db0a6d64e2"}, "id": "aedb8668-e23a-463b-932a-7e95f0d005b1", "label": "private"}, "devname": "tapd8aac4e c-e2", "qbh_params": null, "meta": {}, "address": "fa:16:3e:bb:02:2b", "type": "ovs", "id": "d8aac4ec-e22b-4547-98d5-ce4c0c88ba2c", "qbg_params": null}]', u'deleted_at': None, u'id': 49}, u'hostname': u'vm-54', u'launched_on': u'rock', u'display_description': u'vm -54', u'key_data': None, u'deleted': 0, u'scheduled_at': u'2013-05-23T05:26:31.000000', u'power_state': 0, u'default_ephemeral_device': None, u'progress': 0, u'project_id': u'3bb1aac4f1a547f48af504db0a6d64e2', u'launched_at': None, u'config_drive': u'', u'node': u 'rock.plumgrid.com', u'ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2729', u'access_ip_v6': None, u'access_ip_v4': None, u'kernel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'key_name': None, u'updated_at': u'2013-05-23T05:30:52.158725', u'host': u'rock', u'd isplay_name': u'vm-54', u'system_metadata': [{u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'key': u'image_kernel_id' , u'deleted_at': None, u'id': 625}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'64', u'key': u'instance_type_memory_mb', u'deleted_at': None, u'id': 626}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_swap', u'deleted_at': None, u'id': 627}, {u'instance_uuid': u'22bdea7f-0215-4810- 82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': None, u'key': u'instance_type_vcpu_weight', u'deleted_at': None, u'id': 628}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_root_gb', u'deleted_at': None, u'id': 629}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25. 000000', u'updated_at': None, u'value': u'6', u'key': u'instance_type_id', u'deleted_at': None, u'id': 630}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'6 c283423-2469-4fa5-996e-4b526c2e2729', u'key': u'image_ramdisk_id', u'deleted_at': None, u'id': 631}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'm1.nano', u'key': u'instance_type_name', u'deleted_at': None, u'id': 632}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_ephemeral_gb', u 'deleted_at': None, u'id': 633}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'1', u'key': u'instance_type_rxtx_factor', u'deleted_at': None, u'id': 634}, { u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'42', u'key': u'instance_type_flavorid', u'deleted_at': None, u'id': 635}, {u'instance_uuid': u'22bdea7f-0215-48 10-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'1', u'key': u'instance_type_vcpus', u'deleted_at': None, u'id': 636}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u' created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'key': u'image_base_image_ref', u'deleted_at': None, u'id': 637}], u'task_state': u'spawning', u'shutdown_terminate': False, u'cell_name': None, u' root_gb': 0, u'locked': False, u'name': u'instance-00000031', u'created_at': u'2013-05-23T05:26:25.000000', u'launch_index': 0, u'memory_mb': 64, u'vcpus': 1, u'image_ref': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'architecture': None, u'auto_disk_config': None, u'os_type': None, u'metadata': []} network_info=[({'injected': False, 'bridge': 'br-int', 'multi_host': False, 'bridge_interface': None, 'cidr_v6': None, 'cidr': u'10.0.0.0/24', 'vlan': None, 'id': u'aedb8668-e23a-463b-932a-7e95f0d005b1'}, {'vif_type': u'ovs', 'sh ould_create_bridge': False, 'vif_devname': u'tapd8aac4ec-e2', 'broadcast': '10.0.0.255', 'ips': [{'ip': u'10.0.0.78', 'netmask': '255.255.255.0', 'enabled': '1', 'gateway': u'10.0.0.1'}], 'mac': u'fa:16:3e:bb:02:2b', 'should_create_vlan': False, 'gateway': u'10.0. 0.1', 'ovs_interfaceid': u'd8aac4ec-e22b-4547-98d5-ce4c0c88ba2c', 'rxtx_cap': 0, 'label': u'private', 'qbh_params': None, 'vif_uuid': u'd8aac4ec-e22b-4547-98d5-ce4c0c88ba2c', 'dns': [], 'dhcp_server': u'10.0.0.2', 'qbg_params': None})] disk_info={'disk_bus': 'virt io', 'cdrom_bus': 'ide', 'mapping': {'disk': {'bus': 'virtio', 'type': 'disk', 'dev': 'vda'}, 'root': {'bus': 'virtio', 'type': 'disk', 'dev': 'vda'}}} image_meta={'status': u'active', 'name': u'tty-quantum', 'deleted': False, 'container_format': u'ami', 'created_ at': datetime.datetime(2013, 5, 23, 5, 14, 40, tzinfo=), 'disk_format': u'ami', 'updated_at': datetime.datetime(2013, 5, 23, 5, 14, 40, tzinfo=), 'id': u'431b6066-3bc8-4948-b234-6b54 55cd4a5b', 'owner': u'f612f4b5a5ff4e129cf18705fa4b9f53', 'min_ram': 0, 'checksum': u'bd0818c1e5bf8267f944f5667692e5fc', 'min_disk': 0, 'is_public': True, 'deleted_at': None, 'properties': {u'kernel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'ramdisk_id': u'6c2 83423-2469-4fa5-996e-4b526c2e2729'}, 'size': 25165824} rescue=Noneblock_device_info={'block_device_mapping': [], 'root_device_name': None, 'ephemerals': [], 'swap': None} to_xml /opt/stack/nova/nova/virt/libvirt/driver.py:2333 22bdea7f-0215-4810-82e6-1292fbbddadd 22bdea7f-0215-4810-82e6-1292fbbddadd /opt/stack/data/nova/instances/22bdea7f-0215-4810-82e6-1292fbbddadd/kernel /opt/stack/data/nova/instances/22bdea7f-0215-4810-82e6-1292fbbddadd/ramdisk 2013-05-22 22:32:05.351 DEBUG nova.virt.libvirt.driver [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] End to_xml instance={u'vm_state': u'building', u'availability_zone': None, u'terminated_at': None, u'ephemeral_gb': 0, u'instance_type_id': 6, u'user_data': None, u'vm_mode': None, u'deleted_at': None, u'reservation_id': u'r-oj8cm0i0', u'id': 49, u'security_groups': [], u'disable_terminate': False, u'root_device_name': None, u'user_id': u'3b36a6a76935439cbfa18de2417d61e2', u'uuid': u'22bdea7f-0215-4810-82e6-1292fbbdd add', u'default_swap_device': None, u'info_cache': {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': u'2013-05-23T05:30:18.000000', u'network_info': u'[{"ovs_interfaceid": "d8aac 4ec-e22b-4547-98d5-ce4c0c88ba2c", "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.78"}], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}, "dns": [], "routes": [], "cidr": "10 .0.0.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"}}], "meta": {"injected": false, "tenant_id": "3bb1aac4f1a547f48af504db0a6d64e2"}, "id": "aedb8668-e23a-463b-932a-7e95f0d005b1", "label": "private"}, "devname": "tapd8aac4ec- e2", "qbh_params": null, "meta": {}, "address": "fa:16:3e:bb:02:2b", "type": "ovs", "id": "d8aac4ec-e22b-4547-98d5-ce4c0c88ba2c", "qbg_params": null}]', u'deleted_at': None, u'id': 49}, u'hostname': u'vm-54', u'launched_on': u'rock', u'display_description': u'vm-5 4', u'key_data': None, u'deleted': 0, u'scheduled_at': u'2013-05-23T05:26:31.000000', u'power_state': 0, u'default_ephemeral_device': None, u'progress': 0, u'project_id': u'3bb1aac4f1a547f48af504db0a6d64e2', u'launched_at': None, u'config_drive': u'', u'node': u'r ock.plumgrid.com', u'ramdisk_id': u'6c283423-2469-4fa5-996e-4b526c2e2729', u'access_ip_v6': None, u'access_ip_v4': None, u'kernel_id': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'key_name': None, u'updated_at': u'2013-05-23T05:30:52.158725', u'host': u'rock', u'dis play_name': u'vm-54', u'system_metadata': [{u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'6321291c-bad5-4e3f-b8ee-808820bc8c74', u'key': u'image_kernel_id', u'deleted_at': None, u'id': 625}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'64', u'key': u'instance_type_memory_mb', u'deleted_at': None, u'id': 626}, { u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_swap', u'deleted_at': None, u'id': 627}, {u'instance_uuid': u'22bdea7f-0215-4810-82 e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': None, u'key': u'instance_type_vcpu_weight', u'deleted_at': None, u'id': 628}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u 'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_root_gb', u'deleted_at': None, u'id': 629}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.00 0000', u'updated_at': None, u'value': u'6', u'key': u'instance_type_id', u'deleted_at': None, u'id': 630}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'6c2 83423-2469-4fa5-996e-4b526c2e2729', u'key': u'image_ramdisk_id', u'deleted_at': None, u'id': 631}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'm1.nano', u 'key': u'instance_type_name', u'deleted_at': None, u'id': 632}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_ephemeral_gb', u'd eleted_at': None, u'id': 633}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'1', u'key': u'instance_type_rxtx_factor', u'deleted_at': None, u'id': 634}, {u' instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'42', u'key': u'instance_type_flavorid', u'deleted_at': None, u'id': 635}, {u'instance_uuid': u'22bdea7f-0215-4810 -82e6-1292fbbddadd', u'deleted': 0, u'created_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'1', u'key': u'instance_type_vcpus', u'deleted_at': None, u'id': 636}, {u'instance_uuid': u'22bdea7f-0215-4810-82e6-1292fbbddadd', u'deleted': 0, u'cr eated_at': u'2013-05-23T05:26:25.000000', u'updated_at': None, u'value': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'key': u'image_base_image_ref', u'deleted_at': None, u'id': 637}], u'task_state': u'spawning', u'shutdown_terminate': False, u'cell_name': None, u'ro ot_gb': 0, u'locked': False, u'name': u'instance-00000031', u'created_at': u'2013-05-23T05:26:25.000000', u'launch_index': 0, u'memory_mb': 64, u'vcpus': 1, u'image_ref': u'431b6066-3bc8-4948-b234-6b5455cd4a5b', u'architecture': None, u'auto_disk_config': None, u' os_type': None, u'metadata': []} xml= 22bdea7f-0215-4810-82e6-1292fbbddadd 22bdea7f-0215-4810-82e6-1292fbbddadd /opt/stack/data/nova/instances/22bdea7f-0215-4810-82e6-1292fbbddadd/kernel /opt/stack/data/nova/instances/22bdea7f-0215-4810-82e6-1292fbbddadd/ramdisk 2013-05-22 22:32:13.218 DEBUG nova.utils [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl -- --may-exist add-port br-int qvod8aac4ec-e2 -- set Interface qvod8aac4ec-e2 external-ids: iface-id=d8aac4ec-e22b-4547-98d5-ce4c0c88ba2c external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:bb:02:2b external-ids:vm-uuid=22bdea7f-0215-4810-82e6-1292fbbddadd execute /opt/stack/nova/nova/utils.py:208 2013-05-22 22:32:20.955 26460 INFO nova.compute.manager [-] Lifecycle event 0 on VM 22bdea7f-0215-4810-82e6-1292fbbddadd 2013-05-22 22:32:21.154 26460 INFO nova.compute.manager [-] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] During sync_power_state the instance has a pending task. Skip. 2013-05-22 22:32:21.600 DEBUG nova.virt.libvirt.driver [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Instance is running spawn /opt/stack/nova/nova/virt/libvirt/driver.py:1529 2013-05-22 22:32:23.515 26460 INFO nova.virt.libvirt.driver [-] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Instance spawned successfully. 2013-05-22 22:32:23.517 DEBUG nova.compute.manager [req-597f6296-0a89-4f67-972c-95d3c60883b0 demo demo] [instance: 22bdea7f-0215-4810-82e6-1292fbbddadd] Checking state _get_power_state /opt/stack/nova/nova/compute/manager.py:616 I dont see where the problem could be but in my set-up it seems that the issue is related to the Quantum DB Time out, any extra ideas for testing? Thanks, Edgar