1092900 – Starting instances fails

Bug 1092900 - Starting instances fails

Summary: Starting instances fails

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	openstack-nova
Sub Component:
Version:	22
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	Alan Pevec (Fedora)
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Duplicates (1):	1091873 (view as bug list)
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2014-04-30 08:19 UTC by Matthias Runge
Modified:	2016-06-13 07:20 UTC (History)
CC List:	16 users (show)
Fixed In Version:	python-nova-2014.1.1-1.fc20.noarch
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2016-06-13 07:20:40 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
nova-api.log (87.51 KB, text/x-log) 2014-04-30 11:06 UTC, Matthias Runge	no flags	Details
openvswitch-agent.log (10.18 KB, text/x-log) 2014-04-30 11:07 UTC, Matthias Runge	no flags	Details
neutron-server.log (222.72 KB, text/x-log) 2014-04-30 11:09 UTC, Matthias Runge	no flags	Details
View All

Description Matthias Runge 2014-04-30 08:19:28 UTC

Description of problem:
after provisioning all in one, icehouse release

[root@sofja ~(keystone_admin)]# nova boot --flavor m1.tiny --image cirros mycirr
+--------------------------------------+-----------------------------------------------+
| Property                             | Value                                         |
+--------------------------------------+-----------------------------------------------+
| OS-DCF:diskConfig                    | MANUAL                                        |
| OS-EXT-AZ:availability_zone          | nova                                          |
| OS-EXT-SRV-ATTR:host                 | -                                             |
| OS-EXT-SRV-ATTR:hypervisor_hostname  | -                                             |
| OS-EXT-SRV-ATTR:instance_name        | instance-00000003                             |
| OS-EXT-STS:power_state               | 0                                             |
| OS-EXT-STS:task_state                | scheduling                                    |
| OS-EXT-STS:vm_state                  | building                                      |
| OS-SRV-USG:launched_at               | -                                             |
| OS-SRV-USG:terminated_at             | -                                             |
| accessIPv4                           |                                               |
| accessIPv6                           |                                               |
| adminPass                            | Q3sotWSsmrAS                                  |
| config_drive                         |                                               |
| created                              | 2014-04-30T08:08:04Z                          |
| flavor                               | m1.tiny (1)                                   |
| hostId                               |                                               |
| id                                   | 717565aa-3ae8-4e9d-a1f0-9c328d2f2f82          |
| image                                | cirros (725bbee1-1a92-48d8-9dd6-d3bae934b56c) |
| key_name                             | -                                             |
| metadata                             | {}                                            |
| name                                 | mycirr                                        |
| os-extended-volumes:volumes_attached | []                                            |
| progress                             | 0                                             |
| security_groups                      | default                                       |
| status                               | BUILD                                         |
| tenant_id                            | ec45f1eeb5d94eb785f4b0aeac327696              |
| updated                              | 2014-04-30T08:08:04Z                          |
| user_id                              | 7da61e12a39649baa80e658df8e09636              |
+--------------------------------------+-----------------------------------------------+
[root@sofja ~(keystone_admin)]# nova list
+--------------------------------------+--------+--------+------------+-------------+----------+
| ID                                   | Name   | Status | Task State | Power State | Networks |
+--------------------------------------+--------+--------+------------+-------------+----------+
| 717565aa-3ae8-4e9d-a1f0-9c328d2f2f82 | mycirr | ERROR  | -          | NOSTATE     |          |
+--------------------------------------+--------+--------+------------+-------------+----------+


nova compute log immediately shows:

