openstack nova-api.log: 2021-01-21 05:37:32.396718 | controller | 2021-01-21 05:30:57,421 103895 INFO [tempest.common.waiters] volume 5b6c7a26-7d2a-409d-8b68-99397d0fe438 reached available after waiting for 92.421137 seconds 2021-01-21 05:37:32.396883 | controller | 2021-01-21 05:30:59,307 103895 INFO [tempest.lib.common.rest_client] Request (TestVolumeSwap:test_volume_swap): 202 PUT https://162.253.55.194/compute/v2.1/servers/185d6573-58ee-47bc-8063-b447673db266/os-volume_attachments/345cae5d-ea5b-488f-beb4-70d6790611f1 1.699s 2021-01-21 05:37:32.402570 | controller | Response - Headers: {'date': 'Thu, 21 Jan 2021 05:34:15 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'application/json', 'x-compute-request-id': 'req-7feee7c1-5aa4-45f0-8f86-26c79b07f041', 'content-length': '1210', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version', 'x-openstack-request-id': 'req-7feee7c1-5aa4-45f0-8f86-26c 2021-01-21 05:37:32.402574 | controller | 79b07f041', 'connection': 'close', 'status': '200', 'content-location': 'https://162.253.55.194/volume/v3/d019611b763c4f9497577eb99cb650d0/volumes/345cae5d-ea5b-488f-beb4-70d6790611f1'} 2021-01-21 05:37:32.402577 | controller | Body: b'{"volume": {"id": "345cae5d-ea5b-488f-beb4-70d6790611f1", "status": "detaching", "size": 1, "availability_zone": "nova", "created_at": "2021-01-21T05:28:34.000000", "updated_at": "2021-01-21T05:30:58.000000", "name": "tempest-TestVolumeSwap-volume-1051548447", "description": null, "volume_type": "lvmdriver-1", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "https://162.253.55.194/volume/v3/d019611b763c4f9497577eb99cb650d0/volumes/345cae5d-ea5b-488f-beb4-70d6790611f1"}, {"rel": "bookmark", "href": "https://162.253.55.194/volume/d019611b763c4f9497577eb99cb650d0/volumes/345cae5d-ea5b-488f-beb4-70d6790611f1"}], "user_id": "bd8a0f7ebde74a39be0071177f820a9a", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "attachments": [{"id": "345cae5d-ea5b-488f-beb4-70d6790611f1", "attachment_id": "b8493a38-751e-4b88-9040-7be5e6fbb5d2", "volume_id": "345cae5d-ea5b-488f-beb4-70d6790611f1", "server_id": "185d6573-58ee-47bc-8063-b447673db266", "host_name": null, "device": "/dev/vdb", "attached_at": "2021-01-21T05:29:31.000000"}], "os-vol-tenant-attr:tenant_id": "d019611b763c4f9497577eb99cb650d0"}}' 2021-01-21 05:37:32.402600 | controller | Response - Headers: {'date': 'Thu, 21 Jan 2021 05:34:16 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'application/json', 'x-compute-request-id': 'req-814cb64e-75c1-42f8-9e75-f6f21ad9e978', 'content-length': '914', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version', 'x-openstack-request-id': 'req-814cb64e-75c1-42f8-9e75-f6f21ad9e978', 'connection': 'close', 'status': '200', 'content-location': 'https://162.253.55.194/volume/v3/d019611b763c4f9497577eb99cb650d0/volumes/5b6c7a26-7d2a-409d-8b68-99397d0fe438'} 2021-01-21 05:37:32.402604 | controller | Body: b'{"volume": {"id": "5b6c7a26-7d2a-409d-8b68-99397d0fe438", "status": "attaching", "size": 1, "availability_zone": "nova", "created_at": "2021-01-21T05:28:29.000000", "updated_at": "2021-01-21T05:31:01.000000", "name": "tempest-TestVolumeSwap-volume-325470600", "description": null, "volume_type": "lvmdriver-1", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "https://162.253.55.194/volume/v3/d019611b763c4f9497577eb99cb650d0/volumes/5b6c7a26-7d2a-409d-8b68-99397d0fe438"}, {"rel": "bookmark", "href": "https://162.253.55.194/volume/d019611b763c4f9497577eb99cb650d0/volumes/5b6c7a26-7d2a-409d-8b68-99397d0fe438"}], "user_id": "bd8a0f7ebde74a39be0071177f820a9a", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "attachments": [], "os-vol-tenant-attr:tenant_id": "d019611b763c4f9497577eb99cb650d0"}}' Volume 1: 345cae5d-ea5b-488f-beb4-70d6790611f1 Volume 2: 5b6c7a26-7d2a-409d-8b68-99397d0fe438 Swapping Volume 2 for Volume 1 in openstack nova-compute.log: Jan 21 05:29:27.272437 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: INFO nova.compute.manager [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] [instance: 185d6573-58ee-47bc-8063-b447673db266] Swapping volume 5b6c7a26-7d2a-409d-8b68-99397d0fe438 for 345cae5d-ea5b-488f-beb4-70d6790611f1 Jan 21 05:29:32.651893 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 0 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:29:52.105891 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 292552704 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:29:54.344075 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 318767104 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:30:12.255629 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 1073741823 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} [...] Jan 21 05:30:54.670152 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 1073741823 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:30:55.173557 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 1073741824 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:30:56.256037 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.compute.manager [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] swap_volume: Driver volume swap returned, new connection_info is now : {'driver_volume_type': 'iscsi', 'data': {'target_discovered': False, 'target_portal': '162.253.55.94:3260', 'target_iqn': 'iqn.2010-10.org.openstack:volume-345cae5d-ea5b-488f-beb4-70d6790611f1', 'target_lun': 1, 'volume_id': '345cae5d-ea5b-488f-beb4-70d6790611f1', 'auth_method': 'CHAP', 'auth_username': 'iYpKCbT55MJwvmRXmqig', 'auth_password': '***', 'encrypted': False, 'qos_specs': None, 'access_mode': 'rw', 'cacheable': False, 'device_path': '/dev/sdb'}, 'status': 'reserved', 'instance': '185d6573-58ee-47bc-8063-b447673db266', 'attached_at': '', 'detached_at': '', 'volume_id': '345cae5d-ea5b-488f-beb4-70d6790611f1', 'serial': '345cae5d-ea5b-488f-beb4-70d6790611f1'} {{(pid=93823) _swap_volume /opt/stack/nova/nova/compute/manager.py:7230}} Jan 21 05:30:57.270214 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.compute.manager [None req-200b6bf6-1232-47bf-a10b-389cfe7ab578 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] [instance: 185d6573-58ee-47bc-8063-b447673db266] swap_volume: Updating volume 5b6c7a26-7d2a-409d-8b68-99397d0fe438 BDM record with {'connection_info': '{"driver_volume_type": "iscsi", "data": {"target_discovered": false, "target_portal": "162.253.55.94:3260", "target_iqn": "iqn.2010-10.org.openstack:volume-345cae5d-ea5b-488f-beb4-70d6790611f1", "target_lun": 1, "volume_id": "345cae5d-ea5b-488f-beb4-70d6790611f1", "auth_method": "CHAP", "auth_username": "iYpKCbT55MJwvmRXmqig", "auth_password": "38wnRCi8HAAFRiZr", "encrypted": false, "qos_specs": null, "access_mode": "rw", "cacheable": false, "device_path": "/dev/sdb"}, "status": "reserved", "instance": "185d6573-58ee-47bc-8063-b447673db266", "attached_at": "", "detached_at": "", "volume_id": "345cae5d-ea5b-488f-beb4-70d6790611f1", "serial": "345cae5d-ea5b-488f-beb4-70d6790611f1"}', 'source_type': 'volume', 'destination_type': 'volume', 'snapshot_id': None, 'volume_id': '345cae5d-ea5b-488f-beb4-70d6790611f1', 'no_device': None, 'attachment_id': 'b8493a38-751e-4b88-9040-7be5e6fbb5d2'} {{(pid=93823) _do_swap_volume /opt/stack/nova/nova/compute/manager.py:7414}} Swapping Volume 1 for Volume 2 in openstack nova-compute.log: Jan 21 05:30:59.612424 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: INFO nova.compute.manager [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] [instance: 185d6573-58ee-47bc-8063-b447673db266] Swapping volume 345cae5d-ea5b-488f-beb4-70d6790611f1 for 5b6c7a26-7d2a-409d-8b68-99397d0fe438 Jan 21 05:31:02.207785 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 0 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:31:55.688227 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 1049624576 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} [...] Jan 21 05:31:55.706698 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 1049624576 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:31:56.175248 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 1073741823 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} [...] Jan 21 05:34:30.952371 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 1073741823 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:34:31.460595 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.virt.libvirt.guest [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] COPY block job progress, current cursor: 1073741824 final cursor: 1073741824 {{(pid=93823) is_job_complete /opt/stack/nova/nova/virt/libvirt/guest.py:873}} Jan 21 05:34:36.903961 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.compute.manager [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] swap_volume: Driver volume swap returned, new connection_info is now : {'driver_volume_type': 'iscsi', 'data': {'target_discovered': False, 'target_portal': '162.253.55.194:3260', 'target_iqn': 'iqn.2010-10.org.openstack:volume-5b6c7a26-7d2a-409d-8b68-99397d0fe438', 'target_lun': 1, 'volume_id': '5b6c7a26-7d2a-409d-8b68-99397d0fe438', 'auth_method': 'CHAP', 'auth_username': 'GRDPLW2gmyLMU8hT39iK', 'auth_password': '***', 'encrypted': False, 'qos_specs': None, 'access_mode': 'rw', 'cacheable': False, 'device_path': '/dev/sda'}, 'status': 'reserved', 'instance': '185d6573-58ee-47bc-8063-b447673db266', 'attached_at': '', 'detached_at': '', 'volume_id': '5b6c7a26-7d2a-409d-8b68-99397d0fe438', 'serial': '5b6c7a26-7d2a-409d-8b68-99397d0fe438'} {{(pid=93823) _swap_volume /opt/stack/nova/nova/compute/manager.py:7230}} Jan 21 05:34:46.425861 ubuntu-focal-vexxhost-ca-ymq-1-0022641000 nova-compute[93823]: DEBUG nova.compute.manager [None req-d6170fbb-e023-4cdb-93dc-a2e9ae9b0a56 tempest-TestVolumeSwap-1117975117 tempest-TestVolumeSwap-1117975117] [instance: 185d6573-58ee-47bc-8063-b447673db266] swap_volume: Updating volume 345cae5d-ea5b-488f-beb4-70d6790611f1 BDM record with {'connection_info': '{"driver_volume_type": "iscsi", "data": {"target_discovered": false, "target_portal": "162.253.55.194:3260", "target_iqn": "iqn.2010-10.org.openstack:volume-5b6c7a26-7d2a-409d-8b68-99397d0fe438", "target_lun": 1, "volume_id": "5b6c7a26-7d2a-409d-8b68-99397d0fe438", "auth_method": "CHAP", "auth_username": "GRDPLW2gmyLMU8hT39iK", "auth_password": "C25f9Mu7w8cFyfah", "encrypted": false, "qos_specs": null, "access_mode": "rw", "cacheable": false, "device_path": "/dev/sda"}, "status": "reserved", "instance": "185d6573-58ee-47bc-8063-b447673db266", "attached_at": "", "detached_at": "", "volume_id": "5b6c7a26-7d2a-409d-8b68-99397d0fe438", "serial": "5b6c7a26-7d2a-409d-8b68-99397d0fe438"}', 'source_type': 'volume', 'destination_type': 'volume', 'snapshot_id': None, 'volume_id': '5b6c7a26-7d2a-409d-8b68-99397d0fe438', 'no_device': None, 'attachment_id': '1883c1e3-2231-4e4c-801b-7dc11dc3b7a0'} {{(pid=93823) _do_swap_volume /opt/stack/nova/nova/compute/manager.py:7414}} qemu instance log: 2021-01-21 05:29:06.976+0000: starting up libvirt version: 6.0.0, package: 0ubuntu8.5 (Christian Ehrhardt Thu, 08 Oct 2020 07:36:06 +0200), qemu version: 4.2.1Debian 1:4.2-3ubuntu6.11, kernel: 5.4.0-60-generic, hostname: ubuntu-focal-vexxhost-ca-ymq-1-0022641000 LC_ALL=C \ PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin \ HOME=/var/lib/libvirt/qemu/domain-11-instance-00000013 \ XDG_DATA_HOME=/var/lib/libvirt/qemu/domain-11-instance-00000013/.local/share \ XDG_CACHE_HOME=/var/lib/libvirt/qemu/domain-11-instance-00000013/.cache \ XDG_CONFIG_HOME=/var/lib/libvirt/qemu/domain-11-instance-00000013/.config \ QEMU_AUDIO_DRV=none \ /usr/bin/qemu-system-x86_64 \ -name guest=instance-00000013,debug-threads=on \ -S \ -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-11-instance-00000013/master-key.aes \ -machine pc-i440fx-4.2,accel=tcg,usb=off,dump-guest-core=off \ -cpu qemu64 \ -m 128 \ -overcommit mem-lock=off \ -smp 1,sockets=1,cores=1,threads=1 \ -uuid 185d6573-58ee-47bc-8063-b447673db266 \ libvirtd.log: Swapping Volume 2 for Volume 1: 2021-01-21 05:29:32.631+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-4-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'created'(1) 2021-01-21 05:29:32.631+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-4-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'running'(2) 2021-01-21 05:29:32.646+0000: 60630: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-4-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 0, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-375"}] 2021-01-21 05:29:32.646+0000: 60630: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7fd07813ec80 reply={"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-4-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 0, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-375"} 2021-01-21 05:29:54.267+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-4-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'paused'(3) 2021-01-21 05:29:54.267+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-4-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'running'(2) 2021-01-21 05:30:12.253+0000: 60631: debug : qemuDomainObjBeginJobInternal:9416 : Starting job: job=query agentJob=none asyncJob=none (vm=0x7fd070075720 name=instance-00000013, current job=none agentJob=none async=none) 2021-01-21 05:30:12.253+0000: 60631: debug : qemuDomainObjBeginJobInternal:9470 : Started job: query (async=none vm=0x7fd070075720 name=instance-00000013) 2021-01-21 05:30:12.253+0000: 60631: debug : qemuDomainObjEnterMonitorInternal:9869 : Entering monitor (mon=0x7fd07813ec80 vm=0x7fd070075720 name=instance-00000013) 2021-01-21 05:30:12.253+0000: 60631: debug : qemuMonitorGetBlockJobInfo:3331 : alias=copy-vdb-libvirt-4-format, info=0x7fd085b467b0 2021-01-21 05:30:12.253+0000: 60631: debug : qemuMonitorGetAllBlockJobInfo:3312 : mon:0x7fd07813ec80 vm:0x7fd070075720 fd:33 2021-01-21 05:30:12.253+0000: 60631: info : qemuMonitorSend:993 : QEMU_MONITOR_SEND_MSG: mon=0x7fd07813ec80 msg={"execute":"query-block-jobs","id":"libvirt-417"} fd=-1 2021-01-21 05:30:12.253+0000: 60630: info : qemuMonitorIOWrite:450 : QEMU_MONITOR_IO_WRITE: mon=0x7fd07813ec80 buf={"execute":"query-block-jobs","id":"libvirt-417"} len=51 ret=51 errno=0 2021-01-21 05:30:12.254+0000: 60630: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-4-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1073741824, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-417"}] 2021-01-21 05:30:12.254+0000: 60630: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7fd07813ec80 reply={"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-4-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1073741824, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-417"} 2021-01-21 05:30:12.254+0000: 60631: debug : qemuDomainObjExitMonitorInternal:9892 : Exited monitor (mon=0x7fd07813ec80 vm=0x7fd070075720 name=instance-00000013) 2021-01-21 05:30:12.254+0000: 60631: debug : qemuDomainObjEndJob:9746 : Stopping job: query (async=none vm=0x7fd070075720 name=instance-00000013) 2021-01-21 05:30:12.254+0000: 60631: debug : virThreadJobClear:118 : Thread 60631 (virNetServerHandleJob) finished job remoteDispatchDomainGetBlockJobInfo with ret=0 2021-01-21 05:30:55.171+0000: 60634: debug : qemuDomainObjBeginJobInternal:9416 : Starting job: job=query agentJob=none asyncJob=none (vm=0x7fd070075720 name=instance-00000013, current job=none agentJob=none async=none) 2021-01-21 05:30:55.171+0000: 60634: debug : qemuDomainObjBeginJobInternal:9470 : Started job: query (async=none vm=0x7fd070075720 name=instance-00000013) 2021-01-21 05:30:55.171+0000: 60634: debug : qemuDomainObjEnterMonitorInternal:9869 : Entering monitor (mon=0x7fd07813ec80 vm=0x7fd070075720 name=instance-00000013) 2021-01-21 05:30:55.171+0000: 60634: debug : qemuMonitorGetBlockJobInfo:3331 : alias=copy-vdb-libvirt-4-format, info=0x7fd077ffe7b0 2021-01-21 05:30:55.171+0000: 60634: debug : qemuMonitorGetAllBlockJobInfo:3312 : mon:0x7fd07813ec80 vm:0x7fd070075720 fd:33 2021-01-21 05:30:55.171+0000: 60634: info : qemuMonitorSend:993 : QEMU_MONITOR_SEND_MSG: mon=0x7fd07813ec80 msg={"execute":"query-block-jobs","id":"libvirt-492"} fd=-1 2021-01-21 05:30:55.171+0000: 60630: info : qemuMonitorIOWrite:450 : QEMU_MONITOR_IO_WRITE: mon=0x7fd07813ec80 buf={"execute":"query-block-jobs","id":"libvirt-492"} len=51 ret=51 errno=0 2021-01-21 05:30:55.172+0000: 60630: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-4-format", "auto-dismiss": false, "busy": false, "len": 1073741824, "offset": 1073741824, "status": "ready", "paused": false, "speed": 0, "ready": true, "type": "mirror"}], "id": "libvirt-492"}] 2021-01-21 05:30:55.172+0000: 60630: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7fd07813ec80 reply={"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-4-format", "auto-dismiss": false, "busy": false, "len": 1073741824, "offset": 1073741824, "status": "ready", "paused": false, "speed": 0, "ready": true, "type": "mirror"}], "id": "libvirt-492"} 2021-01-21 05:30:55.172+0000: 60634: debug : qemuDomainObjExitMonitorInternal:9892 : Exited monitor (mon=0x7fd07813ec80 vm=0x7fd070075720 name=instance-00000013) 2021-01-21 05:30:55.172+0000: 60634: debug : qemuDomainObjEndJob:9746 : Stopping job: query (async=none vm=0x7fd070075720 name=instance-00000013) 2021-01-21 05:30:55.172+0000: 60634: debug : virThreadJobClear:118 : Thread 60634 (virNetServerHandleJob) finished job remoteDispatchDomainGetBlockJobInfo with ret=0 2021-01-21 05:30:55.178+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-4-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'waiting'(6) 2021-01-21 05:30:55.178+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-4-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'pending'(7) 2021-01-21 05:30:55.178+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-4-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'concluded'(9) 2021-01-21 05:30:55.180+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-4-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'null'(11) 2021-01-21 05:30:55.180+0000: 60635: debug : qemuBlockJobProcessEventConcludedCopyPivot:1221 : copy job 'copy-vdb-libvirt-4-format' on VM 'instance-00000013' pivoted 2021-01-21 05:30:55.425+0000: 60635: debug : qemuDomainObjEndJob:9746 : Stopping job: modify (async=none vm=0x7fd070075720 name=instance-00000013) Swapping Volume 1 for Volume 2: 2021-01-21 05:31:02.204+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-5-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'created'(1) 2021-01-21 05:31:02.204+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-5-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'running'(2) 021-01-21 05:31:02.206+0000: 60630: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 0, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-501"}] 2021-01-21 05:31:02.206+0000: 60630: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7fd07813ec80 reply={"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 0, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-501"} 2021-01-21 05:31:29.888+0000: 60630: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1049624576, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-537"}] 2021-01-21 05:31:29.889+0000: 60630: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7fd07813ec80 reply={"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1049624576, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-537"} 2021-01-21 05:31:55.666+0000: 60630: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1049624576, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-580"}] 2021-01-21 05:31:55.666+0000: 60630: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7fd07813ec80 reply={"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1049624576, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-580"} len == offset at 05:31:56.174 2021-01-21 05:31:56.174+0000: 60630: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1073741824, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-581"}] 2021-01-21 05:31:56.174+0000: 60630: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7fd07813ec80 reply={"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1073741824, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-581"} 3 minutes later, still len == offset but it's still going 2021-01-21 05:34:31.459+0000: 60630: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": false, "len": 1073741824, "offset": 1073741824, "status": "ready", "paused": false, "speed": 0, "ready": true, "type": "mirror"}], "id": "libvirt-855"}] 2021-01-21 05:34:31.459+0000: 60630: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7fd07813ec80 reply={"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": false, "len": 1073741824, "offset": 1073741824, "status": "ready", "paused": false, "speed": 0, "ready": true, "type": "mirror"}], "id": "libvirt-855"} 2021-01-21 05:34:31.467+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-5-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'waiting'(6) 2021-01-21 05:34:31.467+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-5-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'pending'(7) 2021-01-21 05:34:31.467+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-5-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'concluded'(9) 2021-01-21 05:34:31.468+0000: 60630: debug : qemuProcessHandleJobStatusChange:1002 : job 'copy-vdb-libvirt-5-format'(domain: 0x7fd070075720,instance-00000013) state changed to 'null'(11) 2021-01-21 05:34:31.468+0000: 60634: debug : qemuBlockJobProcessEventConcludedCopyPivot:1221 : copy job 'copy-vdb-libvirt-5-format' on VM 'instance-00000013' pivoted 2021-01-21 05:34:32.292+0000: 60634: debug : qemuDomainObjEndJob:9746 : Stopping job: modify (async=none vm=0x7fd070075720 name=instance-00000013)