Re: [Users] Issues with NFS d­omains and kernel-3.5.0-2­.f17

problem also exist with 3.5.2-1.fc17.x86_64 kernel # uname -a Linux kvm04 3.5.2-1.fc17.x86_64 #1 SMP Wed Aug 15 16:09:27 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux # rpm -q vdsm vdsm-4.10.0-0.331.git69d730d.fc17.x86_64 iso nfs domain d2221cee-7146-4197-aecf-0dfad32b54ea mounted correctly under /rhev/data-center/mnt/ but can't attach to DC here is a part of vdsm.log Thread-37506::DEBUG::2012-08-21 10:23:31,463::task::568::TaskManager.Task::(_updateState) Task=`d2436317-5e3f-4bf1-8414-b3e771a04b76`::moving from state init -> state preparing Thread-37506::INFO::2012-08-21 10:23:31,464::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='8800e8fa-bcee-11e1-9c2b-000c290cc066', options=None) Thread-37506::DEBUG::2012-08-21 10:23:31,464::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066`ReqID=`9698fc65-ad15-4c61-af01-1ce4ad627447`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource' Thread-37506::DEBUG::2012-08-21 10:23:31,464::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066' for lock type 'shared' Thread-37506::DEBUG::2012-08-21 10:23:31,465::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066' is free. Now locking as 'shared' (1 active user) Thread-37506::DEBUG::2012-08-21 10:23:31,465::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066`ReqID=`9698fc65-ad15-4c61-af01-1ce4ad627447`::Granted request Thread-37506::DEBUG::2012-08-21 10:23:31,466::task::794::TaskManager.Task::(resourceAcquired) Task=`d2436317-5e3f-4bf1-8414-b3e771a04b76`::_resourcesAcquired: Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066 (shared) Thread-37506::DEBUG::2012-08-21 10:23:31,466::task::957::TaskManager.Task::(_decref) Task=`d2436317-5e3f-4bf1-8414-b3e771a04b76`::ref 1 aborting False Thread-37506::DEBUG::2012-08-21 10:23:31,466::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:31,470::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_0_lun1|1p_ISCSI_0_lun2|1p_ISCSI_0_lun3%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free e57827fe-f368-4e96-b57c-f14d52cfccb7' (cwd None) Thread-37506::DEBUG::2012-08-21 10:23:31,564::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-37506::DEBUG::2012-08-21 10:23:31,566::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:31,567::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Dummy-86::DEBUG::2012-08-21 10:23:31,773::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=/rhev/data-center/8800e8fa-bcee-11e1-9c2b-000c290cc066/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None) Dummy-86::DEBUG::2012-08-21 10:23:31,833::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0375137 s, 27.3 MB/s\n'; <rc> = 0 Thread-37502::DEBUG::2012-08-21 10:23:33,317::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/sudo -n /sbin/multipath' (cwd None) Thread-37502::DEBUG::2012-08-21 10:23:33,360::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-37502::DEBUG::2012-08-21 10:23:33,361::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-37502::DEBUG::2012-08-21 10:23:33,361::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-37502::DEBUG::2012-08-21 10:23:33,362::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-37502::DEBUG::2012-08-21 10:23:33,362::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-37502::DEBUG::2012-08-21 10:23:33,362::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-37502::DEBUG::2012-08-21 10:23:33,363::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-37502::DEBUG::2012-08-21 10:23:33,363::misc::1071::SamplingMethod::(__call__) Returning last result Thread-37506::DEBUG::2012-08-21 10:23:33,363::misc::1063::SamplingMethod::(__call__) Got in to sampling method Thread-37502::DEBUG::2012-08-21 10:23:33,363::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:33,364::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-37506::DEBUG::2012-08-21 10:23:33,364::misc::1063::SamplingMethod::(__call__) Got in to sampling method Thread-37506::DEBUG::2012-08-21 10:23:33,365::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-37502::DEBUG::2012-08-21 10:23:33,374::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_0_lun1|1p_ISCSI_0_lun2|1p_ISCSI_0_lun3%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free' (cwd None) Thread-37506::DEBUG::2012-08-21 10:23:33,391::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-37506::DEBUG::2012-08-21 10:23:33,391::misc::1071::SamplingMethod::(__call__) Returning last result Thread-37502::DEBUG::2012-08-21 10:23:33,488::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-37502::DEBUG::2012-08-21 10:23:33,492::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Dummy-86::DEBUG::2012-08-21 10:23:33,842::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=/rhev/data-center/8800e8fa-bcee-11e1-9c2b-000c290cc066/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None) Dummy-86::DEBUG::2012-08-21 10:23:33,903::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0377754 s, 27.1 MB/s\n'; <rc> = 0 Thread-37506::DEBUG::2012-08-21 10:23:35,711::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/sudo -n /sbin/multipath' (cwd None) Thread-37506::DEBUG::2012-08-21 10:23:35,752::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-37506::DEBUG::2012-08-21 10:23:35,753::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:35,753::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:35,754::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:35,754::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:35,754::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:35,755::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:35,755::misc::1071::SamplingMethod::(__call__) Returning last result Thread-37506::INFO::2012-08-21 10:23:35,756::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'e57827fe-f368-4e96-b57c-f14d52cfccb7', 'name': 'Default', 'version': '2', 'domains': 'e57827fe-f368-4e96-b57c-f14d52cfccb7:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 3, 'lver': 16}, 'dominfo': {'e57827fe-f368-4e96-b57c-f14d52cfccb7': {'status': 'Active', 'diskfree': '495800287232', 'alerts': [], 'disktotal': '536468258816'}}} Thread-37506::DEBUG::2012-08-21 10:23:35,756::task::1151::TaskManager.Task::(prepare) Task=`d2436317-5e3f-4bf1-8414-b3e771a04b76`::finished: {'info': {'spm_id': 1, 'master_uuid': 'e57827fe-f368-4e96-b57c-f14d52cfccb7', 'name': 'Default', 'version': '2', 'domains': 'e57827fe-f368-4e96-b57c-f14d52cfccb7:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 3, 'lver': 16}, 'dominfo': {'e57827fe-f368-4e96-b57c-f14d52cfccb7': {'status': 'Active', 'diskfree': '495800287232', 'alerts': [], 'disktotal': '536468258816'}}} Thread-37506::DEBUG::2012-08-21 10:23:35,756::task::568::TaskManager.Task::(_updateState) Task=`d2436317-5e3f-4bf1-8414-b3e771a04b76`::moving from state preparing -> state finished Thread-37506::DEBUG::2012-08-21 10:23:35,757::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066': < ResourceRef 'Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066', isValid: 'True' obj: 'None'>} Thread-37502::DEBUG::2012-08-21 10:23:35,757::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-37506::DEBUG::2012-08-21 10:23:35,758::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-37506::DEBUG::2012-08-21 10:23:35,759::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066' Thread-37506::DEBUG::2012-08-21 10:23:35,760::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066' (0 active users) Thread-37506::DEBUG::2012-08-21 10:23:35,760::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066' is free, finding out if anyone is waiting for it. Thread-37506::DEBUG::2012-08-21 10:23:35,761::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.8800e8fa-bcee-11e1-9c2b-000c290cc066', Clearing records. Thread-37506::DEBUG::2012-08-21 10:23:35,761::task::957::TaskManager.Task::(_decref) Task=`d2436317-5e3f-4bf1-8414-b3e771a04b76`::ref 0 aborting False Thread-37502::DEBUG::2012-08-21 10:23:35,766::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_0_lun1|1p_ISCSI_0_lun2|1p_ISCSI_0_lun3%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free d2221cee-7146-4197-aecf-0dfad32b54ea' (cwd None) Thread-37502::DEBUG::2012-08-21 10:23:35,874::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = ' Volume group "d2221cee-7146-4197-aecf-0dfad32b54ea" not found\n'; <rc> = 5 Thread-37502::WARNING::2012-08-21 10:23:35,877::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "d2221cee-7146-4197-aecf-0dfad32b54ea" not found'] Thread-37502::DEBUG::2012-08-21 10:23:35,878::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-37502::DEBUG::2012-08-21 10:23:35,888::fileSD::107::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.130.41:_var_spool_ISO/d2221cee-7146-4197-aecf-0dfad32b54ea Thread-37502::DEBUG::2012-08-21 10:23:35,888::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Dummy-86::DEBUG::2012-08-21 10:23:35,912::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=/rhev/data-center/8800e8fa-bcee-11e1-9c2b-000c290cc066/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None) Thread-37502::WARNING::2012-08-21 10:23:35,969::remoteFileHandler::185::Storage.CrabRPCProxy::(callCrabRPCFunction) Problem with handler, treating as timeout Traceback (most recent call last): File "/usr/share/vdsm/storage/remoteFileHandler.py", line 177, in callCrabRPCFunction rawLength = self._recvAll(LENGTH_STRUCT_LENGTH, timeout) File "/usr/share/vdsm/storage/remoteFileHandler.py", line 146, in _recvAll timeLeft): File "/usr/lib64/python2.7/contextlib.py", line 84, in helper return GeneratorContextManager(func(*args, **kwds)) File "/usr/share/vdsm/storage/remoteFileHandler.py", line 133, in _poll raise Timeout() Timeout Dummy-86::DEBUG::2012-08-21 10:23:35,972::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.034715 s, 29.5 MB/s\n'; <rc> = 0 Thread-37502::ERROR::2012-08-21 10:23:35,972::sdc::145::Storage.StorageDomainCache::(_findDomain) Error while looking for domain `d2221cee-7146-4197-aecf-0dfad32b54ea` Traceback (most recent call last): File "/usr/share/vdsm/storage/sdc.py", line 140, in _findDomain return mod.findDomain(sdUUID) File "/usr/share/vdsm/storage/nfsSD.py", line 131, in findDomain return NfsStorageDomain(NfsStorageDomain.findDomainPath(sdUUID)) File "/usr/share/vdsm/storage/fileSD.py", line 113, in __init__ sdUUID = metadata[sd.DMDK_SDUUID] File "/usr/share/vdsm/storage/persistentDict.py", line 89, in __getitem__ return dec(self._dict[key]) File "/usr/share/vdsm/storage/persistentDict.py", line 199, in __getitem__ with self._accessWrapper(): File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__ return self.gen.next() File "/usr/share/vdsm/storage/persistentDict.py", line 152, in _accessWrapper self.refresh() File "/usr/share/vdsm/storage/persistentDict.py", line 230, in refresh lines = self._metaRW.readlines() File "/usr/share/vdsm/storage/fileSD.py", line 82, in readlines return misc.stripNewLines(self._oop.directReadLines(self._metafile)) File "/usr/share/vdsm/storage/remoteFileHandler.py", line 282, in callCrabRPCFunction raise Timeout("Operation stuck on remote handler") Timeout: Operation stuck on remote handler Thread-37502::ERROR::2012-08-21 10:23:35,982::hsm::2347::Storage.HSM::(getStorageDomainsList) Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/hsm.py", line 2333, in getStorageDomainsList dom = sdCache.produce(sdUUID=sdUUID) File "/usr/share/vdsm/storage/sdc.py", line 110, in produce dom.getRealDomain() File "/usr/share/vdsm/storage/sdc.py", line 51, in getRealDomain return self._cache._realProduce(self._sdUUID) File "/usr/share/vdsm/storage/sdc.py", line 123, in _realProduce dom = self._findDomain(sdUUID) File "/usr/share/vdsm/storage/sdc.py", line 147, in _findDomain raise se.StorageDomainDoesNotExist(sdUUID) StorageDomainDoesNotExist: Storage domain does not exist: ('d2221cee-7146-4197-aecf-0dfad32b54ea',) Втр 07 Авг 2012 22:47:38 +0400, Jason Brooks <jbrooks(a)redhat.com&gt; написал: --