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:
Patches ready for 4.1.3. Re-targeting.
Verified with the following code: ------------------------------------- ovirt-engine-4.2.0-0.0.master.20170523140304.git04be891.el7.centos.noarch vdsm-4.20.0-917.gitf237136.el7.centos.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 are now displayed in the vdsm.log The line: 2017-05-28 11:33:50,074+0300 INFO (jsonrpc/0) [virt.vm] (vmId='83fb6a43-35c2-4809-bc96-8197eaf5ede7') Starting merge with jobUUID=u'7c907432-70be-4d53-bee7-aecddd13b145', original chain=845 a7496-0bd2-457a-abfd-86731aef66c4 < d1e1705e-2ae1-4349-a182-02d0bb01e10c < a6ce9c5c-f274-4a3d-a8cb-768dbbb494a1 < 7fda31df-2b87-4d18-a856-44d2ab0dedf5 (top), disk='sdb', base='sdb[2]', top=' sdb[1]', bandwidth=0, flags=8 (vm:5035) includes the 'original chain' item. Moving to VERIFIED!
Adding all output from logs: ----------------------------------------- Engine.log 2017-05-28 11:33:47,665+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-6) [] EVENT_ID: USER_REMOVE_SNAPSHOT(342), Snapshot 'snap2' deletion for VM 'vm55' was initiated by admin@internal-authz. 2017-05-28 11:33:47,715+03 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-2) [7933a5b9-d436-4204-b230-1d319445eeef] Running command: MergeExtendCommand internal: true. E ntities affected : ID: ab217695-7e38-4684-90c7-9c356b941caa Type: Storage 2017-05-28 11:33:47,716+03 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-2) [7933a5b9-d436-4204-b230-1d319445eeef] Base and top image sizes are the same; no image size update required . . . 2017-05-28 11:35:08,838+03 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (DefaultQuartzScheduler1) [7933a5b9-d436-4204-b230-1d319445eeef] Ending command 'org.ovirt.engine .core.bll.snapshots.RemoveSnapshotCommand' successfully. 2017-05-28 11:35:08,890+03 DEBUG [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] (DefaultQuartzScheduler4) [] Rescheduling DEFAULT.org.ovirt.engine.core.vdsbroker.VdsManager.onTime r#-9223372036854775715 as there is no unfired trigger. 2017-05-28 11:35:08,898+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler1) [7933a5b9-d436-4204-b230-1d319445eeef] EVENT_ID: USER_REMOVE_SNAPSHOT_FINISHED_SUCCESS(356), Snapshot 'snap2' deletion for VM 'vm55' has been completed. vdsm.log 2017-05-28 11:33:50,061+0300 DEBUG (jsonrpc/0) [storage.ResourceManager] No one is waiting for resource '00_storage.ab217695-7e38-4684-90c7-9c356b941caa', Clearing records. (resourceManager: 602) 2017-05-28 11:33:50,062+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='20e424a7-5409-4cdd-8915-628d3559e191') ref 0 aborting False (task:998) 2017-05-28 11:33:50,074+0300 INFO (jsonrpc/0) [virt.vm] (vmId='83fb6a43-35c2-4809-bc96-8197eaf5ede7') Starting merge with jobUUID=u'7c907432-70be-4d53-bee7-aecddd13b145', original chain=845 a7496-0bd2-457a-abfd-86731aef66c4 < d1e1705e-2ae1-4349-a182-02d0bb01e10c < a6ce9c5c-f274-4a3d-a8cb-768dbbb494a1 < 7fda31df-2b87-4d18-a856-44d2ab0dedf5 (top), disk='sdb', base='sdb[2]', top=' sdb[1]', bandwidth=0, flags=8 (vm:5035) 2017-05-28 11:33:50,094+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='a111d689-b253-4d13-bfc4-258bc9dc7a1f') moving from state init -> state preparing (task:600) 2017-05-28 11:33:50,094+0300 INFO (jsonrpc/0) [vdsm.api] START sendExtendMsg(spUUID=u'00000001-0001-0001-0001-000000000311', volDict={'newSize': 3221225472, 'domainID': u'ab217695-7e38-4684 -90c7-9c356b941caa', 'name': 'sdb', 'volumeID': u'd1e1705e-2ae1-4349-a182-02d0bb01e10c', 'imageID': u'4dc14d7a-b4f7-4080-8f3d-fd6d275d0808', 'internal': True, 'poolID': u'00000001-0001-0001- 0001-000000000311'}, newSize=3221225472, callbackFunc=<bound method Vm.__afterVolumeExtension of <virt.vm.Vm object at 0x2e2d850>>) from=::ffff:10.35.161.8,35160, flow_id=7933a5b9-d436-4204- b230-1d319445eeef (api:46) 2017-05-28 11:33:50,095+0300 DEBUG (jsonrpc/0) [storage.SPM.Messages.Extend] new extend msg created: domain: ab217695-7e38-4684-90c7-9c356b941caa, volume: d1e1705e-2ae1-4349-a182-02d0bb01e10 c (mailbox:123) 2017-05-28 11:33:50,095+0300 INFO (jsonrpc/0) [vdsm.api] FINISH sendExtendMsg return=None from=::ffff:10.35.161.8,35160, flow_id=7933a5b9-d436-4204-b230-1d319445eeef (api:52) 2017-05-28 11:33:50,096+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='a111d689-b253-4d13-bfc4-258bc9dc7a1f') finished: None (task:1196) 2017-05-28 11:33:50,096+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='a111d689-b253-4d13-bfc4-258bc9dc7a1f') moving from state preparing -> state finished (task:600) 2017-05-28 11:33:50,096+0300 DEBUG (jsonrpc/0) [storage.ResourceManager.Owner] Owner.releaseAll requests {} resources {} (resourceManager:913) 2017-05-28 11:33:50,096+0300 DEBUG (jsonrpc/0) [storage.ResourceManager.Owner] Owner.cancelAll requests {} (resourceManager:950) 2017-05-28 11:33:50,096+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='a111d689-b253-4d13-bfc4-258bc9dc7a1f') ref 0 aborting False (task:998) 2017-05-28 11:33:50,107+0300 INFO (jsonrpc/0) [virt.vm] (vmId='83fb6a43-35c2-4809-bc96-8197eaf5ede7') Libvirt job 7a3290ab-51c2-4bc8-a42f-6eb85c89b6ad was terminated (vm:4915) 2017-05-28 11:33:50,107+0300 INFO (jsonrpc/0) [virt.vm] (vmId='83fb6a43-35c2-4809-bc96-8197eaf5ede7') Starting cleanup thread for job: 7a3290ab-51c2-4bc8-a42f-6eb85c89b6ad (vm:4923) 2017-05-28 11:33:50,108+0300 INFO (jsonrpc/0) [vdsm.api] FINISH merge return={'status': {'message': 'Done', 'code': 0}} from=::ffff:10.35.161.8,35160, flow_id=7933a5b9-d436-4204-b230-1d3194 45eeef (api:52) 2017-05-28 11:33:50,109+0300 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call VM.merge succeeded in 0.59 seconds (__init__:585) 2017-05-28 11:33:50,110+0300 DEBUG (merge/83fb6a43) [storage.TaskManager.Task] (Task='c30956d0-4d39-4e81-94c9-ed9812b4f576') moving from state init -> state preparing (task:600) 2017-05-28 11:33:50,110+0300 INFO (merge/83fb6a43) [vdsm.api] START getVolumeInfo(sdUUID=u'ab217695-7e38-4684-90c7-9c356b941caa', spUUID=u'00000001-0001-0001-0001-000000000311', imgUUID=u'4 4af6690-2844-4a6f-af5c-6a033ac2896a', volUUID=u'addaaef2-69c2-491a-a26b-3cec6cbe2585', options=None) from=internal (api:46) 2017-05-28 11:33:50,111+0300 DEBUG (merge/83fb6a43) [storage.ResourceManager] Trying to register resource '00_storage.ab217695-7e38-4684-90c7-9c356b941caa' for lock type 'shared' (resourceMa nager:496) 2017-05-28 11:33:50,111+0300 DEBUG (merge/83fb6a43) [storage.ResourceManager] Resource '00_storage.ab217695-7e38-4684-90c7-9c356b941caa' is free. Now locking as 'shared' (1 active user) (res ourceManager:554) ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- tailf vdsm.log|egrep 'Pivot com|libvirt chain|nlinking|Leaf volume|Setting parent|XML up|VM.merge' 2017-05-28 11:33:49,924+0300 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call VM.merge succeeded in 0.67 seconds (__init__:585) 2017-05-28 11:33:50,109+0300 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call VM.merge succeeded in 0.59 seconds (__init__:585) 2017-05-28 11:33:50,643+0300 INFO (merge/83fb6a43) [storage.Image] Unlinking subchain: ['addaaef2-69c2-491a-a26b-3cec6cbe2585'] (image:1223) 2017-05-28 11:33:50,728+0300 INFO (merge/83fb6a43) [storage.Image] Setting parent of volume 4a605fa2-318e-428f-a83e-0736fb86aebc to 95e268aa-a6d7-4318-88b3-fc68e6990333 (image:1236) 2017-05-28 11:33:51,000+0300 INFO (merge/83fb6a43) [storage.StorageDomainManifest] Unlinking volme runtime link: u'/var/run/vdsm/storage/ab217695-7e38-4684-90c7-9c356b941caa/44af6690-2844-4a6f-af5c-6a033ac2896a/addaaef2-69c2-491a-a26b-3cec6cbe2585' (blockSD:917) 2017-05-28 11:34:00,163+0300 INFO (merge/83fb6a43) [storage.Image] Unlinking subchain: ['a6ce9c5c-f274-4a3d-a8cb-768dbbb494a1'] (image:1223) 2017-05-28 11:34:00,241+0300 INFO (merge/83fb6a43) [storage.Image] Setting parent of volume 7fda31df-2b87-4d18-a856-44d2ab0dedf5 to d1e1705e-2ae1-4349-a182-02d0bb01e10c (image:1236) 2017-05-28 11:34:00,519+0300 INFO (merge/83fb6a43) [storage.StorageDomainManifest] Unlinking volme runtime link: u'/var/run/vdsm/storage/ab217695-7e38-4684-90c7-9c356b941caa/4dc14d7a-b4f7-4080-8f3d-fd6d275d0808/a6ce9c5c-f274-4a3d-a8cb-768dbbb494a1' (blockSD:917) 2017-05-28 11:34:18,270+0300 DEBUG (tasks/2) [storage.Volume] Unlinking /rhev/data-center/mnt/blockSD/ab217695-7e38-4684-90c7-9c356b941caa/images/44af6690-2844-4a6f-af5c-6a033ac2896a/addaaef2-69c2-491a-a26b-3cec6cbe2585 (blockVolume:664) 2017-05-28 11:34:41,574+0300 DEBUG (tasks/8) [storage.Volume] Unlinking /rhev/data-center/mnt/blockSD/ab217695-7e38-4684-90c7-9c356b941caa/images/4dc14d7a-b4f7-4080-8f3d-fd6d275d0808/a6ce9c5c-f274-4a3d-a8cb-768dbbb494a1 (blockVolume:664)
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-2018:1489
BZ<2>Jira Resync