Mirantis OpenStack

Nova Tempest test test_server_actions_resize_server_revert failed

Bug #1405658 reported by Alexander Gubanov on 2014-12-25

This bug affects 1 person

	Status	Importance	Assigned to	Milestone
Mirantis OpenStack	Fix Released	Medium	Eugeniya Kudryashova	Mirantis OpenStack 6.0-updates
6.0.x	Won't Fix	Medium	Eugeniya Kudryashova	Mirantis OpenStack 6.0-updates
6.1.x	Fix Released	Medium	Eugeniya Kudryashova	Mirantis OpenStack 6.1

Bug Description

Deployment:

ubuntu / net neutron vlan / 3 controller / 2 compute / ceph

[root@nailgun mos-scale]# fuel --f
api: '1.0'
astute_sha: 16b252d93be6aaa73030b8100cf8c5ca6a970a91
auth_required: true
build_id: 2014-12-18_01-32-01
build_number: '56'
feature_groups:
- mirantis
fuellib_sha: 73332192a257ea02c40a39885c502ad1ebdf3eda
fuelmain_sha: 45caacadb878abfbd9d60e134d72229698b469c9
nailgun_sha: 5f91157daa6798ff522ca9f6d34e7e135f150a90
ostf_sha: a9afb68710d809570460c29d6c3293219d3624d4
production: docker
release: '6.0'
release_versions:
  2014.2-6.0:
    VERSION:
      api: '1.0'
      astute_sha: 16b252d93be6aaa73030b8100cf8c5ca6a970a91
      build_id: 2014-12-18_01-32-01
      build_number: '56'
      feature_groups:
      - mirantis
      fuellib_sha: 73332192a257ea02c40a39885c502ad1ebdf3eda
      fuelmain_sha: 45caacadb878abfbd9d60e134d72229698b469c9
      nailgun_sha: 5f91157daa6798ff522ca9f6d34e7e135f150a90
      ostf_sha: a9afb68710d809570460c29d6c3293219d3624d4
      production: docker
      release: '6.0'

Steps to reproduce:

tempest tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_resize_server_revert

Result:

Test fail with the exception

Traceback (most recent call last):
_StringException: pythonlogging:'': {{{
2014-12-25 15:31:55,062 21996 ERROR [tempest.api.compute.base] Server a93e6533-b624-4e79-98e0-40c726f1e02e failed to build and is in ERROR status
Details: {u'message': u'internal error: early end of file from monitor: possible problem:\nqemu-system-x86_64: -drive file=rbd:compute/a93e6533-b624-4e79-98e0-40c726f1e02e_disk:id=compute:key=AQARGJxUYNGzEBAA/jHo/kj9BXU1N3+HF8UQ3w==:auth_supported=cephx\\;none:mon_host=192.168.0.3', u'code': 500, u'created': u'2014-12-25T15:31:52Z'}
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base Traceback (most recent call last):
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base File "/opt/stack/tempest/tempest/api/compute/base.py", line 136, in server_check_teardown
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base 'ACTIVE')
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base File "/opt/stack/tempest/tempest/services/compute/json/servers_client.py", line 183, in wait_for_server_status
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base ready_wait=ready_wait)
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base File "/opt/stack/tempest/tempest/common/waiters.py", line 77, in wait_for_server_status
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base server_id=server_id)
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base BuildErrorException: Server a93e6533-b624-4e79-98e0-40c726f1e02e failed to build and is in ERROR status
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base Details: {u'message': u'internal error: early end of file from monitor: possible problem:\nqemu-system-x86_64: -drive file=rbd:compute/a93e6533-b624-4e79-98e0-40c726f1e02e_disk:id=compute:key=AQARGJxUYNGzEBAA/jHo/kj9BXU1N3+HF8UQ3w==:auth_supported=cephx\\;none:mon_host=192.168.0.3', u'code': 500, u'created': u'2014-12-25T15:31:52Z'}
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base
}}}

Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/api/compute/servers/test_server_actions.py", line 240, in test_resize_server_revert
    self.client.wait_for_server_status(self.server_id, 'ACTIVE')
  File "/opt/stack/tempest/tempest/services/compute/json/servers_client.py", line 183, in wait_for_server_status
    ready_wait=ready_wait)
  File "/opt/stack/tempest/tempest/common/waiters.py", line 77, in wait_for_server_status
    server_id=server_id)
