Comment 7 for bug 1716920

Revision history for this message
Silvan Kaiser (2-silvan) wrote : Re: online snapshot deletion breaks volume info and backing chain (with remotefs drivers?)

1) correction regarding my last comment (#6): block commit -> block rebase

2) I'm still wondering why the active file ends up with a broken backing file entry. I checked into the libvirt logs and found that libvirt seems to run the correct rebasing in the end but checking the files afterwards shows the active file still having the backing file pointing to the original (now deleted) file and therefore being broken.
If i'm reading this log correctly libvirt sets the new backing file in the end (watch out for volume-669cfd0c-5b5c-470b-8b25-4c15cc655373.a755e1fc-f5ff-4dc1-937f-c03fb5ecc2d8, this file should be pointed to. Afaiu this libvirt log shows exactly that. But checking the volumes files afterwards via qemu-img info shows instead that the active files backing file link points to volume-669cfd0c-5b5c-470b-8b25-4c15cc655373.a24f9a80-9858-478f-871b-7a5f11278c8, which is the former backing file that is deleted during this assisted snapshot deletion and no longer exists.

Libvirt log excerpt:

2017-10-12 08:06:59.321+0000: 4390: debug : qemuMonitorJSONCommandWithFd:296 : Send command '{"execute":"query-block-jobs","id":"libvirt-25"}' for write with FD -1
2017-10-12 08:06:59.321+0000: 4390: info : qemuMonitorSend:1035 : QEMU_MONITOR_SEND_MSG: mon=0x7f0338011150 msg={"execute":"query-block-jobs","id":"libvirt-25"}
 fd=-1
2017-10-12 08:06:59.321+0000: 4388: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0338011150 buf={"execute":"query-block-jobs","id":"libvirt-25"}
 len=50 ret=50 errno=0
2017-10-12 08:06:59.321+0000: 4388: info : qemuMonitorIOProcess:431 : QEMU_MONITOR_IO_PROCESS: mon=0x7f0338011150 buf={"return": [{"io-status": "ok", "device": "drive-virtio-disk1", "busy": false, "len": 3221225
472, "offset": 250609664, "paused": false, "speed": 0, "ready": false, "type": "stream"}], "id": "libvirt-25"}
 len=205
