Bug 1426440 - During Live Merge, clear information about top/base/active volumes is not provided by INFO level logging
Summary: During Live Merge, clear information about top/base/active volumes is not pro...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: vdsm
Version: 4.1.0
Hardware: Unspecified
OS: Linux
urgent
high
Target Milestone: ovirt-4.1.1-1
: ---
Assignee: Ala Hino
QA Contact: Natalie Gavrielov
URL:
Whiteboard:
Depends On:
Blocks: 1425219
TreeView+ depends on / blocked
 
Reported: 2017-02-23 22:45 UTC by Gordon Watson
Modified: 2017-04-25 01:02 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-04-25 01:02:41 UTC
oVirt Team: Storage
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2017:0998 0 normal SHIPPED_LIVE VDSM bug fix and enhancement update 4.1 GA 2017-04-18 20:11:39 UTC
oVirt gerrit 74446 0 master MERGED logging: Fix logged helper to show arguments name 2017-03-23 09:06:19 UTC
oVirt gerrit 74587 0 ovirt-4.1 MERGED logging: Fix logged helper to show arguments name 2017-03-27 11:17:52 UTC
oVirt gerrit 74744 0 ovirt-4.1.1 MERGED logging: Fix logged helper to show arguments name 2017-03-28 11:08:55 UTC

Description Gordon Watson 2017-02-23 22:45:27 UTC
Description of problem:

In prior releases, the following entry in the vdsm logs would provide the top volume, base volume and active volume for a disk that was involved in a live merge;

jsonrpc.Executor/5::DEBUG::2017-02-08 23:46:46,062::__init__::515::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.merge' in bridge with {u'topVolUUID': u'eb470728-0e1f-4dd7-a6b6-66bddd88a213', u'vmID': u'66084ade-6737-49ab-9ce6-837428126c2e', u'drive': {u'domainID': u'a9a5ccbd-5acd-4853-9820-47dd91ec4dac', u'volumeID': u'eb470728-0e1f-4dd7-a6b6-66bddd88a213', u'poolID': u'bc570e88-5262-4baf-889e-aea805c891e3', u'imageID': u'd8dc98bc-5b3a-459d-8cc5-63a11a14fe58'}, u'bandwidth': u'0', u'jobUUID': u'5f8a92aa-1b2d-4a1f-a8fc-80e7b011e9d9', u'baseVolUUID': u'21f84184-189b-4beb-9374-82a3d28c64c5'}


This will now be excluded by default, as it's a DEBUG level statement. 

We will now have something like this;

2017-02-23 17:28:19,665 INFO  (jsonrpc/5) [vdsm.api] START merge args=(<virt.vm.Vm object at 0x3431950>, {u'poolID': u'00000001-0001-0001-0001-000000000311', u'volumeID': u'5d32db4d-c902-4f3c-b040-79b4224a3ce2', u'domainID': u'33905fa3-97eb-4bb9-95a1-28db4fc9a653', u'imageID': u'5fd3333a-c6cc-4044-9c17-7c98e4c883cf'}, u'206ca67a-9e72-444f-a77b-a8378684a216', u'db1fa632-db7d-4c9d-b3ca-be86a5b7cd57', u'0', u'5e22d352-9f3c-4d24-9236-9cabfb6d1c51') kwargs={} (api:37)


Although this does include the top and base volumes of the merge, and the job uuid, it does not include the active volume, and is not clear which volume is which.



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:

Comment 2 Tal Nisan 2017-02-26 12:57:17 UTC
Ala it seems like a low hanging fruit so I'm targeting to 4.1.3, let me know if that's not the case

Comment 3 Nir Soffer 2017-03-23 20:04:26 UTC
This is the merge log in master now, it includes all the info in a readable way:

2017-03-23 15:45:26,524-0400 INFO  (jsonrpc/5) [vdsm.api] START merge(driveSpec={u'poolID': u'151299ea-fbcd-40f5-9747-2bfdd506b82d', u'volumeID': u'78bae18f-e717-4554-bcad-d5be67391caa', u'domainID': u'5f3d1edb-b0aa-45f8-844d-8af8a3322712', u'imageID': u'fd52245f-00e3-4d09-8a4f-19b360495e49'}, baseVolUUID=u'64510db9-e0ec-494b-a1b1-5c53e7285905', topVolUUID=u'd02a8b65-3d23-452d-9b43-481f89f239ba', bandwidth=u'0', jobUUID=u'66224a60-6e18-4d55-a3ee-c44f51f83798') (api:39)
...
2017-03-23 15:45:26,901-0400 INFO  (jsonrpc/5) [vdsm.api] FINISH merge return={'status': {'message': 'Done', 'code': 0}} (api:45)

This was fixed not only for merge, but for most non-storage verbs.

Comment 4 Nir Soffer 2017-03-23 20:05:36 UTC
Tal, this is ready now, it will be nice if we can push this into 4.1.1,
this logging change is very important for non-storage flows (storage
flows always had good api logs).

Comment 5 Allon Mureinik 2017-03-27 07:37:07 UTC
Not sure if there's going to be another 4.1.1-z respin.
If there will be, it should be merged to the ovirt-4.1 branch so it could be included.
If there won't be, it should be merged to the ovirt-4.1 branch so it could be included in 4.1.2.

TL;DR - we need to merge this :-)

Comment 8 Natalie Gavrielov 2017-04-05 17:05:03 UTC
Verified using:
vdsm-4.19.10.1-1.el7ev.x86_64
rhevm-4.1.1.7-0.1.el7.noarch

Scenario:
Perform live merge - delete a snapshot of a running vm.


Now vdsm.log shows:

2017-04-05 19:32:59,170+0300 INFO  (jsonrpc/4) [vdsm.api] START merge(driveSpec={'poolID': 'c1bda416-eaff-4daa-8f32-24a442d66a5c', 'volumeID': '80274a19-5df0-4f32-8d86-7c1b83ab43f7', 'domainID': '5c1ac9a0-6ca4-4fef-b630-6c7483855168', 'imageID': '2d06e755-f0f0-420f-808c-537f54491df1'}, baseVolUUID='78bd46ea-c493-48b7-ab15-0c791d5ee725', topVolUUID='80274a19-5df0-4f32-8d86-7c1b83ab43f7', bandwidth='0', jobUUID='50cbf48e-d6a4-4c5d-bf48-782cbe3018d1') (api:39)
2017-04-05 19:32:59,219+0300 INFO  (jsonrpc/4) [dispatcher] Run and protect: getVolumeInfo(sdUUID='5c1ac9a0-6ca4-4fef-b630-6c7483855168', spUUID='c1bda416-eaff-4daa-8f32-24a442d66a5c', imgUUID='2d06e755-f0f0-420f-808c-537f54491df1', volUUID='78bd46ea-c493-48b7-ab15-0c791d5ee725', options=None) (logUtils:51)

2017-04-05 19:32:59,385+0300 INFO  (jsonrpc/4) [vdsm.api] FINISH merge return={'status': {'message': 'Done', 'code': 0}} (api:45)

Now there are:
poolID
volumeID
domainID
baseVolUUID
topVolUUID
jobUUID
sdUUID
imgUUID
volUUID


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