BuildErrorException: Server a93e6533-b624-4e79-98e0-40c726f1e02e failed to build and is in ERROR status
Details: {u'message': u'internal error: early end of file from monitor: possible problem:\nqemu-system-x86_64: -drive file=rbd:compute/a93e6533-b624-4e79-98e0-40c726f1e02e_disk:id=compute:key=AQARGJxUYNGzEBAA/jHo/kj9BXU1N3+HF8UQ3w==:auth_supported=cephx\\;none:mon_host=192.168.0.3', u'code': 500, u'created': u'2014-12-25T15:31:52Z'}
Traceback (most recent call last):
_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
2014-12-25 15:31:55,062 21996 ERROR [tempest.api.compute.base] Server a93e6533-b624-4e79-98e0-40c726f1e02e failed to build and is in ERROR status
Details: {u'message': u'internal error: early end of file from monitor: possible problem:\nqemu-system-x86_64: -drive file=rbd:compute/a93e6533-b624-4e79-98e0-40c726f1e02e_disk:id=compute:key=AQARGJxUYNGzEBAA/jHo/kj9BXU1N3+HF8UQ3w==:auth_supported=cephx\\;none:mon_host=192.168.0.3', u'code': 500, u'created': u'2014-12-25T15:31:52Z'}
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base Traceback (most recent call last):
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base File "/opt/stack/tempest/tempest/api/compute/base.py", line 136, in server_check_teardown
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base 'ACTIVE')
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base File "/opt/stack/tempest/tempest/services/compute/json/servers_client.py", line 183, in wait_for_server_status
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base ready_wait=ready_wait)
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base File "/opt/stack/tempest/tempest/common/waiters.py", line 77, in wait_for_server_status
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base server_id=server_id)
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base BuildErrorException: Server a93e6533-b624-4e79-98e0-40c726f1e02e failed to build and is in ERROR status
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base Details: {u'message': u'internal error: early end of file from monitor: possible problem:\nqemu-system-x86_64: -drive file=rbd:compute/a93e6533-b624-4e79-98e0-40c726f1e02e_disk:id=compute:key=AQARGJxUYNGzEBAA/jHo/kj9BXU1N3+HF8UQ3w==:auth_supported=cephx\\;none:mon_host=192.168.0.3', u'code': 500, u'created': u'2014-12-25T15:31:52Z'}
2014-12-25 15:31:55.062 21996 TRACE tempest.api.compute.base
}}}

traceback-1: {{{
Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/api/compute/servers/test_server_actions.py", line 51, in tearDown
    self.server_check_teardown()
  File "/opt/stack/tempest/tempest/api/compute/base.py", line 140, in server_check_teardown
    cls.servers_client.wait_for_server_termination(cls.server_id)
  File "/opt/stack/tempest/tempest/services/compute/json/servers_client.py", line 196, in wait_for_server_termination
    raise exceptions.BuildErrorException(server_id=server_id)
BuildErrorException: Server a93e6533-b624-4e79-98e0-40c726f1e02e failed to build and is in ERROR status
}}}

Traceback (most recent call last):
_StringException: Empty attachments:
stderr
stdout

I can provide diagnostic snaphot ( 84 Mb )

Tags:

Timur Nurlygayanov (tnurlygayanov) on 2014-12-25

tags:

added: tempest

Revision history for this message

Timur Nurlygayanov (tnurlygayanov) wrote on 2014-12-25:

Snapshot (90Mb): https://copy.com/tGUgUS3SfAKnKKSe

Dmitry Mescheryakov (dmitrymex) on 2014-12-26

Changed in mos:
importance:	Undecided → Medium
assignee:	nobody → MOS Nova (mos-nova)

Revision history for this message

Roman Podoliaka (rpodolyaka) wrote on 2014-12-29:

The problem is that during the revert of the resize, instance disks are destroyed here - https://github.com/openstack/nova/blob/a7c105aadb97fb411a5e46646a42927df4fbe5a9/nova/compute/manager.py#L3551-L3552

When Ceph is used as a backend for ephemeral disks, the corresponding object will be removed from the pool on destroy() and apparently a new qemu process will fail to start due to a missing disk image.

Revision history for this message

Eugeniya Kudryashova (ekudryashova) wrote on 2015-02-17:

This bug is already fixed in upstream, fix is merged in kilo: https://review.openstack.org/#/c/139693/

But fix is broken, so we can't merge backport to juno until master would be fixed. Fix for master now is on review here: https://review.openstack.org/#/c/154761/2

So we are blocked to merge backport to juno, and should wait for this stuff to be merged.

