Attachment 866428 Details for Bug 1068865 – partial vdsm.log describing an spmId change to -1

partial vdsm.log describing an spmId change to -1

vdsm.log (text/x-log), 34.37 KB, created by Gerasimos Melissaratos on 2014-02-22 16:16:30 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Gerasimos Melissaratos

Created: 2014-02-22 16:16:30 UTC

Size: 34.37 KB

patch

obsolete

>Thread-118778::DEBUG::2014-02-22 10:18:07,422::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91'
>Thread-118778::DEBUG::2014-02-22 10:18:07,422::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' (0 active users)
>Thread-118778::DEBUG::2014-02-22 10:18:07,422::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' is free, finding out if anyone is wai
>ting for it.
>Thread-118778::DEBUG::2014-02-22 10:18:07,423::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91', Clearing recor
>ds.
>Thread-118778::DEBUG::2014-02-22 10:18:07,423::task::974::TaskManager.Task::(_decref) Task=`a0ffe268-ad00-41a3-8501-5ad7a1738192`::ref 0 aborting False
>Thread-31::DEBUG::2014-02-22 10:18:11,344::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/glaros.maria.gr:_srv_vm/1f354860-c425-41c4-a98b-76c3318a8a3e
>/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-31::DEBUG::2014-02-22 10:18:11,357::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n635 bytes (635 B) copied, 0.00041322 s, 1.5 MB/s\n'; <
>rc> = 0
>Thread-37::DEBUG::2014-02-22 10:18:12,818::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/1.99.0.99:_p1/b8526353-e780-47cd-a47c-1b76c719bbbe/dom_md/
>metadata bs=4096 count=1' (cwd None)
>Thread-37::DEBUG::2014-02-22 10:18:12,832::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n335 bytes (335 B) copied, 0.00078924 s, 424 kB/s\n'; <
>rc> = 0
>Thread-33::DEBUG::2014-02-22 10:18:14,268::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/ovirt.maria.gr:_srv/2988930a-e66b-4d5d-93ed-551d26f06d1a/dom
>_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-02-22 10:18:14,281::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n340 bytes (340 B) copied, 0.000409214 s, 831 kB/s\n'; 
><rc> = 0
>Thread-32::DEBUG::2014-02-22 10:18:17,209::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/grouezas.maria.gr:_srv/87ec3c10-9624-443c-aae3-35305a8a7c3a/
>dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-32::DEBUG::2014-02-22 10:18:17,224::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n588 bytes (588 B) copied, 0.000639482 s, 919 kB/s\n'; 
><rc> = 0
>Thread-118783::DEBUG::2014-02-22 10:18:17,535::BindingXMLRPC::167::vds::(wrapper) client [10.5.225.36] flowID [5d75cbb6]
>Thread-118783::DEBUG::2014-02-22 10:18:17,536::task::579::TaskManager.Task::(_updateState) Task=`c36421ee-df2a-47de-b37c-8d6f7ad72c51`::moving from state init -> state preparing
>Thread-118783::INFO::2014-02-22 10:18:17,537::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='f92b1eea-3eb4-11e2-b25b-00188b76de91', options=None)
>Thread-118783::INFO::2014-02-22 10:18:17,537::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 12293}}
>Thread-118783::DEBUG::2014-02-22 10:18:17,538::task::1168::TaskManager.Task::(prepare) Task=`c36421ee-df2a-47de-b37c-8d6f7ad72c51`::finished: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spmLver': 
>12293}}
>Thread-118783::DEBUG::2014-02-22 10:18:17,538::task::579::TaskManager.Task::(_updateState) Task=`c36421ee-df2a-47de-b37c-8d6f7ad72c51`::moving from state preparing -> state finished
>Thread-118783::DEBUG::2014-02-22 10:18:17,538::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-118783::DEBUG::2014-02-22 10:18:17,539::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118783::DEBUG::2014-02-22 10:18:17,539::task::974::TaskManager.Task::(_decref) Task=`c36421ee-df2a-47de-b37c-8d6f7ad72c51`::ref 0 aborting False
>Thread-118784::DEBUG::2014-02-22 10:18:17,544::BindingXMLRPC::167::vds::(wrapper) client [10.5.225.36] flowID [5d75cbb6]
>Thread-118784::DEBUG::2014-02-22 10:18:17,544::task::579::TaskManager.Task::(_updateState) Task=`9077f257-d9c4-451f-a17e-a82f63543599`::moving from state init -> state preparing
>Thread-118784::INFO::2014-02-22 10:18:17,545::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='f92b1eea-3eb4-11e2-b25b-00188b76de91', options=None)
>Thread-118784::DEBUG::2014-02-22 10:18:17,546::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91`ReqID=`27cc5b81-9ca7-4a3d-a8dc-65e29df
>3af8a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2553' at 'getStoragePoolInfo'
>Thread-118784::DEBUG::2014-02-22 10:18:17,546::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' for lock type 'sh
>ared'
>Thread-118784::DEBUG::2014-02-22 10:18:17,547::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' is free. Now locking as 'shared' (1 
>active user)
>Thread-118784::DEBUG::2014-02-22 10:18:17,547::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91`ReqID=`27cc5b81-9ca7-4a3d-a8dc-65e29df3af
>8a`::Granted request
>Thread-118784::DEBUG::2014-02-22 10:18:17,548::task::811::TaskManager.Task::(resourceAcquired) Task=`9077f257-d9c4-451f-a17e-a82f63543599`::_resourcesAcquired: Storage.f92b1eea-3eb4-11e2-b25b-00188
>b76de91 (shared)
>Thread-118784::DEBUG::2014-02-22 10:18:17,548::task::974::TaskManager.Task::(_decref) Task=`9077f257-d9c4-451f-a17e-a82f63543599`::ref 1 aborting False
>Thread-118784::INFO::2014-02-22 10:18:17,556::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 3, 'master_uuid': '1f354860-c425-41c4-a98b-76c3318a8a3e', 'name': 'Default', 'version': '0', 'domains': '1f354860-c425-41c4-a98b-76c3318a8a3e:Active,87ec3c10-9624-443c-aae3-35305a8a7c3a:Active,2988930a-e66b-4d5d-93ed-551d26f06d1a:Active,b8526353-e780-47cd-a47c-1b76c719bbbe:Active,a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/mnt/ovirt.maria.gr:_srv/2988930a-e66b-4d5d-93ed-551d26f06d1a/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 6, 'lver': 12293}, 'dominfo': {'2988930a-e66b-4d5d-93ed-551d26f06d1a': {'status': 'Active', 'diskfree': '340546:
>02752', 'alerts': [], 'version': 0, 'disktotal': '67087892480'}, 'a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6': {'status': 'Active', 'diskfree': '2720064339968', 'alerts': [], 'version': 0, 'disktotal': '2948346937344'}, '1f354860-c425-41c4-a98b-76c3318a8a3e': {'status': 'Active', 'diskfree': '4675347677184', 'alerts': [], 'version': 0, 'disktotal': '5702198231040'}, 'b8526353-e780-47cd-a47c-1b76c719bbbe': {'status': 'Active', 'diskfree': '1361445912576', 'alerts': [], 'version': 0, 'disktotal': '2147255058432'}, '87ec3c10-9624-443c-aae3-35305a8a7c3a': {'status': 'Active', 'diskfree': '3556249698304', 'alerts': [], 'version': 0, 'disktotal': '3997733748736'}}}
>Thread-118784::DEBUG::2014-02-22 10:18:17,556::task::1168::TaskManager.Task::(prepare) Task=`9077f257-d9c4-451f-a17e-a82f63543599`::finished: {'info': {'spm_id': 3, 'master_uuid': '1f354860-c425-41c4-a98b-76c3318a8a3e', 'name': 'Default', 'version': '0', 'domains': '1f354860-c425-41c4-a98b-76c3318a8a3e:Active,87ec3c10-9624-443c-aae3-35305a8a7c3a:Active,2988930a-e66b-4d5d-93ed-551d26f06d1a:Active,b8526353-e780-47cd-a47c-1b76c719bbbe:Active,a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/mnt/ovirt.maria.gr:_srv/2988930a-e66b-4d5d-93ed-551d26f06d1a/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 6, 'lver': 12293}, 'dominfo': {'2988930a-e66b-4d5d-93ed-551d26f06d1a': {'status': 'Active', 'diskfree': '34054602752', 'alerts': [], 'version': 0, 'disktotal': '67087892480'}, 'a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6': {'status': 'Active', 'diskfree': '2720064339968', 'alerts': [], 'version': 0, 'disktotal': '2948346937344'}, '1f354860-c425-41c4-a98b-76c3318a8a3e': {'status': 'Active', 'diskfree': '4675347677184', 'alerts': [], 'version': 0, 'disktotal': '5702198231040'}, 'b8526353-e780-47cd-a47c-1b76c719bbbe': {'status': 'Active', 'diskfree': '1361445912576', 'alerts': [], 'version': 0, 'disktotal': '2147255058432'}, '87ec3c10-9624-443c-aae3-35305a8a7c3a': {'status': 'Active', 'diskfree': '3556249698304', 'alerts': [], 'version': 0, 'disktotal': '3997733748736'}}}
>Thread-118784::DEBUG::2014-02-22 10:18:17,557::task::579::TaskManager.Task::(_updateState) Task=`9077f257-d9c4-451f-a17e-a82f63543599`::moving from state preparing -> state finished
>Thread-118784::DEBUG::2014-02-22 10:18:17,557::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91': < ResourceRef 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91', isValid: 'True' obj: 'None'>}
>Thread-118784::DEBUG::2014-02-22 10:18:17,558::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118784::DEBUG::2014-02-22 10:18:17,558::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91'
>Thread-118784::DEBUG::2014-02-22 10:18:17,559::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' (0 active users)
>Thread-118784::DEBUG::2014-02-22 10:18:17,559::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' is free, finding out if anyone is waiting for it.
>Thread-118784::DEBUG::2014-02-22 10:18:17,559::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91', Clearing records.
>Thread-118784::DEBUG::2014-02-22 10:18:17,560::task::974::TaskManager.Task::(_decref) Task=`9077f257-d9c4-451f-a17e-a82f63543599`::ref 0 aborting False
>Thread-118785::DEBUG::2014-02-22 10:18:19,695::task::579::TaskManager.Task::(_updateState) Task=`1f0f3aa8-5b3e-4441-97e2-2286e205a898`::moving from state init -> state preparing
>Thread-118785::INFO::2014-02-22 10:18:19,695::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-118785::INFO::2014-02-22 10:18:19,696::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2988930a-e66b-4d5d-93ed-551d26f06d1a': {'delay': '0.000409214', 'lastCheck': '5.4', 'code': 0, 'valid': True, 'version': 0}, 'a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6': {'delay': '0.000733711', 'lastCheck': '30.9', 'code': 0, 'valid': True, 'version': 0}, '1f354860-c425-41c4-a98b-76c3318a8a3e': {'delay': '0.00041322', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': 0}, 'b8526353-e780-47cd-a47c-1b76c719bbbe': {'delay': '0.00078924', 'lastCheck': '6.9', 'code': 0, 'valid': True, 'version': 0}, '87ec3c10-9624-443c-aae3-35305a8a7c3a': {'delay': '0.000639482', 'lastCheck': '2.5', 'code': 0, 'valid': True, 'version': 0}}
>Thread-118785::DEBUG::2014-02-22 10:18:19,696::task::1168::TaskManager.Task::(prepare) Task=`1f0f3aa8-5b3e-4441-97e2-2286e205a898`::finished: {'2988930a-e66b-4d5d-93ed-551d26f06d1a': {'delay': '0.000409214', 'lastCheck': '5.4', 'code': 0, 'valid': True, 'version': 0}, 'a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6': {'delay': '0.000733711', 'lastCheck': '30.9', 'code': 0, 'valid': True, 'version': 0}, '1f354860-c425-41c4-a98b-76c3318a8a3e': {'delay': '0.00041322', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': 0}, 'b8526353-e780-47cd-a47c-1b76c719bbbe': {'delay': '0.00078924', 'lastCheck': '6.9', 'code': 0, 'valid': True, 'version': 0}, '87ec3c10-9624-443c-aae3-35305a8a7c3a': {'delay': '0.000639482', 'lastCheck': '2.5', 'code': 0, 'valid': True, 'version': 0}}
>Thread-118785::DEBUG::2014-02-22 10:18:19,697::task::579::TaskManager.Task::(_updateState) Task=`1f0f3aa8-5b3e-4441-97e2-2286e205a898`::moving from state preparing -> state finished
>Thread-118785::DEBUG::2014-02-22 10:18:19,697::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-118785::DEBUG::2014-02-22 10:18:19,697::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118785::DEBUG::2014-02-22 10:18:19,698::task::974::TaskManager.Task::(_decref) Task=`1f0f3aa8-5b3e-4441-97e2-2286e205a898`::ref 0 aborting False
>Thread-31::DEBUG::2014-02-22 10:18:21,383::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/glaros.maria.gr:_srv_vm/1f354860-c425-41c4-a98b-76c3318a8a3e/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-31::DEBUG::2014-02-22 10:18:21,397::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n635 bytes (635 B) copied, 0.000408092 s, 1.6 MB/s\n'; <rc> = 0
>Thread-37::DEBUG::2014-02-22 10:18:22,851::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/1.99.0.99:_p1/b8526353-e780-47cd-a47c-1b76c719bbbe/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-37::DEBUG::2014-02-22 10:18:22,865::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n335 bytes (335 B) copied, 0.000874155 s, 383 kB/s\n'; <rc> = 0
>MainThread::DEBUG::2014-02-22 10:18:23,684::vdsm::50::vds::(sigusr1Handler) Received signal 10
>MainThread::DEBUG::2014-02-22 10:18:23,685::task::579::TaskManager.Task::(_updateState) Task=`09caf45b-f431-4d14-b682-d8b304d66916`::moving from state init -> state preparing
>MainThread::INFO::2014-02-22 10:18:23,685::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>MainThread::INFO::2014-02-22 10:18:23,685::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': ['f92b1eea-3eb4-11e2-b25b-00188b76de91']}
>MainThread::DEBUG::2014-02-22 10:18:23,686::task::1168::TaskManager.Task::(prepare) Task=`09caf45b-f431-4d14-b682-d8b304d66916`::finished: {'poollist': ['f92b1eea-3eb4-11e2-b25b-00188b76de91']}
>MainThread::DEBUG::2014-02-22 10:18:23,686::task::579::TaskManager.Task::(_updateState) Task=`09caf45b-f431-4d14-b682-d8b304d66916`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-02-22 10:18:23,686::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-02-22 10:18:23,687::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-02-22 10:18:23,687::task::974::TaskManager.Task::(_decref) Task=`09caf45b-f431-4d14-b682-d8b304d66916`::ref 0 aborting False
>MainThread::DEBUG::2014-02-22 10:18:23,688::task::579::TaskManager.Task::(_updateState) Task=`08c61277-d72d-4785-a7fd-d8ca9e2d61f2`::moving from state init -> state preparing
>MainThread::INFO::2014-02-22 10:18:23,688::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='f92b1eea-3eb4-11e2-b25b-00188b76de91', options=None)
>MainThread::DEBUG::2014-02-22 10:18:23,689::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91`ReqID=`b58b2cd5-e28b-455a-b79c-f3214c41665c`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '609' at 'spmStop'
>MainThread::DEBUG::2014-02-22 10:18:23,689::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' for lock type 'exclusive'
>MainThread::DEBUG::2014-02-22 10:18:23,690::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' is free. Now locking as 'exclusive' (1 active user)
>MainThread::DEBUG::2014-02-22 10:18:23,690::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91`ReqID=`b58b2cd5-e28b-455a-b79c-f3214c41665c`::Granted request
>MainThread::DEBUG::2014-02.mfa.gr-22 10:18:23,691::task::811::TaskManager.Task::(resourceAcquired) Task=`08c61277-d72d-4785-a7fd-d8ca9e2d61f2`::_resourcesAcquired: Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91 (exclusive)
>MainThread::DEBUG::2014-02-2.mfa.gr2 10:18:23,691::task::974::TaskManager.Task::(_decref) Task=`08c61277-d72d-4785-a7fd-d8ca9e2d61f2`::ref 1 aborting False
>MainThread::DEBUG::2014-02-22 10:18:23,691::sp::350::Storage.StoragePool::(_shutDownUpgrade) Shutting down upgrade process
>MainThread::DEBUG::2014-02-22 10:18:23,692::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_f92b1eea-3eb4-11e2-b25b-00188b76de91`ReqID=`50ebc5cb-ce7a-4934-9a2f-efcf5a7bb629`::Request was made in '/usr/share/vdsm/storage/sp.py' line '352' at '_shutDownUpgrade'
>MainThread::DEBUG::2014-02-22 10:18:2.mfa.gr3,692::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_f92b1eea-3eb4-11e2-b25b-00188b76de91' for lock type 'exclusive'
>MainThread::DEBUG::2014-02-22 10:18:23,692::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.upgrade_f92b1eea-3eb4-11e2-b25b-00188b76de91' is free. Now locking as 'exclusive' (1 active user)
>MainThread::DEBUG::2014-02-22 10:18:23,693::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.upgrade_f92b1eea-3eb4-11e2-b25b-00188b76de91`ReqID=`50ebc5cb-ce7a-4934-9a2f-efcf5a7bb629`::Granted request
>MainThread::DEBUG::2014-02-22 10:18:23,694::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_f92b1eea-3eb4-11e2-b25b-00188b76de91'
>MainThread::DEBUG::2014-02-22 10:18:23,694::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_f92b1eea-3eb4-11e2-b25b-00188b76de91' (0 active users)
>MainThread::DEBUG::2014-02-22 10:18:23,694::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.upgrade_f92b1eea-3eb4-11e2-b25b-00188b76de91' is free, finding out if anyone is waiting for it.
>MainThread::DEBUG::2014-02-22 10:18:23,695::resourceManager.mfa.gr::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_f92b1eea-3eb4-11e2-b25b-00188b76de91', Clearing records.
>MainThread::DEBUG::2014-02-22 10:18:23,695::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>MainThread::DEBUG::2014-02-22 10:18:23,696::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>MainThread::DEBUG::2014-02-22 10:18:23,696::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=temp_store', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=6', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=1f354860-c425-41c4-a98b-76c3318a8a3e:Active,87ec3c10-9624-443c-aae3-35305a8a7c3a:Active,2988930a-e66b-4d5d-93ed-551d26f06d1a:Active,b8526353-e780-47cd-a47c-1b76c719bbbe:Active,a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=12293', 'POOL_UUID=f92b1eea-3eb4-11e2-b25b-00188b76de91', 'REMOTE_PATH=glaros.maria.gr:/srv/vm', 'ROLE=Master', 'SDUUID=1f354860-c425-41c4-a98b-76c3318a8a3e', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=48f597abb10f341522f539e54f0810494d7a7aa0']
>MainThread::DEBUG::2014-02-22 10:18:23,829::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>MainThread::INFO::2014-02-22 10:18:23,830::clusterlock::123::SafeLease::(release) Releasing cluster lock for domain 1f354860-c425-41c4-a98b-76c3318a8a3e
>MainThread::DEBUG::2014-02-22 10:18:23,830::clusterlock::125::Storage.Misc.excCmd::(release) '/usr/libexec/vdsm/spmstop.sh 1f354860-c425-41c4-a98b-76c3318a8a3e' (cwd /usr/libexec/vdsm)
>Thread-33::DEBUG::2014-02-22 10:18:24,301::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/ovirt.maria.gr:_srv/2988930a-e66b-4d5d-93ed-551d26f06d1a/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-02-22 10:18:24,314::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n340 bytes (340 B) copied, 0.000394084 s, 863 kB/s\n'; <rc> = 0
>MainThread::DEBUG::2014-02-22 10:18:24,874::clusterlock::125::Storage.Misc.excCmd::(release) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-02-22 10:18:24,874::clusterlock::130::SafeLease::(release) Cluster lock released successfully
>MainThread::INFO::2014-02-22 10:18:24,875::logUtils::47::dispatcher::(wrapper) Run and protect: spmStop, Return response: None
>MainThread::DEBUG::2014-02-22 10:18:24,875::task::1168::TaskManager.Task::(prepare) Task=`08c61277-d72d-4785-a7fd-d8ca9e2d61f2`::finished: None
>MainThread::DEBUG::2014-02-22 10:18:24,875::task::579::TaskManager.Task::(_updateState) Task=`08c61277-d72d-4785-a7fd-d8ca9e2d61f2`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-02-22 10:18:24,876::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91': < ResourceRef 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91', isValid: 'True' obj: 'None'>}
>MainThread::DEBUG::2014-02-22 10:18:24,876::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-02-22 10:18:24,877::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91'
>MainThread::DEBUG::2014-02-22 10:18:24,877::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' (0 active users)
>MainThread::DEBUG::2014-02-22 10:18:24,878::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91' is free, finding out if anyone is waiting for it.
>MainThread::DEBUG::2014-02-22 10:18:24,878::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f92b1eea-3eb4-11e2-b25b-00188b76de91', Clearing records.
>MainThread::DEBUG::2014-02-22 10:18:24,879::task::974::TaskManager.Task::(_decref) Task=`08c61277-d72d-4785-a7fd-d8ca9e2d61f2`::ref 0 aborting False
>Thread-32::DEBUG::2014-02-22 10:18:27,248::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/grouezas.maria.gr:_srv/87ec3c10-9624-443c-aae3-35305a8a7c3a/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-32::DEBUG::2014-02-22 10:18:27,263::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n588 bytes (588 B) copied, 0.000703997 s, 835 kB/s\n'; <rc> = 0
>Thread-118789::DEBUG::2014-02-22 10:18:27,619::BindingXMLRPC::167::vds::(wrapper) client [10.5.225.36] flowID [644cbe97]
>Thread-118789::DEBUG::2014-02-22 10:18:27,620::task::579::TaskManager.Task::(_updateState) Task=`aceb424d-c0e4-4553-ba80-096430662ce9`::moving from state init -> state preparing
>Thread-118789::INFO::2014-02-22 10:18:27,620::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='f92b1eea-3eb4-11e2-b25b-00188b76de91', options=None)
>Thread-118789::INFO::2014-02-22 10:18:27,621::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 12293}}
>Thread-118789::DEBUG::2014-02-22 10:18:27,621::task::1168::TaskManager.Task::(prepare) Task=`aceb424d-c0e4-4553-ba80-096430662ce9`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 12293}}
>Thread-118789::DEBUG::2014-02-22 10:18:27,622::task::579::TaskManager.Task::(_updateState) Task=`aceb424d-c0e4-4553-ba80-096430662ce9`::moving from state preparing -> state finished
>Thread-118789::DEBUG::2014-02-22 10:18:27,622::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-118789::DEBUG::2014-02-22 10:18:27,622::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118789::DEBUG::2014-02-22 10:18:27,623::task::974::TaskManager.Task::(_decref) Task=`aceb424d-c0e4-4553-ba80-096430662ce9`::ref 0 aborting False
>Thread-118790::DEBUG::2014-02-22 10:18:27,675::BindingXMLRPC::167::vds::(wrapper) client [10.5.225.36] flowID [5186eaa2]
>Thread-118790::DEBUG::2014-02-22 10:18:27,676::task::579::TaskManager.Task::(_updateState) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::moving from state init -> state preparing
>Thread-118790::INFO::2014-02-22 10:18:27,677::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-118790::ERROR::2014-02-22 10:18:27,677::task::850::TaskManager.Task::(_setError) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 857, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 2111, in getAllTasksStatuses
>    allTasksStatus = sp.getAllTasksStatuses()
>  File "/usr/share/vdsm/storage/securable.py", line 66, in wrapper
>    raise SecureError().mfa.gr
>SecureError
>Thread-118790::DEBUG::2014-02-22 10:18:27,678::task::869::TaskManager.Task::(_run) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::Task._run: 3141aa9d-3a64-4776-9564-98ead10b76fd () {} failed - stopping task
>Thread-118790::DEBUG::2014-02-22 10:18:27,678::task::1194::TaskManager.Task::(stop) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::stopping in state preparing (force False)
>Thread-118790::DEBUG::2014-02-22 10:18:27,678::task::974::TaskManager.Task::(_decref) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::ref 1 aborting True
>Thread-118790::INFO::2014-02-22 10:18:27,679::task::1151::TaskManager.Task::(prepare) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::aborting: Task is aborted: u'' - code 100
>Thread-118790::DEBUG::2014-02-22 10:18:27,679::task::1156::TaskManager.Task::(prepare) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::Prepare: aborted: 
>Thread-118790::DEBUG::2014-02-22 10:18:27,680::task::974::TaskManager.Task::(_decref) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::ref 0 aborting True
>Thread-118790::DEBUG::2014-02-22 10:18:27,680::task::909::TaskManager.Task::(_doAbort) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::Task._doAbort: force False
>Thread-118790::DEBUG::2014-02-22 10:18:27,680::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118790::DEBUG::2014-02-22 10:18:27,681::task::579::TaskManager.Task::(_updateState) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::moving from state preparing -> state aborting
>Thread-118790::DEBUG::2014-02-22 10:18:27,681::task::534::TaskManager.Task::(__state_aborting) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::_aborting: recover policy none
>Thread-118790::DEBUG::2014-02-22 10:18:27,681::task::579::TaskManager.Task::(_updateState) Task=`3141aa9d-3a64-4776-9564-98ead10b76fd`::moving from state aborting -> state failed
>Thread-118790::DEBUG::2014-02-22 10:18:27,682::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-118790::DEBUG::2014-02-22 10:18:27,682::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118790::ERROR::2014-02-22 10:18:27,682::dispatcher::70::Storage.Dispatcher.Protect::(run) 
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/dispatcher.py", line 62, in run
>    result = ctask.prepare(self.func, *args, **kwargs)
>  File "/usr/share/vdsm/storage/task.py", line 1159, in prepare
>    raise self.error
>SecureError
>Thread-118791::DEBUG::2014-02-22 10:18:27,819::BindingXMLRPC::167::vds::(wrapper) client [10.5.225.36] flowID [5186eaa2]
>Thread-118791::DEBUG::2014-02-22 10:18:27,820::task::579::TaskManager.Task::(_updateState) Task=`2916eb04-8d46-4ee5-aeb2-b2916ce14f58`::moving from state init -> state preparing
>Thread-118791::INFO::2014-02-22 10:18:27,820::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='f92b1eea-3eb4-11e2-b25b-00188b76de91', options=None)
>Thread-118791::INFO::2014-02-22 10:18:27,821::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 12293}}
>Thread-118791::DEBUG::2014-02-22 10:18:27,821::task::1168::TaskManager.Task::(prepare) Task=`2916eb04-8d46-4ee5-aeb2-b2916ce14f58`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 12293}}
>Thread-118791::DEBUG::2014-02-22 10:18:27,822::task::579::TaskManager.Task::(_updateState) Task=`2916eb04-8d46-4ee5-aeb2-b2916ce14f58`::moving from state preparing -> state finished
>Thread-118791::DEBUG::2014-02-22 10:18:27,822::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-118791::DEBUG::2014-02-22 10:18:27,822::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118791::DEBUG::2014-02-22 10:18:27,823::task::974::TaskManager.Task::(_decref) Task=`2916eb04-8d46-4ee5-aeb2-b2916ce14f58`::ref 0 aborting False
>VM Channels Listener::DEBUG::2014-02-22 10:18:30,536::guestIF::147::vm.Vm::(_connect) vmId=`7179768b-d369-4259-b9cd-b9684fd4a117`::Attempting connection to /var/lib/libvirt/qemu/channels/7179768b-d369-4259-b9cd-b9684fd4a117.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-02-22 10:18:30,536::guestIF::158::vm.Vm::(_connect) vmId=`7179768b-d369-4259-b9cd-b9684fd4a117`::Failed to connect to /var/lib/libvirt/qemu/channels/7179768b-d369-4259-b9cd-b9684fd4a117.com.redhat.rhevm.vdsm with 11
>VM Channels Listener::DEBUG::2014-02-22 10:18:30,537::guestIF::1.mfa.gr47::vm.Vm::(_connect) vmId=`e41c0f9d-aa30-4003-8ade-a580d6a46ef0`::Attempting connection to /var/lib/libvirt/qemu/channels/e41c0f9d-aa30-4003-8ade-a580d6a46ef0.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-02-22 10:18:30,538::guestIF::158::vm.Vm::(_connect) vmId=`e41c0f9d-aa30-4003-8ade-a580d6a46ef0`::Failed to connect to /var/lib/libvirt/qemu/channels/e41c0f9d-aa30-4003-8ade-a580d6a46ef0.com.redhat.rhevm.vdsm with 11
>Thread-31::DEBUG::2014-02-22 10:18:31,420::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/glaros.maria.gr:_srv_vm/1f354860-c425-41c4-a98b-76c3318a8a3e/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-31::DEBUG::2014-02-22 10:18:31,434::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n635 bytes (635 B) copied, 0.000361945 s, 1.8 MB/s\n'; <rc> = 0
>Thread-37::DEBUG::2014-02-22 10:18:32,890::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/1.99.0.99:_p1/b8526353-e780-47cd-a47c-1b76c719bbbe/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-37::DEBUG::2014-02-22 10:18:32,905::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n335 bytes (335 B) copied, 0.000699749 s, 479 kB/s\n'; <rc> = 0
>Thread-19::DEBUG::2014-02-22 10:18:33,801::task::579::TaskManager.Task::(_updateState) Task=`c437b35d-a0e7-45fd-97d6-ac00b79d6c5e`::moving from state init -> state preparing
>Thread-19::INFO::2014-02-22 10:18:33,801::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='b8526353-e780-47cd-a47c-1b76c719bbbe', spUUID='f92b1eea-3eb4-11e2-b25b-00188b76de91', imgUUID='4aa78f80-2adc-4212-94d2-235e6a97df55', volUUID='ee011b74-4c14-4abe-8d37-b89a82ce125e', options=None)
>Thread-19::INFO::2014-02-22 10:18:33,806::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '4814344192', 'apparentsize': '32212254720'}
>Thread-19::DEBUG::2014-02-22 10:18:33,806::task::1168::TaskManager.Task::(prepare) Task=`c437b35d-a0e7-45fd-97d6-ac00b79d6c5e`::finished: {'truesize': '4814344192', 'apparentsize': '32212254720'}
>Thread-19::DEBUG::2014-02-22 10:18:33,807::task::579::TaskManager.Task::(_updateState) Task=`c437b35d-a0e7-45fd-97d6-ac00b79d6c5e`::moving from state preparing -> state finished
>Thread-19::DEBUG::2014-02-22 10:18:33,807::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-19::DEBUG::2014-02-22 10:18:33,807::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-19::DEBUG::2014-02-22 10:18:33,808::task::974::TaskManager.Task::(_decref) Task=`c437b35d-a0e7-45fd-97d6-ac00b79d6c5e`::ref 0 aborting False
>Thread-33::DEBUG::2014-02-22 10:18:34,333::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/ovirt.maria.gr:_srv/2988930a-e66b-4d5d-93ed-551d26f06d1a/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-02-22 10:18:34,347::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n340 bytes (340 B) copied, 0.000308711 s, 1.1 MB/s\n'; <rc> = 0
>Thread-118794::DEBUG::2014-02-22 10:18:34,966::task::579::TaskManager.Task::(_updateState) Task=`5e95c4aa-faac-4f2d-a53d-160c7a9fa41a`::moving from state init -> state preparing
>Thread-118794::INFO::2014-02-22 10:18:34,967::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-118794::INFO::2014-02-22 10:18:34,968::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2988930a-e66b-4d5d-93ed-551d26f06d1a': {'delay': '0.000308711', 'lastCheck': '0.6', 'code': 0, 'valid': True, 'version': 0}, 'a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6': {'delay': '0.000733711', 'lastCheck': '46.2', 'code': 0, 'valid': True, 'version': 0}, '1f354860-c425-41c4-a98b-76c3318a8a3e': {'delay': '0.000361945', 'lastCheck': '3.5', 'code': 0, 'valid': True, 'version': 0}, 'b8526353-e780-47cd-a47c-1b76c719bbbe': {'delay': '0.000699749', 'lastCheck': '2.1', 'code': 0, 'valid': True, 'version': 0}, '87ec3c10-9624-443c-aae3-35305a8a7c3a': {'delay': '0.000703997', 'lastCheck': '7.7', 'code': 0, 'valid': True, 'version': 0}}
>Thread-118794::DEBUG::2014-02-22 10:18:34,968::task::1168::TaskManager.Task::(prepare) Task=`5e95c4aa-faac-4f2d-a53d-160c7a9fa41a`::finished: {'2988930a-e66b-4d5d-93ed-551d26f06d1a': {'delay': '0.000308711', 'lastCheck': '0.6', 'code': 0, 'valid': True, 'version': 0}, 'a71e2d6e-5f4a-4fd1-99fc-7974f972f6c6': {'delay': '0.000733711', 'lastCheck': '46.2', 'code': 0, 'valid': True, 'version': 0}, '1f354860-c425-41c4-a98b-76c3318a8a3e': {'delay': '0.000361945', 'lastCheck': '3.5', 'code': 0, 'valid': True, 'version': 0}, 'b8526353-e780-47cd-a47c-1b76c719bbbe': {'delay': '0.000699749', 'lastCheck': '2.1', 'code': 0, 'valid': True, 'version': 0}, '87ec3c10-9624-443c-aae3-35305a8a7c3a': {'delay': '0.000703997', 'lastCheck': '7.7', 'code': 0, 'valid': True, 'version': 0}}

Actions: View

Attachments on bug 1068865: 866428 | 866570 | 866679 | 866890