Bug 1415803 - Improve logging during live merge
Summary: Improve logging during live merge
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: vdsm
Classification: oVirt
Component: Core
Version: 4.19.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ovirt-4.1.1
: 4.19.5
Assignee: Ala Hino
QA Contact: Kevin Alon Goldblatt
URL:
Whiteboard:
Depends On:
Blocks: 1418280 1425219
TreeView+ depends on / blocked
 
Reported: 2017-01-23 18:56 UTC by Ala Hino
Modified: 2017-04-21 09:34 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1418280 (view as bug list)
Environment:
Last Closed: 2017-04-21 09:34:14 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-4.1+

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 71049 0 ovirt-4.1 MERGED Live Merge: Improve logging 2017-02-01 15:08:05 UTC

Description Ala Hino 2017-01-23 18:56:05 UTC 
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)
Comment 1 Sandro Bonazzola 2017-01-25 07:56:01 UTC 
4.0.6 has been the last oVirt 4.0 release, please re-target this bug.
Comment 2 Kevin Alon Goldblatt 2017-02-16 14:25:01 UTC 
Tested with the following code:
-----------------------------------------------
ovirt-engine-4.1.1-0.1.el7.noarch
rhevm-4.1.1-0.1.el7.noarch
vdsm-4.19.5-1.el7ev.x86_64

Verified with the following scenario:
----------------------------------------------
Created a VM with disks
Start VM and write data to disks
Create Snapshots
Delete on of the snapshots which performs a live merge
All the relevant log entries are reported:


Moving to VERIFIED!