Revision history for this message

Yaroslav Lobankov (ylobankov) wrote on 2015-02-19:

Download full text (22.3 KiB)

VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.0.1"
  api: "1.0"
  build_number: "97"
  build_id: "2015-02-18_20-49-44"
  astute_sha: "f7cda2171b0b677dfaeb59693d980a2d3ee4c3e0"
  fuellib_sha: "faf0a06933fb816a8baf55f208144ea286cc5856"
  ostf_sha: "3b57985d4d2155510894a1f6d03b478b201f7780"
  nailgun_sha: "4eda56b68851e5bf26feedee8ecbdf338a45cc72"
  fuelmain_sha: "c799e3a6d88289e58db764a6be7910aab7da3149"

I have NOT reproduced this issue on
ENVIRONMENT:
HA mode, CentOS, Neutron with GRE segmentation, Cinder LVM, 1 controller, 1 (compute + cinder)

I also have NOT reproduced this issue on
ENVIRONMENT:
HA mode, CentOS, Neutron with GRE segmentation, Ceph RBD for images, volumes, Ceph RadosGW for objects, 1 controller, 1 (compute + ceph)

But I have reproduced this issue on
ENVIRONMENT:
HA mode, CentOS, Neutron with GRE segmentation, Ceph RBD for images, volumes, EPHEMERAL VOLUMES, Ceph RadosGW for objects, 1 controller, 1 (compute + ceph)

It looks like the problem is related to using Ceph RBD for ephemeral volumes. In compute.log I have seen the following error:

I have NOT reproduced this issue on 
ENVIRONMENT:
HA mode, CentOS, Neutron with GRE segmentation, Cinder LVM, 1 controller, 1 (compute + cinder)

I also have NOT reproduced this issue on
ENVIRONMENT:
HA mode, CentOS, Neutron with GRE segmentation, Ceph RBD for images, volumes, Ceph RadosGW for objects, 1 controller, 1 (compute + ceph)

It looks like the problem is related to using Ceph RBD for ephemeral volumes. In compute.log I have seen the following error:

2015-02-19 17:02:09.573 20535 ERROR nova.virt.libvirt.driver [req-987aa887-9e48-4985-97e3-f9ff851255ea None] Error launching a defined domain with XML: <domain type='kvm'>
  <name>instance-00000003</name>
  <uuid>7ee97c46-69e4-40ca-a41d-876a6faa68bc</uuid>
  <metadata>
    <nova:instance xmlns:nova="http://openstack.org/xmlns/libvirt/nova/1.0">
      <nova:package version="2014.2-fuel6.0.1.mira20"/>
      <nova:name>ServerActionsTestJSON-instance-1146312509</nova:name>
      <nova:creationTime>2015-02-19 17:02:08</nova:creationTime>
      <nova:flavor name="m1.nano">
        <nova:memory>64</nova:memory>
        <nova:disk>0</nova:disk>
        <nova:swap>0</nova:swap>
        <nova:ephemeral>0</nova:ephemeral>
        <nova:vcpus>1</nova:vcpus>
      </nova:flavor>
      <nova:owner>
        <nova:user uuid="8d808e3a0cef4e27afdeb73f37116872">ServerActionsTestJSON-2098800342</nova:user>
        <nova:project uuid="7c79a9d0484744dcbf98b174d91c59b3">ServerActionsTestJSON-1650317639</nova:project>
      </nova:owner>
      <nova:root type="image" uuid="ee54c1d3-5a84-4131-b45f-352c37850a5e"/>
    </nova:instance>
  </metadata>
  <memory unit='KiB'>65536</memory>
  <currentMemory unit='KiB'>65536</currentMemory>
  <vcpu placement='static' cpuset='0-7'>1</vcpu>
    <sysinfo type='smbios'>
      <system>
        <entry name='manufacturer'>Red Hat Inc.</entry>
        <entry name='product'>OpenStack Nova</entry>
        <entry name='version'>2014.2-fuel6.0.1.mira20</entry>
        <entry name='serial'>bd073957-5927-4733-a6c8-9ac8d07c9c04</entry>
        <entry name='uuid'>7ee97c46-69e4-40ca-a41d-876a6faa68bc</entry>
      </system>
    </sysinfo>
  <os>
    <type arch='x86_64' machine='pc-i440fx-2.0'>hvm</type>
    <boot dev='hd'/>
    <smbios mode='sysinfo'/>
  </os>
  <features>
    <acpi/>
    <apic/>
  </features>
  <cpu mode='host-model'>
    <model fallback='allow'/>
    <topology sockets='1' cores='1' threads='1'/>
  </cpu>
  <clock offset='utc'>
    <timer name='pit' tickpolicy='delay'/>
    <timer name='rtc' tickpolicy='catchup'/>
    <timer name='hpet' present='no'/>
  </clock>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>restart</on_reboot>
  <on_crash>destroy</on_crash>
  <devices>
    <emulator>/usr/bin/qemu-kvm</emulator>
    <disk type='network' device='disk'>
      <driver name='qemu' type='raw' cache='none'/>
      <auth username='compute'>
        <secret type='ceph' uuid='a5d0dd94-57c4-ae55-ffe0-7e3732a24455'/>
      </auth>
      <source protocol='rbd' name='compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk'>
        <host name='192.168.0.4' port='6789'/>
      </source>
      <target dev='vda' bus='virtio'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>
    </disk>
    <controller type='usb' index='0'>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x2'/>
    </controller>
    <controller type='pci' index='0' model='pci-root'/>
    <interface type='bridge'>
      <mac address='fa:16:3e:0b:01:44'/>
      <source bridge='qbrd8557ad0-2c'/>
      <target dev='tapd8557ad0-2c'/>
      <model type='virtio'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>
    </interface>
    <serial type='file'>
      <source path='/var/lib/nova/instances/7ee97c46-69e4-40ca-a41d-876a6faa68bc/console.log'/>
      <target port='0'/>
    </serial>
    <serial type='pty'>
      <target port='1'/>
    </serial>
    <console type='file'>
      <source path='/var/lib/nova/instances/7ee97c46-69e4-40ca-a41d-876a6faa68bc/console.log'/>
      <target type='serial' port='0'/>
    </console>
    <input type='tablet' bus='usb'/>
    <input type='mouse' bus='ps2'/>
    <input type='keyboard' bus='ps2'/>
    <graphics type='vnc' port='-1' autoport='yes' listen='0.0.0.0' keymap='en-us'>
      <listen type='address' address='0.0.0.0'/>
    </graphics>
    <video>
      <model type='cirrus' vram='9216' heads='1'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>
    </video>
    <memballoon model='virtio'>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x0'/>
      <stats period='10'/>
    </memballoon>
  </devices>