2014-04-30 10:08:05.891 8554 TRACE oslo.messaging.rpc.dispatcher     v2_name)
2014-04-30 10:08:05.891 8554 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 1317, in delete_ovs_vif_port
2014-04-30 10:08:05.891 8554 TRACE oslo.messaging.rpc.dispatcher     _ovs_vsctl(['del-port', bridge, dev])
2014-04-30 10:08:05.891 8554 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 1302, in _ovs_vsctl
2014-04-30 10:08:05.891 8554 TRACE oslo.messaging.rpc.dispatcher     raise exception.AgentError(method=full_args)
2014-04-30 10:08:05.891 8554 TRACE oslo.messaging.rpc.dispatcher AgentError: Error during following call to agent: ['ovs-vsctl', '--timeout=120', 'del-port', 'br-int', u'qvo9829b9e5-09']
2014-04-30 10:08:05.891 8554 TRACE oslo.messaging.rpc.dispatcher 
2014-04-30 10:08:05.892 8554 ERROR oslo.messaging._drivers.common [-] Returning exception Error during following call to agent: ['ovs-vsctl', '--timeout=120', 'del-port', 'br-int', u'qvo9829b9e5-09'] to caller

Comment 1 Matthias Runge 2014-04-30 08:20:10 UTC

Seeing the ovs issue, I suspect, this bug should be a neutron bug, though.

Comment 2 Matthias Runge 2014-04-30 08:29:33 UTC

adding: selinux permissive, as there is https://bugzilla.redhat.com/show_bug.cgi?id=1044960

Comment 3 Matthias Runge 2014-04-30 09:00:19 UTC

full log: 2014-04-30 10:58:43.805 11677 INFO nova.compute.resource_tracker [-] Compute_service record updated for sofja.berg.ol:sofja.berg.ol
2014-04-30 10:59:08.725 11677 AUDIT nova.compute.manager [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Starting instance...
2014-04-30 10:59:08.822 11677 AUDIT nova.compute.claims [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Attempting claim: memory 512 MB, disk 1 GB, VCPUs 1
2014-04-30 10:59:08.822 11677 AUDIT nova.compute.claims [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Total memory: 7868 MB, used: 512.00 MB
2014-04-30 10:59:08.823 11677 AUDIT nova.compute.claims [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] memory limit: 11802.00 MB, free: 11290.00 MB
2014-04-30 10:59:08.823 11677 AUDIT nova.compute.claims [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Total disk: 68 GB, used: 0.00 GB
2014-04-30 10:59:08.823 11677 AUDIT nova.compute.claims [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] disk limit not specified, defaulting to unlimited
2014-04-30 10:59:08.823 11677 AUDIT nova.compute.claims [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Total CPUs: 4 VCPUs, used: 0.00 VCPUs
2014-04-30 10:59:08.823 11677 AUDIT nova.compute.claims [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] CPUs limit: 64.00 VCPUs, free: 64.00 VCPUs
2014-04-30 10:59:08.823 11677 AUDIT nova.compute.claims [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Claim successful
2014-04-30 10:59:09.288 11677 INFO nova.virt.libvirt.driver [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Creating image
2014-04-30 10:59:09.470 11677 ERROR nova.compute.manager [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Instance failed to spawn
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Traceback (most recent call last):
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1720, in _spawn
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     block_device_info)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2246, in spawn
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     admin_pass=admin_password)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2615, in _create_image
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     project_id=instance['project_id'])
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/imagebackend.py", line 192, in cache
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     *args, **kwargs)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/imagebackend.py", line 413, in create_image
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     copy_qcow2_image(base, self.path, size)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py", line 249, in inner
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     return f(*args, **kwargs)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/imagebackend.py", line 377, in copy_qcow2_image
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     libvirt_utils.create_cow_image(base, target)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/utils.py", line 205, in create_cow_image
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     execute(*cmd)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/utils.py", line 53, in execute
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     return utils.execute(*args, **kwargs)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/utils.py", line 164, in execute
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     return processutils.execute(*cmd, **kwargs)
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py", line 193, in execute
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     cmd=' '.join(cmd))
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] ProcessExecutionError: Unexpected error while running command.
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Command: qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/ef4899a65cd7022a670b571b44ac771245fd112d /var/lib/nova/instances/c04dac31-3614-44f8-a65f-d4c03bbae356/disk
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Exit code: -6
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Stdout: "Formatting '/var/lib/nova/instances/c04dac31-3614-44f8-a65f-d4c03bbae356/disk', fmt=qcow2 size=41126400 backing_file='/var/lib/nova/instances/_base/ef4899a65cd7022a670b571b44ac771245fd112d' encryption=off cluster_size=65536 lazy_refcounts=off \n"
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Stderr: 'qemu-img: Huh, first cluster in empty image is already in use?\n'
2014-04-30 10:59:09.470 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] 
2014-04-30 10:59:09.560 11677 AUDIT nova.compute.manager [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Terminating instance
2014-04-30 10:59:09.820 11677 ERROR nova.virt.libvirt.driver [-] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] During wait destroy, instance disappeared.
2014-04-30 10:59:09.886 11677 ERROR nova.network.linux_net [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] Unable to execute ['ovs-vsctl', '--timeout=120', 'del-port', 'br-int', u'qvofd3b5d65-7c']. Exception: Unexpected error while running command.
Command: sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 del-port br-int qvofd3b5d65-7c
Exit code: 1
Stdout: ''
Stderr: 'ovs-vsctl: no port named qvofd3b5d65-7c\n'
2014-04-30 10:59:10.014 11677 ERROR nova.compute.manager [req-7340505c-ef4f-48b9-bee0-0c8c1eb13bd4 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Error: Unexpected error while running command.
Command: qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/ef4899a65cd7022a670b571b44ac771245fd112d /var/lib/nova/instances/c04dac31-3614-44f8-a65f-d4c03bbae356/disk
Exit code: -6
Stdout: "Formatting '/var/lib/nova/instances/c04dac31-3614-44f8-a65f-d4c03bbae356/disk', fmt=qcow2 size=41126400 backing_file='/var/lib/nova/instances/_base/ef4899a65cd7022a670b571b44ac771245fd112d' encryption=off cluster_size=65536 lazy_refcounts=off \n"
Stderr: 'qemu-img: Huh, first cluster in empty image is already in use?\n'
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Traceback (most recent call last):
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1311, in _build_instance
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     set_access_ip=set_access_ip)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 399, in decorated_function
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     return function(self, context, *args, **kwargs)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1723, in _spawn
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     LOG.exception(_('Instance failed to spawn'), instance=instance)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     six.reraise(self.type_, self.value, self.tb)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1720, in _spawn
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     block_device_info)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2246, in spawn
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     admin_pass=admin_password)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2615, in _create_image
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     project_id=instance['project_id'])
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/imagebackend.py", line 192, in cache
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     *args, **kwargs)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/imagebackend.py", line 413, in create_image
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     copy_qcow2_image(base, self.path, size)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py", line 249, in inner
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     return f(*args, **kwargs)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/imagebackend.py", line 377, in copy_qcow2_image
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     libvirt_utils.create_cow_image(base, target)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/utils.py", line 205, in create_cow_image
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     execute(*cmd)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/utils.py", line 53, in execute
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     return utils.execute(*args, **kwargs)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/utils.py", line 164, in execute
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     return processutils.execute(*cmd, **kwargs)
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]   File "/usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py", line 193, in execute
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356]     cmd=' '.join(cmd))
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] ProcessExecutionError: Unexpected error while running command.
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Command: qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/ef4899a65cd7022a670b571b44ac771245fd112d /var/lib/nova/instances/c04dac31-3614-44f8-a65f-d4c03bbae356/disk
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Exit code: -6
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Stdout: "Formatting '/var/lib/nova/instances/c04dac31-3614-44f8-a65f-d4c03bbae356/disk', fmt=qcow2 size=41126400 backing_file='/var/lib/nova/instances/_base/ef4899a65cd7022a670b571b44ac771245fd112d' encryption=off cluster_size=65536 lazy_refcounts=off \n"
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] Stderr: 'qemu-img: Huh, first cluster in empty image is already in use?\n'
2014-04-30 10:59:10.014 11677 TRACE nova.compute.manager [instance: c04dac31-3614-44f8-a65f-d4c03bbae356] 
2014-04-30 10:59:10.230 11677 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: Error during following call to agent: ['ovs-vsctl', '--timeout=120', 'del-port', 'br-int', u'qvofd3b5d65-7c']
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/server.py", line 139, in inner
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     return func(*args, **kwargs)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/exception.py", line 88, in wrapped
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     payload)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/exception.py", line 71, in wrapped
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 280, in decorated_function
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     pass
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 266, in decorated_function
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 333, in decorated_function
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     function(self, context, *args, **kwargs)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 309, in decorated_function
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     e, sys.exc_info())
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 296, in decorated_function
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2075, in run_instance
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     do_run_instance()
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py", line 249, in inner
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     return f(*args, **kwargs)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2074, in do_run_instance
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     legacy_bdm_in_spec)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1207, in _run_instance
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     notify("error", fault=e)  # notify that build failed
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1191, in _run_instance
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     instance, image_meta, legacy_bdm_in_spec)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1355, in _build_instance
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     filter_properties, bdms, legacy_bdm_in_spec)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1401, in _reschedule_or_error
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     self._log_original_error(exc_info, instance_uuid)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1396, in _reschedule_or_error
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     bdms, requested_networks)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2125, in _shutdown_instance
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     requested_networks)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2115, in _shutdown_instance
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     block_device_info)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 953, in destroy
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     destroy_disks)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 989, in cleanup
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     self.unplug_vifs(instance, network_info)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 860, in unplug_vifs
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     self.vif_driver.unplug(instance, vif)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py", line 783, in unplug
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     self.unplug_ovs(instance, vif)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py", line 667, in unplug_ovs
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     self.unplug_ovs_hybrid(instance, vif)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py", line 661, in unplug_ovs_hybrid
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     v2_name)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 1317, in delete_ovs_vif_port
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     _ovs_vsctl(['del-port', bridge, dev])
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 1302, in _ovs_vsctl
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher     raise exception.AgentError(method=full_args)
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher AgentError: Error during following call to agent: ['ovs-vsctl', '--timeout=120', 'del-port', 'br-int', u'qvofd3b5d65-7c']
2014-04-30 10:59:10.230 11677 TRACE oslo.messaging.rpc.dispatcher 
2014-04-30 10:59:10.232 11677 ERROR oslo.messaging._drivers.common [-] Returning exception Error during following call to agent: ['ovs-vsctl', '--timeout=120', 'del-port', 'br-int', u'qvofd3b5d65-7c'] to caller
2014-04-30 10:59:10.232 11677 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/server.py", line 139, in inner\n    return func(*args, **kwargs)\n', '  File "/usr/lib/python2.7/site-packages/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.7/site-packages/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 280, in decorated_function\n    pass\n', '  File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 266, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 333, in decorated_function\n    function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 309, in decorated_function\n    e, sys.exc_info())\n', '  File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 296, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2075, in run_instance\n    do_run_instance()\n', '  File "/usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py", line 249, in inner\n    return f(*args, **kwargs)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2074, in do_run_instance\n    legacy_bdm_in_spec)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1207, in _run_instance\n    notify("error", fault=e)  # notify that build failed\n', '  File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1191, in _run_instance\n    instance, image_meta, legacy_bdm_in_spec)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1355, in _build_instance\n    filter_properties, bdms, legacy_bdm_in_spec)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1401, in _reschedule_or_error\n    self._log_original_error(exc_info, instance_uuid)\n', '  File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1396, in _reschedule_or_error\n    bdms, requested_networks)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2125, in _shutdown_instance\n    requested_networks)\n', '  File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2115, in _shutdown_instance\n    block_device_info)\n', '  File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 953, in destroy\n    destroy_disks)\n', '  File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 989, in cleanup\n    self.unplug_vifs(instance, network_info)\n', '  File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 860, in unplug_vifs\n    self.vif_driver.unplug(instance, vif)\n', '  File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py", line 783, in unplug\n    self.unplug_ovs(instance, vif)\n', '  File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py", line 667, in unplug_ovs\n    self.unplug_ovs_hybrid(instance, vif)\n', '  File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py", line 661, in unplug_ovs_hybrid\n    v2_name)\n', '  File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 1317, in delete_ovs_vif_port\n    _ovs_vsctl([\'del-port\', bridge, dev])\n', '  File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 1302, in _ovs_vsctl\n    raise exception.AgentError(method=full_args)\n', "AgentError: Error during following call to agent: ['ovs-vsctl', '--timeout=120', 'del-port', 'br-int', u'qvofd3b5d65-7c']\n"]

