OpenStack Compute (nova)

qemu-img receives 'None' as source image to snapshot

Bug #1034730 reported by Mauro S M Rodrigues on 2012-08-09

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	Medium	Eoghan Glynn	OpenStack Compute (nova) 2012.2 "folsom"

Bug Description

Hi!
I'm using devstack and I created the follow an instance associated with a 5gb volume, both of them created successfully (I have the logs if needed).
Then I tried to create a snapshot of my instance but this snapshot got queued 'forever' (it's still queued btw). Checking the logs, I found on nova-cpu log the follow trace (which I already reproduced 3 times following the steps above):

2012-08-08 20:28:31 AUDIT nova.compute.manager [req-7b1bb5b3-e70e-4088-b6d1-0946c24e6445 admin demo] [instance: 9cdf4843-54d1-497e-bd70-3f3157e8ca03] instance snapshotting
instance snapshotting
2012-08-08 20:28:38 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=31416) periodic_tasks /opt/stack/nova/nova/manager.py:170
Running periodic task ComputeManager._poll_unconfirmed_resizes
2012-08-08 20:28:40 DEBUG nova.utils [req-7b1bb5b3-e70e-4088-b6d1-0946c24e6445 admin demo] Running cmd (subprocess): sudo /usr/local/bin/nova-rootwrap /etc/nova/rootwrap.conf qemu
-img snapshot -c 1479c0152ae1453e96018275fc3c9197 None from (pid=31416) execute /opt/stack/nova/nova/utils.py:178
Running cmd (subprocess): sudo /usr/local/bin/nova-rootwrap /etc/nova/rootwrap.conf qemu-img snapshot -c 1479c0152ae1453e96018275fc3c9197 None
2012-08-08 20:28:40 DEBUG nova.utils [req-7b1bb5b3-e70e-4088-b6d1-0946c24e6445 admin demo] Result was 1 from (pid=31416) execute /opt/stack/nova/nova/utils.py:194
Result was 1
2012-08-08 20:28:40 ERROR nova.openstack.common.rpc.amqp [-] Exception during message handling
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 275, in _process_data
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 117, in wrapped
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 92, in wrapped
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 210, in decorated_function
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp instance_uuid, e, sys.exc_info())
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 199, in decorated_function
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 1118, in snapshot_instance
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp self.driver.snapshot(context, instance, image_id)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 117, in wrapped
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 92, in wrapped
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 798, in snapshot
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp libvirt_utils.create_snapshot(disk_path, snapshot_name)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/utils.py", line 308, in create_snapshot
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp execute(*qemu_img_cmd, run_as_root=True)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/utils.py", line 54, in execute
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return utils.execute(*args, **kwargs)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/utils.py", line 201, in execute
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp cmd=' '.join(cmd))
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp ProcessExecutionError: Unexpected error while running command.
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Command: sudo /usr/local/bin/nova-rootwrap /etc/nova/rootwrap.conf qemu-img snapshot -c 1479c0152ae1453e96018275fc3c9197 None
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Exit code: 1
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Stdout: ''
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Stderr: "qemu-img: Could not open 'None': No such file or directory\n"
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp
Exception during message handling
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 275, in _process_data
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 117, in wrapped
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 92, in wrapped
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 210, in decorated_function
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp instance_uuid, e, sys.exc_info())
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 199, in decorated_function
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 1118, in snapshot_instance
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp self.driver.snapshot(context, instance, image_id)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 117, in wrapped
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 92, in wrapped
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 798, in snapshot
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp libvirt_utils.create_snapshot(disk_path, snapshot_name)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/utils.py", line 308, in create_snapshot
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp execute(*qemu_img_cmd, run_as_root=True)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/utils.py", line 54, in execute
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp return utils.execute(*args, **kwargs)
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/utils.py", line 201, in execute
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp cmd=' '.join(cmd))
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp ProcessExecutionError: Unexpected error while running command.
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Command: sudo /usr/local/bin/nova-rootwrap /etc/nova/rootwrap.conf qemu-img snapshot -c 1479c0152ae1453e96018275fc3c9197 None
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Exit code: 1
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Stdout: ''
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp Stderr: "qemu-img: Could not open 'None': No such file or directory\n"
2012-08-08 20:28:40 TRACE nova.openstack.common.rpc.amqp

It's clear in the logs that the image id to be snapshoted was lost somehow, I'm trying to figure out where, but it's late and more heads are better than one.

Regards,

Mauro Rodrigues

Tags:

Revision history for this message

Mauro S M Rodrigues (maurorodrigues) wrote on 2012-08-09:

A little more complete version of the log file Edit (30.3 KiB, text/plain)

Revision history for this message

Mauro S M Rodrigues (maurorodrigues) wrote on 2012-08-10:

Investigating for a little while I realized that the problem just happens with instances with a volume attached.

Specifically the snapshot of an instance waits for the disk's file source (you can find that in /opt/stack/nova/nova/virt/libvirt/driver.py", line 787: source = domain.find('devices/disk/source') and then looking for source.get('file')).

This information is gathered from a xml in /opt/stack/nova/instances/instance-<number>/libvirt.xml

When you don't attach a volume to instance during its creation the xml has the follow disk information:

The file attribute is present.

Although when attach the volume during instance creation:

The reference to the source now is dev=<value>, so the snapshot crashes when look for the file key on this xml.

Dan Prince (dan-prince) on 2012-08-24

Changed in nova:
milestone:	none → folsom-rc1
status:	New → Triaged
importance:	Undecided → Medium

Eoghan Glynn (eglynn) on 2012-09-06

Changed in nova:
assignee:	nobody → Eoghan Glynn (eglynn)

Eoghan Glynn (eglynn) on 2012-09-07

Changed in nova:
status:	Triaged → Confirmed

Revision history for this message

Eoghan Glynn (eglynn) wrote on 2012-09-07:

Hi Mauro,

Presumably by "attach the volume during instance creation", you mean a booted-from-volume instance?

Eoghan Glynn (eglynn) on 2012-09-07

Changed in nova:
status:	Confirmed → In Progress

Revision history for this message

Mauro S M Rodrigues (maurorodrigues) wrote on 2012-09-07:

exactly Eoghan!

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2012-09-07: Fix proposed to nova (master)

Fix proposed to branch: master
Review: https://review.openstack.org/12583

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2012-09-09: Fix merged to nova (master)

Reviewed: https://review.openstack.org/12583
Committed: http://github.com/openstack/nova/commit/c3476b5ca7ab5237d3cb8a84fcb7a3292237b764
Submitter: Jenkins
Branch: master

commit c3476b5ca7ab5237d3cb8a84fcb7a3292237b764
Author: Eoghan Glynn <email address hidden>
Date: Fri Sep 7 12:45:27 2012 +0000

Create image of volume-backed instance via native API

Fixes bug 1034730.

Avoids 'qemu-img snapshot' failure when native API create_image action
is applied to a volume-backed instance.

    Applies the same logic as is used to create a placeholder image from
    a volume-backed instance via the EC2 API CreateImage operation, with
    the now-common code refactored into the ComputeAPI class.

Change-Id: I624584ae9adbf30629f0e814d340da6b9e6e59bd