Bug 1418280

Summary: [4.0.z] Improve logging during live merge
Product: Red Hat Enterprise Virtualization Manager Reporter: Tal Nisan <tnisan>
Component: vdsmAssignee: Ala Hino <ahino>
Status: CLOSED ERRATA QA Contact: Kevin Alon Goldblatt <kgoldbla>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 4.0.7CC: ahino, amureini, bazulay, bugs, ebenahar, eheftman, gwatson, kgoldbla, lsurette, mkalinin, ratamir, srevivo, tnisan, ycui, ykaul, ylavi
Target Milestone: ovirt-4.0.7Keywords: ZStream
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1415803
: 1426938 (view as bug list) Environment:
Last Closed: 2017-03-16 15:36:18 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1415803    
Bug Blocks: 1414067, 1422670, 1426938    
Attachments:
Description Flags
server, vdsm, engine.log none

Description Tal Nisan 2017-02-01 12:50:24 UTC
+++ 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.

Comment 2 Kevin Alon Goldblatt 2017-02-19 18:14:57 UTC
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!

Comment 3 Kevin Alon Goldblatt 2017-02-19 18:28:11 UTC
Created attachment 1255506 [details]
server, vdsm, engine.log

Adding logs

Comment 4 Ala Hino 2017-02-20 11:06:49 UTC
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?

Comment 6 Tal Nisan 2017-02-22 15:35:03 UTC
I see no problem, Ala is the 3.6.z backport problematic in any way?

Comment 7 Ala Hino 2017-02-22 15:38:06 UTC
Nope, 3.6.z patch (https://gerrit.ovirt.org/71695) already backported!

Comment 10 Emma Heftman 2017-02-27 08:19:59 UTC
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.

Comment 11 Ala Hino 2017-02-27 08:37:08 UTC
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)

Comment 12 Emma Heftman 2017-02-27 08:55:55 UTC
(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

Comment 14 Kevin Alon Goldblatt 2017-03-06 17:07:51 UTC
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!

Comment 16 Allon Mureinik 2017-03-06 17:14:51 UTC
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.

Comment 17 Yaniv Kaul 2017-03-06 18:17:02 UTC
Kevin, does it fail with the relevant versions, as Allon detailed in comment 16 above?

Comment 18 Yaniv Lavi 2017-03-09 13:18:03 UTC
What is the status of this bug?

Comment 19 Kevin Alon Goldblatt 2017-03-11 21:04:24 UTC
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!

Comment 21 errata-xmlrpc 2017-03-16 15:36:18 UTC
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