Comment 4 Matthias Runge 2014-04-30 09:44:32 UTC

The issue qemu-img failing is already solved https://bugzilla.redhat.com/show_bug.cgi?id=1092920

Created instances still remain in spawning state:

[root@sofja ~(keystone_admin)]# nova list
+--------------------------------------+--------+--------+------------+-------------+---------------------+
| ID                                   | Name   | Status | Task State | Power State | Networks            |
+--------------------------------------+--------+--------+------------+-------------+---------------------+
| a9bae2e8-3864-4737-84ae-44b90c7f656b | mycirr | BUILD  | spawning   | NOSTATE     | public=172.24.4.231 |
+--------------------------------------+--------+--------+------------+-------------+---------------------+
until 
2014-04-30 11:35:43.098 11677 WARNING nova.virt.libvirt.driver [req-3205434f-54c8-41a6-a3db-d2bb9c13c430 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] Timeout waiting for vif plugging callback for instance a9bae2e8-3864-4737-84ae-44b90c7f656b
2014-04-30 11:35:43.672 11677 INFO nova.virt.libvirt.driver [req-3205434f-54c8-41a6-a3db-d2bb9c13c430 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b] Deleting instance files /var/lib/nova/instances/a9bae2e8-3864-4737-84ae-44b90c7f656b
2014-04-30 11:35:43.672 11677 INFO nova.virt.libvirt.driver [req-3205434f-54c8-41a6-a3db-d2bb9c13c430 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b] Deletion of /var/lib/nova/instances/a9bae2e8-3864-4737-84ae-44b90c7f656b complete
2014-04-30 11:35:43.738 11677 ERROR nova.compute.manager [req-3205434f-54c8-41a6-a3db-d2bb9c13c430 e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b] Instance failed to spawn
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b] Traceback (most recent call last):
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1720, in _spawn
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b]     block_device_info)
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2253, in spawn
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b]     block_device_info)
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 3663, in _create_domain_and_network
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b]     raise exception.VirtualInterfaceCreateException()
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b] VirtualInterfaceCreateException: Virtual Interface creation failed
2014-04-30 11:35:43.738 11677 TRACE nova.compute.manager [instance: a9bae2e8-3864-4737-84ae-44b90c7f656b]