2017-10-12 08:06:59.321+0000: 4388: debug : qemuMonitorJSONIOProcessLine:191 : Line [{"return": [{"io-status": "ok", "device": "drive-virtio-disk1", "busy": false, "len": 3221225472, "offset": 250609664, "paused
": false, "speed": 0, "ready": false, "type": "stream"}], "id": "libvirt-25"}]
2017-10-12 08:06:59.321+0000: 4388: info : qemuMonitorJSONIOProcessLine:211 : QEMU_MONITOR_RECV_REPLY: mon=0x7f0338011150 reply={"return": [{"io-status": "ok", "device": "drive-virtio-disk1", "busy": false, "len
": 3221225472, "offset": 250609664, "paused": false, "speed": 0, "ready": false, "type": "stream"}], "id": "libvirt-25"}
2017-10-12 08:06:59.321+0000: 4388: debug : qemuMonitorJSONIOProcess:260 : Total used 205 bytes out of 205 available in buffer
2017-10-12 08:06:59.321+0000: 4390: debug : qemuMonitorJSONCommandWithFd:301 : Receive command reply ret=0 rxObject=0x55f8a29153d0
2017-10-12 08:06:59.321+0000: 4390: debug : qemuDomainObjExitMonitorInternal:3555 : Exited monitor (mon=0x7f0338011150 vm=0x7f03280031d0 name=instance-00000006)
2017-10-12 08:06:59.321+0000: 4390: debug : qemuDomainObjEndJob:3463 : Stopping job: query (async=none vm=0x7f03280031d0 name=instance-00000006)
2017-10-12 08:06:59.321+0000: 4390: debug : virThreadJobClear:121 : Thread 4390 (virNetServerHandleJob) finished job remoteDispatchDomainGetBlockJobInfo with ret=0
2017-10-12 08:06:59.377+0000: 4388: info : qemuMonitorIOProcess:431 : QEMU_MONITOR_IO_PROCESS: mon=0x7f0338011150 buf={"timestamp": {"seconds": 1507795619, "microseconds": 377412}, "event": "BLOCK_JOB_COMPLETED"
, "data": {"device": "drive-virtio-disk1", "len": 3221225472, "offset": 3221225472, "speed": 0, "type": "stream"}}
 len=209
2017-10-12 08:06:59.377+0000: 4388: debug : qemuMonitorJSONIOProcessLine:191 : Line [{"timestamp": {"seconds": 1507795619, "microseconds": 377412}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "drive-virti
o-disk1", "len": 3221225472, "offset": 3221225472, "speed": 0, "type": "stream"}}]
2017-10-12 08:06:59.377+0000: 4388: info : qemuMonitorJSONIOProcessLine:206 : QEMU_MONITOR_RECV_EVENT: mon=0x7f0338011150 event={"timestamp": {"seconds": 1507795619, "microseconds": 377412}, "event": "BLOCK_JOB_
COMPLETED", "data": {"device": "drive-virtio-disk1", "len": 3221225472, "offset": 3221225472, "speed": 0, "type": "stream"}}
2017-10-12 08:06:59.377+0000: 4388: debug : qemuMonitorJSONIOProcessEvent:152 : mon=0x7f0338011150 obj=0x55f8a2942ec0
2017-10-12 08:06:59.377+0000: 4388: debug : qemuMonitorEmitEvent:1298 : mon=0x7f0338011150 event=BLOCK_JOB_COMPLETED
2017-10-12 08:06:59.377+0000: 4388: debug : qemuProcessHandleEvent:616 : vm=0x7f03280031d0
2017-10-12 08:06:59.377+0000: 4388: debug : virObjectEventNew:640 : obj=0x55f8a2943160
2017-10-12 08:06:59.377+0000: 4388: debug : qemuMonitorJSONIOProcessEvent:177 : handle BLOCK_JOB_COMPLETED handler=0x7f031255f980 data=0x55f8a290ccc0
2017-10-12 08:06:59.377+0000: 4388: debug : qemuMonitorEmitBlockJob:1490 : mon=0x7f0338011150
2017-10-12 08:06:59.377+0000: 4388: debug : qemuProcessHandleBlockJob:986 : Block job for device drive-virtio-disk1 (domain: 0x7f03280031d0,instance-00000006) type 1 status 0
2017-10-12 08:06:59.377+0000: 4388: debug : qemuMonitorJSONIOProcess:260 : Total used 209 bytes out of 209 available in buffer
2017-10-12 08:06:59.377+0000: 4388: debug : virObjectEventDispose:134 : obj=0x55f8a2943160
2017-10-12 08:06:59.377+0000: 4726: debug : qemuProcessEventHandler:4571 : vm=0x7f03280031d0, event=5
2017-10-12 08:06:59.377+0000: 4726: debug : qemuDomainObjBeginJobInternal:3268 : Starting job: modify (vm=0x7f03280031d0 name=instance-00000006, current job=none async=none)
2017-10-12 08:06:59.377+0000: 4726: debug : qemuDomainObjBeginJobInternal:3309 : Started job: modify (async=none vm=0x7f03280031d0 name=instance-00000006)
2017-10-12 08:06:59.377+0000: 4726: debug : qemuBlockJobEventProcess:103 : disk=vdb, mirrorState=none, type=1, status=0
2017-10-12 08:06:59.377+0000: 4726: debug : virObjectEventNew:640 : obj=0x7f02f022d2a0
2017-10-12 08:06:59.377+0000: 4726: debug : virObjectEventNew:640 : obj=0x7f02f0191be0
2017-10-12 08:06:59.394+0000: 4726: debug : qemuDomainObjEndJob:3463 : Stopping job: modify (async=none vm=0x7f03280031d0 name=instance-00000006)
2017-10-12 08:06:59.394+0000: 4388: debug : virObjectEventDispose:134 : obj=0x7f02f022d2a0
2017-10-12 08:06:59.394+0000: 4388: debug : virObjectEventDispose:134 : obj=0x7f02f0191be0