Bug 1018867

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

2013-10-14 14:28:54,663 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (pool-5-thread-44) Error code SNAPSHOT_FAILED and error message VDSGenericException: VDSErrorException: Failed to SnapshotVDS, error = Snapshot failed
...
2013-10-14 14:28:54,664 WARN  [org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand] (pool-5-thread-44) Wasnt able to live snapshot due to error: VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to SnapshotVDS, error = Snapshot failed (Failed with error SNAPSHOT_FAILED and code 48). VM will still be configured to the new created snapshot
...
2013-10-14 14:28:54,701 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-44) Correlation ID: null, Call Stack: org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to SnapshotVDS, error = Snapshot failed (Failed with error SNAPSHOT_FAILED and code 48)

Auditlog Message (Warning): Failed to create live snapshot 'Auto-generated for Live Storage Migration' for VM 'vm-tra-tra'. VM restart is recommended.

When a live snapshot fails for an unknown/unrecoverable reason (as in this case) the VM is no longer running on the leaf volume and many flows are not supported anymore, as for example a subsequent live snapshot and therefore live storage migration too.

In the future we can only try to have more cases handled gracefully but anyway with this architecture we'll always have some unrecoverable cases.

We'll tackle this on the vdsm side allowing a live snapshot also when the provided base volume is not the current active layer.

It actually turns out that maybe we can't cleanly address this on the vdsm side.

It seems to me that on live snapshot qemu-kvm is not capable of following one or multiple qcow2 layers between the new image and its base.

Regular live snapshot:

image1 <- qemu-kvm
image1 < image2 <- qemu-kvm

What we are trying to do here to fix the issue is:

image1 <- qemu-kvm
image1 < image2(empty) < image3 <-qemu-kvm

It actually turns out that qemu-kvm assumes that image3 is the direct descendant of image1 leaving image2 closed:

# lvs
...
  af0633b3-5367-4106-8108-702700b90d98 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-ao---- 128.00m
  d9fc0a47-61ca-4fae-a170-dea10a4e61ed 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-ao---- 128.00m
  ce9e7bd8-2715-43a4-871c-8cee20e46c39 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-a----- 128.00m
  6510f3a6-7914-46a5-99e9-ae107badf9a7 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-ao---- 128.00m
  7685c1c8-177d-4532-9ad4-c96c5e935043 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-a----- 128.00m
  d2ef66ea-2de7-4991-82e5-ad29c4e36861 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-ao---- 128.00m

(reorded from the base at the top and the leaf at the bottom)

As we see above trying to reproduce this issue (testing the fix) what happens is that both ce9e7bd8 and 7685c1c8 (empty volumes) are not kept open by the qemu process and as additional proof they can even be deactivated:

# lvchange -an /dev/864df2d0-b022-435f-a9d1-b7ac0bd766bb/{7685c1c8-177d-4532-9ad4-c96c5e935043,ce9e7bd8-2715-43a4-871c-8cee20e46c39}
# lvs
...
  af0633b3-5367-4106-8108-702700b90d98 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-ao---- 128.00m
  d9fc0a47-61ca-4fae-a170-dea10a4e61ed 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-ao---- 128.00m
  ce9e7bd8-2715-43a4-871c-8cee20e46c39 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi------- 128.00m
  6510f3a6-7914-46a5-99e9-ae107badf9a7 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-ao---- 128.00m
  7685c1c8-177d-4532-9ad4-c96c5e935043 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi------- 128.00m
  d2ef66ea-2de7-4991-82e5-ad29c4e36861 864df2d0-b022-435f-a9d1-b7ac0bd766bb -wi-ao---- 128.00m


It seems to me that if this is not going to be addressed in qemu and we still pick this direction we'll end up in some new corner cases, e.g. what if then the user want to live merge? ..it might fail or the result may might be unpredictable.

Kevin any insight?

This will either require changes in qemu or changing the entire approach in engine.
Either way, I don't see this happening for 3.3