Comment 5 Matthias Runge 2014-04-30 09:52:16 UTC

ok, from neutron server log:
2014-04-30 11:34:51.977 14897 INFO neutron.wsgi [req-ccc6dc79-ac1e-43ae-9fbe-2a027c13b444 None] (14897) accepted ('127.0.0.1', 49783)

2014-04-30 11:34:51.979 14897 INFO neutron.wsgi [req-a98aa7db-6e44-4f87-9d5d-cd79e3cc5b31 None] 127.0.0.1 - - [30/Apr/2014 11:34:51] "GET //v2.0/extensions.json HTTP/1.1" 200 3625 0.001729

2014-04-30 11:35:45.753 14897 ERROR neutron.notifiers.nova [-] Failed to notify nova on events: [{'status': 'completed', 'tag': u'2818120c-f4e9-4381-bba3-f16274e945a8', 'name': 'network-vif-unplugged', 'server_u
uid': u'a9bae2e8-3864-4737-84ae-44b90c7f656b'}]
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova Traceback (most recent call last):
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova   File "/usr/lib/python2.7/site-packages/neutron/notifiers/nova.py", line 187, in send_events
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova     batched_events)
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova   File "/usr/lib/python2.7/site-packages/novaclient/v1_1/contrib/server_external_events.py", line 39, in create
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova     return_raw=True)
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova   File "/usr/lib/python2.7/site-packages/novaclient/base.py", line 152, in _create
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova     _resp, body = self.api.client.post(url, body=body)
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova   File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 286, in post
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova     return self._cs_request(url, 'POST', **kwargs)
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova   File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 260, in _cs_request
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova     **kwargs)
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova   File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 242, in _time_request
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova     resp, body = self.request(url, method, **kwargs)
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova   File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 236, in request
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova     raise exceptions.from_response(resp, body, url, method)
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova BadRequest: The server could not comply with the request since it is either malformed or otherwise incorrect. (HTTP 400)
2014-04-30 11:35:45.753 14897 TRACE neutron.notifiers.nova 
2014-04-30 11:35:54.557 14897 INFO neutron.wsgi [-] (14897) accepted ('127.0.0.1', 49803)