Log printout vdsm.lo
---------------------------------------------
2017-02-16 16:04:42,452 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Start (vm:535)
2017-02-16 16:04:42,455 INFO  (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') VM wrapper has started (vm:1903)
2017-02-16 16:04:49,020 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Ignoring param (target, 1048576) in Balloon (core:52)
2017-02-16 16:04:49,036 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Looking for drive with attributes {'name': 'hdc', 'bootOrder': '', 'readonly': True, 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'path': '', 'type': 'cdrom'} (storage:105)
2017-02-16 16:04:49,036 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Matched {'name': ('hdc', 'hdc'), 'bootOrder': ('', None), 'readonly': (True, True), 'address': ({'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}), 'path': ('', ''), 'type': ('cdrom', 'cdrom')} (storage:126)
2017-02-16 16:04:49,036 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Matched {'name': ('hdc', None), 'bootOrder': ('', None), 'readonly': (True, None), 'address': ({'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, None), 'path': ('', None), 'type': ('cdrom', None)} (storage:146)
2017-02-16 16:04:49,037 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Looking for drive with attributes {'name': 'vda', 'bootOrder': '1', 'readonly': False, 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'path': '/rhev/data-center/00000001-0001-0001-0001-000000000311/4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24/images/204d4928-50e0-4f2b-9a9b-ebc926cebb1f/10a8b0e1-4597-499e-9c59-199ab1c477b9', 'type': 'disk'} (storage:105)
2017-02-16 16:04:49,037 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Matched {'name': ('vda', 'vda'), 'bootOrder': ('1', '1'), 'readonly': (False, False), 'address': ({'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}), 'path': ('/rhev/data-center/00000001-0001-0001-0001-000000000311/4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24/images/204d4928-50e0-4f2b-9a9b-ebc926cebb1f/10a8b0e1-4597-499e-9c59-199ab1c477b9', '/rhev/data-center/00000001-0001-0001-0001-000000000311/4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24/images/204d4928-50e0-4f2b-9a9b-ebc926cebb1f/10a8b0e1-4597-499e-9c59-199ab1c477b9'), 'type': ('disk', 'disk')} (storage:126)
2017-02-16 16:04:49,037 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Matched {'name': ('vda', None), 'bootOrder': ('1', None), 'readonly': (False, None), 'address': ({'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, None), 'path': ('/rhev/data-center/00000001-0001-0001-0001-000000000311/4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24/images/204d4928-50e0-4f2b-9a9b-ebc926cebb1f/10a8b0e1-4597-499e-9c59-199ab1c477b9', None), 'type': ('disk', None)} (storage:146)
2017-02-16 16:04:49,037 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Looking for drive with attributes {'name': 'sda', 'bootOrder': '', 'readonly': False, 'address': {'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '2'}, 'path': '/dev/mapper/3514f0c5a516003f6', 'type': 'disk'} (storage:105)
2017-02-16 16:04:49,038 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Matched {'name': ('sda', 'sda'), 'bootOrder': ('', None), 'readonly': (False, False), 'address': ({'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '2'}, {'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '2'}), 'path': ('/dev/mapper/3514f0c5a516003f6', '/dev/mapper/3514f0c5a516003f6'), 'type': ('disk', 'disk')} (storage:126)
2017-02-16 16:04:49,038 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Matched {'name': ('sda', None), 'bootOrder': ('', None), 'readonly': (False, None), 'address': ({'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '2'}, None), 'path': ('/dev/mapper/3514f0c5a516003f6', None), 'type': ('disk', None)} (storage:146)
2017-02-16 16:04:49,038 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Looking for drive with attributes {'name': 'sdb', 'bootOrder': '', 'readonly': False, 'address': {'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '1'}, 'path': '/rhev/data-center/00000001-0001-0001-0001-000000000311/431e9018-0f83-49cc-825a-5eb194041f5d/images/150fb1b7-908b-41f0-a51a-e6cf73b7159a/032c1eb5-f1ec-41cd-8fd7-b568bd428eaf', 'type': 'disk'} (storage:105)
2017-02-16 16:04:49,038 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Matched {'name': ('sdb', 'sdb'), 'bootOrder': ('', None), 'readonly': (False, False), 'address': ({'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '1'}, {'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '1'}), 'path': ('/rhev/data-center/00000001-0001-0001-0001-000000000311/431e9018-0f83-49cc-825a-5eb194041f5d/images/150fb1b7-908b-41f0-a51a-e6cf73b7159a/032c1eb5-f1ec-41cd-8fd7-b568bd428eaf', '/rhev/data-center/00000001-0001-0001-0001-000000000311/431e9018-0f83-49cc-825a-5eb194041f5d/images/150fb1b7-908b-41f0-a51a-e6cf73b7159a/032c1eb5-f1ec-41cd-8fd7-b568bd428eaf'), 'type': ('disk', 'disk')} (storage:126)
2017-02-16 16:04:49,039 DEBUG (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Matched {'name': ('sdb', None), 'bootOrder': ('', None), 'readonly': (False, None), 'address': ({'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '1'}, None), 'path': ('/rhev/data-center/00000001-0001-0001-0001-000000000311/431e9018-0f83-49cc-825a-5eb194041f5d/images/150fb1b7-908b-41f0-a51a-e6cf73b7159a/032c1eb5-f1ec-41cd-8fd7-b568bd428eaf', None), 'type': ('disk', None)} (storage:146)
2017-02-16 16:04:49,042 INFO  (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Starting connection (guestagent:245)
2017-02-16 16:04:49,045 INFO  (vm/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') CPU running: domain initialization (vm:4890)
2017-02-16 16:04:49,305 DEBUG (vmchannels) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Attempting connection to /var/lib/libvirt/qemu/channels/1f836809-1e90-4f0d-b0ba-a0294f63bf0c.com.redhat.rhevm.vdsm (guestagent:299)
2017-02-16 16:04:49,306 DEBUG (vmchannels) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Connected to /var/lib/libvirt/qemu/channels/1f836809-1e90-4f0d-b0ba-a0294f63bf0c.com.redhat.rhevm.vdsm (guestagent:303)
2017-02-16 16:04:49,307 INFO  (vmchannels) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Guest API version changed from 0 to 3 (guestagent:281)
2017-02-16 16:04:49,981 DEBUG (vmchannels) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') username: u'None' (guestagent:390)
2017-02-16 16:12:20,552 INFO  (jsonrpc/5) [vdsm.api] START snapshot args=(<virt.vm.Vm object at 0x374d610>, [{'baseVolumeID': '032c1eb5-f1ec-41cd-8fd7-b568bd428eaf', 'domainID': '431e9018-0f83-49cc-825a-5eb194041f5d', 'volumeID': 'f0c56263-7682-4b77-a2f7-058a8b7d443b', 'imageID': '150fb1b7-908b-41f0-a51a-e6cf73b7159a'}, {'baseVolumeID': '10a8b0e1-4597-499e-9c59-199ab1c477b9', 'domainID': '4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24', 'volumeID': '3fb2e9df-0f3b-4566-89dc-08902a95e3f0', 'imageID': '204d4928-50e0-4f2b-9a9b-ebc926cebb1f'}], {'dst': {'device': 'disk', 'imageID': '80e11a0c-4e51-4648-a44c-6474f661746c', 'domainID': '431e9018-0f83-49cc-825a-5eb194041f5d', 'volumeID': '58142afb-f275-49a0-844a-02efa296fc29', 'poolID': '00000001-0001-0001-0001-000000000311'}, 'dstparams': {'device': 'disk', 'imageID': '9542e6d8-eeed-49f7-86a0-d87d6a40589a', 'domainID': '431e9018-0f83-49cc-825a-5eb194041f5d', 'volumeID': 'b53b9d14-fed2-4788-90d5-32927cfc3ca8', 'poolID': '00000001-0001-0001-0001-000000000311'}}, False) kwargs={} (api:37)
2017-02-16 16:12:24,162 INFO  (jsonrpc/5) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') <?xml version='1.0' encoding='UTF-8'?>
2017-02-16 16:12:24,163 INFO  (jsonrpc/5) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Taking a live snapshot (drives=vda, sdb, memory=True) (vm:3507)
2017-02-16 16:12:24,180 DEBUG (libvirt/events) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') event Suspended detail 0 opaque None (vm:4328)
2017-02-16 16:12:24,181 INFO  (libvirt/events) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') CPU stopped: onSuspend (vm:4890)
2017-02-16 16:12:28,941 DEBUG (libvirt/events) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') event Resumed detail 0 opaque None (vm:4328)
2017-02-16 16:12:28,941 INFO  (libvirt/events) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') CPU running: onResume (vm:4890)
2017-02-16 16:12:28,942 INFO  (jsonrpc/5) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Completed live snapshot (vm:3509)
2017-02-16 16:12:29,372 DEBUG (jsonrpc/5) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Drive vda moved from '/rhev/data-center/00000001-0001-0001-0001-000000000311/4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24/images/204d4928-50e0-4f2b-9a9b-ebc926cebb1f/10a8b0e1-4597-499e-9c59-199ab1c477b9' to '/rhev/data-center/00000001-0001-0001-0001-000000000311/4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24/images/204d4928-50e0-4f2b-9a9b-ebc926cebb1f/3fb2e9df-0f3b-4566-89dc-08902a95e3f0' (storage:316)
2017-02-16 16:12:29,390 DEBUG (jsonrpc/5) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Drive sdb moved from '/rhev/data-center/00000001-0001-0001-0001-000000000311/431e9018-0f83-49cc-825a-5eb194041f5d/images/150fb1b7-908b-41f0-a51a-e6cf73b7159a/032c1eb5-f1ec-41cd-8fd7-b568bd428eaf' to '/rhev/data-center/00000001-0001-0001-0001-000000000311/431e9018-0f83-49cc-825a-5eb194041f5d/images/150fb1b7-908b-41f0-a51a-e6cf73b7159a/f0c56263-7682-4b77-a2f7-058a8b7d443b' (storage:316)
2017-02-16 16:17:45,892 INFO  (jsonrpc/1) [vdsm.api] START merge args=(<virt.vm.Vm object at 0x374d610>, {'poolID': '00000001-0001-0001-0001-000000000311', 'volumeID': '3fb2e9df-0f3b-4566-89dc-08902a95e3f0', 'domainID': '4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24', 'imageID': '204d4928-50e0-4f2b-9a9b-ebc926cebb1f'}, '9f152d3a-8b69-42d7-a976-84c4608688d3', '10a8b0e1-4597-499e-9c59-199ab1c477b9', '0', '6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1') kwargs={} (api:37)
2017-02-16 16:17:46,917 INFO  (jsonrpc/3) [vdsm.api] START merge args=(<virt.vm.Vm object at 0x374d610>, {'poolID': '00000001-0001-0001-0001-000000000311', 'volumeID': 'f0c56263-7682-4b77-a2f7-058a8b7d443b', 'domainID': '431e9018-0f83-49cc-825a-5eb194041f5d', 'imageID': '150fb1b7-908b-41f0-a51a-e6cf73b7159a'}, '51d646cc-caed-4a7c-8afe-bb7a5f30cfe4', '032c1eb5-f1ec-41cd-8fd7-b568bd428eaf', '0', '54cb5699-acb8-44fa-ba9c-905cba336be5') kwargs={} (api:37)
2017-02-16 16:17:52,501 INFO  (jsonrpc/3) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Starting merge with jobUUID='54cb5699-acb8-44fa-ba9c-905cba336be5' (vm:4688)
2017-02-16 16:17:52,523 DEBUG (jsonrpc/3) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Checking job 54cb5699-acb8-44fa-ba9c-905cba336be5 (vm:4531)
2017-02-16 16:17:52,525 DEBUG (jsonrpc/3) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Job 54cb5699-acb8-44fa-ba9c-905cba336be5 live info: {'end': 9663676416L, 'bandwidth': 0L, 'type': 3, 'cur': 87556096L} (vm:4561)
2017-02-16 16:17:52,541 INFO  (jsonrpc/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Starting merge with jobUUID='6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1' (vm:4688)
2017-02-16 16:17:52,564 DEBUG (jsonrpc/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Requesting an extension for the volume: {'newSize': 11811160064, 'domainID': '4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24', 'name': 'vda', 'volumeID': '9f152d3a-8b69-42d7-a976-84c4608688d3', 'imageID': '204d4928-50e0-4f2b-9a9b-ebc926cebb1f', 'internal': True, 'poolID': '00000001-0001-0001-0001-000000000311'} (vm:952)
2017-02-16 16:17:52,565 INFO  (jsonrpc/1) [dispatcher] Run and protect: sendExtendMsg(spUUID='00000001-0001-0001-0001-000000000311', volDict={'newSize': 11811160064, 'domainID': '4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24', 'name': 'vda', 'volumeID': '9f152d3a-8b69-42d7-a976-84c4608688d3', 'imageID': '204d4928-50e0-4f2b-9a9b-ebc926cebb1f', 'internal': True, 'poolID': '00000001-0001-0001-0001-000000000311'}, newSize=11811160064, callbackFunc=<bound method Vm.__afterVolumeExtension of <virt.vm.Vm object at 0x374d610>>) (logUtils:49)
2017-02-16 16:17:52,577 DEBUG (jsonrpc/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Checking job 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1 (vm:4531)
2017-02-16 16:17:52,579 DEBUG (jsonrpc/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Job 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1 live info: {'end': 10737418240L, 'bandwidth': 0L, 'type': 3, 'cur': 4325376L} (vm:4561)
2017-02-16 16:17:52,579 DEBUG (jsonrpc/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Checking job 54cb5699-acb8-44fa-ba9c-905cba336be5 (vm:4531)
2017-02-16 16:17:52,582 DEBUG (jsonrpc/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Job 54cb5699-acb8-44fa-ba9c-905cba336be5 live info: {'end': 9663676416L, 'bandwidth': 0L, 'type': 3, 'cur': 2443706368L} (vm:4561)
2017-02-16 16:17:52,788 WARN  (libvirt/events) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') unknown eventid 8 args ('/rhev/data-center/00000001-0001-0001-0001-000000000311/431e9018-0f83-49cc-825a-5eb194041f5d/images/150fb1b7-908b-41f0-a51a-e6cf73b7159a/f0c56263-7682-4b77-a2f7-058a8b7d443b', 3, 0, 8) (clientIF:540)
2017-02-16 16:17:56,170 WARN  (libvirt/events) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') unknown eventid 8 args ('/rhev/data-center/00000001-0001-0001-0001-000000000311/4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24/images/204d4928-50e0-4f2b-9a9b-ebc926cebb1f/3fb2e9df-0f3b-4566-89dc-08902a95e3f0', 3, 0, 8) (clientIF:540)
2017-02-16 16:17:56,655 INFO  (mailbox-hsm/2) [storage.ThreadPool.WorkerThread] START task 0f7a60c5-7410-487d-b415-f67972fbc4ff (cmd=<function runTask at 0x2f03230>, args=(<bound method Vm.__afterVolumeExtension of <virt.vm.Vm object at 0x374d610>>, {'newSize': 11811160064, 'domainID': '4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24', 'name': 'vda', 'volumeID': '9f152d3a-8b69-42d7-a976-84c4608688d3', 'imageID': '204d4928-50e0-4f2b-9a9b-ebc926cebb1f', 'internal': True, 'poolID': '00000001-0001-0001-0001-000000000311'})) (threadPool:208)
2017-02-16 16:17:56,656 DEBUG (mailbox-hsm/2) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Refreshing drive volume for vda (domainID: 4b79fb24-3e90-4e9f-bb8d-2c9aef63dd24, volumeID: 9f152d3a-8b69-42d7-a976-84c4608688d3) (vm:915)
2017-02-16 16:17:56,798 DEBUG (mailbox-hsm/2) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Verifying extension for volume 9f152d3a-8b69-42d7-a976-84c4608688d3, requested size 11811160064, current size 11811160064 (vm:923)
2017-02-16 16:17:56,802 INFO  (mailbox-hsm/2) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') CPU running: continue (vm:4890)
2017-02-16 16:17:57,778 DEBUG (periodic/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Checking job 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1 (vm:4531)
2017-02-16 16:17:57,805 INFO  (periodic/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Libvirt job 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1 was terminated (vm:4570)
2017-02-16 16:17:57,805 INFO  (periodic/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Starting cleanup thread for job: 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1 (vm:4578)
2017-02-16 16:17:57,806 DEBUG (periodic/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Checking job 54cb5699-acb8-44fa-ba9c-905cba336be5 (vm:4531)
2017-02-16 16:17:57,807 INFO  (periodic/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Libvirt job 54cb5699-acb8-44fa-ba9c-905cba336be5 was terminated (vm:4570)
2017-02-16 16:17:57,808 INFO  (periodic/1) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Starting cleanup thread for job: 54cb5699-acb8-44fa-ba9c-905cba336be5 (vm:4578)
2017-02-16 16:17:58,050 INFO  (merge/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Synchronizing volume chain after live merge (job 54cb5699-acb8-44fa-ba9c-905cba336be5) (vm:5023)
2017-02-16 16:17:58,076 DEBUG (merge/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') vdsm chain: ['51d646cc-caed-4a7c-8afe-bb7a5f30cfe4', '032c1eb5-f1ec-41cd-8fd7-b568bd428eaf', 'f0c56263-7682-4b77-a2f7-058a8b7d443b'], libvirt chain: ['51d646cc-caed-4a7c-8afe-bb7a5f30cfe4', 'f0c56263-7682-4b77-a2f7-058a8b7d443b'] (vm:4805)
2017-02-16 16:17:58,165 INFO  (merge/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Synchronizing volume chain after live merge (job 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1) (vm:5023)
2017-02-16 16:17:58,209 DEBUG (merge/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') vdsm chain: ['4a491a53-53e2-49b6-8458-45f4a9d58f18', '9f152d3a-8b69-42d7-a976-84c4608688d3', '3fb2e9df-0f3b-4566-89dc-08902a95e3f0', '10a8b0e1-4597-499e-9c59-199ab1c477b9'], libvirt chain: ['4a491a53-53e2-49b6-8458-45f4a9d58f18', '9f152d3a-8b69-42d7-a976-84c4608688d3', '3fb2e9df-0f3b-4566-89dc-08902a95e3f0'] (vm:4805)
2017-02-16 16:17:58,952 INFO  (merge/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Synchronization completed (job 54cb5699-acb8-44fa-ba9c-905cba336be5) (vm:5030)
2017-02-16 16:17:58,986 INFO  (merge/1f836809) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Synchronization completed (job 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1) (vm:5030)
2017-02-16 16:18:12,780 DEBUG (periodic/3) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Checking job 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1 (vm:4531)
2017-02-16 16:18:12,780 INFO  (periodic/3) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Cleanup thread <virt.vm.LiveMergeCleanupThread object at 0x30a6410> successfully completed, untracking job 6bec71dd-8c5f-4f4c-9a1f-3e02772a0bb1 (base=9f152d3a-8b69-42d7-a976-84c4608688d3, top=10a8b0e1-4597-499e-9c59-199ab1c477b9) (vm:4541)
2017-02-16 16:18:12,799 DEBUG (periodic/3) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Checking job 54cb5699-acb8-44fa-ba9c-905cba336be5 (vm:4531)
2017-02-16 16:18:12,799 INFO  (periodic/3) [virt.vm] (vmId='1f836809-1e90-4f0d-b0ba-a0294f63bf0c') Cleanup thread <virt.vm.LiveMergeCleanupThread object at 0x2821d90> successfully completed, untracking job 54cb5699-acb8-44fa-ba9c-905cba336be5 (base=51d646cc-caed-4a7c-8afe-bb7a5f30cfe4, top=032c1eb5-f1ec-41cd-8fd7-b568bd428eaf) (vm:4541)
[root@purple-vds2 vdsm]#
Note You need to log in before you can comment on or make changes to this bug.