</domain>

2015-02-19 17:02:09.574 20535 ERROR nova.compute.manager [req-987aa887-9e48-4985-97e3-f9ff851255ea None] [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc] Setting instance vm_state to ERROR
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc] Traceback (most recent call last):
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 6088, in _error_out_instance_on_exception
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     yield
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3558, in finish_revert_resize
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     block_device_info, power_on)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 6098, in finish_revert_migration
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     block_device_info, power_on)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 4424, in _create_domain_and_network
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     power_on=power_on)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 4348, in _create_domain
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     LOG.error(err)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     six.reraise(self.type_, self.value, self.tb)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 4339, in _create_domain
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     domain.createWithFlags(launch_flags)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 183, in doit
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     result = proxy_call(self._autowrap, f, *args, **kwargs)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 141, in proxy_call
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     rv = execute(f, *args, **kwargs)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 122, in execute
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     six.reraise(c, e, tb)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 80, in tworker
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     rv = meth(*args, **kwargs)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 947, in createWithFlags
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc]     if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc] libvirtError: internal error: process exited while connecting to monitor: 2015-02-19T17:02:09.410549Z qemu-system-x86_64: -drive file=rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789,if=none,id=drive-virtio-disk0,format=raw,cache=none: error reading header from 7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc] 2015-02-19T17:02:09.413068Z qemu-system-x86_64: -drive file=rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789,if=none,id=drive-virtio-disk0,format=raw,cache=none: could not open disk image rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789: Could not open 'rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192
2015-02-19 17:02:09.574 20535 TRACE nova.compute.manager [instance: 7ee97c46-69e4-40ca-a41d-876a6faa68bc] 
2015-02-19 17:02:09.666 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Created new semaphore "compute_resources" internal_lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:206
2015-02-19 17:02:09.667 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Acquired semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:229
2015-02-19 17:02:09.667 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Got semaphore / lock "update_usage" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:271
2015-02-19 17:02:09.697 20535 INFO nova.scheduler.client.report [req-987aa887-9e48-4985-97e3-f9ff851255ea None] Compute_service record updated for ('node-5.domain.tld', 'node-5.domain.tld')
2015-02-19 17:02:09.698 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Releasing semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:238
2015-02-19 17:02:09.698 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Semaphore / lock released "update_usage" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:275
2015-02-19 17:02:09.792 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Created new semaphore "compute_resources" internal_lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:206
2015-02-19 17:02:09.793 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Acquired semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:229
2015-02-19 17:02:09.793 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Got semaphore / lock "update_usage" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:271
2015-02-19 17:02:09.821 20535 INFO nova.scheduler.client.report [req-987aa887-9e48-4985-97e3-f9ff851255ea None] Compute_service record updated for ('node-5.domain.tld', 'node-5.domain.tld')
2015-02-19 17:02:09.822 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Releasing semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:238
2015-02-19 17:02:09.822 20535 DEBUG nova.openstack.common.lockutils [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Semaphore / lock released "update_usage" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:275
2015-02-19 17:02:09.824 20535 ERROR oslo.messaging.rpc.dispatcher [req-987aa887-9e48-4985-97e3-f9ff851255ea ] Exception during message handling: internal error: process exited while connecting to monitor: 2015-02-19T17:02:09.410549Z qemu-system-x86_64: -drive file=rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789,if=none,id=drive-virtio-disk0,format=raw,cache=none: error reading header from 7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk
2015-02-19T17:02:09.413068Z qemu-system-x86_64: -drive file=rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789,if=none,id=drive-virtio-disk0,format=raw,cache=none: could not open disk image rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789: Could not open 'rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 137, in _dispatch_and_reply
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 180, in _dispatch
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 126, in _do_dispatch
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     payload)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 298, in decorated_function
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     pass
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 284, in decorated_function
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 348, in decorated_function
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 326, in decorated_function
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     kwargs['instance'], e, sys.exc_info())
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 314, in decorated_function
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3558, in finish_revert_resize
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     block_device_info, power_on)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 6098, in finish_revert_migration
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     block_device_info, power_on)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 4424, in _create_domain_and_network
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     power_on=power_on)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 4348, in _create_domain
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     LOG.error(err)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 4339, in _create_domain
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     domain.createWithFlags(launch_flags)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 183, in doit
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     result = proxy_call(self._autowrap, f, *args, **kwargs)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 141, in proxy_call
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     rv = execute(f, *args, **kwargs)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 122, in execute
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     six.reraise(c, e, tb)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 80, in tworker
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     rv = meth(*args, **kwargs)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 947, in createWithFlags
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher     if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher libvirtError: internal error: process exited while connecting to monitor: 2015-02-19T17:02:09.410549Z qemu-system-x86_64: -drive file=rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789,if=none,id=drive-virtio-disk0,format=raw,cache=none: error reading header from 7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher 2015-02-19T17:02:09.413068Z qemu-system-x86_64: -drive file=rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789,if=none,id=drive-virtio-disk0,format=raw,cache=none: could not open disk image rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192.168.0.4\:6789: Could not open 'rbd:compute/7ee97c46-69e4-40ca-a41d-876a6faa68bc_disk:id=compute:key=AQDLEeZUgPyMFBAA/QR/PiWutnCDl6XbneeoFg==:auth_supported=cephx\;none:mon_host=192
2015-02-19 17:02:09.824 20535 TRACE oslo.messaging.rpc.dispatcher

Revision history for this message

Yaroslav Lobankov (ylobankov) wrote on 2015-02-19:

Error http://paste.openstack.org/show/177757/

Revision history for this message

Roman Podoliaka (rpodolyaka) wrote on 2015-02-23:

Not enough priority to be backported to 6.0.1

Revision history for this message

Yaroslav Lobankov (ylobankov) wrote on 2015-04-23:

Verified on
VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.1"
  openstack_version: "2014.2.2-6.1"
  api: "1.0"
  build_number: "338"
  build_id: "2015-04-22_22-54-31"
  nailgun_sha: "4972120d5a5d41efe9be2d10b81329adf3258a78"
  python-fuelclient_sha: "2b311b3b82a1e2df1dc3484a0f37e282273cd988"
  astute_sha: "5be3506e6a4f8b7f0a858db2e162dabcc07347df"
  fuel-library_sha: "9b26cb98e7ceb905fe85b744eee2f808f7e4737b"
  fuel-ostf_sha: "dcda5a869d1780efc265b6f6b7b8c14c8324a68b"
  fuelmain_sha: "2f8be90209e709810674f73abb02bb54a700ce5e"

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

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