<p dir="ltr">I noticed that you're getting a 304 error. There was just a case of that when starting a DC. Check the list archives going back the last 4-5 days and see if that scenario applies to you...</p>
<div class="gmail_quote">On Apr 27, 2013 7:25 AM, "Steven Wiltshire" <<a href="mailto:stevenwiltshire@gmail.com">stevenwiltshire@gmail.com</a>> wrote:<br type="attribution"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Hi,<br>
<br>
I am using NFS storage, although it is local.<br>
<br>
Looking in to the NFS problems further, I read the NFS troubleshooting section of the oVirt wiki and made a few changes. nfs-check.py gives me the following:<br>
<br>
------------------------------<u></u>------------------------------<u></u>------<br>
Current hostname: bigserver - IP addr 10.0.0.154<br>
Trying to /bin/mount -t nfs 10.0.0.154:/home/vm/data/data.<u></u>..<br>
Executing NFS tests..<br>
Removing vdsmTest file..<br>
Status of tests [OK]<br>
Disconnecting from NFS Server..<br>
Done!<br>
------------------------------<u></u>------------------------------<u></u>------<br>
<br>
Success! Or so it seems, because when the machine boots there are no NFS shares mounted. When I attempt to activate the data centre in the oVirt web admin tool, the activation fails but an NFS share is mounted:<br>
<br>
------------------------------<u></u>------------------------------<u></u>------<br>
10.0.0.154:/home/vm/data/data on /rhev/data-center/mnt/<a href="http://10.0.0." target="_blank">10.0.0.</a><u></u>154:_home_vm_data_data type nfs (rw,relatime,vers=3,rsize=<u></u>1048576,wsize=1048576,namlen=<u></u>255,soft,nosharecache,proto=<u></u>tcp,timeo=600,retrans=6,sec=<u></u>sys,mountaddr=10.0.0.154,<u></u>mountvers=3,mountport=20048,<u></u>mountproto=udp,local_lock=<u></u>none,addr=10.0.0.154)<br>
------------------------------<u></u>------------------------------<u></u>------<br>
<br>
Here is the engine.log associated with trying to activate the data centre:<br>
<br>
------------------------------<u></u>------------------------------<u></u>------<br>
2013-04-27 22:45:01,229 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand] (pool-5-thread-44) Lock Acquired to object EngineLock [exclusiveLocks= key: org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand val<br>
ue: 025062dd-d69e-40ac-9031-<u></u>c080b51647ae<br>
, sharedLocks= ]<br>
2013-04-27 22:45:01,231 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand] (pool-5-thread-44) Running command: ActivateStorageDomainCommand internal: false. Entities affected : ID: 025062dd-d69e-40ac-9031-<u></u>c080b51647a<br>
e Type: Storage<br>
2013-04-27 22:45:01,243 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand] (pool-5-thread-44) Lock freed to object EngineLock [exclusiveLocks= key: org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand value:<br>
025062dd-d69e-40ac-9031-<u></u>c080b51647ae<br>
, sharedLocks= ]<br>
2013-04-27 22:45:01,244 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand] (pool-5-thread-44) ActivateStorage Domain. Before Connect all hosts to pool. Time:4/27/13 10:45 PM<br>
2013-04-27 22:45:01,285 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ValidateStorageServerConnectio<u></u>nVDSCommand] (pool-5-thread-50) START, ValidateStorageServerConnectio<u></u>nVDSCommand(vdsId = aeac7aa6-8840-11e1-99aa-<u></u>7fbd3e56e26e, storage<br>
PoolId = 00000000-0000-0000-0000-<u></u>000000000000, storageType = NFS, connectionList = [{ id: 60e73855-daa2-45f5-9c59-<u></u>5973ca89e830, connection: 10.0.0.154:/home/vm/data/data };]), log id: 27174693<br>
2013-04-27 22:45:01,400 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ValidateStorageServerConnectio<u></u>nVDSCommand] (pool-5-thread-50) FINISH, ValidateStorageServerConnectio<u></u>nVDSCommand, return: {60e73855-daa2-45f5-9c59-<u></u>5973ca89e830=0}, l<br>
og id: 27174693<br>
2013-04-27 22:45:01,402 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ConnectStorageToVdsCommand] (pool-5-thread-50) Running command: ConnectStorageToVdsCommand internal: true. Entities affected : ID: aaa00000-0000-0000-0000-<u></u>123456789aaa Typ<br>
e: System<br>
2013-04-27 22:45:01,412 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ConnectStorageServerVDSCommand<u></u>] (pool-5-thread-50) START, ConnectStorageServerVDSCommand<u></u>(vdsId = aeac7aa6-8840-11e1-99aa-<u></u>7fbd3e56e26e, storagePoolId = 00000000-0000<br>
-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: 60e73855-daa2-45f5-9c59-<u></u>5973ca89e830, connection: 10.0.0.154:/home/vm/data/data };]), log id: 397edfdf<br>
2013-04-27 22:45:01,447 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ConnectStorageServerVDSCommand<u></u>] (pool-5-thread-50) FINISH, ConnectStorageServerVDSCommand<u></u>, return: {60e73855-daa2-45f5-9c59-<u></u>5973ca89e830=0}, log id: 397edfdf<br>
2013-04-27 22:45:01,450 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand] (pool-5-thread-44) ActivateStorage Domain. After Connect all hosts to pool. Time:4/27/13 10:45 PM<br>
2013-04-27 22:45:01,451 INFO [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>ActivateStorageDomainVDSComman<u></u>d] (pool-5-thread-44) START, ActivateStorageDomainVDSComman<u></u>d(storagePoolId = 2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 025062dd-d69e-40ac-9031-<u></u>c080b51647ae), log id: 4a58fee6<br>
2013-04-27 22:45:30,061 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>BrokerCommandBase] (QuartzScheduler_Worker-95) Command org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ConnectStoragePoolVDSCommand return value<br>
Class Name: org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>StatusOnlyReturnForXmlRpc<br>
mStatus Class Name: org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>StatusForXmlRpc<br>
mCode 304<br>
mMessage Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
<br>
<br>
2013-04-27 22:45:30,062 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>BrokerCommandBase] (QuartzScheduler_Worker-95) Vds: BigServer<br>
2013-04-27 22:45:30,062 ERROR [org.ovirt.engine.core.<u></u>vdsbroker.VDSCommandBase] (QuartzScheduler_Worker-95) Command ConnectStoragePoolVDS execution failed. Exception: IRSNoMasterDomainException: IRSGenericException: IRSErrorException: IRSNoMasterDomainException: Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
2013-04-27 22:45:30,063 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ConnectStoragePoolVDSCommand] (QuartzScheduler_Worker-95) FINISH, ConnectStoragePoolVDSCommand, log id: 1891eb24<br>
2013-04-27 22:45:30,064 INFO [org.ovirt.engine.core.utils.<u></u>transaction.<u></u>TransactionSupport] (QuartzScheduler_Worker-95) transaction rolled back<br>
2013-04-27 22:45:30,064 ERROR [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (QuartzScheduler_Worker-95) IrsBroker::Failed::<u></u>GetStoragePoolInfoVDS<br>
2013-04-27 22:45:30,065 ERROR [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (QuartzScheduler_Worker-95) Exception: IRSGenericException: IRSErrorException: IRSNoMasterDomainException: Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
2013-04-27 22:45:30,086 WARN [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ReconstructMasterDomainCommand<u></u>] (QuartzScheduler_Worker-95) CanDoAction of action ReconstructMasterDomain failed. Reasons:VAR__ACTION__<u></u>RECONSTRUCT_MASTER,VAR__TYPE__<u></u>STORAGE__DOMAIN,ACTION_TYPE_<u></u>FAILED_STORAGE_DOMAIN_STATUS_<u></u>ILLEGAL2<br>
2013-04-27 22:45:30,120 INFO [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (pool-5-thread-44) hostFromVds::selectedVds - BigServer, spmStatus Unknown_Pool, storage pool Default<br>
2013-04-27 22:45:30,146 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ConnectStoragePoolVDSCommand] (pool-5-thread-44) START, ConnectStoragePoolVDSCommand(<u></u>vdsId = aeac7aa6-8840-11e1-99aa-<u></u>7fbd3e56e26e, storagePoolId = 2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84, vds_spm_id = 1, masterDomainId = 025062dd-d69e-40ac-9031-<u></u>c080b51647ae, masterVersion = 1), log id: 460d5550<br>
2013-04-27 22:45:43,303 INFO [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (QuartzScheduler_Worker-7) starting ProcessDomainRecovery for domain 503e6677-2d51-4668-ab17-<u></u>f914bdb57c19<br>
2013-04-27 22:45:43,327 WARN [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (QuartzScheduler_Worker-7) domain 503e6677-2d51-4668-ab17-<u></u>f914bdb57c19 was reported by all hosts in status UP as problematic. Moving the Domain to NonOperational.<br>
2013-04-27 22:45:43,335 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>HandleFailedStorageDomainComma<u></u>nd] (QuartzScheduler_Worker-7) Running command: HandleFailedStorageDomainComma<u></u>nd internal: true. Entities affected : ID: 503e6677-2d51-4668-ab17-<u></u>f914bdb57c19 Type: Storage<br>
2013-04-27 22:45:43,344 WARN [org.ovirt.engine.core.bll.<u></u>storage.<u></u>DeactivateStorageDomainCommand<u></u>] (QuartzScheduler_Worker-7) CanDoAction of action DeactivateStorageDomain failed. Reasons:VAR__TYPE__STORAGE__<u></u>DOMAIN,VAR__ACTION__<u></u>DEACTIVATE,ACTION_TYPE_FAILED_<u></u>STORAGE_DOMAIN_STATUS_ILLEGAL<br>
2013-04-27 22:45:43,349 ERROR [org.ovirt.engine.core.bll.<u></u>storage.<u></u>HandleFailedStorageDomainComma<u></u>nd] (QuartzScheduler_Worker-7) Transaction rolled-back for command: org.ovirt.engine.core.bll.<u></u>storage.<u></u>HandleFailedStorageDomainComma<u></u>nd.<br>
2013-04-27 22:45:43,350 INFO [org.ovirt.engine.core.dal.<u></u>dbbroker.auditloghandling.<u></u>AuditLogDirector] (QuartzScheduler_Worker-7) No string for UNASSIGNED type. Use default Log<br>
2013-04-27 22:45:43,351 INFO [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (QuartzScheduler_Worker-8) starting ProcessDomainRecovery for domain d30604e3-3ca8-470a-8da4-<u></u>18c9402f7504<br>
2013-04-27 22:45:43,360 WARN [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (QuartzScheduler_Worker-8) domain d30604e3-3ca8-470a-8da4-<u></u>18c9402f7504 was reported by all hosts in status UP as problematic. Moving the Domain to NonOperational.<br>
2013-04-27 22:45:43,368 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>HandleFailedStorageDomainComma<u></u>nd] (QuartzScheduler_Worker-8) Running command: HandleFailedStorageDomainComma<u></u>nd internal: true. Entities affected : ID: d30604e3-3ca8-470a-8da4-<u></u>18c9402f7504 Type: Storage<br>
2013-04-27 22:45:43,376 WARN [org.ovirt.engine.core.bll.<u></u>storage.<u></u>DeactivateStorageDomainCommand<u></u>] (QuartzScheduler_Worker-8) CanDoAction of action DeactivateStorageDomain failed. Reasons:VAR__TYPE__STORAGE__<u></u>DOMAIN,VAR__ACTION__<u></u>DEACTIVATE,ACTION_TYPE_FAILED_<u></u>STORAGE_DOMAIN_STATUS_ILLEGAL<br>
2013-04-27 22:45:43,381 ERROR [org.ovirt.engine.core.bll.<u></u>storage.<u></u>HandleFailedStorageDomainComma<u></u>nd] (QuartzScheduler_Worker-8) Transaction rolled-back for command: org.ovirt.engine.core.bll.<u></u>storage.<u></u>HandleFailedStorageDomainComma<u></u>nd.<br>
2013-04-27 22:45:43,381 INFO [org.ovirt.engine.core.dal.<u></u>dbbroker.auditloghandling.<u></u>AuditLogDirector] (QuartzScheduler_Worker-8) No string for UNASSIGNED type. Use default Log<br>
2013-04-27 22:45:48,445 WARN [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (QuartzScheduler_Worker-23) domain 503e6677-2d51-4668-ab17-<u></u>f914bdb57c19 in problem. vds: BigServer<br>
2013-04-27 22:46:34,040 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>BrokerCommandBase] (pool-5-thread-44) Command org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ConnectStoragePoolVDSCommand return value<br>
Class Name: org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>StatusOnlyReturnForXmlRpc<br>
mStatus Class Name: org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>StatusForXmlRpc<br>
mCode 304<br>
mMessage Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
<br>
<br>
2013-04-27 22:46:34,040 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>BrokerCommandBase] (pool-5-thread-44) Vds: BigServer<br>
2013-04-27 22:46:34,040 ERROR [org.ovirt.engine.core.<u></u>vdsbroker.VDSCommandBase] (pool-5-thread-44) Command ConnectStoragePoolVDS execution failed. Exception: IRSNoMasterDomainException: IRSGenericException: IRSErrorException: IRSNoMasterDomainException: Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
2013-04-27 22:46:34,041 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ConnectStoragePoolVDSCommand] (pool-5-thread-44) FINISH, ConnectStoragePoolVDSCommand, log id: 460d5550<br>
2013-04-27 22:46:34,042 INFO [org.ovirt.engine.core.utils.<u></u>transaction.<u></u>TransactionSupport] (pool-5-thread-44) transaction rolled back<br>
2013-04-27 22:46:34,042 ERROR [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (pool-5-thread-44) IrsBroker::Failed::<u></u>ActivateStorageDomainVDS<br>
2013-04-27 22:46:34,043 ERROR [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (pool-5-thread-44) Exception: IRSGenericException: IRSErrorException: IRSNoMasterDomainException: Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
2013-04-27 22:46:34,058 WARN [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ReconstructMasterDomainCommand<u></u>] (pool-5-thread-44) CanDoAction of action ReconstructMasterDomain failed. Reasons:VAR__ACTION__<u></u>RECONSTRUCT_MASTER,VAR__TYPE__<u></u>STORAGE__DOMAIN,ACTION_TYPE_<u></u>FAILED_STORAGE_DOMAIN_STATUS_<u></u>ILLEGAL2<br>
2013-04-27 22:46:34,059 INFO [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>ActivateStorageDomainVDSComman<u></u>d] (pool-5-thread-44) FINISH, ActivateStorageDomainVDSComman<u></u>d, log id: 4a58fee6<br>
2013-04-27 22:46:34,059 ERROR [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand] (pool-5-thread-44) Command org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IRSNoMasterDomainException: IRSGenericException: IRSErrorException: IRSNoMasterDomainException: Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
2013-04-27 22:46:34,067 INFO [org.ovirt.engine.core.bll.<u></u>storage.<u></u>ActivateStorageDomainCommand] (pool-5-thread-44) Command [id=7fe48e9f-b3c3-455e-a869-<u></u>7cde583084cf]: Compensating CHANGED_STATUS_ONLY of org.ovirt.engine.core.common.<u></u>businessentities.storage_pool_<u></u>iso_map; snapshot: EntityStatusSnapshot [id=storagePoolId = 2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84, storageId = 025062dd-d69e-40ac-9031-<u></u>c080b51647ae, status=InActive].<br>
2013-04-27 22:46:34,094 INFO [org.ovirt.engine.core.<u></u>vdsbroker.irsbroker.<u></u>IrsBrokerCommand] (QuartzScheduler_Worker-93) hostFromVds::selectedVds - BigServer, spmStatus Unknown_Pool, storage pool Default<br>
2013-04-27 22:46:34,106 INFO [org.ovirt.engine.core.<u></u>vdsbroker.vdsbroker.<u></u>ConnectStoragePoolVDSCommand] (QuartzScheduler_Worker-93) START, ConnectStoragePoolVDSCommand(<u></u>vdsId = aeac7aa6-8840-11e1-99aa-<u></u>7fbd3e56e26e, storagePoolId = 2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84, vds_spm_id = 1, masterDomainId = 025062dd-d69e-40ac-9031-<u></u>c080b51647ae, masterVersion = 1), log id: 9632afe<br>
------------------------------<u></u>------------------------------<u></u>------<br>
<br>
Here is vdsm.log for the same time period:<br>
<br>
------------------------------<u></u>------------------------------<u></u>------<br>
Thread-309::DEBUG::2013-04-27 22:45:01,297::clientIF::261::<u></u>Storage.Dispatcher.Protect::(<u></u>wrapper) [10.0.0.154]<br>
Thread-309::DEBUG::2013-04-27 22:45:01,298::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`da5d1ac1-8b0e-4a9a-bd28-<u></u>24c30125654a`::moving from state init -> state preparing<br>
Thread-309::INFO::2013-04-27 22:45:01,299::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: validateStorageServerConnectio<u></u>n(domType=1, spUUID='00000000-0000-0000-<u></u>0000-000000000000', conList=[{'connection': '10.0.0.154:/home/vm/data/d<br>
ata', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '60e73855-daa2-45f5-9c59-<u></u>5973ca89e830', 'port': ''}], options=None)<br>
Thread-309::INFO::2013-04-27 22:45:01,300::storage_<u></u>connection::188::Storage.<u></u>ServerConnection::(validate) Request to validate NFS storage server<br>
Thread-309::DEBUG::2013-04-27 22:45:01,301::mount::111::<u></u>Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,<u></u>retrans=6 10.0.0.154:/home/vm/data/data /tmp/tmpXShfR0' (cwd None)<br>
Thread-309::DEBUG::2013-04-27 22:45:01,348::mount::111::<u></u>Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/umount /tmp/tmpXShfR0' (cwd None)<br>
Thread-309::INFO::2013-04-27 22:45:01,394::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: validateStorageServerConnectio<u></u>n, Return response: {'statuslist': [{'status': 0, 'id': '60e73855-daa2-45f5-9c59-<u></u>5973ca89e830'}]}<br>
Thread-309::DEBUG::2013-04-27 22:45:01,395::task::1174::<u></u>TaskManager.Task::(prepare) Task=`da5d1ac1-8b0e-4a9a-bd28-<u></u>24c30125654a`::finished: {'statuslist': [{'status': 0, 'id': '60e73855-daa2-45f5-9c59-<u></u>5973ca89e830'}]}<br>
Thread-309::DEBUG::2013-04-27 22:45:01,396::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`da5d1ac1-8b0e-4a9a-bd28-<u></u>24c30125654a`::moving from state preparing -> state finished<br>
Thread-309::DEBUG::2013-04-27 22:45:01,397::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-309::DEBUG::2013-04-27 22:45:01,397::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-309::DEBUG::2013-04-27 22:45:01,398::task::980::<u></u>TaskManager.Task::(_decref) Task=`da5d1ac1-8b0e-4a9a-bd28-<u></u>24c30125654a`::ref 0 aborting False<br>
Thread-310::DEBUG::2013-04-27 22:45:01,424::clientIF::261::<u></u>Storage.Dispatcher.Protect::(<u></u>wrapper) [10.0.0.154]<br>
Thread-310::DEBUG::2013-04-27 22:45:01,425::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`6e1d398a-02dc-423d-b500-<u></u>6f7f8ccb20e7`::moving from state init -> state preparing<br>
Thread-310::INFO::2013-04-27 22:45:01,425::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: connectStorageServer(domType=<u></u>1, spUUID='00000000-0000-0000-<u></u>0000-000000000000', conList=[{'connection': '10.0.0.154:/home/vm/data/<u></u>data', 'iqn'<br>
: '', 'portal': '', 'user': '', 'password': '******', 'id': '60e73855-daa2-45f5-9c59-<u></u>5973ca89e830', 'port': ''}], options=None)<br>
Thread-310::INFO::2013-04-27 22:45:01,426::storage_<u></u>connection::146::Storage.<u></u>ServerConnection::(connect) Request to connect NFS storage server<br>
Thread-310::DEBUG::2013-04-27 22:45:01,438::lvm::460::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-310::DEBUG::2013-04-27 22:45:01,438::lvm::462::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-310::DEBUG::2013-04-27 22:45:01,439::lvm::472::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-310::DEBUG::2013-04-27 22:45:01,440::lvm::474::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-310::DEBUG::2013-04-27 22:45:01,440::lvm::493::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-310::DEBUG::2013-04-27 22:45:01,441::lvm::495::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-310::INFO::2013-04-27 22:45:01,442::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '60e73855-daa2-45f5-9c59-<u></u>5973ca89e830'}]}<br>
Thread-310::DEBUG::2013-04-27 22:45:01,442::task::1174::<u></u>TaskManager.Task::(prepare) Task=`6e1d398a-02dc-423d-b500-<u></u>6f7f8ccb20e7`::finished: {'statuslist': [{'status': 0, 'id': '60e73855-daa2-45f5-9c59-<u></u>5973ca89e830'}]}<br>
Thread-310::DEBUG::2013-04-27 22:45:01,443::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`6e1d398a-02dc-423d-b500-<u></u>6f7f8ccb20e7`::moving from state preparing -> state finished<br>
Thread-310::DEBUG::2013-04-27 22:45:01,443::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-310::DEBUG::2013-04-27 22:45:01,444::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-310::DEBUG::2013-04-27 22:45:01,444::task::980::<u></u>TaskManager.Task::(_decref) Task=`6e1d398a-02dc-423d-b500-<u></u>6f7f8ccb20e7`::ref 0 aborting False<br>
Thread-314::DEBUG::2013-04-27 22:45:07,704::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`f43264f4-0160-4737-8e1a-<u></u>1322b35cfe3f`::moving from state init -> state preparing<br>
Thread-314::INFO::2013-04-27 22:45:07,705::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-314::INFO::2013-04-27 22:45:07,705::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-314::DEBUG::2013-04-27 22:45:07,706::task::1174::<u></u>TaskManager.Task::(prepare) Task=`f43264f4-0160-4737-8e1a-<u></u>1322b35cfe3f`::finished: {}<br>
Thread-314::DEBUG::2013-04-27 22:45:07,706::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`f43264f4-0160-4737-8e1a-<u></u>1322b35cfe3f`::moving from state preparing -> state finished<br>
Thread-314::DEBUG::2013-04-27 22:45:07,707::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-314::DEBUG::2013-04-27 22:45:07,708::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-314::DEBUG::2013-04-27 22:45:07,708::task::980::<u></u>TaskManager.Task::(_decref) Task=`f43264f4-0160-4737-8e1a-<u></u>1322b35cfe3f`::ref 0 aborting False<br>
Thread-320::DEBUG::2013-04-27 22:45:17,899::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`b3c57791-d573-4dc5-99ef-<u></u>9f17578a54d2`::moving from state init -> state preparing<br>
Thread-320::INFO::2013-04-27 22:45:17,900::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-320::INFO::2013-04-27 22:45:17,901::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-320::DEBUG::2013-04-27 22:45:17,901::task::1174::<u></u>TaskManager.Task::(prepare) Task=`b3c57791-d573-4dc5-99ef-<u></u>9f17578a54d2`::finished: {}<br>
Thread-320::DEBUG::2013-04-27 22:45:17,902::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`b3c57791-d573-4dc5-99ef-<u></u>9f17578a54d2`::moving from state preparing -> state finished<br>
Thread-320::DEBUG::2013-04-27 22:45:17,902::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-320::DEBUG::2013-04-27 22:45:17,903::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-320::DEBUG::2013-04-27 22:45:17,904::task::980::<u></u>TaskManager.Task::(_decref) Task=`b3c57791-d573-4dc5-99ef-<u></u>9f17578a54d2`::ref 0 aborting False<br>
Thread-326::DEBUG::2013-04-27 22:45:28,062::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`4cec58af-afca-4003-a3d0-<u></u>789ed881116f`::moving from state init -> state preparing<br>
Thread-326::INFO::2013-04-27 22:45:28,063::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-326::INFO::2013-04-27 22:45:28,063::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-326::DEBUG::2013-04-27 22:45:28,064::task::1174::<u></u>TaskManager.Task::(prepare) Task=`4cec58af-afca-4003-a3d0-<u></u>789ed881116f`::finished: {}<br>
Thread-326::DEBUG::2013-04-27 22:45:28,065::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`4cec58af-afca-4003-a3d0-<u></u>789ed881116f`::moving from state preparing -> state finished<br>
Thread-326::DEBUG::2013-04-27 22:45:28,065::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-326::DEBUG::2013-04-27 22:45:28,066::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-326::DEBUG::2013-04-27 22:45:28,066::task::980::<u></u>TaskManager.Task::(_decref) Task=`4cec58af-afca-4003-a3d0-<u></u>789ed881116f`::ref 0 aborting False<br>
Thread-286::ERROR::2013-04-27 22:45:30,046::sdc::113::<u></u>Storage.StorageDomainCache::(_<u></u>findDomain) Error while looking for domain `025062dd-d69e-40ac-9031-<u></u>c080b51647ae`<br>
Traceback (most recent call last):<br>
File "/usr/share/vdsm/storage/sdc.<u></u>py", line 109, in _findDomain<br>
return mod.findDomain(sdUUID)<br>
File "/usr/share/vdsm/storage/<u></u>nfsSD.py", line 149, in findDomain<br>
return NfsStorageDomain(<u></u>NfsStorageDomain.<u></u>findDomainPath(sdUUID))<br>
File "/usr/share/vdsm/storage/<u></u>fileSD.py", line 104, in __init__<br>
sdUUID = metadata[sd.DMDK_SDUUID]<br>
File "/usr/share/vdsm/storage/<u></u>persistentDict.py", line 75, in __getitem__<br>
return dec(self._dict[key])<br>
File "/usr/share/vdsm/storage/<u></u>persistentDict.py", line 183, in __getitem__<br>
with self._accessWrapper():<br>
File "/usr/lib64/python2.7/<u></u>contextlib.py", line 17, in __enter__<br>
return self.gen.next()<br>
File "/usr/share/vdsm/storage/<u></u>persistentDict.py", line 137, in _accessWrapper<br>
self.refresh()<br>
File "/usr/share/vdsm/storage/<u></u>persistentDict.py", line 214, in refresh<br>
lines = self._metaRW.readlines()<br>
File "/usr/share/vdsm/storage/<u></u>fileSD.py", line 71, in readlines<br>
return misc.stripNewLines(self._oop.<u></u>directReadLines(self._<u></u>metafile))<br>
File "/usr/share/vdsm/storage/<u></u>processPool.py", line 53, in wrapper<br>
return self.runExternally(func, *args, **kwds)<br>
File "/usr/share/vdsm/storage/<u></u>processPool.py", line 64, in runExternally<br>
return self._procPool.runExternally(*<u></u>args, **kwargs)<br>
File "/usr/share/vdsm/storage/<u></u>processPool.py", line 145, in runExternally<br>
raise Timeout("Operation Stuck")<br>
Timeout: Operation Stuck<br>
Thread-286::DEBUG::2013-04-27 22:45:30,048::resourceManager:<u></u>:535::ResourceManager::(<u></u>releaseResource) Trying to release resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84'<br>
Thread-286::DEBUG::2013-04-27 22:45:30,049::resourceManager:<u></u>:550::ResourceManager::(<u></u>releaseResource) Released resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84' (0 active users)<br>
Thread-286::DEBUG::2013-04-27 22:45:30,049::resourceManager:<u></u>:555::ResourceManager::(<u></u>releaseResource) Resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84' is free, finding out if anyone is waiting for it.<br>
Thread-286::DEBUG::2013-04-27 22:45:30,050::resourceManager:<u></u>:562::ResourceManager::(<u></u>releaseResource) No one is waiting for resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84', Clearing records.<br>
Thread-286::ERROR::2013-04-27 22:45:30,051::task::855::<u></u>TaskManager.Task::(_setError) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::Unexpected error<br>
Traceback (most recent call last):<br>
File "/usr/share/vdsm/storage/task.<u></u>py", line 863, in _run<br>
return fn(*args, **kargs)<br>
File "/usr/share/vdsm/logUtils.py", line 38, in wrapper<br>
res = f(*args, **kwargs)<br>
File "/usr/share/vdsm/storage/hsm.<u></u>py", line 721, in connectStoragePool<br>
return self._connectStoragePool(<u></u>spUUID, hostID, scsiKey, msdUUID, masterVersion, options)<br>
File "/usr/share/vdsm/storage/hsm.<u></u>py", line 763, in _connectStoragePool<br>
res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)<br>
File "/usr/share/vdsm/storage/sp.<u></u>py", line 624, in connect<br>
self.__rebuild(msdUUID=<u></u>msdUUID, masterVersion=masterVersion)<br>
File "/usr/share/vdsm/storage/sp.<u></u>py", line 1097, in __rebuild<br>
self.masterDomain = self.getMasterDomain(msdUUID=<u></u>msdUUID, masterVersion=masterVersion)<br>
File "/usr/share/vdsm/storage/sp.<u></u>py", line 1435, in getMasterDomain<br>
raise se.StoragePoolMasterNotFound(<u></u>self.spUUID, msdUUID)<br>
StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
Thread-286::DEBUG::2013-04-27 22:45:30,052::task::874::<u></u>TaskManager.Task::(_run) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::Task._run: a7d4f658-136b-46f5-9458-<u></u>f86f059498b1 ('2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84', 1, '2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84', '025062dd-d69e-40ac-9031-<u></u>c080b51647ae', 1) {} failed - stopping task<br>
Thread-286::DEBUG::2013-04-27 22:45:30,052::task::1201::<u></u>TaskManager.Task::(stop) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::stopping in state preparing (force False)<br>
Thread-286::DEBUG::2013-04-27 22:45:30,053::task::980::<u></u>TaskManager.Task::(_decref) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::ref 1 aborting True<br>
Thread-286::INFO::2013-04-27 22:45:30,053::task::1159::<u></u>TaskManager.Task::(prepare) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::aborting: Task is aborted: 'Cannot find master domain' - code 304<br>
Thread-286::DEBUG::2013-04-27 22:45:30,054::task::1164::<u></u>TaskManager.Task::(prepare) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::Prepare: aborted: Cannot find master domain<br>
Thread-286::DEBUG::2013-04-27 22:45:30,054::task::980::<u></u>TaskManager.Task::(_decref) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::ref 0 aborting True<br>
Thread-286::DEBUG::2013-04-27 22:45:30,055::task::915::<u></u>TaskManager.Task::(_doAbort) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::Task._doAbort: force False<br>
Thread-286::DEBUG::2013-04-27 22:45:30,055::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-286::DEBUG::2013-04-27 22:45:30,056::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::moving from state preparing -> state aborting<br>
Thread-286::DEBUG::2013-04-27 22:45:30,056::task::537::<u></u>TaskManager.Task::(__state_<u></u>aborting) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::_aborting: recover policy none<br>
Thread-286::DEBUG::2013-04-27 22:45:30,057::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`a7d4f658-136b-46f5-9458-<u></u>f86f059498b1`::moving from state aborting -> state failed<br>
Thread-286::DEBUG::2013-04-27 22:45:30,057::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-286::DEBUG::2013-04-27 22:45:30,058::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-286::ERROR::2013-04-27 22:45:30,059::dispatcher::90::<u></u>Storage.Dispatcher.Protect::(<u></u>run) {'status': {'message': "Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'", 'code': 304}}<br>
Thread-329::DEBUG::2013-04-27 22:45:30,107::clientIF::261::<u></u>Storage.Dispatcher.Protect::(<u></u>wrapper) [10.0.0.154]<br>
Thread-329::DEBUG::2013-04-27 22:45:30,108::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::moving from state init -> state preparing<br>
Thread-329::INFO::2013-04-27 22:45:30,109::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='2b633f9a-<u></u>8840-11e1-9ed7-17e6c491db84', options=None)<br>
Thread-329::ERROR::2013-04-27 22:45:30,110::task::855::<u></u>TaskManager.Task::(_setError) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::Unexpected error<br>
Traceback (most recent call last):<br>
File "/usr/share/vdsm/storage/task.<u></u>py", line 863, in _run<br>
return fn(*args, **kargs)<br>
File "/usr/share/vdsm/logUtils.py", line 38, in wrapper<br>
res = f(*args, **kwargs)<br>
File "/usr/share/vdsm/storage/hsm.<u></u>py", line 438, in getSpmStatus<br>
pool = self.getPool(spUUID)<br>
File "/usr/share/vdsm/storage/hsm.<u></u>py", line 186, in getPool<br>
raise se.StoragePoolUnknown(spUUID)<br>
StoragePoolUnknown: Unknown pool id, pool not connected: ('2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84',)<br>
Thread-329::DEBUG::2013-04-27 22:45:30,110::task::874::<u></u>TaskManager.Task::(_run) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::Task._run: 162609d1-b21e-49ac-b4e6-<u></u>061283cfa375 ('2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84',) {} failed - stopping task<br>
Thread-329::DEBUG::2013-04-27 22:45:30,111::task::1201::<u></u>TaskManager.Task::(stop) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::stopping in state preparing (force False)<br>
Thread-329::DEBUG::2013-04-27 22:45:30,111::task::980::<u></u>TaskManager.Task::(_decref) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::ref 1 aborting True<br>
Thread-329::INFO::2013-04-27 22:45:30,112::task::1159::<u></u>TaskManager.Task::(prepare) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309<br>
Thread-329::DEBUG::2013-04-27 22:45:30,112::task::1164::<u></u>TaskManager.Task::(prepare) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::Prepare: aborted: Unknown pool id, pool not connected<br>
Thread-329::DEBUG::2013-04-27 22:45:30,113::task::980::<u></u>TaskManager.Task::(_decref) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::ref 0 aborting True<br>
Thread-329::DEBUG::2013-04-27 22:45:30,114::task::915::<u></u>TaskManager.Task::(_doAbort) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::Task._doAbort: force False<br>
Thread-329::DEBUG::2013-04-27 22:45:30,114::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-329::DEBUG::2013-04-27 22:45:30,115::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::moving from state preparing -> state aborting<br>
Thread-329::DEBUG::2013-04-27 22:45:30,115::task::537::<u></u>TaskManager.Task::(__state_<u></u>aborting) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::_aborting: recover policy none<br>
Thread-329::DEBUG::2013-04-27 22:45:30,116::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`162609d1-b21e-49ac-b4e6-<u></u>061283cfa375`::moving from state aborting -> state failed<br>
Thread-329::DEBUG::2013-04-27 22:45:30,116::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-329::DEBUG::2013-04-27 22:45:30,117::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-329::ERROR::2013-04-27 22:45:30,117::dispatcher::90::<u></u>Storage.Dispatcher.Protect::(<u></u>run) {'status': {'message': "Unknown pool id, pool not connected: ('2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84',)", 'code': 309}}<br>
Thread-331::DEBUG::2013-04-27 22:45:30,159::clientIF::261::<u></u>Storage.Dispatcher.Protect::(<u></u>wrapper) [10.0.0.154]<br>
Thread-331::DEBUG::2013-04-27 22:45:30,160::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::moving from state init -> state preparing<br>
Thread-331::INFO::2013-04-27 22:45:30,161::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='<u></u>2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84', hostID=1, scsiKey='2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84', msdUUID='025062dd-d69e-40ac-<u></u>9031-c080b51647ae', masterVersion=1, options=None)<br>
Thread-331::DEBUG::2013-04-27 22:45:30,162::resourceManager:<u></u>:175::ResourceManager.Request:<u></u>:(__init__) ResName=`Storage.2b633f9a-<u></u>8840-11e1-9ed7-17e6c491db84`<u></u>ReqID=`f6f7913c-4cb2-4811-<u></u>baa8-431b4e4eac91`::Request was made in '/usr/share/vdsm/storage/hsm.<u></u>py' line '747' at '_connectStoragePool'<br>
Thread-331::DEBUG::2013-04-27 22:45:30,162::resourceManager:<u></u>:483::ResourceManager::(<u></u>registerResource) Trying to register resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84' for lock type 'exclusive'<br>
Thread-331::DEBUG::2013-04-27 22:45:30,163::resourceManager:<u></u>:525::ResourceManager::(<u></u>registerResource) Resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84' is free. Now locking as 'exclusive' (1 active user)<br>
Thread-331::DEBUG::2013-04-27 22:45:30,164::resourceManager:<u></u>:212::ResourceManager.Request:<u></u>:(grant) ResName=`Storage.2b633f9a-<u></u>8840-11e1-9ed7-17e6c491db84`<u></u>ReqID=`f6f7913c-4cb2-4811-<u></u>baa8-431b4e4eac91`::Granted request<br>
Thread-331::INFO::2013-04-27 22:45:30,165::sp::608::<u></u>Storage.StoragePool::(connect) Connect host #1 to the storage pool 2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84 with master domain: 025062dd-d69e-40ac-9031-<u></u>c080b51647ae (ver = 1)<br>
Thread-331::DEBUG::2013-04-27 22:45:30,166::lvm::460::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:30,166::lvm::462::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:30,167::lvm::472::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:30,167::lvm::474::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:30,168::lvm::493::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:30,169::lvm::495::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:30,169::misc::1017::<u></u>SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)<br>
Thread-331::DEBUG::2013-04-27 22:45:30,170::misc::1019::<u></u>SamplingMethod::(__call__) Got in to sampling method<br>
Thread-331::DEBUG::2013-04-27 22:45:30,170::misc::1017::<u></u>SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)<br>
Thread-331::DEBUG::2013-04-27 22:45:30,171::misc::1019::<u></u>SamplingMethod::(__call__) Got in to sampling method<br>
Thread-331::DEBUG::2013-04-27 22:45:30,172::iscsi::389::<u></u>Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)<br>
Thread-331::DEBUG::2013-04-27 22:45:30,194::iscsi::389::<u></u>Storage.Misc.excCmd::(rescan) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21<br>
Thread-331::DEBUG::2013-04-27 22:45:30,195::misc::1027::<u></u>SamplingMethod::(__call__) Returning last result<br>
Thread-331::DEBUG::2013-04-27 22:45:31,778::multipath::71::<u></u>Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)<br>
Thread-331::DEBUG::2013-04-27 22:45:31,807::multipath::71::<u></u>Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0<br>
Thread-331::DEBUG::2013-04-27 22:45:31,808::lvm::460::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:31,808::lvm::462::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:31,809::lvm::472::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:31,810::lvm::474::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:31,810::lvm::493::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:31,811::lvm::495::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:31,811::misc::1027::<u></u>SamplingMethod::(__call__) Returning last result<br>
Thread-331::DEBUG::2013-04-27 22:45:31,812::lvm::352::<u></u>OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:31,815::lvm::287::<u></u>Storage.Misc.excCmd::(cmd) '/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%<u></u>36782bcb063f75600162a25c119f14<u></u>819%\\", \\"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,<u></u>extent_size,extent_count,free_<u></u>count,tags,vg_mda_size,vg_mda_<u></u>free 025062dd-d69e-40ac-9031-<u></u>c080b51647ae' (cwd None)<br>
Thread-331::DEBUG::2013-04-27 22:45:31,934::lvm::287::<u></u>Storage.Misc.excCmd::(cmd) FAILED: <err> = ' Volume group "025062dd-d69e-40ac-9031-<u></u>c080b51647ae" not found\n'; <rc> = 5<br>
Thread-331::WARNING::2013-04-<u></u>27 22:45:31,937::lvm::356::<u></u>Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "025062dd-d69e-40ac-9031-<u></u>c080b51647ae" not found']<br>
Thread-331::DEBUG::2013-04-27 22:45:31,938::lvm::379::<u></u>OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex<br>
Thread-331::DEBUG::2013-04-27 22:45:31,958::fileSD::98::<u></u>Storage.StorageDomain::(__<u></u>init__) Reading domain in path /rhev/data-center/mnt/<a href="http://10.0.0." target="_blank">10.0.0.</a><u></u>154:_home_vm_data_data/<u></u>025062dd-d69e-40ac-9031-<u></u>c080b51647ae<br>
Thread-331::DEBUG::2013-04-27 22:45:31,960::persistentDict::<u></u>175::Storage.PersistentDict::(<u></u>__init__) Created a persistant dict with FileMetadataRW backend<br>
Thread-336::DEBUG::2013-04-27 22:45:38,237::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`1a7e26c3-d715-4cac-bce5-<u></u>d0ddd21ab373`::moving from state init -> state preparing<br>
Thread-336::INFO::2013-04-27 22:45:38,238::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-336::INFO::2013-04-27 22:45:38,238::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-336::DEBUG::2013-04-27 22:45:38,239::task::1174::<u></u>TaskManager.Task::(prepare) Task=`1a7e26c3-d715-4cac-bce5-<u></u>d0ddd21ab373`::finished: {}<br>
Thread-336::DEBUG::2013-04-27 22:45:38,240::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`1a7e26c3-d715-4cac-bce5-<u></u>d0ddd21ab373`::moving from state preparing -> state finished<br>
Thread-336::DEBUG::2013-04-27 22:45:38,240::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-336::DEBUG::2013-04-27 22:45:38,241::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-336::DEBUG::2013-04-27 22:45:38,241::task::980::<u></u>TaskManager.Task::(_decref) Task=`1a7e26c3-d715-4cac-bce5-<u></u>d0ddd21ab373`::ref 0 aborting False<br>
Thread-342::DEBUG::2013-04-27 22:45:48,395::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`cf4c41c0-e453-4493-9a68-<u></u>b4044d0f0124`::moving from state init -> state preparing<br>
Thread-342::INFO::2013-04-27 22:45:48,396::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-342::INFO::2013-04-27 22:45:48,396::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-342::DEBUG::2013-04-27 22:45:48,397::task::1174::<u></u>TaskManager.Task::(prepare) Task=`cf4c41c0-e453-4493-9a68-<u></u>b4044d0f0124`::finished: {}<br>
Thread-342::DEBUG::2013-04-27 22:45:48,397::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`cf4c41c0-e453-4493-9a68-<u></u>b4044d0f0124`::moving from state preparing -> state finished<br>
Thread-342::DEBUG::2013-04-27 22:45:48,398::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-342::DEBUG::2013-04-27 22:45:48,399::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-342::DEBUG::2013-04-27 22:45:48,399::task::980::<u></u>TaskManager.Task::(_decref) Task=`cf4c41c0-e453-4493-9a68-<u></u>b4044d0f0124`::ref 0 aborting False<br>
Thread-348::DEBUG::2013-04-27 22:45:58,557::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`b536de2b-6e78-43a9-b2b1-<u></u>3667b51828df`::moving from state init -> state preparing<br>
Thread-348::INFO::2013-04-27 22:45:58,558::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-348::INFO::2013-04-27 22:45:58,558::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-348::DEBUG::2013-04-27 22:45:58,559::task::1174::<u></u>TaskManager.Task::(prepare) Task=`b536de2b-6e78-43a9-b2b1-<u></u>3667b51828df`::finished: {}<br>
Thread-348::DEBUG::2013-04-27 22:45:58,560::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`b536de2b-6e78-43a9-b2b1-<u></u>3667b51828df`::moving from state preparing -> state finished<br>
Thread-348::DEBUG::2013-04-27 22:45:58,560::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-348::DEBUG::2013-04-27 22:45:58,561::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-348::DEBUG::2013-04-27 22:45:58,561::task::980::<u></u>TaskManager.Task::(_decref) Task=`b536de2b-6e78-43a9-b2b1-<u></u>3667b51828df`::ref 0 aborting False<br>
Thread-354::DEBUG::2013-04-27 22:46:08,718::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`a8e24fe3-5490-480c-a497-<u></u>ee3f291698b0`::moving from state init -> state preparing<br>
Thread-354::INFO::2013-04-27 22:46:08,719::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-354::INFO::2013-04-27 22:46:08,720::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-354::DEBUG::2013-04-27 22:46:08,720::task::1174::<u></u>TaskManager.Task::(prepare) Task=`a8e24fe3-5490-480c-a497-<u></u>ee3f291698b0`::finished: {}<br>
Thread-354::DEBUG::2013-04-27 22:46:08,721::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`a8e24fe3-5490-480c-a497-<u></u>ee3f291698b0`::moving from state preparing -> state finished<br>
Thread-354::DEBUG::2013-04-27 22:46:08,721::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-354::DEBUG::2013-04-27 22:46:08,722::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-354::DEBUG::2013-04-27 22:46:08,722::task::980::<u></u>TaskManager.Task::(_decref) Task=`a8e24fe3-5490-480c-a497-<u></u>ee3f291698b0`::ref 0 aborting False<br>
Thread-360::DEBUG::2013-04-27 22:46:18,879::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`9febbab9-7bae-4df5-9d16-<u></u>5e89397ae101`::moving from state init -> state preparing<br>
Thread-360::INFO::2013-04-27 22:46:18,880::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-360::INFO::2013-04-27 22:46:18,880::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-360::DEBUG::2013-04-27 22:46:18,881::task::1174::<u></u>TaskManager.Task::(prepare) Task=`9febbab9-7bae-4df5-9d16-<u></u>5e89397ae101`::finished: {}<br>
Thread-360::DEBUG::2013-04-27 22:46:18,882::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`9febbab9-7bae-4df5-9d16-<u></u>5e89397ae101`::moving from state preparing -> state finished<br>
Thread-360::DEBUG::2013-04-27 22:46:18,882::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-360::DEBUG::2013-04-27 22:46:18,883::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-360::DEBUG::2013-04-27 22:46:18,883::task::980::<u></u>TaskManager.Task::(_decref) Task=`9febbab9-7bae-4df5-9d16-<u></u>5e89397ae101`::ref 0 aborting False<br>
Thread-366::DEBUG::2013-04-27 22:46:29,039::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`f0468880-10a0-429b-8fce-<u></u>547289a14fd1`::moving from state init -> state preparing<br>
Thread-366::INFO::2013-04-27 22:46:29,040::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: repoStats(options=None)<br>
Thread-366::INFO::2013-04-27 22:46:29,041::logUtils::39::<u></u>dispatcher::(wrapper) Run and protect: repoStats, Return response: {}<br>
Thread-366::DEBUG::2013-04-27 22:46:29,041::task::1174::<u></u>TaskManager.Task::(prepare) Task=`f0468880-10a0-429b-8fce-<u></u>547289a14fd1`::finished: {}<br>
Thread-366::DEBUG::2013-04-27 22:46:29,042::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`f0468880-10a0-429b-8fce-<u></u>547289a14fd1`::moving from state preparing -> state finished<br>
Thread-366::DEBUG::2013-04-27 22:46:29,042::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-366::DEBUG::2013-04-27 22:46:29,043::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-366::DEBUG::2013-04-27 22:46:29,043::task::980::<u></u>TaskManager.Task::(_decref) Task=`f0468880-10a0-429b-8fce-<u></u>547289a14fd1`::ref 0 aborting False<br>
Thread-331::ERROR::2013-04-27 22:46:34,024::sdc::113::<u></u>Storage.StorageDomainCache::(_<u></u>findDomain) Error while looking for domain `025062dd-d69e-40ac-9031-<u></u>c080b51647ae`<br>
Traceback (most recent call last):<br>
File "/usr/share/vdsm/storage/sdc.<u></u>py", line 109, in _findDomain<br>
return mod.findDomain(sdUUID)<br>
File "/usr/share/vdsm/storage/<u></u>nfsSD.py", line 149, in findDomain<br>
return NfsStorageDomain(<u></u>NfsStorageDomain.<u></u>findDomainPath(sdUUID))<br>
File "/usr/share/vdsm/storage/<u></u>fileSD.py", line 104, in __init__<br>
sdUUID = metadata[sd.DMDK_SDUUID]<br>
File "/usr/share/vdsm/storage/<u></u>persistentDict.py", line 75, in __getitem__<br>
return dec(self._dict[key])<br>
File "/usr/share/vdsm/storage/<u></u>persistentDict.py", line 183, in __getitem__<br>
with self._accessWrapper():<br>
File "/usr/lib64/python2.7/<u></u>contextlib.py", line 17, in __enter__<br>
return self.gen.next()<br>
File "/usr/share/vdsm/storage/<u></u>persistentDict.py", line 137, in _accessWrapper<br>
self.refresh()<br>
File "/usr/share/vdsm/storage/<u></u>persistentDict.py", line 214, in refresh<br>
lines = self._metaRW.readlines()<br>
File "/usr/share/vdsm/storage/<u></u>fileSD.py", line 71, in readlines<br>
return misc.stripNewLines(self._oop.<u></u>directReadLines(self._<u></u>metafile))<br>
File "/usr/share/vdsm/storage/<u></u>processPool.py", line 53, in wrapper<br>
return self.runExternally(func, *args, **kwds)<br>
File "/usr/share/vdsm/storage/<u></u>processPool.py", line 64, in runExternally<br>
return self._procPool.runExternally(*<u></u>args, **kwargs)<br>
File "/usr/share/vdsm/storage/<u></u>processPool.py", line 145, in runExternally<br>
raise Timeout("Operation Stuck")<br>
Timeout: Operation Stuck<br>
Thread-331::DEBUG::2013-04-27 22:46:34,026::resourceManager:<u></u>:535::ResourceManager::(<u></u>releaseResource) Trying to release resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84'<br>
Thread-331::DEBUG::2013-04-27 22:46:34,027::resourceManager:<u></u>:550::ResourceManager::(<u></u>releaseResource) Released resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84' (0 active users)<br>
Thread-331::DEBUG::2013-04-27 22:46:34,028::resourceManager:<u></u>:555::ResourceManager::(<u></u>releaseResource) Resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84' is free, finding out if anyone is waiting for it.<br>
Thread-331::DEBUG::2013-04-27 22:46:34,028::resourceManager:<u></u>:562::ResourceManager::(<u></u>releaseResource) No one is waiting for resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84', Clearing records.<br>
Thread-331::ERROR::2013-04-27 22:46:34,029::task::855::<u></u>TaskManager.Task::(_setError) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::Unexpected error<br>
Traceback (most recent call last):<br>
File "/usr/share/vdsm/storage/task.<u></u>py", line 863, in _run<br>
return fn(*args, **kargs)<br>
File "/usr/share/vdsm/logUtils.py", line 38, in wrapper<br>
res = f(*args, **kwargs)<br>
File "/usr/share/vdsm/storage/hsm.<u></u>py", line 721, in connectStoragePool<br>
return self._connectStoragePool(<u></u>spUUID, hostID, scsiKey, msdUUID, masterVersion, options)<br>
File "/usr/share/vdsm/storage/hsm.<u></u>py", line 763, in _connectStoragePool<br>
res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)<br>
File "/usr/share/vdsm/storage/sp.<u></u>py", line 624, in connect<br>
self.__rebuild(msdUUID=<u></u>msdUUID, masterVersion=masterVersion)<br>
File "/usr/share/vdsm/storage/sp.<u></u>py", line 1097, in __rebuild<br>
self.masterDomain = self.getMasterDomain(msdUUID=<u></u>msdUUID, masterVersion=masterVersion)<br>
File "/usr/share/vdsm/storage/sp.<u></u>py", line 1435, in getMasterDomain<br>
raise se.StoragePoolMasterNotFound(<u></u>self.spUUID, msdUUID)<br>
StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'<br>
Thread-331::DEBUG::2013-04-27 22:46:34,030::task::874::<u></u>TaskManager.Task::(_run) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::Task._run: 4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0 ('2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84', 1, '2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84', '025062dd-d69e-40ac-9031-<u></u>c080b51647ae', 1) {} failed - stopping task<br>
Thread-331::DEBUG::2013-04-27 22:46:34,030::task::1201::<u></u>TaskManager.Task::(stop) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::stopping in state preparing (force False)<br>
Thread-331::DEBUG::2013-04-27 22:46:34,031::task::980::<u></u>TaskManager.Task::(_decref) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::ref 1 aborting True<br>
Thread-331::INFO::2013-04-27 22:46:34,032::task::1159::<u></u>TaskManager.Task::(prepare) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::aborting: Task is aborted: 'Cannot find master domain' - code 304<br>
Thread-331::DEBUG::2013-04-27 22:46:34,032::task::1164::<u></u>TaskManager.Task::(prepare) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::Prepare: aborted: Cannot find master domain<br>
Thread-331::DEBUG::2013-04-27 22:46:34,033::task::980::<u></u>TaskManager.Task::(_decref) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::ref 0 aborting True<br>
Thread-331::DEBUG::2013-04-27 22:46:34,033::task::915::<u></u>TaskManager.Task::(_doAbort) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::Task._doAbort: force False<br>
Thread-331::DEBUG::2013-04-27 22:46:34,034::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-331::DEBUG::2013-04-27 22:46:34,034::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::moving from state preparing -> state aborting<br>
Thread-331::DEBUG::2013-04-27 22:46:34,035::task::537::<u></u>TaskManager.Task::(__state_<u></u>aborting) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::_aborting: recover policy none<br>
Thread-331::DEBUG::2013-04-27 22:46:34,035::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`4a7f87fa-cbbc-41de-a457-<u></u>bfe6a87e00a0`::moving from state aborting -> state failed<br>
Thread-331::DEBUG::2013-04-27 22:46:34,036::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-331::DEBUG::2013-04-27 22:46:34,036::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-331::ERROR::2013-04-27 22:46:34,037::dispatcher::90::<u></u>Storage.Dispatcher.Protect::(<u></u>run) {'status': {'message': "Cannot find master domain: 'spUUID=2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84, msdUUID=025062dd-d69e-40ac-<u></u>9031-c080b51647ae'", 'code': 304}}<br>
Thread-371::DEBUG::2013-04-27 22:46:34,082::clientIF::261::<u></u>Storage.Dispatcher.Protect::(<u></u>wrapper) [10.0.0.154]<br>
Thread-371::DEBUG::2013-04-27 22:46:34,083::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::moving from state init -> state preparing<br>
Thread-371::INFO::2013-04-27 22:46:34,084::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='2b633f9a-<u></u>8840-11e1-9ed7-17e6c491db84', options=None)<br>
Thread-371::ERROR::2013-04-27 22:46:34,084::task::855::<u></u>TaskManager.Task::(_setError) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::Unexpected error<br>
Traceback (most recent call last):<br>
File "/usr/share/vdsm/storage/task.<u></u>py", line 863, in _run<br>
return fn(*args, **kargs)<br>
File "/usr/share/vdsm/logUtils.py", line 38, in wrapper<br>
res = f(*args, **kwargs)<br>
File "/usr/share/vdsm/storage/hsm.<u></u>py", line 438, in getSpmStatus<br>
pool = self.getPool(spUUID)<br>
File "/usr/share/vdsm/storage/hsm.<u></u>py", line 186, in getPool<br>
raise se.StoragePoolUnknown(spUUID)<br>
StoragePoolUnknown: Unknown pool id, pool not connected: ('2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84',)<br>
Thread-371::DEBUG::2013-04-27 22:46:34,085::task::874::<u></u>TaskManager.Task::(_run) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::Task._run: e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b ('2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84',) {} failed - stopping task<br>
Thread-371::DEBUG::2013-04-27 22:46:34,086::task::1201::<u></u>TaskManager.Task::(stop) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::stopping in state preparing (force False)<br>
Thread-371::DEBUG::2013-04-27 22:46:34,086::task::980::<u></u>TaskManager.Task::(_decref) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::ref 1 aborting True<br>
Thread-371::INFO::2013-04-27 22:46:34,087::task::1159::<u></u>TaskManager.Task::(prepare) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309<br>
Thread-371::DEBUG::2013-04-27 22:46:34,087::task::1164::<u></u>TaskManager.Task::(prepare) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::Prepare: aborted: Unknown pool id, pool not connected<br>
Thread-371::DEBUG::2013-04-27 22:46:34,088::task::980::<u></u>TaskManager.Task::(_decref) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::ref 0 aborting True<br>
Thread-371::DEBUG::2013-04-27 22:46:34,088::task::915::<u></u>TaskManager.Task::(_doAbort) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::Task._doAbort: force False<br>
Thread-371::DEBUG::2013-04-27 22:46:34,089::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-371::DEBUG::2013-04-27 22:46:34,089::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::moving from state preparing -> state aborting<br>
Thread-371::DEBUG::2013-04-27 22:46:34,090::task::537::<u></u>TaskManager.Task::(__state_<u></u>aborting) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::_aborting: recover policy none<br>
Thread-371::DEBUG::2013-04-27 22:46:34,090::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`e8ba0700-30eb-4467-b1d0-<u></u>fbbd7636441b`::moving from state aborting -> state failed<br>
Thread-371::DEBUG::2013-04-27 22:46:34,091::resourceManager:<u></u>:806::ResourceManager.Owner::(<u></u>releaseAll) Owner.releaseAll requests {} resources {}<br>
Thread-371::DEBUG::2013-04-27 22:46:34,092::resourceManager:<u></u>:841::ResourceManager.Owner::(<u></u>cancelAll) Owner.cancelAll requests {}<br>
Thread-371::ERROR::2013-04-27 22:46:34,092::dispatcher::90::<u></u>Storage.Dispatcher.Protect::(<u></u>run) {'status': {'message': "Unknown pool id, pool not connected: ('2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84',)", 'code': 309}}<br>
Thread-372::DEBUG::2013-04-27 22:46:34,116::clientIF::261::<u></u>Storage.Dispatcher.Protect::(<u></u>wrapper) [10.0.0.154]<br>
Thread-372::DEBUG::2013-04-27 22:46:34,117::task::588::<u></u>TaskManager.Task::(_<u></u>updateState) Task=`4a764a93-93ca-432b-ac1d-<u></u>ca18c36f4b47`::moving from state init -> state preparing<br>
Thread-372::INFO::2013-04-27 22:46:34,118::logUtils::37::<u></u>dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='<u></u>2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84', hostID=1, scsiKey='2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84', msdUUID='025062dd-d69e-40ac-<u></u>9031-c080b51647ae', masterVersion=1, options=None)<br>
Thread-372::DEBUG::2013-04-27 22:46:34,119::resourceManager:<u></u>:175::ResourceManager.Request:<u></u>:(__init__) ResName=`Storage.2b633f9a-<u></u>8840-11e1-9ed7-17e6c491db84`<u></u>ReqID=`da6e89ed-9d5c-46d7-<u></u>831a-53f401443358`::Request was made in '/usr/share/vdsm/storage/hsm.<u></u>py' line '747' at '_connectStoragePool'<br>
Thread-372::DEBUG::2013-04-27 22:46:34,119::resourceManager:<u></u>:483::ResourceManager::(<u></u>registerResource) Trying to register resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84' for lock type 'exclusive'<br>
Thread-372::DEBUG::2013-04-27 22:46:34,120::resourceManager:<u></u>:525::ResourceManager::(<u></u>registerResource) Resource 'Storage.2b633f9a-8840-11e1-<u></u>9ed7-17e6c491db84' is free. Now locking as 'exclusive' (1 active user)<br>
Thread-372::DEBUG::2013-04-27 22:46:34,120::resourceManager:<u></u>:212::ResourceManager.Request:<u></u>:(grant) ResName=`Storage.2b633f9a-<u></u>8840-11e1-9ed7-17e6c491db84`<u></u>ReqID=`da6e89ed-9d5c-46d7-<u></u>831a-53f401443358`::Granted request<br>
Thread-372::INFO::2013-04-27 22:46:34,121::sp::608::<u></u>Storage.StoragePool::(connect) Connect host #1 to the storage pool 2b633f9a-8840-11e1-9ed7-<u></u>17e6c491db84 with master domain: 025062dd-d69e-40ac-9031-<u></u>c080b51647ae (ver = 1)<br>
Thread-372::DEBUG::2013-04-27 22:46:34,122::lvm::460::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:34,123::lvm::462::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:34,124::lvm::472::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:34,124::lvm::474::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:34,125::lvm::493::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:34,126::lvm::495::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:34,126::misc::1017::<u></u>SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)<br>
Thread-372::DEBUG::2013-04-27 22:46:34,127::misc::1019::<u></u>SamplingMethod::(__call__) Got in to sampling method<br>
Thread-372::DEBUG::2013-04-27 22:46:34,127::misc::1017::<u></u>SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)<br>
Thread-372::DEBUG::2013-04-27 22:46:34,128::misc::1019::<u></u>SamplingMethod::(__call__) Got in to sampling method<br>
Thread-372::DEBUG::2013-04-27 22:46:34,128::iscsi::389::<u></u>Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)<br>
Thread-372::DEBUG::2013-04-27 22:46:34,151::iscsi::389::<u></u>Storage.Misc.excCmd::(rescan) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21<br>
Thread-372::DEBUG::2013-04-27 22:46:34,152::misc::1027::<u></u>SamplingMethod::(__call__) Returning last result<br>
Thread-372::DEBUG::2013-04-27 22:46:35,735::multipath::71::<u></u>Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)<br>
Thread-372::DEBUG::2013-04-27 22:46:35,764::multipath::71::<u></u>Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0<br>
Thread-372::DEBUG::2013-04-27 22:46:35,765::lvm::460::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:35,766::lvm::462::<u></u>OperationMutex::(_<u></u>invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:35,766::lvm::472::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:35,767::lvm::474::<u></u>OperationMutex::(_<u></u>invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:35,768::lvm::493::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:35,768::lvm::495::<u></u>OperationMutex::(_<u></u>invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:35,769::misc::1027::<u></u>SamplingMethod::(__call__) Returning last result<br>
Thread-372::DEBUG::2013-04-27 22:46:35,770::lvm::352::<u></u>OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:35,772::lvm::287::<u></u>Storage.Misc.excCmd::(cmd) '/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%<u></u>36782bcb063f75600162a25c119f14<u></u>819%\\", \\"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,<u></u>extent_size,extent_count,free_<u></u>count,tags,vg_mda_size,vg_mda_<u></u>free 025062dd-d69e-40ac-9031-<u></u>c080b51647ae' (cwd None)<br>
Thread-372::DEBUG::2013-04-27 22:46:35,874::lvm::287::<u></u>Storage.Misc.excCmd::(cmd) FAILED: <err> = ' Volume group "025062dd-d69e-40ac-9031-<u></u>c080b51647ae" not found\n'; <rc> = 5<br>
Thread-372::WARNING::2013-04-<u></u>27 22:46:35,877::lvm::356::<u></u>Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "025062dd-d69e-40ac-9031-<u></u>c080b51647ae" not found']<br>
Thread-372::DEBUG::2013-04-27 22:46:35,878::lvm::379::<u></u>OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex<br>
Thread-372::DEBUG::2013-04-27 22:46:35,898::fileSD::98::<u></u>Storage.StorageDomain::(__<u></u>init__) Reading domain in path /rhev/data-center/mnt/<a href="http://10.0.0." target="_blank">10.0.0.</a><u></u>154:_home_vm_data_data/<u></u>025062dd-d69e-40ac-9031-<u></u>c080b51647ae<br>
------------------------------<u></u>------------------------------<u></u>------<br>
<br>
Now, one interesting aspect I've noticed is that when I reboot the server, the mounted NFS shares change. As I mentioned earlier, in this instance there were no NFS shares mounted when the machine booted and none were mounted until I tried to activate the data centre. I subsequently rebooted the server after making some changes to nfsmount.conf, and upon booting the ISO share was mounted. Intrigued, I rebooted again and both the ISO and Export shares were mounted, but not the data share.<br>
<br>
Do you - or does anybody - have any further insight?<br>
<br>
Thanks for your help so far - looking in to the NFS side of things is giving some interesting results, and I'm sure that we're on the path to great success.<br>
<br>
--Steven.<br>
______________________________<u></u>_________________<br>
Users mailing list<br>
<a href="mailto:Users@ovirt.org" target="_blank">Users@ovirt.org</a><br>
<a href="http://lists.ovirt.org/mailman/listinfo/users" target="_blank">http://lists.ovirt.org/<u></u>mailman/listinfo/users</a><br>
</blockquote></div>