(In reply to Federico Simoncelli from comment #9)
> As we see above trying to reproduce this issue (testing the fix) what
> happens is that both ce9e7bd8 and 7685c1c8 (empty volumes) are not kept open
> by the qemu process and as additional proof they can even be deactivated:
> [...]
> Kevin any insight?

Can you please describe in detail which QMP commands you sent to get into
this state?

Also, as I told you on IRC, qemu is definitely supposed to open all images in
the backing file chain. It keeps a file descriptor open for each of them.

I am not exactly sure what the "open" flag of lvs indicates. To get the
information from a bit closer to the qemu process, can you check if the backing
file doesn't appear in lsof either?

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

(In reply to Kevin Wolf from comment #11)
> (In reply to Federico Simoncelli from comment #9)
> > As we see above trying to reproduce this issue (testing the fix) what
> > happens is that both ce9e7bd8 and 7685c1c8 (empty volumes) are not kept open
> > by the qemu process and as additional proof they can even be deactivated:
> > [...]
> > Kevin any insight?
> 
> Can you please describe in detail which QMP commands you sent to get into
> this state?

# qemu-img create -f qcow2 /tmp/image1.qcow2 1G

# qemu-kvm -hda /tmp/image1.qcow2 -qmp stdio
{"QMP": {"version": {"qemu": {"micro": 1, "minor": 12, "major": 0}, "package": "(qemu-kvm-0.12.1.2)"}, "capabilities": []}}

{ "execute": "qmp_capabilities" }
{"return": {}}

# ls -l /proc/$(pgrep qemu-kvm)/fd | grep /tmp
lrwx------. 1 root root 64 Nov 14 05:57 7 -> /tmp/image1.qcow2

# qemu-img create -f qcow2 -b /tmp/image1.qcow2 /tmp/image2.qcow2 
Formatting '/tmp/image2.qcow2', fmt=qcow2 size=1073741824 backing_file='/tmp/image1.qcow2' encryption=off cluster_size=65536 

# qemu-img create -f qcow2 -b /tmp/image2.qcow2 /tmp/image3.qcow2 
Formatting '/tmp/image3.qcow2', fmt=qcow2 size=1073741824 backing_file='/tmp/image2.qcow2' encryption=off cluster_size=65536 

{ "execute": "blockdev-snapshot-sync", "arguments": { "device": "ide0-hd0", "snapshot-file": "/tmp/image3.qcow2", "mode": "existing" } }
{"return": {}}

# ls -l /proc/$(pgrep qemu-kvm)/fd | grep /tmp
lrwx------. 1 root root 64 Nov 14 06:03 15 -> /tmp/image3.qcow2
lr-x------. 1 root root 64 Nov 14 06:03 16 -> /tmp/image1.qcow2

image2.qcow2 is not open (even if it's part of the chain).
Restarting qemu-kvm:

# qemu-kvm -hda /tmp/image3.qcow2 -qmp stdio

# ls -l /proc/$(pgrep qemu-kvm)/fd | grep /tmp
lr-x------. 1 root root 64 Nov 14 06:06 10 -> /tmp/image1.qcow2
lrwx------. 1 root root 64 Nov 14 06:06 7 -> /tmp/image3.qcow2
lr-x------. 1 root root 64 Nov 14 06:06 9 -> /tmp/image2.qcow2

(In reply to Federico Simoncelli from comment #14)
> # qemu-img create -f qcow2 -b /tmp/image1.qcow2 /tmp/image2.qcow2 
> Formatting '/tmp/image2.qcow2', fmt=qcow2 size=1073741824
> backing_file='/tmp/image1.qcow2' encryption=off cluster_size=65536 
> 
> # qemu-img create -f qcow2 -b /tmp/image2.qcow2 /tmp/image3.qcow2 
> Formatting '/tmp/image3.qcow2', fmt=qcow2 size=1073741824
> backing_file='/tmp/image2.qcow2' encryption=off cluster_size=65536 
> 
> { "execute": "blockdev-snapshot-sync", "arguments": { "device": "ide0-hd0",
> "snapshot-file": "/tmp/image3.qcow2", "mode": "existing" } }
> {"return": {}}

Oh, now I understand.

When you call 'blockdev-snapshot-sync' with mode=existing, you're making a
promise that the existig image file points to the old top-level image as its
backing file. qemu only opens that file and puts it on top of what's already
openend, without even looking at the backing file path stored in that image
file.

So if you want to add two files at once, you still need to issue two
'blockdev-snapshot-sync' commands.

Fede, any update on this one?

After fixing other bugs related to live snapshots and LSM (bug 1018876 and bug 957703) the severity of this one has been very much reduced.

Engine now is much more reliable handling negative flows and I remember that the only way I found to trigger this was by setting multiple unlikely breakpoints in the engine.

I think we should keep this bug for reference as we know that the issue is theoretically present and it may be addressable in the future in some clean way (for example when/if the engine will be able to monitor what's the current active layer of the VM).

(In reply to Federico Simoncelli from comment #17)
> After fixing other bugs related to live snapshots and LSM (bug 1018876 and
> bug 957703) the severity of this one has been very much reduced.
> 
> Engine now is much more reliable handling negative flows and I remember that
> the only way I found to trigger this was by setting multiple unlikely
> breakpoints in the engine.
> 
> I think we should keep this bug for reference as we know that the issue is
> theoretically present and it may be addressable in the future in some clean
> way (for example when/if the engine will be able to monitor what's the
> current active layer of the VM).

Acked, moving it to future tracking
Sean

A live storage migration task failed due to a network error:

    2015-08-03 21:23:16,437 WARN  [org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand] (org.ovirt.thread.pool-12-thread-45) [] Could not perform live snapshot due to error, VM will still be configured to the new created snapshot: VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: VDSGenericException: VDSNetworkException: Message timeout which can be caused by communication issues (Failed with error VDS_NETWORK_ERROR and code 5022)
    2015-08-03 21:23:16,450 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-12-thread-45) [] Correlation ID: null, Call Stack: org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: VDSGenericException: VDSNetworkException: Message timeout which can be caused by communication issues (Failed with error VDS_NETWORK_ERROR and code 5022)
            at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:117)
            at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.RunVdsCommand(VDSBrokerFrontendImpl.java:33)
            at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2029)
            at org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand$2.runInTransaction(CreateAllSnapshotsFromVmCommand.java:400)
            ...

As a consequence, Engine is showing a failed snapshot as "Current", while libvirt is still reporting the previous correct snapshot.
I guess next time Engine will probably try to resume the failed snapshot and VM won't start anymore.
What is the correct way to solve this issue?

(In reply to Christopher Pereira from comment #20)
> A live storage migration task failed due to a network error:
> 
>     2015-08-03 21:23:16,437 WARN 
> [org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand]
> (org.ovirt.thread.pool-12-thread-45) [] Could not perform live snapshot due
> to error, VM will still be configured to the new created snapshot:
> VdcBLLException:
> org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException:
> VDSGenericException: VDSNetworkException: Message timeout which can be
> caused by communication issues (Failed with error VDS_NETWORK_ERROR and code
> 5022)
>     2015-08-03 21:23:16,450 WARN 
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (org.ovirt.thread.pool-12-thread-45) [] Correlation ID: null, Call Stack:
> org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException:
> org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException:
> VDSGenericException: VDSNetworkException: Message timeout which can be
> caused by communication issues (Failed with error VDS_NETWORK_ERROR and code
> 5022)
>             at
> org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:117)
>             at
> org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.
> RunVdsCommand(VDSBrokerFrontendImpl.java:33)
>             at
> org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2029)
>             at
> org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand$2.
> runInTransaction(CreateAllSnapshotsFromVmCommand.java:400)
>             ...
> 
> As a consequence, Engine is showing a failed snapshot as "Current", while
> libvirt is still reporting the previous correct snapshot.
> I guess next time Engine will probably try to resume the failed snapshot and
> VM won't start anymore.
> What is the correct way to solve this issue?

The error was in live snapshot phase, which means that a VM restart is recommended (using the created snapshot might cause data inconsistency). Next time, the engine won't resume the failed snapshot but will try to create a new one instead. The VM should still be able to start.

Thanks Daniel,

I first tried restarting Engine, but the snapshots list continues wrong (BUG).

The first snapshots in the list are bogus entries caused by the network error (in this case Engine is controlling hosts overseas :-).

The snapshots list displays:

Current : Active VM <--- Wrong! failed probably because of previous error
Date 3 : Auto-generated for Live Storage Migration <--- Wrong! failed network
Date 2 : Auto-generated for Live Storage Migration <---- Real current 'snapshot' (according to libvirt)
Date 1 : Original image

This problem with this bug is it disables most of oVirt features.
It also sounds dangerous to have oVirt confusing the current snapshot.
Do we exactly know why restarting the VM is necessary?

Can we avoid restarting the VM?
In general, restarting a VM is not an option.

Maybe we just need to move the code that is creating snapshot entries in the DB/Cache after the point where the new created snapshot was succesfully changed in libvirt/QEMU as the new current snapshot.

I confirm that after restarting the VM it points to the last snapshot.
It would be desirable not having to restart the VM.

Added: https://bugzilla.redhat.com/show_bug.cgi?id=1258659

Why is this targeted to future?

(In reply to Yaniv Dary from comment #25)
> Why is this targeted to future?

It's more of an RFE than a bug. If a live snapshot fails, we have no way of knowing which volumes the VM really writes to, and a restart is required.
When the flow is rewritten (e.g., during the SDM effort), we MAY have a better solution.

Are we better positioned to fix this in 4.3?

(In reply to Yaniv Lavi from comment #27)
> Are we better positioned to fix this in 4.3?

We made no improvement in that direction, unfortunately.

This bug didn't get any attention for a while, we didn't have the capacity to make any progress. If you deeply care about it or want to work on it please assign/target accordingly

This bug didn't get any attention for a while, we didn't have the capacity to make any progress. If you deeply care about it or want to work on it please assign/target accordingly

ok, closing. Please reopen if still relevant/you want to work on it.

ok, closing. Please reopen if still relevant/you want to work on it.