Bug 1418280 - [4.0.z] Improve logging during live merge
Summary: [4.0.z] Improve logging during live merge
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: vdsm
Version: 4.0.7
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ovirt-4.0.7
: ---
Assignee: Ala Hino
QA Contact: Kevin Alon Goldblatt
URL:
Whiteboard:
Depends On: 1415803
Blocks: 1414067 1422670 1426938
TreeView+ depends on / blocked
 
Reported: 2017-02-01 12:50 UTC by Tal Nisan
Modified: 2020-06-11 13:15 UTC (History)
16 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1415803
: 1426938 (view as bug list)
Environment:
Last Closed: 2017-03-16 15:36:18 UTC
oVirt Team: Storage
Target Upstream Version:


Attachments (Terms of Use)
server, vdsm, engine.log (2.93 MB, application/x-gzip)
2017-02-19 18:28 UTC, Kevin Alon Goldblatt
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2017:0544 0 normal SHIPPED_LIVE vdsm 4.0.7 bug fix and enhancement update 2017-03-16 19:25:18 UTC
oVirt gerrit 71528 0 None None None 2017-02-01 15:32:21 UTC

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


Note You need to log in before you can comment on or make changes to this bug.