--Apple-Mail=_FD1EC933-69E2-46CC-9BC0-B55FE93993D1 Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=us-ascii On 09/08/2012, at 4:18 PM, Yaniv Kaul wrote:
Engine log, and possibly VDSM log, would be most helpful. Y.
Thanks Yaniv, good point. :) These are the logs from a fresh run just now. --Apple-Mail=_FD1EC933-69E2-46CC-9BC0-B55FE93993D1 Content-Disposition: attachment; filename=engine.log Content-Type: application/octet-stream; name="engine.log" Content-Transfer-Encoding: 7bit 2012-08-09 08:16:56,945 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp--0.0.0.0-8009-10) [77eb9bef] START, ValidateStorageServerConnectionVDSCommand(vdsId = 6509b226-e117-11e1-bf22-532c8b4f1e9e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: null, connection: storage1.au.aeolusproject.org:/ext/ovirt31storage };]), log id: a33b997 2012-08-09 08:16:56,968 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp--0.0.0.0-8009-10) [77eb9bef] FINISH, ValidateStorageServerConnectionVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: a33b997 2012-08-09 08:16:56,985 INFO [org.ovirt.engine.core.bll.storage.AddStorageServerConnectionCommand] (ajp--0.0.0.0-8009-10) [77eb9bef] Running command: AddStorageServerConnectionCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2012-08-09 08:16:56,987 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp--0.0.0.0-8009-10) [77eb9bef] START, ConnectStorageServerVDSCommand(vdsId = 6509b226-e117-11e1-bf22-532c8b4f1e9e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: d1a705d3-b09b-4749-9586-fb3e1949a601, connection: storage1.au.aeolusproject.org:/ext/ovirt31storage };]), log id: 263296f8 2012-08-09 08:16:57,199 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp--0.0.0.0-8009-10) [77eb9bef] FINISH, ConnectStorageServerVDSCommand, return: {d1a705d3-b09b-4749-9586-fb3e1949a601=0}, log id: 263296f8 2012-08-09 08:16:57,276 INFO [org.ovirt.engine.core.bll.storage.AddNFSStorageDomainCommand] (ajp--0.0.0.0-8009-1) [22ec2cd9] Running command: AddNFSStorageDomainCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2012-08-09 08:16:57,295 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (ajp--0.0.0.0-8009-1) [22ec2cd9] START, CreateStorageDomainVDSCommand(vdsId = 6509b226-e117-11e1-bf22-532c8b4f1e9e, storageDomain=org.ovirt.engine.core.common.businessentities.storage_domain_static@65f83843, args=storage1.au.aeolusproject.org:/ext/ovirt31storage), log id: 8ed735b 2012-08-09 08:17:57,373 INFO [org.ovirt.engine.core.bll.storage.RemoveStorageServerConnectionCommand] (ajp--0.0.0.0-8009-10) [5feeb68f] Running command: RemoveStorageServerConnectionCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2012-08-09 08:17:57,376 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp--0.0.0.0-8009-10) [5feeb68f] START, DisconnectStorageServerVDSCommand(vdsId = 6509b226-e117-11e1-bf22-532c8b4f1e9e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: null, connection: storage1.au.aeolusproject.org:/ext/ovirt31storage };]), log id: 5b01e1a 2012-08-09 08:17:59,342 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp--0.0.0.0-8009-10) [5feeb68f] FINISH, DisconnectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: 5b01e1a 2012-08-09 08:18:01,621 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (ajp--0.0.0.0-8009-1) [22ec2cd9] Failed in CreateStorageDomainVDS method 2012-08-09 08:18:01,622 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (ajp--0.0.0.0-8009-1) [22ec2cd9] Error code StorageDomainCreationError and error message VDSGenericException: VDSErrorException: Failed to CreateStorageDomainVDS, error = Error creating a storage domain: ('storageType=1, sdUUID=322166bd-ddfd-4ac4-a946-7e66819f70aa, domainName=storage1-nfs, domClass=1, typeSpecificArg=storage1.au.aeolusproject.org:/ext/ovirt31storage domVersion=0',) 2012-08-09 08:18:01,624 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (ajp--0.0.0.0-8009-1) [22ec2cd9] Command org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand return value Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusOnlyReturnForXmlRpc mStatus Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusForXmlRpc mCode 351 mMessage Error creating a storage domain: ('storageType=1, sdUUID=322166bd-ddfd-4ac4-a946-7e66819f70aa, domainName=storage1-nfs, domClass=1, typeSpecificArg=storage1.au.aeolusproject.org:/ext/ovirt31storage domVersion=0',) 2012-08-09 08:18:01,626 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (ajp--0.0.0.0-8009-1) [22ec2cd9] Vds: host1.au.aeolusproject.org 2012-08-09 08:18:01,627 ERROR [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (ajp--0.0.0.0-8009-1) [22ec2cd9] Command CreateStorageDomainVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateStorageDomainVDS, error = Error creating a storage domain: ('storageType=1, sdUUID=322166bd-ddfd-4ac4-a946-7e66819f70aa, domainName=storage1-nfs, domClass=1, typeSpecificArg=storage1.au.aeolusproject.org:/ext/ovirt31storage domVersion=0',) 2012-08-09 08:18:01,629 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (ajp--0.0.0.0-8009-1) [22ec2cd9] FINISH, CreateStorageDomainVDSCommand, log id: 8ed735b 2012-08-09 08:18:01,630 ERROR [org.ovirt.engine.core.bll.storage.AddNFSStorageDomainCommand] (ajp--0.0.0.0-8009-1) [22ec2cd9] Command org.ovirt.engine.core.bll.storage.AddNFSStorageDomainCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateStorageDomainVDS, error = Error creating a storage domain: ('storageType=1, sdUUID=322166bd-ddfd-4ac4-a946-7e66819f70aa, domainName=storage1-nfs, domClass=1, typeSpecificArg=storage1.au.aeolusproject.org:/ext/ovirt31storage domVersion=0',) 2012-08-09 08:18:01,633 INFO [org.ovirt.engine.core.bll.storage.AddNFSStorageDomainCommand] (ajp--0.0.0.0-8009-1) [22ec2cd9] Command [id=e5eabd66-46fa-4e1b-bd22-6b26cf4538fb]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.storage_domain_dynamic; snapshot: 322166bd-ddfd-4ac4-a946-7e66819f70aa. 2012-08-09 08:18:01,635 INFO [org.ovirt.engine.core.bll.storage.AddNFSStorageDomainCommand] (ajp--0.0.0.0-8009-1) [22ec2cd9] Command [id=e5eabd66-46fa-4e1b-bd22-6b26cf4538fb]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.storage_domain_static; snapshot: 322166bd-ddfd-4ac4-a946-7e66819f70aa. 2012-08-09 08:18:01,661 ERROR [org.ovirt.engine.core.bll.storage.AddNFSStorageDomainCommand] (ajp--0.0.0.0-8009-1) [22ec2cd9] Transaction rolled-back for command: org.ovirt.engine.core.bll.storage.AddNFSStorageDomainCommand. --Apple-Mail=_FD1EC933-69E2-46CC-9BC0-B55FE93993D1 Content-Disposition: attachment; filename=vdsm.log Content-Type: application/octet-stream; name="vdsm.log" Content-Transfer-Encoding: 7bit Thread-353::DEBUG::2012-08-09 08:17:08,782::BindingXMLRPC::156::vds::(wrapper) [10.10.10.89] Thread-353::DEBUG::2012-08-09 08:17:08,782::task::588::TaskManager.Task::(_updateState) Task=`e8ea7cb4-68ce-45ae-8c1d-55a9c56c3806`::moving from state init -> state preparing Thread-353::INFO::2012-08-09 08:17:08,783::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'storage1.au.aeolusproject.org:/ext/ovirt31storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None) Thread-353::INFO::2012-08-09 08:17:08,783::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]} Thread-353::DEBUG::2012-08-09 08:17:08,783::task::1172::TaskManager.Task::(prepare) Task=`e8ea7cb4-68ce-45ae-8c1d-55a9c56c3806`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]} Thread-353::DEBUG::2012-08-09 08:17:08,783::task::588::TaskManager.Task::(_updateState) Task=`e8ea7cb4-68ce-45ae-8c1d-55a9c56c3806`::moving from state preparing -> state finished Thread-353::DEBUG::2012-08-09 08:17:08,784::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-353::DEBUG::2012-08-09 08:17:08,784::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-353::DEBUG::2012-08-09 08:17:08,784::task::978::TaskManager.Task::(_decref) Task=`e8ea7cb4-68ce-45ae-8c1d-55a9c56c3806`::ref 0 aborting False Thread-354::DEBUG::2012-08-09 08:17:08,826::BindingXMLRPC::156::vds::(wrapper) [10.10.10.89] Thread-354::DEBUG::2012-08-09 08:17:08,826::task::588::TaskManager.Task::(_updateState) Task=`0df60185-0c09-428b-9d2c-19d4f30cfe31`::moving from state init -> state preparing Thread-354::INFO::2012-08-09 08:17:08,827::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'storage1.au.aeolusproject.org:/ext/ovirt31storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'd1a705d3-b09b-4749-9586-fb3e1949a601', 'port': ''}], options=None) Thread-355::DEBUG::2012-08-09 08:17:08,897::task::588::TaskManager.Task::(_updateState) Task=`a6631af4-0724-4853-aba0-c98e85a7cc74`::moving from state init -> state preparing Thread-355::INFO::2012-08-09 08:17:08,897::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-355::INFO::2012-08-09 08:17:08,897::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-355::DEBUG::2012-08-09 08:17:08,897::task::1172::TaskManager.Task::(prepare) Task=`a6631af4-0724-4853-aba0-c98e85a7cc74`::finished: {} Thread-355::DEBUG::2012-08-09 08:17:08,901::task::588::TaskManager.Task::(_updateState) Task=`a6631af4-0724-4853-aba0-c98e85a7cc74`::moving from state preparing -> state finished Thread-355::DEBUG::2012-08-09 08:17:08,901::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-355::DEBUG::2012-08-09 08:17:08,903::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-355::DEBUG::2012-08-09 08:17:08,905::task::978::TaskManager.Task::(_decref) Task=`a6631af4-0724-4853-aba0-c98e85a7cc74`::ref 0 aborting False Thread-354::DEBUG::2012-08-09 08:17:08,974::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6 storage1.au.aeolusproject.org:/ext/ovirt31storage /rhev/data-center/mnt/storage1.au.aeolusproject.org:_ext_ovirt31storage' (cwd None) Thread-354::DEBUG::2012-08-09 08:17:09,011::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-354::DEBUG::2012-08-09 08:17:09,011::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-354::DEBUG::2012-08-09 08:17:09,012::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-354::DEBUG::2012-08-09 08:17:09,012::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-354::DEBUG::2012-08-09 08:17:09,012::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-354::DEBUG::2012-08-09 08:17:09,013::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-354::INFO::2012-08-09 08:17:09,013::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'd1a705d3-b09b-4749-9586-fb3e1949a601'}]} Thread-354::DEBUG::2012-08-09 08:17:09,013::task::1172::TaskManager.Task::(prepare) Task=`0df60185-0c09-428b-9d2c-19d4f30cfe31`::finished: {'statuslist': [{'status': 0, 'id': 'd1a705d3-b09b-4749-9586-fb3e1949a601'}]} Thread-354::DEBUG::2012-08-09 08:17:09,014::task::588::TaskManager.Task::(_updateState) Task=`0df60185-0c09-428b-9d2c-19d4f30cfe31`::moving from state preparing -> state finished Thread-354::DEBUG::2012-08-09 08:17:09,014::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-354::DEBUG::2012-08-09 08:17:09,014::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-354::DEBUG::2012-08-09 08:17:09,014::task::978::TaskManager.Task::(_decref) Task=`0df60185-0c09-428b-9d2c-19d4f30cfe31`::ref 0 aborting False Thread-357::DEBUG::2012-08-09 08:17:09,136::BindingXMLRPC::156::vds::(wrapper) [10.10.10.89] Thread-357::DEBUG::2012-08-09 08:17:09,136::task::588::TaskManager.Task::(_updateState) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::moving from state init -> state preparing Thread-357::INFO::2012-08-09 08:17:09,137::logUtils::37::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=1, sdUUID='322166bd-ddfd-4ac4-a946-7e66819f70aa', domainName='storage1-nfs', typeSpecificArg='storage1.au.aeolusproject.org:/ext/ovirt31storage', domClass=1, domVersion='0', options=None) Thread-357::DEBUG::2012-08-09 08:17:09,137::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Thread-357::DEBUG::2012-08-09 08:17:09,137::misc::1055::SamplingMethod::(__call__) Got in to sampling method Thread-357::DEBUG::2012-08-09 08:17:09,137::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-357::DEBUG::2012-08-09 08:17:09,138::misc::1055::SamplingMethod::(__call__) Got in to sampling method Thread-357::DEBUG::2012-08-09 08:17:09,138::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-357::DEBUG::2012-08-09 08:17:09,151::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21 Thread-357::DEBUG::2012-08-09 08:17:09,152::misc::1063::SamplingMethod::(__call__) Returning last result Thread-357::DEBUG::2012-08-09 08:17:10,987::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None) Thread-357::DEBUG::2012-08-09 08:17:11,022::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-357::DEBUG::2012-08-09 08:17:11,023::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-357::DEBUG::2012-08-09 08:17:11,023::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-357::DEBUG::2012-08-09 08:17:11,024::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-357::DEBUG::2012-08-09 08:17:11,024::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-357::DEBUG::2012-08-09 08:17:11,024::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-357::DEBUG::2012-08-09 08:17:11,024::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-357::DEBUG::2012-08-09 08:17:11,025::misc::1063::SamplingMethod::(__call__) Returning last result Thread-357::DEBUG::2012-08-09 08:17:11,025::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-357::DEBUG::2012-08-09 08:17:11,027::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/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_ST3160827AS_3MT021ZA%\\", \\"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 322166bd-ddfd-4ac4-a946-7e66819f70aa' (cwd None) Thread-357::DEBUG::2012-08-09 08:17:11,215::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = ' Volume group "322166bd-ddfd-4ac4-a946-7e66819f70aa" not found\n'; <rc> = 5 Thread-357::WARNING::2012-08-09 08:17:11,217::lvm::353::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "322166bd-ddfd-4ac4-a946-7e66819f70aa" not found'] Thread-357::DEBUG::2012-08-09 08:17:11,217::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-357::INFO::2012-08-09 08:17:11,221::nfsSD::64::Storage.StorageDomain::(create) sdUUID=322166bd-ddfd-4ac4-a946-7e66819f70aa domainName=storage1-nfs remotePath=storage1.au.aeolusproject.org:/ext/ovirt31storage domClass=1 Thread-357::DEBUG::2012-08-09 08:17:11,388::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-357::DEBUG::2012-08-09 08:17:11,389::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[] Thread-357::WARNING::2012-08-09 08:17:11,389::persistentDict::248::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is Thread-357::DEBUG::2012-08-09 08:17:11,389::persistentDict::162::Storage.PersistentDict::(transaction) Starting transaction Thread-357::DEBUG::2012-08-09 08:17:11,390::persistentDict::168::Storage.PersistentDict::(transaction) Flushing changes Thread-357::DEBUG::2012-08-09 08:17:11,390::persistentDict::287::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=storage1-nfs', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=storage1.au.aeolusproject.org:/ext/ovirt31storage', 'ROLE=Regular', 'SDUUID=322166bd-ddfd-4ac4-a946-7e66819f70aa', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=28fc3417f77ce0c7fc25167a658a5f05c33554aa'] Thread-357::DEBUG::2012-08-09 08:17:11,394::persistentDict::170::Storage.PersistentDict::(transaction) Finished transaction Thread-357::DEBUG::2012-08-09 08:17:11,395::fileSD::107::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/storage1.au.aeolusproject.org:_ext_ovirt31storage/322166bd-ddfd-4ac4-a946-7e66819f70aa Thread-357::DEBUG::2012-08-09 08:17:11,396::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-363::DEBUG::2012-08-09 08:17:19,079::task::588::TaskManager.Task::(_updateState) Task=`3a0a3a1f-8056-4c4f-a917-75e027d25b3c`::moving from state init -> state preparing Thread-363::INFO::2012-08-09 08:17:19,079::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-363::INFO::2012-08-09 08:17:19,079::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-363::DEBUG::2012-08-09 08:17:19,080::task::1172::TaskManager.Task::(prepare) Task=`3a0a3a1f-8056-4c4f-a917-75e027d25b3c`::finished: {} Thread-363::DEBUG::2012-08-09 08:17:19,080::task::588::TaskManager.Task::(_updateState) Task=`3a0a3a1f-8056-4c4f-a917-75e027d25b3c`::moving from state preparing -> state finished Thread-363::DEBUG::2012-08-09 08:17:19,080::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-363::DEBUG::2012-08-09 08:17:19,080::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-363::DEBUG::2012-08-09 08:17:19,081::task::978::TaskManager.Task::(_decref) Task=`3a0a3a1f-8056-4c4f-a917-75e027d25b3c`::ref 0 aborting False Thread-369::DEBUG::2012-08-09 08:17:29,242::task::588::TaskManager.Task::(_updateState) Task=`d80dcc6e-34c6-4197-a7ac-5f3a812f0e50`::moving from state init -> state preparing Thread-369::INFO::2012-08-09 08:17:29,243::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-369::INFO::2012-08-09 08:17:29,243::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-369::DEBUG::2012-08-09 08:17:29,243::task::1172::TaskManager.Task::(prepare) Task=`d80dcc6e-34c6-4197-a7ac-5f3a812f0e50`::finished: {} Thread-369::DEBUG::2012-08-09 08:17:29,243::task::588::TaskManager.Task::(_updateState) Task=`d80dcc6e-34c6-4197-a7ac-5f3a812f0e50`::moving from state preparing -> state finished Thread-369::DEBUG::2012-08-09 08:17:29,244::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-369::DEBUG::2012-08-09 08:17:29,244::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-369::DEBUG::2012-08-09 08:17:29,244::task::978::TaskManager.Task::(_decref) Task=`d80dcc6e-34c6-4197-a7ac-5f3a812f0e50`::ref 0 aborting False Thread-375::DEBUG::2012-08-09 08:17:39,412::task::588::TaskManager.Task::(_updateState) Task=`c895a747-6dd3-4085-9fb6-078cf699c5a8`::moving from state init -> state preparing Thread-375::INFO::2012-08-09 08:17:39,412::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-375::INFO::2012-08-09 08:17:39,412::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-375::DEBUG::2012-08-09 08:17:39,412::task::1172::TaskManager.Task::(prepare) Task=`c895a747-6dd3-4085-9fb6-078cf699c5a8`::finished: {} Thread-375::DEBUG::2012-08-09 08:17:39,413::task::588::TaskManager.Task::(_updateState) Task=`c895a747-6dd3-4085-9fb6-078cf699c5a8`::moving from state preparing -> state finished Thread-375::DEBUG::2012-08-09 08:17:39,413::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-375::DEBUG::2012-08-09 08:17:39,413::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-375::DEBUG::2012-08-09 08:17:39,413::task::978::TaskManager.Task::(_decref) Task=`c895a747-6dd3-4085-9fb6-078cf699c5a8`::ref 0 aborting False Thread-381::DEBUG::2012-08-09 08:17:49,572::task::588::TaskManager.Task::(_updateState) Task=`5f7b4c27-9251-4bc3-86a3-3a9aeae5ef42`::moving from state init -> state preparing Thread-381::INFO::2012-08-09 08:17:49,572::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-381::INFO::2012-08-09 08:17:49,572::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-381::DEBUG::2012-08-09 08:17:49,573::task::1172::TaskManager.Task::(prepare) Task=`5f7b4c27-9251-4bc3-86a3-3a9aeae5ef42`::finished: {} Thread-381::DEBUG::2012-08-09 08:17:49,573::task::588::TaskManager.Task::(_updateState) Task=`5f7b4c27-9251-4bc3-86a3-3a9aeae5ef42`::moving from state preparing -> state finished Thread-381::DEBUG::2012-08-09 08:17:49,573::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-381::DEBUG::2012-08-09 08:17:49,573::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-381::DEBUG::2012-08-09 08:17:49,574::task::978::TaskManager.Task::(_decref) Task=`5f7b4c27-9251-4bc3-86a3-3a9aeae5ef42`::ref 0 aborting False Thread-387::DEBUG::2012-08-09 08:17:59,762::task::588::TaskManager.Task::(_updateState) Task=`fff381cc-97c8-4688-93e2-6ded44ec48a0`::moving from state init -> state preparing Thread-387::INFO::2012-08-09 08:17:59,762::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-387::INFO::2012-08-09 08:17:59,762::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-387::DEBUG::2012-08-09 08:17:59,763::task::1172::TaskManager.Task::(prepare) Task=`fff381cc-97c8-4688-93e2-6ded44ec48a0`::finished: {} Thread-387::DEBUG::2012-08-09 08:17:59,763::task::588::TaskManager.Task::(_updateState) Task=`fff381cc-97c8-4688-93e2-6ded44ec48a0`::moving from state preparing -> state finished Thread-387::DEBUG::2012-08-09 08:17:59,763::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-387::DEBUG::2012-08-09 08:17:59,763::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-387::DEBUG::2012-08-09 08:17:59,764::task::978::TaskManager.Task::(_decref) Task=`fff381cc-97c8-4688-93e2-6ded44ec48a0`::ref 0 aborting False Thread-393::DEBUG::2012-08-09 08:18:09,215::BindingXMLRPC::156::vds::(wrapper) [10.10.10.89] Thread-393::DEBUG::2012-08-09 08:18:09,216::task::588::TaskManager.Task::(_updateState) Task=`8aa0983d-dac0-43e9-aa99-9afad7caff5f`::moving from state init -> state preparing Thread-393::INFO::2012-08-09 08:18:09,216::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'storage1.au.aeolusproject.org:/ext/ovirt31storage', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None) Thread-393::DEBUG::2012-08-09 08:18:09,216::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/umount -f -l /rhev/data-center/mnt/storage1.au.aeolusproject.org:_ext_ovirt31storage' (cwd None) Thread-393::DEBUG::2012-08-09 08:18:09,267::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Thread-393::DEBUG::2012-08-09 08:18:09,267::misc::1055::SamplingMethod::(__call__) Got in to sampling method Thread-393::DEBUG::2012-08-09 08:18:09,267::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-393::DEBUG::2012-08-09 08:18:09,267::misc::1055::SamplingMethod::(__call__) Got in to sampling method Thread-393::DEBUG::2012-08-09 08:18:09,268::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-393::DEBUG::2012-08-09 08:18:09,281::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21 Thread-393::DEBUG::2012-08-09 08:18:09,282::misc::1063::SamplingMethod::(__call__) Returning last result Thread-393::DEBUG::2012-08-09 08:18:11,118::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None) Thread-393::DEBUG::2012-08-09 08:18:11,154::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 Thread-393::DEBUG::2012-08-09 08:18:11,154::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-393::DEBUG::2012-08-09 08:18:11,154::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-393::DEBUG::2012-08-09 08:18:11,155::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-393::DEBUG::2012-08-09 08:18:11,155::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-393::DEBUG::2012-08-09 08:18:11,155::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-393::DEBUG::2012-08-09 08:18:11,156::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-393::DEBUG::2012-08-09 08:18:11,156::misc::1063::SamplingMethod::(__call__) Returning last result Thread-393::INFO::2012-08-09 08:18:11,156::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]} Thread-393::DEBUG::2012-08-09 08:18:11,156::task::1172::TaskManager.Task::(prepare) Task=`8aa0983d-dac0-43e9-aa99-9afad7caff5f`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]} Thread-393::DEBUG::2012-08-09 08:18:11,157::task::588::TaskManager.Task::(_updateState) Task=`8aa0983d-dac0-43e9-aa99-9afad7caff5f`::moving from state preparing -> state finished Thread-393::DEBUG::2012-08-09 08:18:11,157::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-393::DEBUG::2012-08-09 08:18:11,157::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-393::DEBUG::2012-08-09 08:18:11,157::task::978::TaskManager.Task::(_decref) Task=`8aa0983d-dac0-43e9-aa99-9afad7caff5f`::ref 0 aborting False Thread-394::DEBUG::2012-08-09 08:18:11,179::task::588::TaskManager.Task::(_updateState) Task=`ecb23219-f9df-48c7-b6ad-872a7c5bc626`::moving from state init -> state preparing Thread-394::INFO::2012-08-09 08:18:11,180::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-394::INFO::2012-08-09 08:18:11,180::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-394::DEBUG::2012-08-09 08:18:11,180::task::1172::TaskManager.Task::(prepare) Task=`ecb23219-f9df-48c7-b6ad-872a7c5bc626`::finished: {} Thread-394::DEBUG::2012-08-09 08:18:11,180::task::588::TaskManager.Task::(_updateState) Task=`ecb23219-f9df-48c7-b6ad-872a7c5bc626`::moving from state preparing -> state finished Thread-394::DEBUG::2012-08-09 08:18:11,180::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-394::DEBUG::2012-08-09 08:18:11,181::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-394::DEBUG::2012-08-09 08:18:11,181::task::978::TaskManager.Task::(_decref) Task=`ecb23219-f9df-48c7-b6ad-872a7c5bc626`::ref 0 aborting False Thread-357::ERROR::2012-08-09 08:18:13,433::task::853::TaskManager.Task::(_setError) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 861, in _run File "/usr/share/vdsm/logUtils.py", line 38, in wrapper File "/usr/share/vdsm/storage/hsm.py", line 2136, in createStorageDomain File "/usr/share/vdsm/storage/nfsSD.py", line 90, in create File "/usr/share/vdsm/storage/fileSD.py", line 113, in __init__ File "/usr/share/vdsm/storage/persistentDict.py", line 85, in __getitem__ File "/usr/share/vdsm/storage/persistentDict.py", line 193, in __getitem__ File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__ File "/usr/share/vdsm/storage/persistentDict.py", line 147, in _accessWrapper File "/usr/share/vdsm/storage/persistentDict.py", line 224, in refresh File "/usr/share/vdsm/storage/fileSD.py", line 82, in readlines File "/usr/share/vdsm/storage/processPool.py", line 63, in wrapper File "/usr/share/vdsm/storage/processPool.py", line 74, in runExternally File "/usr/share/vdsm/storage/processPool.py", line 161, in runExternally Timeout: Operation Stuck Thread-357::DEBUG::2012-08-09 08:18:13,434::task::872::TaskManager.Task::(_run) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::Task._run: 3b761b3d-44b7-4150-beaf-6d7b23513270 (1, '322166bd-ddfd-4ac4-a946-7e66819f70aa', 'storage1-nfs', 'storage1.au.aeolusproject.org:/ext/ovirt31storage', 1, '0') {} failed - stopping task Thread-357::DEBUG::2012-08-09 08:18:13,434::task::1199::TaskManager.Task::(stop) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::stopping in state preparing (force False) Thread-357::DEBUG::2012-08-09 08:18:13,434::task::978::TaskManager.Task::(_decref) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::ref 1 aborting True Thread-357::INFO::2012-08-09 08:18:13,435::task::1157::TaskManager.Task::(prepare) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::aborting: Task is aborted: u'Operation Stuck' - code 100 Thread-357::DEBUG::2012-08-09 08:18:13,435::task::1162::TaskManager.Task::(prepare) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::Prepare: aborted: Operation Stuck Thread-357::DEBUG::2012-08-09 08:18:13,435::task::978::TaskManager.Task::(_decref) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::ref 0 aborting True Thread-357::DEBUG::2012-08-09 08:18:13,436::task::913::TaskManager.Task::(_doAbort) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::Task._doAbort: force False Thread-357::DEBUG::2012-08-09 08:18:13,436::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-357::DEBUG::2012-08-09 08:18:13,436::task::588::TaskManager.Task::(_updateState) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::moving from state preparing -> state aborting Thread-357::DEBUG::2012-08-09 08:18:13,436::task::537::TaskManager.Task::(__state_aborting) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::_aborting: recover policy none Thread-357::DEBUG::2012-08-09 08:18:13,437::task::588::TaskManager.Task::(_updateState) Task=`3b761b3d-44b7-4150-beaf-6d7b23513270`::moving from state aborting -> state failed Thread-357::DEBUG::2012-08-09 08:18:13,437::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-357::DEBUG::2012-08-09 08:18:13,437::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-357::ERROR::2012-08-09 08:18:13,438::dispatcher::69::Storage.Dispatcher.Protect::(run) Operation Stuck Traceback (most recent call last): File "/usr/share/vdsm/storage/dispatcher.py", line 61, in run File "/usr/share/vdsm/storage/task.py", line 1164, in prepare Timeout: Operation Stuck Thread-401::DEBUG::2012-08-09 08:18:21,334::task::588::TaskManager.Task::(_updateState) Task=`a942c5d4-5760-41ca-ab5c-278c013e7e98`::moving from state init -> state preparing Thread-401::INFO::2012-08-09 08:18:21,334::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-401::INFO::2012-08-09 08:18:21,335::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-401::DEBUG::2012-08-09 08:18:21,335::task::1172::TaskManager.Task::(prepare) Task=`a942c5d4-5760-41ca-ab5c-278c013e7e98`::finished: {} Thread-401::DEBUG::2012-08-09 08:18:21,335::task::588::TaskManager.Task::(_updateState) Task=`a942c5d4-5760-41ca-ab5c-278c013e7e98`::moving from state preparing -> state finished Thread-401::DEBUG::2012-08-09 08:18:21,335::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-401::DEBUG::2012-08-09 08:18:21,336::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-401::DEBUG::2012-08-09 08:18:21,336::task::978::TaskManager.Task::(_decref) Task=`a942c5d4-5760-41ca-ab5c-278c013e7e98`::ref 0 aborting False --Apple-Mail=_FD1EC933-69E2-46CC-9BC0-B55FE93993D1 Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=us-ascii It's just the part of the log from where I hit enter on the screen to add the storage. Nothing else was happening on the boxes at the time. Btw, if it's useful, I can give you remote ssh and https into the boxes this is happening on. Regards and best wishes, Justin Clift -- Aeolus Community Manager http://www.aeolusproject.org --Apple-Mail=_FD1EC933-69E2-46CC-9BC0-B55FE93993D1--