+++ This bug was initially created as a clone of Bug #1415803 +++ Description of problem: Improve logging while performing live merge. Additional info: To verify, following message should be displayed in the vdsm.log (of course with different values): 2017-01-23 19:04:30,873 DEBUG (jsonrpc/5) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Checking job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4542) 2017-01-23 19:04:32,193 DEBUG (jsonrpc/5) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 live info {'end': 1409220608L, 'bandwidth': 0L, 'type': 4, 'cur': 1572864L} (vm:4570) 2017-01-23 19:05:07,371 DEBUG (periodic/2) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Checking job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4542) 2017-01-23 19:05:07,674 DEBUG (periodic/2) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 live info {'end': 1409417216L, 'bandwidth': 0L, 'type': 4, 'cur': 492175360L} (vm:4570) 2017-01-23 19:05:22,372 DEBUG (periodic/3) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Checking job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4542) 2017-01-23 19:05:22,525 DEBUG (periodic/3) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 live info {'end': 1409417216L, 'bandwidth': 0L, 'type': 4, 'cur': 669974528L} (vm:4570) >>> more >>> 2017-01-23 19:06:22,394 DEBUG (periodic/3) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 live info {'end': 1409417216L, 'bandwidth': 0L, 'type': 4, 'cur': 1409417216L} (vm:4570) 2017-01-23 19:06:22,394 INFO (periodic/3) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Starting cleanup thread for job: b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4587) 2017-01-23 19:06:37,390 DEBUG (periodic/2) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Checking job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4542) 2017-01-23 19:06:37,391 INFO (periodic/2) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Cleanup thread <virt.vm.LiveMergeCleanupThread object at 0x1cb2ed0> successfully completed, untracking job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 base volume 9a07f8c7-65f5-4761-9186-0327eb0fa5d3 top volume 8e5c3593-4042-43e7-a84c-16c482fa8336 (vm:4550) --- Additional comment from Sandro Bonazzola on 2017-01-25 09:56:01 IST --- 4.0.6 has been the last oVirt 4.0 release, please re-target this bug.
Tested with the following code: ------------------------------------------ ovirt-engine-4.0.7-0.1.el7ev.noarch rhevm-4.0.7-0.1.el7ev.noarch vdsm-4.19.4-1.el7ev.x86_64 Tested with the following scenario: ----------------------------------------- Engine and hosts are running in debug logging mode Created VM with a disk Wrote at least 1g of data to the disk Created snapshot sa1, sa2, sa3, sa4 Delete sa2 - live merge is successful None of the new logs appear in the vdsm.log The same scenario in 4.1.1 does generate the above logs Moving to ASSIGNED!
Created attachment 1255506 [details] server, vdsm, engine.log Adding logs
I verified that the tested build does not contain the changes. Looks that this patch is included in 4.19.5 and later builds. Kevin, can you please verify again with a newer build?
I see no problem, Ala is the 3.6.z backport problematic in any way?
Nope, 3.6.z patch (https://gerrit.ovirt.org/71695) already backported!
Hi Ala. This bug has been flagged as needing doc text for the Advisory. Please add the text so that I can review and edit it.
Hi Emma, is the doc text really required? This bug is all about log messages, no user experience changed. In any case, below are the new log messages (as listed in the bug description): 2017-01-23 19:04:30,873 DEBUG (jsonrpc/5) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Checking job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4542) 2017-01-23 19:04:32,193 DEBUG (jsonrpc/5) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 live info {'end': 1409220608L, 'bandwidth': 0L, 'type': 4, 'cur': 1572864L} (vm:4570) 2017-01-23 19:06:22,394 INFO (periodic/3) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Starting cleanup thread for job: b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4587) 2017-01-23 19:06:37,391 INFO (periodic/2) [virt.vm] (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Cleanup thread <virt.vm.LiveMergeCleanupThread object at 0x1cb2ed0> successfully completed, untracking job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 base volume 9a07f8c7-65f5-4761-9186-0327eb0fa5d3 top volume 8e5c3593-4042-43e7-a84c-16c482fa8336 (vm:4550)
(In reply to Ala Hino from comment #11) > Hi Emma, is the doc text really required? This bug is all about log > messages, no user experience changed. > > In any case, below are the new log messages (as listed in the bug > description): > > 2017-01-23 19:04:30,873 DEBUG (jsonrpc/5) [virt.vm] > (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Checking job > b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4542) > > 2017-01-23 19:04:32,193 DEBUG (jsonrpc/5) [virt.vm] > (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Job > b321e3ad-5156-4a76-921f-b7a9ed6c68e2 live info {'end': 1409220608L, > 'bandwidth': 0L, 'type': 4, 'cur': 1572864L} (vm:4570) > > > 2017-01-23 19:06:22,394 INFO (periodic/3) [virt.vm] > (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Starting cleanup thread for > job: b321e3ad-5156-4a76-921f-b7a9ed6c68e2 (vm:4587) > > 2017-01-23 19:06:37,391 INFO (periodic/2) [virt.vm] > (vmId='63ad6e6d-76c9-4ab0-a929-8a4a710185ac') Cleanup thread > <virt.vm.LiveMergeCleanupThread object at 0x1cb2ed0> successfully completed, > untracking job b321e3ad-5156-4a76-921f-b7a9ed6c68e2 base volume > 9a07f8c7-65f5-4761-9186-0327eb0fa5d3 top volume > 8e5c3593-4042-43e7-a84c-16c482fa8336 (vm:4550) Hi Ala. It's your decision. The requires_doc_text flag was set to +. Please set it to - to remove the doc text from the advisory. Thanks
Tested with the following code: ------------------------------------------ ovirt-engine-4.0.7.4-0.1.el7ev.noarch rhevm-4.0.7.4-0.1.el7ev.noarch vdsm-4.19.4-1.el7ev.x86_64 Tested with the following scenario: ----------------------------------------- Engine and hosts are running in debug logging mode Created VM with a disk Wrote at least 1g of data to the disk Created snapshot sa1, sn2, sn3 Delete sn2 - live merge is successful None of the new logs appear in the vdsm.log The same scenario in 4.1.1 does generate the above logs Moving to ASSIGNED!
4.19 is part of RHV 4.1, and regardless 4.19.4-1 doesn't contain any version of this patch. Please use v4.18.23 (and above) for the 4.18 generation or v4.19.5 (and above) for the 4.19 generation.
Kevin, does it fail with the relevant versions, as Allon detailed in comment 16 above?
What is the status of this bug?
Yes it failed with the versions indicated Tested with the following code: ------------------------------------------ ovirt-engine-4.0.7.4-0.1.el7ev.noarch rhevm-4.0.7.4-0.1.el7ev.noarch vdsm-4.18.24-3.el7ev.x86_64 Tested with the following scenario: ----------------------------------------- Engine and hosts are running in debug logging mode Created VM with a disk Wrote at least 1g of data to the disk Created snapshot sa1, sn2, sn3 Delete sn2 - live merge is successful The Above New Logs are reported in the vdsm.log Moving to VERIFIED!
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://rhn.redhat.com/errata/RHBA-2017-0544.html