Bug 1426440
| Summary: | During Live Merge, clear information about top/base/active volumes is not provided by INFO level logging | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Virtualization Manager | Reporter: | Gordon Watson <gwatson> |
| Component: | vdsm | Assignee: | Ala Hino <ahino> |
| Status: | CLOSED ERRATA | QA Contact: | Natalie Gavrielov <ngavrilo> |
| Severity: | high | Docs Contact: | |
| Priority: | urgent | ||
| Version: | 4.1.0 | CC: | amureini, bazulay, gklein, lsurette, nsoffer, srevivo, tnisan, ycui, ykaul, ylavi |
| Target Milestone: | ovirt-4.1.1-1 | ||
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2017-04-25 01:02:41 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: | |||
| Bug Blocks: | 1425219 | ||
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 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.
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). 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 :-) 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
|
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: