Attachment 936516 Details for Bug 1140633 – vdsm from host

vdsm from host

vdsm.log (text/plain), 33.37 KB, created by Lukas Svaty on 2014-09-11 11:41:16 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Lukas Svaty

Created: 2014-09-11 11:41:16 UTC

Size: 33.37 KB

patch

obsolete

>Thread-67::DEBUG::2014-09-11 07:32:08,213::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/_home_local/d3c59943-3404-46c8-a9e2-ba0f176a4e4c/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-67::DEBUG::2014-09-11 07:32:08,226::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n500 bytes (500 B) copied, 0.00939016 s, 53.2 kB/s\n'; <rc> = 0
>Thread-84::DEBUG::2014-09-11 07:32:08,405::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.61]
>Thread-84::DEBUG::2014-09-11 07:32:08,405::task::595::TaskManager.Task::(_updateState) Task=`dc377513-0900-4347-b3d2-5c48c4d9372d`::moving from state init -> state preparing
>Thread-84::INFO::2014-09-11 07:32:08,405::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='5fee1120-4e30-47eb-874c-45db26cce80a', options=None)
>Thread-84::DEBUG::2014-09-11 07:32:08,406::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.5fee1120-4e30-47eb-874c-45db26cce80a`ReqID=`05c7260c-8024-4dd9-943f-02cc7e26eedc`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2572' at 'getStoragePoolInfo'
>Thread-84::DEBUG::2014-09-11 07:32:08,406::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' for lock type 'shared'
>Thread-84::DEBUG::2014-09-11 07:32:08,406::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' is free. Now locking as 'shared' (1 active user)
>Thread-84::DEBUG::2014-09-11 07:32:08,407::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.5fee1120-4e30-47eb-874c-45db26cce80a`ReqID=`05c7260c-8024-4dd9-943f-02cc7e26eedc`::Granted request
>Thread-84::DEBUG::2014-09-11 07:32:08,407::task::827::TaskManager.Task::(resourceAcquired) Task=`dc377513-0900-4347-b3d2-5c48c4d9372d`::_resourcesAcquired: Storage.5fee1120-4e30-47eb-874c-45db26cce80a (shared)
>Thread-84::DEBUG::2014-09-11 07:32:08,407::task::990::TaskManager.Task::(_decref) Task=`dc377513-0900-4347-b3d2-5c48c4d9372d`::ref 1 aborting False
>Thread-84::INFO::2014-09-11 07:32:08,408::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'DC-ppc', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 2, 'domains': '812a943d-a046-449e-add2-8976efd523fb:Active,d3c59943-3404-46c8-a9e2-ba0f176a4e4c:Active', 'master_uuid': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'812a943d-a046-449e-add2-8976efd523fb': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '20999434240', 'version': 0}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '', 'alerts': [], 'disktotal': '20999434240', 'version': 3}}}
>Thread-84::DEBUG::2014-09-11 07:32:08,408::task::1185::TaskManager.Task::(prepare) Task=`dc377513-0900-4347-b3d2-5c48c4d9372d`::finished: {'info': {'name': 'DC-ppc', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 2, 'domains': '812a943d-a046-449e-add2-8976efd523fb:Active,d3c59943-3404-46c8-a9e2-ba0f176a4e4c:Active', 'master_uuid': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'812a943d-a046-449e-add2-8976efd523fb': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '20999434240', 'version': 0}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '', 'alerts': [], 'disktotal': '20999434240', 'version': 3}}}
>Thread-84::DEBUG::2014-09-11 07:32:08,408::task::595::TaskManager.Task::(_updateState) Task=`dc377513-0900-4347-b3d2-5c48c4d9372d`::moving from state preparing -> state finished
>Thread-84::DEBUG::2014-09-11 07:32:08,408::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5fee1120-4e30-47eb-874c-45db26cce80a': < ResourceRef 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a', isValid: 'True' obj: 'None'>}
>Thread-84::DEBUG::2014-09-11 07:32:08,409::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-84::DEBUG::2014-09-11 07:32:08,409::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a'
>Thread-84::DEBUG::2014-09-11 07:32:08,409::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' (0 active users)
>Thread-84::DEBUG::2014-09-11 07:32:08,409::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' is free, finding out if anyone is waiting for it.
>Thread-84::DEBUG::2014-09-11 07:32:08,409::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a', Clearing records.
>Thread-84::DEBUG::2014-09-11 07:32:08,410::task::990::TaskManager.Task::(_decref) Task=`dc377513-0900-4347-b3d2-5c48c4d9372d`::ref 0 aborting False
>Thread-87::DEBUG::2014-09-11 07:32:16,361::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-87::DEBUG::2014-09-11 07:32:16,376::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n330 bytes (330 B) copied, 0.0115662 s, 28.5 kB/s\n'; <rc> = 0
>Thread-91::DEBUG::2014-09-11 07:32:16,984::task::595::TaskManager.Task::(_updateState) Task=`ebc461fc-e269-49dd-b02f-b02eb4a9c7b3`::moving from state init -> state preparing
>Thread-91::INFO::2014-09-11 07:32:16,985::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-91::INFO::2014-09-11 07:32:16,985::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'812a943d-a046-449e-add2-8976efd523fb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0115662', 'lastCheck': '0.6', 'valid': True}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00939016', 'lastCheck': '8.8', 'valid': True}}
>Thread-91::DEBUG::2014-09-11 07:32:16,985::task::1185::TaskManager.Task::(prepare) Task=`ebc461fc-e269-49dd-b02f-b02eb4a9c7b3`::finished: {'812a943d-a046-449e-add2-8976efd523fb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0115662', 'lastCheck': '0.6', 'valid': True}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00939016', 'lastCheck': '8.8', 'valid': True}}
>Thread-91::DEBUG::2014-09-11 07:32:16,985::task::595::TaskManager.Task::(_updateState) Task=`ebc461fc-e269-49dd-b02f-b02eb4a9c7b3`::moving from state preparing -> state finished
>Thread-91::DEBUG::2014-09-11 07:32:16,985::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-91::DEBUG::2014-09-11 07:32:16,985::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-91::DEBUG::2014-09-11 07:32:16,986::task::990::TaskManager.Task::(_decref) Task=`ebc461fc-e269-49dd-b02f-b02eb4a9c7b3`::ref 0 aborting False
>Thread-67::DEBUG::2014-09-11 07:32:18,229::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/_home_local/d3c59943-3404-46c8-a9e2-ba0f176a4e4c/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-67::DEBUG::2014-09-11 07:32:18,244::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n500 bytes (500 B) copied, 0.0113007 s, 44.2 kB/s\n'; <rc> = 0
>Thread-91::DEBUG::2014-09-11 07:32:18,750::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.61]::call vmCreate with ({'acpiEnable': 'true', 'emulatedMachine': 'pseries', 'tabletEnable': 'true', 'vmId': '2430de31-b194-42dc-a86a-a8aaf193127d', 'memGuaranteedSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'timeOffset': '0', 'cpuType': 'POWER8_v2_1.1', 'smp': '1', 'custom': {}, 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'vm', 'nice': '0', 'smartcardEnable': 'false', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'vga', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '6e5ec9f0-1b24-4108-81fc-d4462c27a7e2'}, {'index': '0', 'iface': 'scsi', 'address': {'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '8337167c-1c98-41cf-86b2-5787fc6fe367', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'volumeID': 'ece508fb-8696-4a8f-aa2b-f8e801c82826', 'imageID': '8e0e6a91-9bfc-4d8c-aeab-e3e0b9fa9aa1', 'specParams': {}, 'readonly': 'false', 'domainID': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'deviceId': '8e0e6a91-9bfc-4d8c-aeab-e3e0b9fa9aa1', 'poolID': '5fee1120-4e30-47eb-874c-45db26cce80a', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'device': 'scsi', 'index': '0', 'type': 'controller', 'address': {'type': 'spapr-vio'}}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:9e:86:05', 'linkActive': 'true', 'network': 'rhevm', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {}, 'outbound': {}}, 'deviceId': '13f5f43e-ff01-4009-9528-c2f65b609c0f', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '782dd304-1619-4527-b58f-eaf939d85df7'}, {'index': '1', 'specParams': {}, 'deviceId': 'bec1527d-badb-407c-86e4-2202ff1778cf', 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'vnc'},) {} flowID [6ddcc631]
>Thread-91::DEBUG::2014-09-11 07:32:18,750::BindingXMLRPC::1074::vds::(wrapper) return vmCreate with {'status': {'message': 'Unknown host operating system', 'code': 9}}
>Thread-97::DEBUG::2014-09-11 07:32:19,510::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.61] flowID [40140a74]
>Thread-97::DEBUG::2014-09-11 07:32:19,510::task::595::TaskManager.Task::(_updateState) Task=`b2480c28-131e-49b0-9163-efc81801b9cb`::moving from state init -> state preparing
>Thread-97::INFO::2014-09-11 07:32:19,510::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='5fee1120-4e30-47eb-874c-45db26cce80a', options=None)
>Thread-97::INFO::2014-09-11 07:32:19,510::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2}}
>Thread-97::DEBUG::2014-09-11 07:32:19,511::task::1185::TaskManager.Task::(prepare) Task=`b2480c28-131e-49b0-9163-efc81801b9cb`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2}}
>Thread-97::DEBUG::2014-09-11 07:32:19,511::task::595::TaskManager.Task::(_updateState) Task=`b2480c28-131e-49b0-9163-efc81801b9cb`::moving from state preparing -> state finished
>Thread-97::DEBUG::2014-09-11 07:32:19,511::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-97::DEBUG::2014-09-11 07:32:19,511::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-97::DEBUG::2014-09-11 07:32:19,511::task::990::TaskManager.Task::(_decref) Task=`b2480c28-131e-49b0-9163-efc81801b9cb`::ref 0 aborting False
>Thread-84::DEBUG::2014-09-11 07:32:19,723::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.61] flowID [40140a74]
>Thread-84::DEBUG::2014-09-11 07:32:19,723::task::595::TaskManager.Task::(_updateState) Task=`fda1d351-f2ba-4afc-91f1-8d431d0f328e`::moving from state init -> state preparing
>Thread-84::INFO::2014-09-11 07:32:19,723::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='5fee1120-4e30-47eb-874c-45db26cce80a', options=None)
>Thread-84::DEBUG::2014-09-11 07:32:19,724::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.5fee1120-4e30-47eb-874c-45db26cce80a`ReqID=`b11e58ef-a9e8-41e3-8b51-aead1fcb10e5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2572' at 'getStoragePoolInfo'
>Thread-84::DEBUG::2014-09-11 07:32:19,724::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' for lock type 'shared'
>Thread-84::DEBUG::2014-09-11 07:32:19,724::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' is free. Now locking as 'shared' (1 active user)
>Thread-84::DEBUG::2014-09-11 07:32:19,724::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.5fee1120-4e30-47eb-874c-45db26cce80a`ReqID=`b11e58ef-a9e8-41e3-8b51-aead1fcb10e5`::Granted request
>Thread-84::DEBUG::2014-09-11 07:32:19,725::task::827::TaskManager.Task::(resourceAcquired) Task=`fda1d351-f2ba-4afc-91f1-8d431d0f328e`::_resourcesAcquired: Storage.5fee1120-4e30-47eb-874c-45db26cce80a (shared)
>Thread-84::DEBUG::2014-09-11 07:32:19,725::task::990::TaskManager.Task::(_decref) Task=`fda1d351-f2ba-4afc-91f1-8d431d0f328e`::ref 1 aborting False
>Thread-84::INFO::2014-09-11 07:32:19,726::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'DC-ppc', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 2, 'domains': '812a943d-a046-449e-add2-8976efd523fb:Active,d3c59943-3404-46c8-a9e2-ba0f176a4e4c:Active', 'master_uuid': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'812a943d-a046-449e-add2-8976efd523fb': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '20999434240', 'version': 0}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '', 'alerts': [], 'disktotal': '20999434240', 'version': 3}}}
>Thread-84::DEBUG::2014-09-11 07:32:19,726::task::1185::TaskManager.Task::(prepare) Task=`fda1d351-f2ba-4afc-91f1-8d431d0f328e`::finished: {'info': {'name': 'DC-ppc', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 2, 'domains': '812a943d-a046-449e-add2-8976efd523fb:Active,d3c59943-3404-46c8-a9e2-ba0f176a4e4c:Active', 'master_uuid': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'812a943d-a046-449e-add2-8976efd523fb': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '20999434240', 'version': 0}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '', 'alerts': [], 'disktotal': '20999434240', 'version': 3}}}
>Thread-84::DEBUG::2014-09-11 07:32:19,726::task::595::TaskManager.Task::(_updateState) Task=`fda1d351-f2ba-4afc-91f1-8d431d0f328e`::moving from state preparing -> state finished
>Thread-84::DEBUG::2014-09-11 07:32:19,726::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5fee1120-4e30-47eb-874c-45db26cce80a': < ResourceRef 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a', isValid: 'True' obj: 'None'>}
>Thread-84::DEBUG::2014-09-11 07:32:19,726::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-84::DEBUG::2014-09-11 07:32:19,727::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a'
>Thread-84::DEBUG::2014-09-11 07:32:19,727::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' (0 active users)
>Thread-84::DEBUG::2014-09-11 07:32:19,727::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' is free, finding out if anyone is waiting for it.
>Thread-84::DEBUG::2014-09-11 07:32:19,727::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a', Clearing records.
>Thread-84::DEBUG::2014-09-11 07:32:19,727::task::990::TaskManager.Task::(_decref) Task=`fda1d351-f2ba-4afc-91f1-8d431d0f328e`::ref 0 aborting False
>Thread-87::DEBUG::2014-09-11 07:32:26,379::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-87::DEBUG::2014-09-11 07:32:26,383::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n330 bytes (330 B) copied, 0.000617574 s, 534 kB/s\n'; <rc> = 0
>Thread-67::DEBUG::2014-09-11 07:32:28,247::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/_home_local/d3c59943-3404-46c8-a9e2-ba0f176a4e4c/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-67::DEBUG::2014-09-11 07:32:28,262::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n500 bytes (500 B) copied, 0.0113161 s, 44.2 kB/s\n'; <rc> = 0
>Thread-97::DEBUG::2014-09-11 07:32:31,571::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.61]
>Thread-97::DEBUG::2014-09-11 07:32:31,571::task::595::TaskManager.Task::(_updateState) Task=`0257bbc0-94c0-4348-a535-234d60148421`::moving from state init -> state preparing
>Thread-97::INFO::2014-09-11 07:32:31,571::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='5fee1120-4e30-47eb-874c-45db26cce80a', options=None)
>Thread-97::INFO::2014-09-11 07:32:31,572::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2}}
>Thread-97::DEBUG::2014-09-11 07:32:31,572::task::1185::TaskManager.Task::(prepare) Task=`0257bbc0-94c0-4348-a535-234d60148421`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2}}
>Thread-97::DEBUG::2014-09-11 07:32:31,572::task::595::TaskManager.Task::(_updateState) Task=`0257bbc0-94c0-4348-a535-234d60148421`::moving from state preparing -> state finished
>Thread-97::DEBUG::2014-09-11 07:32:31,572::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-97::DEBUG::2014-09-11 07:32:31,572::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-97::DEBUG::2014-09-11 07:32:31,572::task::990::TaskManager.Task::(_decref) Task=`0257bbc0-94c0-4348-a535-234d60148421`::ref 0 aborting False
>Thread-84::DEBUG::2014-09-11 07:32:31,763::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.61]
>Thread-84::DEBUG::2014-09-11 07:32:31,763::task::595::TaskManager.Task::(_updateState) Task=`19c393ef-1518-4262-92eb-0a4984ffeff1`::moving from state init -> state preparing
>Thread-84::INFO::2014-09-11 07:32:31,764::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='5fee1120-4e30-47eb-874c-45db26cce80a', options=None)
>Thread-84::DEBUG::2014-09-11 07:32:31,764::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.5fee1120-4e30-47eb-874c-45db26cce80a`ReqID=`c2bc4b63-3dcb-4a75-8d26-64341eb81ff8`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2572' at 'getStoragePoolInfo'
>Thread-84::DEBUG::2014-09-11 07:32:31,764::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' for lock type 'shared'
>Thread-84::DEBUG::2014-09-11 07:32:31,764::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' is free. Now locking as 'shared' (1 active user)
>Thread-84::DEBUG::2014-09-11 07:32:31,765::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.5fee1120-4e30-47eb-874c-45db26cce80a`ReqID=`c2bc4b63-3dcb-4a75-8d26-64341eb81ff8`::Granted request
>Thread-84::DEBUG::2014-09-11 07:32:31,765::task::827::TaskManager.Task::(resourceAcquired) Task=`19c393ef-1518-4262-92eb-0a4984ffeff1`::_resourcesAcquired: Storage.5fee1120-4e30-47eb-874c-45db26cce80a (shared)
>Thread-84::DEBUG::2014-09-11 07:32:31,765::task::990::TaskManager.Task::(_decref) Task=`19c393ef-1518-4262-92eb-0a4984ffeff1`::ref 1 aborting False
>Thread-84::INFO::2014-09-11 07:32:31,766::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'DC-ppc', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 2, 'domains': '812a943d-a046-449e-add2-8976efd523fb:Active,d3c59943-3404-46c8-a9e2-ba0f176a4e4c:Active', 'master_uuid': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'812a943d-a046-449e-add2-8976efd523fb': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '20999434240', 'version': 0}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '', 'alerts': [], 'disktotal': '20999434240', 'version': 3}}}
>Thread-84::DEBUG::2014-09-11 07:32:31,766::task::1185::TaskManager.Task::(prepare) Task=`19c393ef-1518-4262-92eb-0a4984ffeff1`::finished: {'info': {'name': 'DC-ppc', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 2, 'domains': '812a943d-a046-449e-add2-8976efd523fb:Active,d3c59943-3404-46c8-a9e2-ba0f176a4e4c:Active', 'master_uuid': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'812a943d-a046-449e-add2-8976efd523fb': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '20999434240', 'version': 0}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '', 'alerts': [], 'disktotal': '20999434240', 'version': 3}}}
>Thread-84::DEBUG::2014-09-11 07:32:31,766::task::595::TaskManager.Task::(_updateState) Task=`19c393ef-1518-4262-92eb-0a4984ffeff1`::moving from state preparing -> state finished
>Thread-84::DEBUG::2014-09-11 07:32:31,766::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5fee1120-4e30-47eb-874c-45db26cce80a': < ResourceRef 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a', isValid: 'True' obj: 'None'>}
>Thread-84::DEBUG::2014-09-11 07:32:31,767::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-84::DEBUG::2014-09-11 07:32:31,767::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a'
>Thread-84::DEBUG::2014-09-11 07:32:31,767::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' (0 active users)
>Thread-84::DEBUG::2014-09-11 07:32:31,767::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' is free, finding out if anyone is waiting for it.
>Thread-84::DEBUG::2014-09-11 07:32:31,767::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a', Clearing records.
>Thread-84::DEBUG::2014-09-11 07:32:31,768::task::990::TaskManager.Task::(_decref) Task=`19c393ef-1518-4262-92eb-0a4984ffeff1`::ref 0 aborting False
>Thread-97::DEBUG::2014-09-11 07:32:33,746::task::595::TaskManager.Task::(_updateState) Task=`e7d8362a-ab98-4e04-88d2-4fcb2b6f6f32`::moving from state init -> state preparing
>Thread-97::INFO::2014-09-11 07:32:33,746::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-97::INFO::2014-09-11 07:32:33,747::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'812a943d-a046-449e-add2-8976efd523fb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000617574', 'lastCheck': '7.4', 'valid': True}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0113161', 'lastCheck': '5.5', 'valid': True}}
>Thread-97::DEBUG::2014-09-11 07:32:33,747::task::1185::TaskManager.Task::(prepare) Task=`e7d8362a-ab98-4e04-88d2-4fcb2b6f6f32`::finished: {'812a943d-a046-449e-add2-8976efd523fb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000617574', 'lastCheck': '7.4', 'valid': True}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0113161', 'lastCheck': '5.5', 'valid': True}}
>Thread-97::DEBUG::2014-09-11 07:32:33,747::task::595::TaskManager.Task::(_updateState) Task=`e7d8362a-ab98-4e04-88d2-4fcb2b6f6f32`::moving from state preparing -> state finished
>Thread-97::DEBUG::2014-09-11 07:32:33,747::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-97::DEBUG::2014-09-11 07:32:33,747::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-97::DEBUG::2014-09-11 07:32:33,748::task::990::TaskManager.Task::(_decref) Task=`e7d8362a-ab98-4e04-88d2-4fcb2b6f6f32`::ref 0 aborting False
>Thread-87::DEBUG::2014-09-11 07:32:36,385::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-87::DEBUG::2014-09-11 07:32:36,407::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n330 bytes (330 B) copied, 0.0115676 s, 28.5 kB/s\n'; <rc> = 0
>Thread-67::DEBUG::2014-09-11 07:32:38,265::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/_home_local/d3c59943-3404-46c8-a9e2-ba0f176a4e4c/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-67::DEBUG::2014-09-11 07:32:38,280::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n500 bytes (500 B) copied, 0.0109531 s, 45.6 kB/s\n'; <rc> = 0
>Thread-97::DEBUG::2014-09-11 07:32:42,226::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.61]
>Thread-97::DEBUG::2014-09-11 07:32:42,227::task::595::TaskManager.Task::(_updateState) Task=`f2cbbc58-c684-4f42-9289-ad6696b71ad5`::moving from state init -> state preparing
>Thread-97::INFO::2014-09-11 07:32:42,227::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='5fee1120-4e30-47eb-874c-45db26cce80a', options=None)
>Thread-97::INFO::2014-09-11 07:32:42,227::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2}}
>Thread-97::DEBUG::2014-09-11 07:32:42,227::task::1185::TaskManager.Task::(prepare) Task=`f2cbbc58-c684-4f42-9289-ad6696b71ad5`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2}}
>Thread-97::DEBUG::2014-09-11 07:32:42,228::task::595::TaskManager.Task::(_updateState) Task=`f2cbbc58-c684-4f42-9289-ad6696b71ad5`::moving from state preparing -> state finished
>Thread-97::DEBUG::2014-09-11 07:32:42,228::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-97::DEBUG::2014-09-11 07:32:42,228::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-97::DEBUG::2014-09-11 07:32:42,228::task::990::TaskManager.Task::(_decref) Task=`f2cbbc58-c684-4f42-9289-ad6696b71ad5`::ref 0 aborting False
>Thread-84::DEBUG::2014-09-11 07:32:42,477::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.61]
>Thread-84::DEBUG::2014-09-11 07:32:42,477::task::595::TaskManager.Task::(_updateState) Task=`66b8e4e6-7323-4b81-b09b-5a7b239d49cb`::moving from state init -> state preparing
>Thread-84::INFO::2014-09-11 07:32:42,478::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='5fee1120-4e30-47eb-874c-45db26cce80a', options=None)
>Thread-84::DEBUG::2014-09-11 07:32:42,478::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.5fee1120-4e30-47eb-874c-45db26cce80a`ReqID=`fb298add-b2d6-475e-97c0-f6af2bccbeba`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2572' at 'getStoragePoolInfo'
>Thread-84::DEBUG::2014-09-11 07:32:42,478::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' for lock type 'shared'
>Thread-84::DEBUG::2014-09-11 07:32:42,478::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' is free. Now locking as 'shared' (1 active user)
>Thread-84::DEBUG::2014-09-11 07:32:42,479::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.5fee1120-4e30-47eb-874c-45db26cce80a`ReqID=`fb298add-b2d6-475e-97c0-f6af2bccbeba`::Granted request
>Thread-84::DEBUG::2014-09-11 07:32:42,479::task::827::TaskManager.Task::(resourceAcquired) Task=`66b8e4e6-7323-4b81-b09b-5a7b239d49cb`::_resourcesAcquired: Storage.5fee1120-4e30-47eb-874c-45db26cce80a (shared)
>Thread-84::DEBUG::2014-09-11 07:32:42,479::task::990::TaskManager.Task::(_decref) Task=`66b8e4e6-7323-4b81-b09b-5a7b239d49cb`::ref 1 aborting False
>Thread-84::INFO::2014-09-11 07:32:42,480::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'DC-ppc', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 2, 'domains': '812a943d-a046-449e-add2-8976efd523fb:Active,d3c59943-3404-46c8-a9e2-ba0f176a4e4c:Active', 'master_uuid': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'812a943d-a046-449e-add2-8976efd523fb': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '20999434240', 'version': 0}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '', 'alerts': [], 'disktotal': '20999434240', 'version': 3}}}
>Thread-84::DEBUG::2014-09-11 07:32:42,480::task::1185::TaskManager.Task::(prepare) Task=`66b8e4e6-7323-4b81-b09b-5a7b239d49cb`::finished: {'info': {'name': 'DC-ppc', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 2, 'domains': '812a943d-a046-449e-add2-8976efd523fb:Active,d3c59943-3404-46c8-a9e2-ba0f176a4e4c:Active', 'master_uuid': 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'812a943d-a046-449e-add2-8976efd523fb': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '/rhev/data-center/mnt/_home_iso/812a943d-a046-449e-add2-8976efd523fb/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '20999434240', 'version': 0}, 'd3c59943-3404-46c8-a9e2-ba0f176a4e4c': {'status': 'Active', 'diskfree': '7347437568', 'isoprefix': '', 'alerts': [], 'disktotal': '20999434240', 'version': 3}}}
>Thread-84::DEBUG::2014-09-11 07:32:42,480::task::595::TaskManager.Task::(_updateState) Task=`66b8e4e6-7323-4b81-b09b-5a7b239d49cb`::moving from state preparing -> state finished
>Thread-84::DEBUG::2014-09-11 07:32:42,480::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5fee1120-4e30-47eb-874c-45db26cce80a': < ResourceRef 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a', isValid: 'True' obj: 'None'>}
>Thread-84::DEBUG::2014-09-11 07:32:42,481::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-84::DEBUG::2014-09-11 07:32:42,481::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a'
>Thread-84::DEBUG::2014-09-11 07:32:42,481::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' (0 active users)
>Thread-84::DEBUG::2014-09-11 07:32:42,481::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a' is free, finding out if anyone is waiting for it.
>Thread-84::DEBUG::2014-09-11 07:32:42,481::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5fee1120-4e30-47eb-874c-45db26cce80a', Clearing records.
>Thread-84::DEBUG::2014-09-11 07:32:42,482::task::990::TaskManager.Task::(_decref) Task=`66b8e4e6-7323-4b81-b09b-5a7b239d49cb`::ref 0 aborting False

Actions: View

Attachments on bug 1140633: 936515 | 936516