looks like a nova issue...

Comment 6 Matthias Runge 2014-04-30 09:54:50 UTC

and nova api log mentions: 
2014-04-30 11:53:58.139 6288 INFO nova.osapi_compute.wsgi.server [req-09b28a13-8082-4402-96db-dbf1822df43d e7d367faff8e49e59d7a3cd4e5884876 94ab05ec8b76413dbf58483ffd5d0ab5] 127.0.0.1 "GET /v2/94ab05ec8b76413dbf58483ffd5d0ab5/images/e9251a79-7e22-437b-8206-798e6c06cc1e HTTP/1.1" status: 200 len: 884 time: 0.0572050
2014-04-30 11:54:06.152 6288 ERROR nova.api.openstack.wsgi [-] Exception handling resource: multi() got an unexpected keyword argument 'body'
2014-04-30 11:54:06.152 6288 TRACE nova.api.openstack.wsgi Traceback (most recent call last):
2014-04-30 11:54:06.152 6288 TRACE nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 983, in _process_stack
2014-04-30 11:54:06.152 6288 TRACE nova.api.openstack.wsgi     action_result = self.dispatch(meth, request, action_args)
2014-04-30 11:54:06.152 6288 TRACE nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 1070, in dispatch
2014-04-30 11:54:06.152 6288 TRACE nova.api.openstack.wsgi     return method(req=request, **action_args)
2014-04-30 11:54:06.152 6288 TRACE nova.api.openstack.wsgi TypeError: multi() got an unexpected keyword argument 'body'
2014-04-30 11:54:06.152 6288 TRACE nova.api.openstack.wsgi 
2014-04-30 11:54:06.153 6288 INFO nova.osapi_compute.wsgi.server [-] 127.0.0.1 "POST /None/os-server-external-events HTTP/1.1" status: 400 len: 274 time: 0.0015261

Comment 7 Matthias Runge 2014-04-30 11:06:38 UTC

Created attachment 891115 [details]
nova-api.log

Comment 8 Matthias Runge 2014-04-30 11:07:28 UTC

Created attachment 891126 [details]
openvswitch-agent.log

Comment 9 Matthias Runge 2014-04-30 11:09:08 UTC

Created attachment 891127 [details]
neutron-server.log

Comment 10 Matthias Runge 2014-04-30 11:24:54 UTC

*** Bug 1091873 has been marked as a duplicate of this bug. ***

Comment 11 sagar 2014-04-30 11:45:49 UTC

when can we expect a fix for this ?

Comment 12 Matthias Runge 2014-04-30 11:58:32 UTC

I wonder if this is a duplicate of bug 1090605

Comment 13 Vladan Popovic 2014-06-30 15:21:01 UTC

Tried 3 instances (with selinux in permissive and enforcing mode) and they were booted successfully.
Version used: python-nova-2014.1.1-1.fc20.noarch

Comment 15 Fedora Admin XMLRPC Client 2014-09-03 13:38:37 UTC

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Comment 16 Fedora Admin XMLRPC Client 2014-09-03 13:41:14 UTC

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Comment 17 Fedora Admin XMLRPC Client 2014-09-11 08:36:58 UTC

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Comment 18 Jaroslav Reznik 2015-03-03 17:13:12 UTC

This bug appears to have been reported against 'rawhide' during the Fedora 22 development cycle.
Changing version to '22'.

More information and reason for this action is here:
https://fedoraproject.org/wiki/Fedora_Program_Management/HouseKeeping/Fedora22

Comment 19 Fedora Admin XMLRPC Client 2015-12-08 19:27:16 UTC

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Note You need to log in before you can comment on or make changes to this bug.