+++ This bug is a downstream clone. The original bug is: +++ +++ bug 1428147 +++ ====================================================================== Description of problem: In previous releases, the "libvirt chain" message was displayed during a live merge in the vdsm logs. It was very useful in being able to determine if a merge had actually been successful or not when reviewing logs of a live merge failure. In 4.1 it isn't displayed by default as it is a DEBUG message. Version-Release number of selected component (if applicable): RHV 4.1 How reproducible: Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info: (Originally by Gordon Watson)
Patches ready for 4.1.3. Re-targeting. (Originally by Adam Litke)
Verified with the following code: -------------------------------------- ovirt-engine-4.1.3-0.1.el7.noarch rhevm-4.1.3-0.1.el7.noarch vdsm-4.19.16-1.el7ev.x86_64 Verified with the following scenario: -------------------------------------- 1. Create a VM with 2 disks and start the VM 2. Create snapshots snap1, snap2, snap3 3. Delete snap2 and live merge is performed >>>> The required lines "original chain" are now displayed in the vdsm.log Moving to VERIFIED! vdsm.log ------------------------------------------ 2017-06-05 12:15:11,120+0300 INFO (jsonrpc/0) [virt.vm] (vmId='f26c20c8-7320-4b3e-b833-4cff9ed83353') Starting merge with jobUUID='fdb5c314-6a7e-4377-987e-3e0251b19141' original chain=043a6a76-7dda-4686-a3da-05514c20a7b6 < dfd6294f-29bd-4ad3-9b8f-ed9526e9325b < 2a9959ac-ffe3-4082-94d4-93f7b95d82b0 < d4260c6e-f2be-483a-a643-47e95fe652d2 < e99648d8-8198-46ae-a9bb-175ab652699f (top) (vm:4879) 2017-06-05 12:15:11,149+0300 INFO (jsonrpc/0) [vdsm.api] START sendExtendMsg(spUUID='00000001-0001-0001-0001-000000000311', volDict={'newSize': 3221225472, 'domainID': '5f6e0626-3a8c-41ed-b843-7a9290a4db5a', 'name': 'vda', 'volumeID': '2a9959ac-ffe3-4082-94d4-93f7b95d82b0', 'imageID': 'd68319a1-e84f-4ed2-997d-d4d326bdfbcb', 'internal': True, 'poolID': '00000001-0001-0001-0001-000000000311'}, newSize=3221225472, callbackFunc=<bound method Vm.__afterVolumeExtension of <virt.vm.Vm object at 0x2fdccd0>>) from=::ffff:10.35.161.23,41148, flow_id=d4398914-d68b-480a-a8e5-96650be56960 (api:46) 2017-06-05 12:15:11,150+0300 INFO (jsonrpc/0) [vdsm.api] FINISH sendExtendMsg return=None from=::ffff:10.35.161.23,41148, flow_id=d4398914-d68b-480a-a8e5-96650be56960 (api:52) 2017-06-05 12:15:11,153+0300 INFO (jsonrpc/0) [virt.vm] (vmId='f26c20c8-7320-4b3e-b833-4cff9ed83353') Libvirt job 3e49bd53-85dd-4526-9e72-31e1a2570d25 was terminated (vm:4757) 2017-06-05 12:15:11,153+0300 INFO (jsonrpc/0) [virt.vm] (vmId='f26c20c8-7320-4b3e-b833-4cff9ed83353') Starting cleanup thread for job: 3e49bd53-85dd-4526-9e72-31e1a2570d25 (vm:4765) 2017-06-05 12:15:11,154+0300 INFO (jsonrpc/0) [vdsm.api] FINISH merge return={'status': {'message': 'Done', 'code': 0}} from=::ffff:10.35.161.23,41148, flow_id=d4398914-d68b-480a-a8e5-96650be56960 (api:52) 2017-06-05 12:15:11,154+0300 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call VM.merge succeeded in 0.54 seconds (__init__:539) 2017-06-05 12:15:11,156+0300 INFO (merge/f26c20c8) [vdsm.api] START getVolumeInfo(sdUUID='5f6e0626-3a8c-41ed-b843-7a9290a4db5a', spUUID='00000001-0001-0001-0001-000000000311', imgUUID='7cda9122-f4b6-4177-a21b-593c55c65ab7', volUUID='386b4bbf-c6f1-4796-9227-c58f07af7c5d', options=None) from=internal (api:46) 2017-06-05 12:15:11,157+0300 INFO (merge/f26c20c8) [storage.VolumeManifest] Info request: sdUUID=5f6e0626-3a8c-41ed-b843-7a9290a4db5a imgUUID=7cda9122-f4b6-4177-a21b-593c55c65ab7 volUUID = 386b4bbf-c6f1-4796-9227-c58f07af7c5d (volume:238) 2017-06-05 12:15:11,168+0300 INFO (merge/f26c20c8) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 12:15:11,169+0300 INFO (merge/f26c20c8) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 12:15:11,309+0300 WARN (libvirt/events) [virt.vm] (vmId='f26c20c8-7320-4b3e-b833-4cff9ed83353') unknown eventid 8 args ('/rhev/data-center/00000001-0001-0001-0001-000000000311/5f6e0626-3a8c-41ed-b843-7a9290a4db5a/images/d68319a1-e84f-4ed2-997d-d4d326bdfbcb/e99648d8-8198-46ae-a9bb-175ab652699f', 3, 0, 8) (clientIF:543) 2017-06-05 12:15:11,348+0300 INFO (merge/f26c20c8) [storage.VolumeManifest] 5f6e0626-3a8c-41ed-b843-7a9290a4db5a/7cda9122-f4b6-4177-a21b-593c55c65ab7/386b4bbf-c6f1-4796-9227-c58f07af7c5d info is {'status': 'OK', 'domain': '5f6e0626-3a8c-41ed-b843-7a9290a4db5a', 'voltype': 'INTERNAL', 'description': '', 'parent': 'e606976b-4243-47f4-a6e4-2f5ddbb8c7b3', 'format': 'COW', 'generation': 0, 'image': '7cda9122-f4b6-4177-a21b-593c55c65ab7', 'ctime': '1496652693', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1073741824', 'children': [], 'pool': '', 'capacity': '5368709120', 'uuid': '386b4bbf-c6f1-4796-9227-c58f07af7c5d', 'truesize': '1073741824', 'type': 'SPARSE', 'lease': {'owners': [], 'version': None}} (volume:272) 2017-06-05 12:15:11,349+0300 INFO (merge/f26c20c8) [vdsm.api] FINISH getVolumeInfo return={'info': {'status': 'OK', 'domain': '5f6e0626-3a8c-41ed-b843-7a9290a4db5a', 'voltype': 'INTERNAL', 'description': '', 'parent': 'e606976b-4243-47f4-a6e4-2f5ddbb8c7b3', 'format': 'COW', 'generation': 0, 'image': '7cda9122-f4b6-4177-a21b-593c55c65ab7', 'ctime': '1496652693', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1073741824', 'children': [], 'pool': '', 'capacity': '5368709120', 'uuid': '386b4bbf-c6f1-4796-9227-c58f07af7c5d', 'truesize': '1073741824', 'type': 'SPARSE', 'lease': {'owners': [], 'version': None}}} from=internal (api:52) 2017-06-05 12:15:11,350+0300 INFO (merge/f26c20c8) [vdsm.api] START setVolumeSize(sdUUID='5f6e0626-3a8c-41ed-b843-7a9290a4db5a', spUUID='00000001-0001-0001-0001-000000000311', imgUUID='7cda9122-f4b6-4177-a21b-593c55c65ab7', volUUID='e606976b-4243-47f4-a6e4-2f5ddbb8c7b3', capacity='5368709120') from=internal (api:46) 2017-06-05 12:15:11,365+0300 INFO (merge/f26c20c8) [vdsm.api] FINISH setVolumeSize return=None from=internal (api:52) 2017-06-05 12:15:11,366+0300 INFO (merge/f26c20c8) [virt.vm] (vmId='f26c20c8-7320-4b3e-b833-4cff9ed83353') Synchronizing volume chain after live merge (job 3e49bd53-85dd-4526-9e72-31e1a2570d25) (vm:5271) 2017-06-05 12:15:11,397+0300 INFO (merge/f26c20c8) [vdsm.api] START imageSyncVolumeChain(sdUUID='5f6e0626-3a8c-41ed-b843-7a9290a4db5a', imgUUID='7cda9122-f4b6-4177-a21b-593c55c65ab7', volUUID='ad4cf777-f9c6-4967-9ae0-cbe542e80eed', newChain=['e2d710fd-0f1f-44b3-82be-7fcd94a87e57', 'e606976b-4243-47f4-a6e4-2f5ddbb8c7b3', 'ad4cf777-f9c6-4967-9ae0-cbe542e80eed']) from=internal (api:46) 2017-06-05 12:15:11,623+0300 INFO (merge/f26c20c8) [storage.Image] Current chain=e2d710fd-0f1f-44b3-82be-7fcd94a87e57 < e606976b-4243-47f4-a6e4-2f5ddbb8c7b3 < 386b4bbf-c6f1-4796-9227-c58f07af7c5d < ad4cf777-f9c6-4967-9ae0-cbe542e80eed (top) (image:1266) 2017-06-05 12:15:11,624+0300 INFO (merge/f26c20c8) [storage.Image] Unlinking subchain: ['386b4bbf-c6f1-4796-9227-c58f07af7c5d'] (image:1276) 2017-06-05 12:15:11,732+0300 INFO (merge/f26c20c8) [storage.Image] Setting parent of volume ad4cf777-f9c6-4967-9ae0-cbe542e80eed to e606976b-4243-47f4-a6e4-2f5ddbb8c7b3 (image:1289) 2017-06-05 12:15:11,745+0300 INFO (merge/f26c20c8) [vdsm.api] FINISH imageSyncVolumeChain return=None from=internal (api:52) 2017-06-05 12:15:11,746+0300 INFO (merge/f26c20c8) [vdsm.api] START getVolumeInfo(sdUUID='5f6e0626-3a8c-41ed-b843-7a9290a4db5a', spUUID='00000001-0001-0001-0001-000000000311', imgUUID='7cda9122-f4b6-4177-a21b-593c55c65ab7', volUUID='ad4cf777-f9c6-4967-9ae0-cbe542e80eed', options=None) from=internal (api:46) 2017-06-05 12:15:11,747+0300 INFO (merge/f26c20c8) [storage.VolumeManifest] Info request: sdUUID=5f6e0626-3a8c-41ed-b843-7a9290a4db5a imgUUID=7cda9122-f4b6-4177-a21b-593c55c65ab7 volUUID = ad4cf777-f9c6-4967-9ae0-cbe542e80eed (volume:238) 2017-06-05 12:15:11,761+0300 INFO (merge/f26c20c8) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 12:15:11,762+0300 INFO (merge/f26c20c8) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 12:15:11,915+0300 INFO (merge/f26c20c8) [storage.VolumeManifest] 5f6e0626-3a8c-41ed-b843-7a9290a4db5a/7cda9122-f4b6-4177-a21b-593c55c65ab7/ad4cf777-f9c6-4967-9ae0-cbe542e80eed info : tail -f output ------------------------------------------ tailf vdsm.log|egrep 'Pivot com|libvirt chain|nlinking|Leaf volume|Setting parent|XML up|VM.merge' 2017-06-05 12:15:10,901+0300 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call VM.merge succeeded in 0.53 seconds (__init__:539) 2017-06-05 12:15:11,154+0300 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call VM.merge succeeded in 0.54 seconds (__init__:539) 2017-06-05 12:15:11,624+0300 INFO (merge/f26c20c8) [storage.Image] Unlinking subchain: ['386b4bbf-c6f1-4796-9227-c58f07af7c5d'] (image:1276) 2017-06-05 12:15:11,732+0300 INFO (merge/f26c20c8) [storage.Image] Setting parent of volume ad4cf777-f9c6-4967-9ae0-cbe542e80eed to e606976b-4243-47f4-a6e4-2f5ddbb8c7b3 (image:1289) 2017-06-05 12:15:12,052+0300 INFO (merge/f26c20c8) [storage.StorageDomainManifest] Unlinking volme runtime link: '/var/run/vdsm/storage/5f6e0626-3a8c-41ed-b843-7a9290a4db5a/7cda9122-f4b6-4177-a21b-593c55c65ab7/386b4bbf-c6f1-4796-9227-c58f07af7c5d' (blockSD:926) 2017-06-05 12:15:19,627+0300 INFO (merge/f26c20c8) [storage.Image] Unlinking subchain: ['d4260c6e-f2be-483a-a643-47e95fe652d2'] (image:1276) 2017-06-05 12:15:19,733+0300 INFO (merge/f26c20c8) [storage.Image] Setting parent of volume e99648d8-8198-46ae-a9bb-175ab652699f to 2a9959ac-ffe3-4082-94d4-93f7b95d82b0 (image:1289) 2017-06-05 12:15:20,255+0300 INFO (merge/f26c20c8) [storage.StorageDomainManifest] Unlinking volme runtime link: '/var/run/vdsm/storage/5f6e0626-3a8c-41ed-b843-7a9290a4db5a/d68319a1-e84f-4ed2-997d-d4d326bdfbcb/d4260c6e-f2be-483a-a643-47e95fe652d2' (blockSD:926) Engine.log ------------------------------------------ 2017-06-05 12:15:07,562+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-2) [] EVENT_ID: USER_REMOVE_SNAPSHOT(342), Correlation ID: d4398914-d68b-48 0a-a8e5-96650be56960, Job ID: 8dd05411-9076-4cc4-a447-8962432c8e11, Call Stack: null, Custom Event ID: -1, Message: Snapshot 'snappy2' deletion for VM 'vm12_from_tp' was initiated by admin@inte rnal-authz. 2017-06-05 12:15:08,048+03 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler6) [d4398914-d68b-480a-a8e5-96650be56960] Executing Live Merge command step 'EXTEND' . . . 2017-06-05 12:16:21,440+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler1) [d4398914-d68b-480a-a8e5-96650be56960] EVENT_ID: USER_REMOVE_SNAPSHOT_FINISHED_SUCCESS(356), Correlation ID: d4398914-d68b-480a-a8e5-96650be56960, Job ID: 8dd05411-9076-4cc4-a447-8962432c8e11, Call Stack: null, Custom Event ID: -1, Message: Snapshot 'snappy2' deletion for VM 'vm12_from_tp' has been completed.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHEA-2017:1696