6:12 p.m.
Hi all,
everyday at 01:00 AM we perform a daily backup on many VMs hosted in multiple hosts (all
with oVirt 4.3) using a custom sciprt written in python3 (using SDK) and everything works
"almost" fine.
There is one single VM (Windows Server 2016) with a disk of 600 GB (the real disk usage is
about 150 GB) hosted on a single node that has a strange behaviour.
1) The export start after a few seconds of the execution of the script, we use
"vm_service.export_to_path_on_host" class for exporting the VM as ova file;
2) After few minutes i see in the engine the command "START, DumpXmlsVDSCommand"
that is completely istantly both on the host side ad the engine side, and it's fine:
2020-07-02 01:05:45,428+0200 INFO (jsonrpc/7) [api.host] START
dumpxmls(vmList=[u'10e88cab-ec4f-4491-b51f-94e3d2e81a0a'])
from=::ffff:$ENGINE_IP,39308 (api:48)
2020-07-02 01:05:45,428+0200 INFO (jsonrpc/7) [api.host] FINISH dumpxmls return={... LONG
XML ...}
3) after 3 hours i see the following logs about the export task:
2020-07-02 04:11:39,201+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-91) [895d6936-f45c-4766-afd4-408a4e4e9a41]
START, GetVolumeInfoVDSCommand(HostName = $OVIRT_HOST,
GetVolumeInfoVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697'}), log id: 3cbf2c7c
2020-07-02 04:11:39,299+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetQemuImageInfoVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-91) [895d6936-f45c-4766-afd4-408a4e4e9a41]
START, GetQemuImageInfoVDSCommand(HostName = $OVIRT_HOST,
GetVolumeInfoVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697'}), log id: 47d5122e
2020-07-02 04:43:21,339+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.PrepareImageVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] START,
PrepareImageVDSCommand(HostName = $OVIRT_HOST,
PrepareImageVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 28c880d12020-07-02 04:43:21,650+02 INFO
[org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] Executing Ansible command:
ANSIBLE_STDOUT_CALLBACK=imagemeasureplugin /usr/bin/ansible-playbook --ssh-common-args=-F
/var/lib/ovirt-engine/.ssh/config --private-key=/etc/pki/ovirt-engine/keys/engine_id_rsa
--inventory=/tmp/ansible-inventory1121551177697847734
--extra-vars=image_path="/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04"
/usr/share/ovirt-engine/playbooks/ovirt-image-measure.yml [Logfile:
/var/log/ovirt-engine/ova
/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log]
2020-07-02 05:05:20,428+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-8) [64c95c4d] START,
UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 666809cb
2020-07-02 05:05:22,104+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-8) [64c95c4d] START,
UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 33ff46bf
2020-07-02 05:05:29,602+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-287) [64c95c4d] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='e40a2740-37f6-455d-bed7-554efef761ff'}), log id: f01ff26
2020-07-02 05:05:29,619+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-269) [64c95c4d] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='1c94df38-88c1-4bf8-89a2-8c322513b21b'}), log id: 6150e13b
4) And then, after several hours, the export fail with the following logs:
engine logs.
2020-07-02 12:43:21,653+02 ERROR [org.ovirt.engine.core.bll.CreateOvaCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] Failed to measure image:
null. Please check logs for more details:
/var/log/ovirt-engine/ova/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log
2020-07-02 12:43:23,741+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-28) [] EVENT_ID:
IMPORTEXPORT_EXPORT_VM_TO_OVA_FAILED(1,225), Failed to export Vm $OVIRT_VM_TO_EXPORT as a
Virtual Appliance to path /backup/$OVIRT_VM_TO_EXPORT_daily_2020Jul02.ova on Host
$OVIRT_HOST
2020-07-02 12:43:26,162+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8] START,
MergeVDSCommand(HostName = $OVIRT_HOST,
MergeVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697',
baseImageId='5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topImageId='55b3eac5-05b2-4bae-be50-37cde7050697', bandwidth='0'}), log
id: a0b417d
2020-07-02 12:43:26,328+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8] EVENT_ID:
VDS_BROKER_COMMAND_FAILURE(10,802), VDSM $OVIRT_HOST command MergeVDS failed: Merge
failed
2020-07-02 12:43:26,328+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8] HostName = $OVIRT_HOST
2020-07-02 12:43:26,328+02 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8] Command
'MergeVDSCommand(HostName = $OVIRT_HOST,
MergeVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697',
baseImageId='5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topImageId='55b3eac5-05b2-4bae-be50-37cde7050697', bandwidth='0'})'
execution failed: VDSGenericException: VDSErrorException: Failed to MergeVDS, error =
Merge failed, code = 52
2020-07-02 12:43:28,996+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-2) [54b569e8] START,
DumpXmlsVDSCommand(HostName = $OVIRT_HOST,
Params:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmIds='[10e88cab-ec4f-4491-b51f-94e3d2e81a0a]'}), log id: 65709a96
2020-07-02 13:05:38,206+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-45) [5179fcb] START,
UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 44e9ec23
2020-07-02 13:05:39,851+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-45) [5179fcb] START,
UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 68231c70
2020-07-02 13:05:40,356+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-240) [5179fcb] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='5d61682b-cf47-4637-9014-c647eb5265ee'}), log id: 718885f3
2020-07-02 13:05:50,357+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-290) [5179fcb] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='5709eb6c-a656-4a4d-b67f-72dd0bebf3e4'}), log id: 40c18d57
And here the vdsm.log of the host:
2020-07-02 12:43:26,169+0200 INFO (jsonrpc/6) [api.virt] START
merge(drive={u'imageID': u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
u'volumeID': u'55b3eac5-05b2-4bae-be50-37cde7050697', u'domainID':
u'6775c41c-7d67-451b-8beb-4fd086eade2e', u'poolID':
u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84'},
baseVolUUID=u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topVolUUID=u'55b3eac5-05b2-4bae-be50-37cde7050697', bandwidth=u'0',
jobUUID=u'b49fa67b-4a5a-4f73-823f-9e33a8e20cd2') from=::ffff:$ENGINE_IP,39308,
flow_id=54b569e8, vmId=10e88cab-ec4f-4491-b51f-94e3d2e81a0a (api:48)
2020-07-02 12:43:26,196+0200 INFO (jsonrpc/6) [vdsm.api] START
getVolumeInfo(sdUUID=u'6775c41c-7d67-451b-8beb-4fd086eade2e',
spUUID='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
imgUUID=u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
volUUID=u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', options=None)
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=bb1d1fd0-9746-4949-9c6c-b069947f5875 (api:48)
2020-07-02 12:43:26,199+0200 INFO (jsonrpc/6) [storage.VolumeManifest] Info request:
sdUUID=6775c41c-7d67-451b-8beb-4fd086eade2e imgUUID=a084fa36-0f93-45c2-a323-ea9ca2d16677
volUUID = 5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04 (volume:240)
2020-07-02 12:43:26,205+0200 INFO (jsonrpc/6) [storage.VolumeManifest]
6775c41c-7d67-451b-8beb-4fd086eade2e/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04
info is {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype': 'INTERNAL',
'description': '', 'parent':
'7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013', 'format': 'COW',
'generation': 0, 'image': 'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL', 'mtime':
'0', 'apparentsize': '6635716608', 'children': [],
'pool': '', 'ctime': '1593558283', 'capacity':
'644245094400', 'uuid': u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
'truesize': '6637277184', 'type': 'SPARSE'} (volume:279)
2020-07-02 12:43:26,205+0200 INFO (jsonrpc/6) [vdsm.api] FINISH getVolumeInfo
return={'info': {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype': 'INTERNAL',
'description': '', 'parent':
'7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013', 'format': 'COW',
'generation': 0, 'image': 'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL', 'mtime':
'0', 'apparentsize': '6635716608','children': [],
'pool': '', 'ctime': '1593558283', 'capacity':
'644245094400', 'uuid': u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
'truesize': '6637277184', 'type': 'SPARSE'}}
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=bb1d1fd0-9746-4949-9c6c-b069947f5875 (api:54)
2020-07-02 12:43:26,206+0200 INFO (jsonrpc/6) [vdsm.api] START
getVolumeInfo(sdUUID=u'6775c41c-7d67-451b-8beb-4fd086eade2e',
spUUID='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
imgUUID=u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
volUUID=u'55b3eac5-05b2-4bae-be50-37cde7050697', options=None)
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=32ce9b21-b9f3-4319-a229-b32df1fb9283 (api:48)
2020-07-02 12:43:26,208+0200 INFO (jsonrpc/6) [storage.VolumeManifest] Info request:
sdUUID=6775c41c-7d67-451b-8beb-4fd086eade2e imgUUID=a084fa36-0f93-45c2-a323-ea9ca2d16677
volUUID = 55b3eac5-05b2-4bae-be50-37cde7050697 (volume:240)
2020-07-02 12:43:26,219+0200 INFO (jsonrpc/6) [storage.VolumeManifest]
6775c41c-7d67-451b-8beb-4fd086eade2e/a084fa36-0f93-45c2-a323-ea9ca2d16677/55b3eac5-05b2-4bae-be50-37cde7050697
info is {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype': 'LEAF',
'description': '', 'parent':
'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', 'format': 'COW',
'generation': 0, 'image': 'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL', 'mtime':
'0', 'apparentsize': '4077387776', 'children': [],
'pool': '', 'ctime': '1593644682', 'capacity':
'644245094400', 'uuid': u'55b3eac5-05b2-4bae-be50-37cde7050697',
'truesize': '4077940736', 'type': 'SPARSE'} (volume:279)
2020-07-02 12:43:26,219+0200 INFO (jsonrpc/6) [vdsm.api] FINISH getVolumeInfo
return={'info': {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype': 'LEAF',
'description': '', 'parent':
'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', 'format': 'COW',
'generation': 0, 'image': 'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL', 'mtime':
'0', 'apparentsize': '4077387776', 'children': [],
'pool': '', 'ctime': '1593644682', 'capacity':
'644245094400', 'uuid': u'55b3eac5-05b2-4bae-be50-37cde7050697',
'truesize': '4077940736', 'type': 'SPARSE'}}
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=32ce9b21-b9f3-4319-a229-b32df1fb9283 (api:54)
2020-07-02 12:43:26,235+0200 INFO (jsonrpc/6) [virt.vm]
(vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a') Starting merge with
jobUUID=u'b49fa67b-4a5a-4f73-823f-9e33a8e20cd2', original
chain=e2bad960-6ad4-44b6-8ff0-69dcca6bf722 < 7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013 <
5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04 < 55b3eac5-05b2-4bae-be50-37cde7050697 (top),
disk='sda', base='sda[1]', top=None, bandwidth=0, flags=12 (vm:5951)
2020-07-02 12:43:26,280+0200 ERROR (jsonrpc/6) [virt.vm]
(vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a') Live merge failed (job:
b49fa67b-4a5a-4f73-823f-9e33a8e20cd2) (vm:5957)
2020-07-02 12:43:26,296+0200 INFO (jsonrpc/6) [api.virt] FINISH merge
return={'status': {'message': 'Merge failed', 'code': 52}}
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8, vmId=10e88cab-ec4f-4491-b51f-94e3d2e81a0a
(api:54)
2020-07-02 12:43:26,296+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call VM.merge
failed (error 52) in 0.13 seconds (__init__:312)
2020-07-02 12:43:26,627+0200 INFO (jsonrpc/1) [vdsm.api] START
getSpmStatus(spUUID=u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84', options=None)
from=::ffff:$ENGINE_IP,39308, flow_id=4968c8cb,
task_id=ee82b2d6-39f5-43ad-83a3-803f1af8e234 (api:48)
2020-07-02 12:43:26,628+0200 INFO (jsonrpc/1) [vdsm.api] FINISH getSpmStatus
return={'spm_st': {'spmId': 1, 'spmStatus': 'SPM',
'spmLver': -1}} from=::ffff:$ENGINE_IP,39308, flow_id=4968c8cb,
task_id=ee82b2d6-39f5-43ad-83a3-803f1af8e234 (api:54)
2020-07-02 12:43:26,628+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call
StoragePool.getSpmStatus succeeded in 0.00 seconds (__init__:312)
2020-07-02 12:43:26,645+0200 INFO (jsonrpc/3) [vdsm.api] START
getStoragePoolInfo(spUUID=u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84', options=None)
from=::ffff:$ENGINE_IP,39304, flow_id=4968c8cb,
task_id=ab1124bc-651d-4ade-aae4-ff9fea23f6a0 (api:48)
2020-07-02 12:43:26,646+0200 INFO (jsonrpc/3) [vdsm.api] FINISH getStoragePoolInfo
return={'info': {'name': 'No Description', 'isoprefix':
'', 'pool_status': 'connected', 'lver': -1,
'domains': u'6775c41c-7d67-451b-8beb-4fd086eade2e:Active',
'master_uuid': u'6775c41c-7d67-451b-8beb-4fd086eade2e', 'version':
'5', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver':
1}, 'dominfo': {u'6775c41c-7d67-451b-8beb-4fd086eade2e':
{'status': u'Active', 'diskfree': '3563234983936',
'isoprefix': '', 'alerts': [], 'disktotal':
'3923683311616', 'version': 5}}} from=::ffff:$ENGINE_IP,39304,
flow_id=4968c8cb, task_id=ab1124bc-651d-4ade-aae4-ff9fea23f6a0 (api:54)
2020-07-02 12:43:26,647+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call
StoragePool.getInfo succeeded in 0.01 seconds (__init__:312)
5) His task seems block any other export tasks, leave them in pending. There were about 5
export tasks and 1 import temaplte task and as soon we killed the following process, the
other 4 tasks and the import one completed after few minutes.
2020-07-02 04:43:21,339+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.PrepareImageVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] START,
PrepareImageVDSCommand(HostName = $OVIRT_HOST,
PrepareImageVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 28c880d12020-07-02 04:43:21,650+02 INFO
[org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] Executing Ansible command:
ANSIBLE_STDOUT_CALLBACK=imagemeasureplugin /usr/bin/ansible-playbook --ssh-common-args=-F
/var/lib/ovirt-engine/.ssh/config --private-key=/etc/pki/ovirt-engine/keys/engine_id_rsa
--inventory=/tmp/ansible-inventory1121551177697847734
--extra-vars=image_path="/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04"
/usr/share/ovirt-engine/playbooks/ovirt-image-measure.yml [Logfile:
/var/log/ovirt-engine/ova
/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log]
The process that we killed was:
vdsm 25338 25332 99 04:14 pts/0 07:40:09 qemu-img measure -O qcow2
/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/55b3eac5-05b2-4bae-be50-37cde705069
A strace -p of the PID 25338 showed following lines:
lseek(11, 3056795648, SEEK_DATA) = 3056795648
lseek(11, 3056795648, SEEK_HOLE) = 13407092736
lseek(14, 128637468672, SEEK_DATA) = 128637468672
lseek(14, 128637468672, SEEK_HOLE) = 317708828672
lseek(14, 128646250496, SEEK_DATA) = 128646250496
lseek(14, 128646250496, SEEK_HOLE) = 317708828672
lseek(14, 128637730816, SEEK_DATA) = 128637730816
lseek(14, 128637730816, SEEK_HOLE) = 317708828672
lseek(14, 128646774784, SEEK_DATA) = 128646774784
lseek(14, 128646774784, SEEK_HOLE) = 317708828672
lseek(14, 128646709248, SEEK_DATA) = 128646709248
Can yu help us figuring out what is going on?
If any other informations is needed I'll provide 'em ASAP.
Thank you for your patience and your time,
Regards
Francesco
9:03 a.m.
Hi Francesco,
Can you please submit a bug too -
https://bugzilla.redhat.com/enter_bug.cgi?product=ovirt-engine
Please add the steps you are doing when this bug occurs and all the
relevant logs (engine and VDSM logs etc..)
Thanks
On Tue, 7 Jul 2020 at 16:22, francesco--- via Devel <devel(a)ovirt.org> wrote:
Hi all,
everyday at 01:00 AM we perform a daily backup on many VMs hosted in
multiple hosts (all with oVirt 4.3) using a custom sciprt written in
python3 (using SDK) and everything works "almost" fine.
There is one single VM (Windows Server 2016) with a disk of 600 GB (the
real disk usage is about 150 GB) hosted on a single node that has a strange
behaviour.
1) The export start after a few seconds of the execution of the script, we
use "vm_service.export_to_path_on_host" class for exporting the VM as ova
file;
2) After few minutes i see in the engine the command "START,
DumpXmlsVDSCommand" that is completely istantly both on the host side ad
the engine side, and it's fine:
2020-07-02 01:05:45,428+0200 INFO (jsonrpc/7) [api.host] START
dumpxmls(vmList=[u'10e88cab-ec4f-4491-b51f-94e3d2e81a0a'])
from=::ffff:$ENGINE_IP,39308 (api:48)
2020-07-02 01:05:45,428+0200 INFO (jsonrpc/7) [api.host] FINISH dumpxmls
return={... LONG XML ...}
3) after 3 hours i see the following logs about the export task:
2020-07-02 04:11:39,201+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-91)
[895d6936-f45c-4766-afd4-408a4e4e9a41] START,
GetVolumeInfoVDSCommand(HostName = $OVIRT_HOST,
GetVolumeInfoVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697'}), log id: 3cbf2c7c
2020-07-02 04:11:39,299+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetQemuImageInfoVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-91)
[895d6936-f45c-4766-afd4-408a4e4e9a41] START,
GetQemuImageInfoVDSCommand(HostName = $OVIRT_HOST,
GetVolumeInfoVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697'}), log id: 47d5122e
2020-07-02 04:43:21,339+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.PrepareImageVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] START,
PrepareImageVDSCommand(HostName = $OVIRT_HOST,
PrepareImageVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 28c880d12020-07-02 04:43:21,650+02 INFO
[org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] Executing
Ansible command: ANSIBLE_STDOUT_CALLBACK=imagemeasureplugin
/usr/bin/ansible-playbook --ssh-common-args=-F
/var/lib/ovirt-engine/.ssh/config
--private-key=/etc/pki/ovirt-engine/keys/engine_id_rsa
--inventory=/tmp/ansible-inventory1121551177697847734
--extra-vars=image_path="/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04"
/usr/share/ovirt-engine/playbooks/ovirt-image-measure.yml [Logfile:
/var/log/ovirt-engine/ova
/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log]
2020-07-02 05:05:20,428+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-8) [64c95c4d] START,
UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 666809cb
2020-07-02 05:05:22,104+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-8) [64c95c4d] START,
UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 33ff46bf
2020-07-02 05:05:29,602+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-287) [64c95c4d] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='e40a2740-37f6-455d-bed7-554efef761ff'}), log id: f01ff26
2020-07-02 05:05:29,619+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-269) [64c95c4d] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='1c94df38-88c1-4bf8-89a2-8c322513b21b'}), log id: 6150e13b
4) And then, after several hours, the export fail with the following logs:
engine logs.
2020-07-02 12:43:21,653+02 ERROR
[org.ovirt.engine.core.bll.CreateOvaCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] Failed to
measure image: null. Please check logs for more details:
/var/log/ovirt-engine/ova/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log
2020-07-02 12:43:23,741+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-28) [] EVENT_ID:
IMPORTEXPORT_EXPORT_VM_TO_OVA_FAILED(1,225), Failed to export Vm
$OVIRT_VM_TO_EXPORT as a Virtual Appliance to path
/backup/$OVIRT_VM_TO_EXPORT_daily_2020Jul02.ova on Host $OVIRT_HOST
2020-07-02 12:43:26,162+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8] START,
MergeVDSCommand(HostName = $OVIRT_HOST,
MergeVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697',
baseImageId='5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topImageId='55b3eac5-05b2-4bae-be50-37cde7050697', bandwidth='0'}), log
id:
a0b417d
2020-07-02 12:43:26,328+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8] EVENT_ID:
VDS_BROKER_COMMAND_FAILURE(10,802), VDSM $OVIRT_HOST command MergeVDS
failed: Merge failed
2020-07-02 12:43:26,328+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8] HostName =
$OVIRT_HOST
2020-07-02 12:43:26,328+02 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8] Command
'MergeVDSCommand(HostName = $OVIRT_HOST,
MergeVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697',
baseImageId='5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topImageId='55b3eac5-05b2-4bae-be50-37cde7050697', bandwidth='0'})'
execution failed: VDSGenericException: VDSErrorException: Failed to
MergeVDS, error = Merge failed, code = 52
2020-07-02 12:43:28,996+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-2) [54b569e8] START,
DumpXmlsVDSCommand(HostName = $OVIRT_HOST,
Params:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmIds='[10e88cab-ec4f-4491-b51f-94e3d2e81a0a]'}), log id: 65709a96
2020-07-02 13:05:38,206+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-45) [5179fcb] START,
UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 44e9ec23
2020-07-02 13:05:39,851+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-45) [5179fcb] START,
UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 68231c70
2020-07-02 13:05:40,356+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-240) [5179fcb] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='5d61682b-cf47-4637-9014-c647eb5265ee'}), log id: 718885f3
2020-07-02 13:05:50,357+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-290) [5179fcb] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='5709eb6c-a656-4a4d-b67f-72dd0bebf3e4'}), log id: 40c18d57
And here the vdsm.log of the host:
2020-07-02 12:43:26,169+0200 INFO (jsonrpc/6) [api.virt] START
merge(drive={u'imageID': u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
u'volumeID': u'55b3eac5-05b2-4bae-be50-37cde7050697',
u'domainID':
u'6775c41c-7d67-451b-8beb-4fd086eade2e', u'poolID':
u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84'},
baseVolUUID=u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topVolUUID=u'55b3eac5-05b2-4bae-be50-37cde7050697', bandwidth=u'0',
jobUUID=u'b49fa67b-4a5a-4f73-823f-9e33a8e20cd2')
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
vmId=10e88cab-ec4f-4491-b51f-94e3d2e81a0a (api:48)
2020-07-02 12:43:26,196+0200 INFO (jsonrpc/6) [vdsm.api] START
getVolumeInfo(sdUUID=u'6775c41c-7d67-451b-8beb-4fd086eade2e',
spUUID='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
imgUUID=u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
volUUID=u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', options=None)
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=bb1d1fd0-9746-4949-9c6c-b069947f5875 (api:48)
2020-07-02 12:43:26,199+0200 INFO (jsonrpc/6) [storage.VolumeManifest]
Info request: sdUUID=6775c41c-7d67-451b-8beb-4fd086eade2e
imgUUID=a084fa36-0f93-45c2-a323-ea9ca2d16677 volUUID =
5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04 (volume:240)
2020-07-02 12:43:26,205+0200 INFO (jsonrpc/6) [storage.VolumeManifest]
6775c41c-7d67-451b-8beb-4fd086eade2e/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04
info is {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e',
'voltype': 'INTERNAL', 'description': '',
'parent':
'7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013', 'format': 'COW',
'generation': 0,
'image': 'a084fa36-0f93-45c2-a323-ea9ca2d16677', 'disktype':
'DATA',
'legality': 'LEGAL', 'mtime': '0',
'apparentsize': '6635716608',
'children': [], 'pool': '', 'ctime':
'1593558283', 'capacity':
'644245094400', 'uuid': u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
'truesize': '6637277184', 'type': 'SPARSE'} (volume:279)
2020-07-02 12:43:26,205+0200 INFO (jsonrpc/6) [vdsm.api] FINISH
getVolumeInfo return={'info': {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype': 'INTERNAL',
'description': '', 'parent':
'7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013',
'format': 'COW', 'generation': 0, 'image':
'a084fa36-0f93-45c2-a323-ea9ca2d16677', 'disktype': 'DATA',
'legality':
'LEGAL', 'mtime': '0', 'apparentsize':
'6635716608','children': [], 'pool':
'', 'ctime': '1593558283', 'capacity':
'644245094400', 'uuid':
u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', 'truesize':
'6637277184', 'type':
'SPARSE'}} from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=bb1d1fd0-9746-4949-9c6c-b069947f5875 (api:54)
2020-07-02 12:43:26,206+0200 INFO (jsonrpc/6) [vdsm.api] START
getVolumeInfo(sdUUID=u'6775c41c-7d67-451b-8beb-4fd086eade2e',
spUUID='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
imgUUID=u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
volUUID=u'55b3eac5-05b2-4bae-be50-37cde7050697', options=None)
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=32ce9b21-b9f3-4319-a229-b32df1fb9283 (api:48)
2020-07-02 12:43:26,208+0200 INFO (jsonrpc/6) [storage.VolumeManifest]
Info request: sdUUID=6775c41c-7d67-451b-8beb-4fd086eade2e
imgUUID=a084fa36-0f93-45c2-a323-ea9ca2d16677 volUUID =
55b3eac5-05b2-4bae-be50-37cde7050697 (volume:240)
2020-07-02 12:43:26,219+0200 INFO (jsonrpc/6) [storage.VolumeManifest]
6775c41c-7d67-451b-8beb-4fd086eade2e/a084fa36-0f93-45c2-a323-ea9ca2d16677/55b3eac5-05b2-4bae-be50-37cde7050697
info is {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e',
'voltype': 'LEAF', 'description': '', 'parent':
'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', 'format': 'COW',
'generation': 0,
'image': 'a084fa36-0f93-45c2-a323-ea9ca2d16677', 'disktype':
'DATA',
'legality': 'LEGAL', 'mtime': '0',
'apparentsize': '4077387776',
'children': [], 'pool': '', 'ctime':
'1593644682', 'capacity':
'644245094400', 'uuid': u'55b3eac5-05b2-4bae-be50-37cde7050697',
'truesize': '4077940736', 'type': 'SPARSE'} (volume:279)
2020-07-02 12:43:26,219+0200 INFO (jsonrpc/6) [vdsm.api] FINISH
getVolumeInfo return={'info': {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype': 'LEAF',
'description':
'', 'parent': '5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
'format': 'COW',
'generation': 0, 'image':
'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL', 'mtime':
'0', 'apparentsize':
'4077387776', 'children': [], 'pool': '',
'ctime': '1593644682',
'capacity': '644245094400', 'uuid':
u'55b3eac5-05b2-4bae-be50-37cde7050697', 'truesize':
'4077940736', 'type':
'SPARSE'}} from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=32ce9b21-b9f3-4319-a229-b32df1fb9283 (api:54)
2020-07-02 12:43:26,235+0200 INFO (jsonrpc/6) [virt.vm]
(vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a') Starting merge with
jobUUID=u'b49fa67b-4a5a-4f73-823f-9e33a8e20cd2', original
chain=e2bad960-6ad4-44b6-8ff0-69dcca6bf722 <
7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013 < 5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04
< 55b3eac5-05b2-4bae-be50-37cde7050697 (top), disk='sda',
base='sda[1]',
top=None, bandwidth=0, flags=12 (vm:5951)
2020-07-02 12:43:26,280+0200 ERROR (jsonrpc/6) [virt.vm]
(vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a') Live merge failed (job:
b49fa67b-4a5a-4f73-823f-9e33a8e20cd2) (vm:5957)
2020-07-02 12:43:26,296+0200 INFO (jsonrpc/6) [api.virt] FINISH merge
return={'status': {'message': 'Merge failed', 'code':
52}}
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
vmId=10e88cab-ec4f-4491-b51f-94e3d2e81a0a (api:54)
2020-07-02 12:43:26,296+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC
call VM.merge failed (error 52) in 0.13 seconds (__init__:312)
2020-07-02 12:43:26,627+0200 INFO (jsonrpc/1) [vdsm.api] START
getSpmStatus(spUUID=u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84', options=None)
from=::ffff:$ENGINE_IP,39308, flow_id=4968c8cb,
task_id=ee82b2d6-39f5-43ad-83a3-803f1af8e234 (api:48)
2020-07-02 12:43:26,628+0200 INFO (jsonrpc/1) [vdsm.api] FINISH
getSpmStatus return={'spm_st': {'spmId': 1, 'spmStatus':
'SPM', 'spmLver':
-1}} from=::ffff:$ENGINE_IP,39308, flow_id=4968c8cb,
task_id=ee82b2d6-39f5-43ad-83a3-803f1af8e234 (api:54)
2020-07-02 12:43:26,628+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC
call StoragePool.getSpmStatus succeeded in 0.00 seconds (__init__:312)
2020-07-02 12:43:26,645+0200 INFO (jsonrpc/3) [vdsm.api] START
getStoragePoolInfo(spUUID=u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
options=None) from=::ffff:$ENGINE_IP,39304, flow_id=4968c8cb,
task_id=ab1124bc-651d-4ade-aae4-ff9fea23f6a0 (api:48)
2020-07-02 12:43:26,646+0200 INFO (jsonrpc/3) [vdsm.api] FINISH
getStoragePoolInfo return={'info': {'name': 'No Description',
'isoprefix':
'', 'pool_status': 'connected', 'lver': -1,
'domains':
u'6775c41c-7d67-451b-8beb-4fd086eade2e:Active', 'master_uuid':
u'6775c41c-7d67-451b-8beb-4fd086eade2e', 'version': '5',
'spm_id': 1,
'type': 'LOCALFS', 'master_ver': 1}, 'dominfo':
{u'6775c41c-7d67-451b-8beb-4fd086eade2e': {'status': u'Active',
'diskfree':
'3563234983936', 'isoprefix': '', 'alerts': [],
'disktotal':
'3923683311616', 'version': 5}}} from=::ffff:$ENGINE_IP,39304,
flow_id=4968c8cb, task_id=ab1124bc-651d-4ade-aae4-ff9fea23f6a0 (api:54)
2020-07-02 12:43:26,647+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC
call StoragePool.getInfo succeeded in 0.01 seconds (__init__:312)
5) His task seems block any other export tasks, leave them in pending.
There were about 5 export tasks and 1 import temaplte task and as soon we
killed the following process, the other 4 tasks and the import one
completed after few minutes.
2020-07-02 04:43:21,339+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.PrepareImageVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] START,
PrepareImageVDSCommand(HostName = $OVIRT_HOST,
PrepareImageVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 28c880d12020-07-02 04:43:21,650+02 INFO
[org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb] Executing
Ansible command: ANSIBLE_STDOUT_CALLBACK=imagemeasureplugin
/usr/bin/ansible-playbook --ssh-common-args=-F
/var/lib/ovirt-engine/.ssh/config
--private-key=/etc/pki/ovirt-engine/keys/engine_id_rsa
--inventory=/tmp/ansible-inventory1121551177697847734
--extra-vars=image_path="/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04"
/usr/share/ovirt-engine/playbooks/ovirt-image-measure.yml [Logfile:
/var/log/ovirt-engine/ova
/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log]
The process that we killed was:
vdsm 25338 25332 99 04:14 pts/0 07:40:09 qemu-img measure -O qcow2
/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/55b3eac5-05b2-4bae-be50-37cde705069
A strace -p of the PID 25338 showed following lines:
lseek(11, 3056795648, SEEK_DATA) = 3056795648
lseek(11, 3056795648, SEEK_HOLE) = 13407092736
lseek(14, 128637468672, SEEK_DATA) = 128637468672
lseek(14, 128637468672, SEEK_HOLE) = 317708828672
lseek(14, 128646250496, SEEK_DATA) = 128646250496
lseek(14, 128646250496, SEEK_HOLE) = 317708828672
lseek(14, 128637730816, SEEK_DATA) = 128637730816
lseek(14, 128637730816, SEEK_HOLE) = 317708828672
lseek(14, 128646774784, SEEK_DATA) = 128646774784
lseek(14, 128646774784, SEEK_HOLE) = 317708828672
lseek(14, 128646709248, SEEK_DATA) = 128646709248
Can yu help us figuring out what is going on?
If any other informations is needed I'll provide 'em ASAP.
Thank you for your patience and your time,
Regards
Francesco
_______________________________________________
Devel mailing list -- devel(a)ovirt.org
To unsubscribe send an email to devel-leave(a)ovirt.org
Privacy Statement: https://www.ovirt.org/privacy-policy.html
oVirt Code of Conduct:
https://www.ovirt.org/community/about/community-guidelines/
List Archives:
https://lists.ovirt.org/archives/list/devel@ovirt.org/message/DUYQNBUXV67...
--
Regards,
Eyal Shenitzky
4:49 p.m.
Hi Eyal,
done! https://bugzilla.redhat.com/show_bug.cgi?id=1855782
Thank you for your time,
Francesco
Il 08/07/2020 08:03, Eyal Shenitzky ha scritto:
Hi Francesco,
Can you please submit a bug too -
https://bugzilla.redhat.com/enter_bug.cgi?product=ovirt-engine
Please add the steps you are doing when this bug occurs and all the
relevant logs (engine and VDSM logs etc..)
Thanks
On Tue, 7 Jul 2020 at 16:22, francesco--- via Devel <devel(a)ovirt.org
<mailto:devel@ovirt.org>> wrote:
Hi all,
everyday at 01:00 AM we perform a daily backup on many VMs hosted
in multiple hosts (all with oVirt 4.3) using a custom sciprt
written in python3 (using SDK) and everything works "almost" fine.
There is one single VM (Windows Server 2016) with a disk of 600 GB
(the real disk usage is about 150 GB) hosted on a single node that
has a strange behaviour.
1) The export start after a few seconds of the execution of the
script, we use "vm_service.export_to_path_on_host" class for
exporting the VM as ova file;
2) After few minutes i see in the engine the command "START,
DumpXmlsVDSCommand" that is completely istantly both on the host
side ad the engine side, and it's fine:
2020-07-02 01:05:45,428+0200 INFO (jsonrpc/7) [api.host] START
dumpxmls(vmList=[u'10e88cab-ec4f-4491-b51f-94e3d2e81a0a'])
from=::ffff:$ENGINE_IP,39308 (api:48)
2020-07-02 01:05:45,428+0200 INFO (jsonrpc/7) [api.host] FINISH
dumpxmls return={... LONG XML ...}
3) after 3 hours i see the following logs about the export task:
2020-07-02 04:11:39,201+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-91)
[895d6936-f45c-4766-afd4-408a4e4e9a41] START,
GetVolumeInfoVDSCommand(HostName = $OVIRT_HOST,
GetVolumeInfoVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697'}), log id: 3cbf2c7c
2020-07-02 04:11:39,299+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetQemuImageInfoVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-91)
[895d6936-f45c-4766-afd4-408a4e4e9a41] START,
GetQemuImageInfoVDSCommand(HostName = $OVIRT_HOST,
GetVolumeInfoVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697'}), log id: 47d5122e
2020-07-02 04:43:21,339+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.PrepareImageVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb]
START, PrepareImageVDSCommand(HostName = $OVIRT_HOST,
PrepareImageVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 28c880d12020-07-02 04:43:21,650+02 INFO
[org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb]
Executing Ansible command:
ANSIBLE_STDOUT_CALLBACK=imagemeasureplugin
/usr/bin/ansible-playbook --ssh-common-args=-F
/var/lib/ovirt-engine/.ssh/config
--private-key=/etc/pki/ovirt-engine/keys/engine_id_rsa
--inventory=/tmp/ansible-inventory1121551177697847734
--extra-vars=image_path="/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04"
/usr/share/ovirt-engine/playbooks/ovirt-image-measure.yml
[Logfile: /var/log/ovirt-engine/ova
/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log]
2020-07-02 05:05:20,428+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-8) [64c95c4d]
START, UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 666809cb
2020-07-02 05:05:22,104+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-8) [64c95c4d]
START, UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 33ff46bf
2020-07-02 05:05:29,602+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-287) [64c95c4d] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='e40a2740-37f6-455d-bed7-554efef761ff'}), log id: f01ff26
2020-07-02 05:05:29,619+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-269) [64c95c4d] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='1c94df38-88c1-4bf8-89a2-8c322513b21b'}), log id: 6150e13b
4) And then, after several hours, the export fail with the
following logs:
engine logs.
2020-07-02 12:43:21,653+02 ERROR
[org.ovirt.engine.core.bll.CreateOvaCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb]
Failed to measure image: null. Please check logs for more details:
/var/log/ovirt-engine/ova/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log
2020-07-02 12:43:23,741+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-28) [] EVENT_ID:
IMPORTEXPORT_EXPORT_VM_TO_OVA_FAILED(1,225), Failed to export Vm
$OVIRT_VM_TO_EXPORT as a Virtual Appliance to path
/backup/$OVIRT_VM_TO_EXPORT_daily_2020Jul02.ova on Host $OVIRT_HOST
2020-07-02 12:43:26,162+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8]
START, MergeVDSCommand(HostName = $OVIRT_HOST,
MergeVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697',
baseImageId='5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topImageId='55b3eac5-05b2-4bae-be50-37cde7050697',
bandwidth='0'}), log id: a0b417d
2020-07-02 12:43:26,328+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8]
EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM $OVIRT_HOST
command MergeVDS failed: Merge failed
2020-07-02 12:43:26,328+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8]
HostName = $OVIRT_HOST
2020-07-02 12:43:26,328+02 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-9) [54b569e8]
Command 'MergeVDSCommand(HostName = $OVIRT_HOST,
MergeVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a',
storagePoolId='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
storageDomainId='6775c41c-7d67-451b-8beb-4fd086eade2e',
imageGroupId='a084fa36-0f93-45c2-a323-ea9ca2d16677',
imageId='55b3eac5-05b2-4bae-be50-37cde7050697',
baseImageId='5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topImageId='55b3eac5-05b2-4bae-be50-37cde7050697',
bandwidth='0'})' execution failed: VDSGenericException:
VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52
2020-07-02 12:43:28,996+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand]
(EE-ManagedThreadFactory-commandCoordinator-Thread-2) [54b569e8]
START, DumpXmlsVDSCommand(HostName = $OVIRT_HOST,
Params:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
vmIds='[10e88cab-ec4f-4491-b51f-94e3d2e81a0a]'}), log id: 65709a96
2020-07-02 13:05:38,206+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-45) [5179fcb]
START, UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 44e9ec23
2020-07-02 13:05:39,851+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-45) [5179fcb]
START, UploadStreamVDSCommand(HostName = $OVIRT_HOST,
UploadStreamVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 68231c70
2020-07-02 13:05:40,356+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-240) [5179fcb] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='5d61682b-cf47-4637-9014-c647eb5265ee'}), log id: 718885f3
2020-07-02 13:05:50,357+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-290) [5179fcb] START,
HSMClearTaskVDSCommand(HostName = $OVIRT_HOST,
HSMTaskGuidBaseVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5',
taskId='5709eb6c-a656-4a4d-b67f-72dd0bebf3e4'}), log id: 40c18d57
And here the vdsm.log of the host:
2020-07-02 12:43:26,169+0200 INFO (jsonrpc/6) [api.virt] START
merge(drive={u'imageID': u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
u'volumeID': u'55b3eac5-05b2-4bae-be50-37cde7050697',
u'domainID':
u'6775c41c-7d67-451b-8beb-4fd086eade2e', u'poolID':
u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84'},
baseVolUUID=u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04',
topVolUUID=u'55b3eac5-05b2-4bae-be50-37cde7050697',
bandwidth=u'0', jobUUID=u'b49fa67b-4a5a-4f73-823f-9e33a8e20cd2')
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
vmId=10e88cab-ec4f-4491-b51f-94e3d2e81a0a (api:48)
2020-07-02 12:43:26,196+0200 INFO (jsonrpc/6) [vdsm.api] START
getVolumeInfo(sdUUID=u'6775c41c-7d67-451b-8beb-4fd086eade2e',
spUUID='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
imgUUID=u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
volUUID=u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', options=None)
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=bb1d1fd0-9746-4949-9c6c-b069947f5875 (api:48)
2020-07-02 12:43:26,199+0200 INFO (jsonrpc/6)
[storage.VolumeManifest] Info request:
sdUUID=6775c41c-7d67-451b-8beb-4fd086eade2e
imgUUID=a084fa36-0f93-45c2-a323-ea9ca2d16677 volUUID =
5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04 (volume:240)
2020-07-02 12:43:26,205+0200 INFO (jsonrpc/6)
[storage.VolumeManifest]
6775c41c-7d67-451b-8beb-4fd086eade2e/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04
info is {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype':
'INTERNAL',
'description': '', 'parent':
'7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013', 'format': 'COW',
'generation': 0, 'image':
'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL',
'mtime': '0',
'apparentsize': '6635716608', 'children': [], 'pool':
'', 'ctime':
'1593558283', 'capacity': '644245094400', 'uuid':
u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', 'truesize':
'6637277184',
'type': 'SPARSE'} (volume:279)
2020-07-02 12:43:26,205+0200 INFO (jsonrpc/6) [vdsm.api] FINISH
getVolumeInfo return={'info': {'status': 'OK',
'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype':
'INTERNAL',
'description': '', 'parent':
'7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013', 'format': 'COW',
'generation': 0, 'image':
'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL',
'mtime': '0',
'apparentsize': '6635716608','children': [], 'pool':
'', 'ctime':
'1593558283', 'capacity': '644245094400', 'uuid':
u'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', 'truesize':
'6637277184',
'type': 'SPARSE'}} from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=bb1d1fd0-9746-4949-9c6c-b069947f5875 (api:54)
2020-07-02 12:43:26,206+0200 INFO (jsonrpc/6) [vdsm.api] START
getVolumeInfo(sdUUID=u'6775c41c-7d67-451b-8beb-4fd086eade2e',
spUUID='79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
imgUUID=u'a084fa36-0f93-45c2-a323-ea9ca2d16677',
volUUID=u'55b3eac5-05b2-4bae-be50-37cde7050697', options=None)
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=32ce9b21-b9f3-4319-a229-b32df1fb9283 (api:48)
2020-07-02 12:43:26,208+0200 INFO (jsonrpc/6)
[storage.VolumeManifest] Info request:
sdUUID=6775c41c-7d67-451b-8beb-4fd086eade2e
imgUUID=a084fa36-0f93-45c2-a323-ea9ca2d16677 volUUID =
55b3eac5-05b2-4bae-be50-37cde7050697 (volume:240)
2020-07-02 12:43:26,219+0200 INFO (jsonrpc/6)
[storage.VolumeManifest]
6775c41c-7d67-451b-8beb-4fd086eade2e/a084fa36-0f93-45c2-a323-ea9ca2d16677/55b3eac5-05b2-4bae-be50-37cde7050697
info is {'status': 'OK', 'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype': 'LEAF',
'description': '', 'parent':
'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', 'format': 'COW',
'generation': 0, 'image':
'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL',
'mtime': '0',
'apparentsize': '4077387776', 'children': [], 'pool':
'', 'ctime':
'1593644682', 'capacity': '644245094400', 'uuid':
u'55b3eac5-05b2-4bae-be50-37cde7050697', 'truesize':
'4077940736',
'type': 'SPARSE'} (volume:279)
2020-07-02 12:43:26,219+0200 INFO (jsonrpc/6) [vdsm.api] FINISH
getVolumeInfo return={'info': {'status': 'OK',
'domain':
'6775c41c-7d67-451b-8beb-4fd086eade2e', 'voltype': 'LEAF',
'description': '', 'parent':
'5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04', 'format': 'COW',
'generation': 0, 'image':
'a084fa36-0f93-45c2-a323-ea9ca2d16677',
'disktype': 'DATA', 'legality': 'LEGAL',
'mtime': '0',
'apparentsize': '4077387776', 'children': [], 'pool':
'', 'ctime':
'1593644682', 'capacity': '644245094400', 'uuid':
u'55b3eac5-05b2-4bae-be50-37cde7050697', 'truesize':
'4077940736',
'type': 'SPARSE'}} from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
task_id=32ce9b21-b9f3-4319-a229-b32df1fb9283 (api:54)
2020-07-02 12:43:26,235+0200 INFO (jsonrpc/6) [virt.vm]
(vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a') Starting merge with
jobUUID=u'b49fa67b-4a5a-4f73-823f-9e33a8e20cd2', original
chain=e2bad960-6ad4-44b6-8ff0-69dcca6bf722 <
7e802d0d-d6cd-4979-8f8d-5f4c5d5c3013 <
5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04 <
55b3eac5-05b2-4bae-be50-37cde7050697 (top), disk='sda',
base='sda[1]', top=None, bandwidth=0, flags=12 (vm:5951)
2020-07-02 12:43:26,280+0200 ERROR (jsonrpc/6) [virt.vm]
(vmId='10e88cab-ec4f-4491-b51f-94e3d2e81a0a') Live merge failed
(job: b49fa67b-4a5a-4f73-823f-9e33a8e20cd2) (vm:5957)
2020-07-02 12:43:26,296+0200 INFO (jsonrpc/6) [api.virt] FINISH
merge return={'status': {'message': 'Merge failed',
'code': 52}}
from=::ffff:$ENGINE_IP,39308, flow_id=54b569e8,
vmId=10e88cab-ec4f-4491-b51f-94e3d2e81a0a (api:54)
2020-07-02 12:43:26,296+0200 INFO (jsonrpc/6)
[jsonrpc.JsonRpcServer] RPC call VM.merge failed (error 52) in
0.13 seconds (__init__:312)
2020-07-02 12:43:26,627+0200 INFO (jsonrpc/1) [vdsm.api] START
getSpmStatus(spUUID=u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
options=None) from=::ffff:$ENGINE_IP,39308, flow_id=4968c8cb,
task_id=ee82b2d6-39f5-43ad-83a3-803f1af8e234 (api:48)
2020-07-02 12:43:26,628+0200 INFO (jsonrpc/1) [vdsm.api] FINISH
getSpmStatus return={'spm_st': {'spmId': 1, 'spmStatus':
'SPM',
'spmLver': -1}} from=::ffff:$ENGINE_IP,39308, flow_id=4968c8cb,
task_id=ee82b2d6-39f5-43ad-83a3-803f1af8e234 (api:54)
2020-07-02 12:43:26,628+0200 INFO (jsonrpc/1)
[jsonrpc.JsonRpcServer] RPC call StoragePool.getSpmStatus
succeeded in 0.00 seconds (__init__:312)
2020-07-02 12:43:26,645+0200 INFO (jsonrpc/3) [vdsm.api] START
getStoragePoolInfo(spUUID=u'79d774b7-ca5b-49c2-baf8-9275ba3f1a84',
options=None) from=::ffff:$ENGINE_IP,39304, flow_id=4968c8cb,
task_id=ab1124bc-651d-4ade-aae4-ff9fea23f6a0 (api:48)
2020-07-02 12:43:26,646+0200 INFO (jsonrpc/3) [vdsm.api] FINISH
getStoragePoolInfo return={'info': {'name': 'No
Description',
'isoprefix': '', 'pool_status': 'connected',
'lver': -1,
'domains': u'6775c41c-7d67-451b-8beb-4fd086eade2e:Active',
'master_uuid': u'6775c41c-7d67-451b-8beb-4fd086eade2e',
'version':
'5', 'spm_id': 1, 'type': 'LOCALFS',
'master_ver': 1}, 'dominfo':
{u'6775c41c-7d67-451b-8beb-4fd086eade2e': {'status':
u'Active',
'diskfree': '3563234983936', 'isoprefix': '',
'alerts': [],
'disktotal': '3923683311616', 'version': 5}}}
from=::ffff:$ENGINE_IP,39304, flow_id=4968c8cb,
task_id=ab1124bc-651d-4ade-aae4-ff9fea23f6a0 (api:54)
2020-07-02 12:43:26,647+0200 INFO (jsonrpc/3)
[jsonrpc.JsonRpcServer] RPC call StoragePool.getInfo succeeded in
0.01 seconds (__init__:312)
5) His task seems block any other export tasks, leave them in
pending. There were about 5 export tasks and 1 import temaplte
task and as soon we killed the following process, the other 4
tasks and the import one completed after few minutes.
2020-07-02 04:43:21,339+02 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.PrepareImageVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb]
START, PrepareImageVDSCommand(HostName = $OVIRT_HOST,
PrepareImageVDSCommandParameters:{hostId='e8c07142-fcd8-4f78-9158-ffb2caa06dc5'}),
log id: 28c880d12020-07-02 04:43:21,650+02 INFO
[org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor]
(EE-ManagedThreadFactory-engineScheduled-Thread-19) [312261bb]
Executing Ansible command:
ANSIBLE_STDOUT_CALLBACK=imagemeasureplugin
/usr/bin/ansible-playbook --ssh-common-args=-F
/var/lib/ovirt-engine/.ssh/config
--private-key=/etc/pki/ovirt-engine/keys/engine_id_rsa
--inventory=/tmp/ansible-inventory1121551177697847734
--extra-vars=image_path="/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/5b76cc6c-1a6b-4e02-8ce4-dc80faf9ed04"
/usr/share/ovirt-engine/playbooks/ovirt-image-measure.yml
[Logfile: /var/log/ovirt-engine/ova
/ovirt-image-measure-ansible-20200702044321-$OVIRT_HOST-312261bb.log]
The process that we killed was:
vdsm 25338 25332 99 04:14 pts/0 07:40:09 qemu-img measure
-O qcow2
/rhev/data-center/mnt/_data/6775c41c-7d67-451b-8beb-4fd086eade2e/images/a084fa36-0f93-45c2-a323-ea9ca2d16677/55b3eac5-05b2-4bae-be50-37cde705069
A strace -p of the PID 25338 showed following lines:
lseek(11, 3056795648, SEEK_DATA) = 3056795648
lseek(11, 3056795648, SEEK_HOLE) = 13407092736
lseek(14, 128637468672, SEEK_DATA) = 128637468672
lseek(14, 128637468672, SEEK_HOLE) = 317708828672
lseek(14, 128646250496, SEEK_DATA) = 128646250496
lseek(14, 128646250496, SEEK_HOLE) = 317708828672
lseek(14, 128637730816, SEEK_DATA) = 128637730816
lseek(14, 128637730816, SEEK_HOLE) = 317708828672
lseek(14, 128646774784, SEEK_DATA) = 128646774784
lseek(14, 128646774784, SEEK_HOLE) = 317708828672
lseek(14, 128646709248, SEEK_DATA) = 128646709248
Can yu help us figuring out what is going on?
If any other informations is needed I'll provide 'em ASAP.
Thank you for your patience and your time,
Regards
Francesco
_______________________________________________
Devel mailing list -- devel(a)ovirt.org <mailto:devel@ovirt.org>
To unsubscribe send an email to devel-leave(a)ovirt.org
<mailto:devel-leave@ovirt.org>
Privacy Statement: https://www.ovirt.org/privacy-policy.html
oVirt Code of Conduct:
https://www.ovirt.org/community/about/community-guidelines/
List Archives:
https://lists.ovirt.org/archives/list/devel@ovirt.org/message/DUYQNBUXV67...
--
Regards,
Eyal Shenitzky
--
--
Shellrent - Il primo hosting italiano Security First
*Francesco Lorenzini*
/System Administrator & DevOps Engineer/
Shellrent Srl
Via dell'Edilizia, 19 - 36100 Vicenza
Tel. 0444321155 <tel:+390444321155> | Fax 04441492177
1596
days inactive
1603
days old
2 comments
3 participants
participants (3)
-
Eyal Shenitzky -
Francesco -
francesco＠shellrent.com