Re: [Users] Error Attaching NFS Data Domain to Data Center - oVirt 3.3

Tuesday, 30 April 2013

Hi Sherry,

Since it doesn't seem like permissions, the next guess would be - 
There was a workaround done in regard to broken watchdog.
This workaround is in the latest sanlock for fedora 18, which you are already using.
If this is indeed the case, all you have to do is update sanlock to latest, which can be
found in
http://koji.fedoraproject.org/koji/buildinfo?buildID=408258 .

In case this doesn't help, or you already have the latest sanlock, we'll need more
information in order to detect the issue.
We'd need the following logs:
sanlock.log and /var/log/messages.log from both engine and vdsm, just to be on the safe
side.
Please attach the full logs.

Thanks,
Vered

----- Original Message -----
...
 From: "Sherry Yu" <syu(a)redhat.com&gt;
 To: "Allon Mureinik" <amureini(a)redhat.com&gt;
 Cc: users(a)ovirt.org
 Sent: Monday, April 29, 2013 7:23:14 PM
 Subject: Re: [Users] Error Attaching NFS Data Domain to Data Center - oVirt 3.3

 Hi Allon, vdsm has write permission to the directory on NFS. I can see that
 on the hypervisor host the NFS share is mounted and directories have been
 created by vdsm. vdsm log is attached. The error is at
 "AcquireHostIdFailure: Cannot acquire host id:
 ('a7138327-930c-49d7-9f39-c34ee36fc7fb', SanlockException(19, 'Sanlock
 lockspace add failure', 'No such device'))". Appreciate any input!

 [root@sbhost-58 vdsm]# df -k

 storage2.phx.salab.redhat.com:/data/sap/ovirt-domain 309637120 187031552
 106876928 64%
 /rhev/data-center/mnt/storage2.phx.salab.redhat.com:_data_sap_ovirt-domain

 [root@sbhost-58 dom_md]# pwd

/rhev/data-center/mnt/storage2.phx.salab.redhat.com:_data_sap_ovirt-domain/a7138327-930c-49d7-9f39-c34ee36fc7fb/dom_md

 [root@sbhost-58 dom_md]# ls -la
 total 2060
 drwxr-xr-x. 2 vdsm kvm 4096 Apr 25 20:35 .
 drwxr-xr-x. 4 vdsm kvm 4096 Apr 25 20:35 ..
 -rw-rw----. 1 vdsm kvm 1048576 Apr 25 20:35 ids
 -rw-rw----. 1 vdsm kvm 0 Apr 25 20:35 inbox
 -rw-rw----. 1 vdsm kvm 2097152 Apr 25 20:35 leases
 -rw-r--r--. 1 vdsm kvm 319 Apr 25 20:35 metadata
 -rw-rw----. 1 vdsm kvm 0 Apr 25 20:35 outbox

 vdsm.log:

 Thread-186874::DEBUG::2013-04-29
 12:16:05,229::BindingXMLRPC::161::vds::(wrapper) [10.3.76.215]
 Thread-186874::DEBUG::2013-04-29
 12:16:05,229::task::568::TaskManager.Task::(_updateState)
 Task=`6a316ab2-3d08-44d4-b3d9-60620f23fc72`::moving from state init -> state
 preparing
 Thread-186874::INFO::2013-04-29
 12:16:05,230::logUtils::41::dispatcher::(wrapper) Run and protect:
 validateStorageServerConnection(domType=1,
 spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port':
'',
 'connection': 'storage2.phx.salab.redhat.com:/data/sap/ovirt-domain',
'iqn':
 '', 'portal': '', 'user': '',
'protocol_version': 'auto', 'password':
 '******', 'id': 'c925e43f-ff52-45ae-8484-e4ac6b670143'}],
options=None)
 Thread-186874::INFO::2013-04-29
 12:16:05,230::logUtils::44::dispatcher::(wrapper) Run and protect:
 validateStorageServerConnection, Return response: {'statuslist':
[{'status':
 0, 'id': 'c925e43f-ff52-45ae-8484-e4ac6b670143'}]}
 Thread-186874::DEBUG::2013-04-29
 12:16:05,230::task::1151::TaskManager.Task::(prepare)
 Task=`6a316ab2-3d08-44d4-b3d9-60620f23fc72`::finished: {'statuslist':
 [{'status': 0, 'id': 'c925e43f-ff52-45ae-8484-e4ac6b670143'}]}
 Thread-186874::DEBUG::2013-04-29
 12:16:05,230::task::568::TaskManager.Task::(_updateState)
 Task=`6a316ab2-3d08-44d4-b3d9-60620f23fc72`::moving from state preparing ->
 state finished
 Thread-186874::DEBUG::2013-04-29
 12:16:05,231::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources {}
 Thread-186874::DEBUG::2013-04-29
 12:16:05,231::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186874::DEBUG::2013-04-29
 12:16:05,231::task::957::TaskManager.Task::(_decref)
 Task=`6a316ab2-3d08-44d4-b3d9-60620f23fc72`::ref 0 aborting False
 Thread-186875::DEBUG::2013-04-29
 12:16:05,240::BindingXMLRPC::161::vds::(wrapper) [10.3.76.215]
 Thread-186875::DEBUG::2013-04-29
 12:16:05,240::task::568::TaskManager.Task::(_updateState)
 Task=`e6da9cb6-f577-44bd-a8ba-d08d8946a027`::moving from state init -> state
 preparing
 Thread-186875::INFO::2013-04-29
 12:16:05,240::logUtils::41::dispatcher::(wrapper) Run and protect:
 connectStorageServer(domType=1,
 spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port':
'',
 'connection': 'storage2.phx.salab.redhat.com:/data/sap/ovirt-domain',
'iqn':
 '', 'portal': '', 'user': '',
'protocol_version': 'auto', 'password':
 '******', 'id': 'c925e43f-ff52-45ae-8484-e4ac6b670143'}],
options=None)
 Thread-186875::INFO::2013-04-29
 12:16:05,247::logUtils::44::dispatcher::(wrapper) Run and protect:
 connectStorageServer, Return response: {'statuslist': [{'status': 0,
'id':
 'c925e43f-ff52-45ae-8484-e4ac6b670143'}]}
 Thread-186875::DEBUG::2013-04-29
 12:16:05,248::task::1151::TaskManager.Task::(prepare)
 Task=`e6da9cb6-f577-44bd-a8ba-d08d8946a027`::finished: {'statuslist':
 [{'status': 0, 'id': 'c925e43f-ff52-45ae-8484-e4ac6b670143'}]}
 Thread-186875::DEBUG::2013-04-29
 12:16:05,248::task::568::TaskManager.Task::(_updateState)
 Task=`e6da9cb6-f577-44bd-a8ba-d08d8946a027`::moving from state preparing ->
 state finished
 Thread-186875::DEBUG::2013-04-29
 12:16:05,248::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources {}
 Thread-186875::DEBUG::2013-04-29
 12:16:05,249::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186875::DEBUG::2013-04-29
 12:16:05,249::task::957::TaskManager.Task::(_decref)
 Task=`e6da9cb6-f577-44bd-a8ba-d08d8946a027`::ref 0 aborting False
 Thread-186876::DEBUG::2013-04-29
 12:16:05,272::BindingXMLRPC::161::vds::(wrapper) [10.3.76.215]
 Thread-186876::DEBUG::2013-04-29
 12:16:05,272::task::568::TaskManager.Task::(_updateState)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::moving from state init -> state
 preparing
 Thread-186876::INFO::2013-04-29
 12:16:05,273::logUtils::41::dispatcher::(wrapper) Run and protect:
 createStoragePool(poolType=None,
 spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', poolName='Default',
 masterDom='a7138327-930c-49d7-9f39-c34ee36fc7fb',
 domList=['a7138327-930c-49d7-9f39-c34ee36fc7fb'], masterVersion=11,
 lockPolicy=None, lockRenewalIntervalSec=5, leaseTimeSec=60,
 ioOpTimeoutSec=10, leaseRetries=3, options=None)
 Thread-186876::INFO::2013-04-29
 12:16:05,273::fileSD::302::Storage.StorageDomain::(validate)
 sdUUID=a7138327-930c-49d7-9f39-c34ee36fc7fb
 Thread-186876::DEBUG::2013-04-29
 12:16:05,291::persistentDict::234::Storage.PersistentDict::(refresh) read
 lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=oVirt',
 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60',
'LOCKPOLICY=',
 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=',
 'REMOTE_PATH=storage2.phx.salab.redhat.com:/data/sap/ovirt-domain',
 'ROLE=Regular', 'SDUUID=a7138327-930c-49d7-9f39-c34ee36fc7fb',
'TYPE=NFS',
 'VERSION=3', '_SHA_CKSUM=d25ce9538d484fbc938cde09f5247bbe709b1549']
 Thread-186876::DEBUG::2013-04-29
 12:16:05,292::resourceManager::190::ResourceManager.Request::(__init__)

ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`56e7c8fa-abb0-4247-8806-138b24dd95ad`::Request
 was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at
 '__init__'
 Thread-186876::DEBUG::2013-04-29
 12:16:05,293::resourceManager::504::ResourceManager::(registerResource)
 Trying to register resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3'
 for lock type 'exclusive'
 Thread-186876::DEBUG::2013-04-29
 12:16:05,293::resourceManager::547::ResourceManager::(registerResource)
 Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free. Now locking
 as 'exclusive' (1 active user)
 Thread-186876::DEBUG::2013-04-29
 12:16:05,293::resourceManager::227::ResourceManager.Request::(grant)

ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`56e7c8fa-abb0-4247-8806-138b24dd95ad`::Granted
 request
 Thread-186876::DEBUG::2013-04-29
 12:16:05,294::task::794::TaskManager.Task::(resourceAcquired)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::_resourcesAcquired:
 Storage.5849b030-626e-47cb-ad90-3ce782d831b3 (exclusive)
 Thread-186876::DEBUG::2013-04-29
 12:16:05,294::task::957::TaskManager.Task::(_decref)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::ref 1 aborting False
 Thread-186876::DEBUG::2013-04-29
 12:16:05,294::resourceManager::190::ResourceManager.Request::(__init__)

ResName=`Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb`ReqID=`818107d5-c2a5-4384-b81b-d0393b7727de`::Request
 was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at
 '__init__'
 Thread-186876::DEBUG::2013-04-29
 12:16:05,295::resourceManager::504::ResourceManager::(registerResource)
 Trying to register resource 'Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb'
 for lock type 'exclusive'
 Thread-186876::DEBUG::2013-04-29
 12:16:05,295::resourceManager::547::ResourceManager::(registerResource)
 Resource 'Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb' is free. Now locking
 as 'exclusive' (1 active user)
 Thread-186876::DEBUG::2013-04-29
 12:16:05,295::resourceManager::227::ResourceManager.Request::(grant)

ResName=`Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb`ReqID=`818107d5-c2a5-4384-b81b-d0393b7727de`::Granted
 request
 Thread-186876::DEBUG::2013-04-29
 12:16:05,296::task::794::TaskManager.Task::(resourceAcquired)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::_resourcesAcquired:
 Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb (exclusive)
 Thread-186876::DEBUG::2013-04-29
 12:16:05,296::task::957::TaskManager.Task::(_decref)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::ref 1 aborting False
 Thread-186876::INFO::2013-04-29
 12:16:05,296::sp::542::Storage.StoragePool::(create)
 spUUID=5849b030-626e-47cb-ad90-3ce782d831b3 poolName=Default
 master_sd=a7138327-930c-49d7-9f39-c34ee36fc7fb
 domList=['a7138327-930c-49d7-9f39-c34ee36fc7fb'] masterVersion=11
 {'LEASETIMESEC': 60, 'IOOPTIMEOUTSEC': 10, 'LEASERETRIES': 3,
 'LOCKRENEWALINTERVALSEC': 5}
 Thread-186876::INFO::2013-04-29
 12:16:05,297::fileSD::302::Storage.StorageDomain::(validate)
 sdUUID=a7138327-930c-49d7-9f39-c34ee36fc7fb
 Thread-186876::DEBUG::2013-04-29
 12:16:05,311::persistentDict::234::Storage.PersistentDict::(refresh) read
 lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=oVirt',
 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60',
'LOCKPOLICY=',
 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=',
 'REMOTE_PATH=storage2.phx.salab.redhat.com:/data/sap/ovirt-domain',
 'ROLE=Regular', 'SDUUID=a7138327-930c-49d7-9f39-c34ee36fc7fb',
'TYPE=NFS',
 'VERSION=3', '_SHA_CKSUM=d25ce9538d484fbc938cde09f5247bbe709b1549']
 Thread-186876::DEBUG::2013-04-29
 12:16:05,325::persistentDict::234::Storage.PersistentDict::(refresh) read
 lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=oVirt',
 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60',
'LOCKPOLICY=',
 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=',
 'REMOTE_PATH=storage2.phx.salab.redhat.com:/data/sap/ovirt-domain',
 'ROLE=Regular', 'SDUUID=a7138327-930c-49d7-9f39-c34ee36fc7fb',
'TYPE=NFS',
 'VERSION=3', '_SHA_CKSUM=d25ce9538d484fbc938cde09f5247bbe709b1549']
 Thread-186876::WARNING::2013-04-29
 12:16:05,325::fileUtils::185::fileUtils::(createdir) Dir
 /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3 already exists
 Thread-186876::DEBUG::2013-04-29
 12:16:05,327::persistentDict::167::Storage.PersistentDict::(transaction)
 Starting transaction
 Thread-186876::DEBUG::2013-04-29
 12:16:05,327::persistentDict::175::Storage.PersistentDict::(transaction)
 Finished transaction
 Thread-186876::INFO::2013-04-29
 12:16:05,327::clusterlock::172::SANLock::(acquireHostId) Acquiring host id
 for domain a7138327-930c-49d7-9f39-c34ee36fc7fb (id: 250)
 Thread-186876::ERROR::2013-04-29
 12:16:06,329::task::833::TaskManager.Task::(_setError)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::Unexpected error
 Traceback (most recent call last):
 File "/usr/share/vdsm/storage/task.py", line 840, in _run
 return fn(*args, **kargs)
 File "/usr/share/vdsm/logUtils.py", line 42, in wrapper
 res = f(*args, **kwargs)
 File "/usr/share/vdsm/storage/hsm.py", line 895, in createStoragePool
 masterVersion, leaseParams)
 File "/usr/share/vdsm/storage/sp.py", line 567, in create
 self._acquireTemporaryClusterLock(msdUUID, leaseParams)
 File "/usr/share/vdsm/storage/sp.py", line 509, in
 _acquireTemporaryClusterLock
 msd.acquireHostId(self.id)
 File "/usr/share/vdsm/storage/sd.py", line 436, in acquireHostId
 self._clusterLock.acquireHostId(hostId, async)
 File "/usr/share/vdsm/storage/clusterlock.py", line 187, in acquireHostId
 raise se.AcquireHostIdFailure(self._sdUUID, e)
 AcquireHostIdFailure: Cannot acquire host id:
 ('a7138327-930c-49d7-9f39-c34ee36fc7fb', SanlockException(19, 'Sanlock
 lockspace add failure', 'No such device'))
 Thread-186876::DEBUG::2013-04-29
 12:16:06,330::task::852::TaskManager.Task::(_run)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::Task._run:
 c62d6d31-4888-40e2-857d-aded3936f6fe (None,
 '5849b030-626e-47cb-ad90-3ce782d831b3', 'Default',
 'a7138327-930c-49d7-9f39-c34ee36fc7fb',
 ['a7138327-930c-49d7-9f39-c34ee36fc7fb'], 11, None, 5, 60, 10, 3) {} failed
 - stopping task
 Thread-186876::DEBUG::2013-04-29
 12:16:06,330::task::1177::TaskManager.Task::(stop)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::stopping in state preparing
 (force False)
 Thread-186876::DEBUG::2013-04-29
 12:16:06,330::task::957::TaskManager.Task::(_decref)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::ref 1 aborting True
 Thread-186876::INFO::2013-04-29
 12:16:06,330::task::1134::TaskManager.Task::(prepare)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::aborting: Task is aborted:
 'Cannot acquire host id' - code 661
 Thread-186876::DEBUG::2013-04-29
 12:16:06,331::task::1139::TaskManager.Task::(prepare)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::Prepare: aborted: Cannot
 acquire host id
 Thread-186876::DEBUG::2013-04-29
 12:16:06,331::task::957::TaskManager.Task::(_decref)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::ref 0 aborting True
 Thread-186876::DEBUG::2013-04-29
 12:16:06,331::task::892::TaskManager.Task::(_doAbort)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::Task._doAbort: force False
 Thread-186876::DEBUG::2013-04-29
 12:16:06,332::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186876::DEBUG::2013-04-29
 12:16:06,332::task::568::TaskManager.Task::(_updateState)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::moving from state preparing ->
 state aborting
 Thread-186876::DEBUG::2013-04-29
 12:16:06,332::task::523::TaskManager.Task::(__state_aborting)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::_aborting: recover policy none
 Thread-186876::DEBUG::2013-04-29
 12:16:06,332::task::568::TaskManager.Task::(_updateState)
 Task=`c62d6d31-4888-40e2-857d-aded3936f6fe`::moving from state aborting ->
 state failed
 Thread-186876::DEBUG::2013-04-29
 12:16:06,333::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources
 {'Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb': < ResourceRef
 'Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb', isValid: 'True' obj:
 'None'>, 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3': <
ResourceRef
 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', isValid: 'True' obj:
 'None'>}
 Thread-186876::DEBUG::2013-04-29
 12:16:06,333::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186876::DEBUG::2013-04-29
 12:16:06,333::resourceManager::557::ResourceManager::(releaseResource)
 Trying to release resource 'Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb'
 Thread-186876::DEBUG::2013-04-29
 12:16:06,334::resourceManager::573::ResourceManager::(releaseResource)
 Released resource 'Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb' (0 active
 users)
 Thread-186876::DEBUG::2013-04-29
 12:16:06,334::resourceManager::578::ResourceManager::(releaseResource)
 Resource 'Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb' is free, finding out
 if anyone is waiting for it.
 Thread-186876::DEBUG::2013-04-29
 12:16:06,334::resourceManager::585::ResourceManager::(releaseResource) No
 one is waiting for resource 'Storage.a7138327-930c-49d7-9f39-c34ee36fc7fb',
 Clearing records.
 Thread-186876::DEBUG::2013-04-29
 12:16:06,335::resourceManager::557::ResourceManager::(releaseResource)
 Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3'
 Thread-186876::DEBUG::2013-04-29
 12:16:06,335::resourceManager::573::ResourceManager::(releaseResource)
 Released resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' (0 active
 users)
 Thread-186876::DEBUG::2013-04-29
 12:16:06,335::resourceManager::578::ResourceManager::(releaseResource)
 Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out
 if anyone is waiting for it.
 Thread-186876::DEBUG::2013-04-29
 12:16:06,335::resourceManager::585::ResourceManager::(releaseResource) No
 one is waiting for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3',
 Clearing records.
 Thread-186876::ERROR::2013-04-29
 12:16:06,336::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status':
 {'message': "Cannot acquire host id:
 ('a7138327-930c-49d7-9f39-c34ee36fc7fb', SanlockException(19, 'Sanlock
 lockspace add failure', 'No such device'))", 'code': 661}}
 Thread-186878::DEBUG::2013-04-29
 12:16:07,704::task::568::TaskManager.Task::(_updateState)
 Task=`54200799-1659-4e8a-99d2-4a82a940468a`::moving from state init -> state
 preparing
 Thread-186878::INFO::2013-04-29
 12:16:07,705::logUtils::41::dispatcher::(wrapper) Run and protect:
 repoStats(options=None)
 Thread-186878::INFO::2013-04-29
 12:16:07,705::logUtils::44::dispatcher::(wrapper) Run and protect:
 repoStats, Return response: {}
 Thread-186878::DEBUG::2013-04-29
 12:16:07,705::task::1151::TaskManager.Task::(prepare)
 Task=`54200799-1659-4e8a-99d2-4a82a940468a`::finished: {}
 Thread-186878::DEBUG::2013-04-29
 12:16:07,705::task::568::TaskManager.Task::(_updateState)
 Task=`54200799-1659-4e8a-99d2-4a82a940468a`::moving from state preparing ->
 state finished
 Thread-186878::DEBUG::2013-04-29
 12:16:07,705::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources {}
 Thread-186878::DEBUG::2013-04-29
 12:16:07,705::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186878::DEBUG::2013-04-29
 12:16:07,706::task::957::TaskManager.Task::(_decref)
 Task=`54200799-1659-4e8a-99d2-4a82a940468a`::ref 0 aborting False
 Thread-186884::DEBUG::2013-04-29
 12:16:17,875::task::568::TaskManager.Task::(_updateState)
 Task=`e4a57bc0-1b03-4048-baef-fc8862f332cd`::moving from state init -> state
 preparing
 Thread-186884::INFO::2013-04-29
 12:16:17,875::logUtils::41::dispatcher::(wrapper) Run and protect:
 repoStats(options=None)
 Thread-186884::INFO::2013-04-29
 12:16:17,875::logUtils::44::dispatcher::(wrapper) Run and protect:
 repoStats, Return response: {}
 Thread-186884::DEBUG::2013-04-29
 12:16:17,875::task::1151::TaskManager.Task::(prepare)
 Task=`e4a57bc0-1b03-4048-baef-fc8862f332cd`::finished: {}
 Thread-186884::DEBUG::2013-04-29
 12:16:17,876::task::568::TaskManager.Task::(_updateState)
 Task=`e4a57bc0-1b03-4048-baef-fc8862f332cd`::moving from state preparing ->
 state finished
 Thread-186884::DEBUG::2013-04-29
 12:16:17,876::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources {}
 Thread-186884::DEBUG::2013-04-29
 12:16:17,876::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186884::DEBUG::2013-04-29
 12:16:17,876::task::957::TaskManager.Task::(_decref)
 Task=`e4a57bc0-1b03-4048-baef-fc8862f332cd`::ref 0 aborting False
 Thread-186890::DEBUG::2013-04-29
 12:16:28,123::task::568::TaskManager.Task::(_updateState)
 Task=`9619cb33-4f18-4372-a619-b8cc6a1a82a8`::moving from state init -> state
 preparing
 Thread-186890::INFO::2013-04-29
 12:16:28,124::logUtils::41::dispatcher::(wrapper) Run and protect:
 repoStats(options=None)
 Thread-186890::INFO::2013-04-29
 12:16:28,124::logUtils::44::dispatcher::(wrapper) Run and protect:
 repoStats, Return response: {}
 Thread-186890::DEBUG::2013-04-29
 12:16:28,124::task::1151::TaskManager.Task::(prepare)
 Task=`9619cb33-4f18-4372-a619-b8cc6a1a82a8`::finished: {}
 Thread-186890::DEBUG::2013-04-29
 12:16:28,124::task::568::TaskManager.Task::(_updateState)
 Task=`9619cb33-4f18-4372-a619-b8cc6a1a82a8`::moving from state preparing ->
 state finished
 Thread-186890::DEBUG::2013-04-29
 12:16:28,125::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources {}
 Thread-186890::DEBUG::2013-04-29
 12:16:28,125::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186890::DEBUG::2013-04-29
 12:16:28,125::task::957::TaskManager.Task::(_decref)
 Task=`9619cb33-4f18-4372-a619-b8cc6a1a82a8`::ref 0 aborting False
 Thread-186896::DEBUG::2013-04-29
 12:16:38,519::task::568::TaskManager.Task::(_updateState)
 Task=`0885f499-5f08-4e30-bc5e-a8fad600c67f`::moving from state init -> state
 preparing
 Thread-186896::INFO::2013-04-29
 12:16:38,520::logUtils::41::dispatcher::(wrapper) Run and protect:
 repoStats(options=None)
 Thread-186896::INFO::2013-04-29
 12:16:38,520::logUtils::44::dispatcher::(wrapper) Run and protect:
 repoStats, Return response: {}
 Thread-186896::DEBUG::2013-04-29
 12:16:38,520::task::1151::TaskManager.Task::(prepare)
 Task=`0885f499-5f08-4e30-bc5e-a8fad600c67f`::finished: {}
 Thread-186896::DEBUG::2013-04-29
 12:16:38,520::task::568::TaskManager.Task::(_updateState)
 Task=`0885f499-5f08-4e30-bc5e-a8fad600c67f`::moving from state preparing ->
 state finished
 Thread-186896::DEBUG::2013-04-29
 12:16:38,520::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources {}
 Thread-186896::DEBUG::2013-04-29
 12:16:38,520::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186896::DEBUG::2013-04-29
 12:16:38,521::task::957::TaskManager.Task::(_decref)
 Task=`0885f499-5f08-4e30-bc5e-a8fad600c67f`::ref 0 aborting False
 Thread-186902::DEBUG::2013-04-29
 12:16:48,641::task::568::TaskManager.Task::(_updateState)
 Task=`d7ffd21b-5b75-4b6b-b2f2-2b7fb02cd7be`::moving from state init -> state
 preparing
 Thread-186902::INFO::2013-04-29
 12:16:48,642::logUtils::41::dispatcher::(wrapper) Run and protect:
 repoStats(options=None)
 Thread-186902::INFO::2013-04-29
 12:16:48,642::logUtils::44::dispatcher::(wrapper) Run and protect:
 repoStats, Return response: {}
 Thread-186902::DEBUG::2013-04-29
 12:16:48,642::task::1151::TaskManager.Task::(prepare)
 Task=`d7ffd21b-5b75-4b6b-b2f2-2b7fb02cd7be`::finished: {}
 Thread-186902::DEBUG::2013-04-29
 12:16:48,642::task::568::TaskManager.Task::(_updateState)
 Task=`d7ffd21b-5b75-4b6b-b2f2-2b7fb02cd7be`::moving from state preparing ->
 state finished
 Thread-186902::DEBUG::2013-04-29
 12:16:48,642::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources {}
 Thread-186902::DEBUG::2013-04-29
 12:16:48,642::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186902::DEBUG::2013-04-29
 12:16:48,643::task::957::TaskManager.Task::(_decref)
 Task=`d7ffd21b-5b75-4b6b-b2f2-2b7fb02cd7be`::ref 0 aborting False
 Thread-186908::DEBUG::2013-04-29
 12:16:58,840::task::568::TaskManager.Task::(_updateState)
 Task=`5bd18ef7-5152-40c6-9d86-416ab53b6c37`::moving from state init -> state
 preparing
 Thread-186908::INFO::2013-04-29
 12:16:58,841::logUtils::41::dispatcher::(wrapper) Run and protect:
 repoStats(options=None)
 Thread-186908::INFO::2013-04-29
 12:16:58,841::logUtils::44::dispatcher::(wrapper) Run and protect:
 repoStats, Return response: {}
 Thread-186908::DEBUG::2013-04-29
 12:16:58,841::task::1151::TaskManager.Task::(prepare)
 Task=`5bd18ef7-5152-40c6-9d86-416ab53b6c37`::finished: {}
 Thread-186908::DEBUG::2013-04-29
 12:16:58,841::task::568::TaskManager.Task::(_updateState)
 Task=`5bd18ef7-5152-40c6-9d86-416ab53b6c37`::moving from state preparing ->
 state finished
 Thread-186908::DEBUG::2013-04-29
 12:16:58,842::resourceManager::830::ResourceManager.Owner::(releaseAll)
 Owner.releaseAll requests {} resources {}
 Thread-186908::DEBUG::2013-04-29
 12:16:58,842::resourceManager::864::ResourceManager.Owner::(cancelAll)
 Owner.cancelAll requests {}
 Thread-186908::DEBUG::2013-04-29
 12:16:58,842::task::957::TaskManager.Task::(_decref)
 Task=`5bd18ef7-5152-40c6-9d86-416ab53b6c37`::ref 0 aborting False

 ----- Original Message -----

 | Hi Sherry,

 | Please check the that vdsm has permissions to write to the directory you're
 | trying to create.

 | Also, if you could attach the vdsm log that would be great.

 | ----- Original Message -----

 | | From: "Sherry Yu" <syu(a)redhat.com&gt;
 | 
 | | To: users(a)ovirt.org
 | 
 | | Sent: Friday, April 26, 2013 4:04:21 AM
 | 
 | | Subject: [Users] Error Attaching NFS Data Domain to Data Center - oVirt
 | | 3.3
 | 

 | | In oVirt 3.3, I created the first data domain in NFS but it failed to
 | | attach
 | | to the default data center. The hypervisor is a Fedora 18 minimum
 | | installation. Below is the configuration and logs
 | 

 | | /var/log/sanlock.log
 | 

 | | 2013-04-25 20:45:25-0400 3710 [941]: s8 lockspace
 | |
a7138327-930c-49d7-9f39-c34ee36fc7fb:250:/rhev/data-center/mnt/storage2.phx.salab.redhat.com:_data_sap_ovirt-domain/a7138327-930c-49d7-9f39-c34ee36fc7fb/dom_md/ids:0
 | 
 | | 2013-04-25 20:45:25-0400 3710 [5116]: open error -13
 | |
/rhev/data-center/mnt/storage2.phx.salab.redhat.com:_data_sap_ovirt-domain/a7138327-930c-49d7-9f39-c34ee36fc7fb/dom_md/ids
 | 
 | | 2013-04-25 20:45:25-0400 3710 [5116]: s8 open_disk
 | |
/rhev/data-center/mnt/storage2.phx.salab.redhat.com:_data_sap_ovirt-domain/a7138327-930c-49d7-9f39-c34ee36fc7fb/dom_md/ids
 | | error -13
 | 
 | | 2013-04-25 20:45:26-0400 3711 [941]: s8 add_lockspace fail result -19
 | 
 | | /var/log/ovirt-engine/engine.log
 | 

 | | 2013-04-25 17:55:00,002 INFO
 | | [org.ovirt.engine.core.bll.AutoRecoveryManager]
 | | (DefaultQuartzScheduler_Worker-2) Autorecovering 0 hosts
 | 
 | | 2013-04-25 17:55:00,008 INFO
 | | [org.ovirt.engine.core.bll.AutoRecoveryManager]
 | | (DefaultQuartzScheduler_Worker-2) Autorecovering 0 storage domains
 | 
 | | 2013-04-25 17:55:01,574 INFO
 | | [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand]
 | | (ajp--127.0.0.1-8702-2) Lock Acquired to object EngineLock
 | | [exclusiveLocks=
 | | key: 5849b030-626e-47cb-ad90-3ce782d831b3 value: POOL
 | 
 | | , sharedLocks= ]
 | 
 | | 2013-04-25 17:55:01,687 INFO
 | | [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand]
 | | (pool-3-thread-49) [1ed8155e] Running command:
 | | AddStoragePoolWithStoragesCommand internal: false. Entities affected :
 | | ID:
 | | 5849b030-626e-47cb-ad90-3ce782d831b3 Type: StoragePool
 | 
 | | 2013-04-25 17:55:01,768 INFO
 | |
[org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand]
 | | (pool-3-thread-49) [783c9d00] START,
 | | ValidateStorageServerConnectionVDSCommand(HostName = sbhost-58, HostId =
 | | d576e7aa-c2fc-4fee-9125-d8dd61d005be, storagePoolId =
 | | 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList =
 | | [{
 | | id: c925e43f-ff52-45ae-8484-e4ac6b670143, connection:
 | | storage2.phx.salab.redhat.com:/data/sap/ovirt-domain, iqn: null, vfsType:
 | | null, mountOptions: null, nfsVersion: AUTO, nfsRetrans: null, nfsTimeo:
 | | null
 | | };]), log id: 71197b7a
 | 
 | | 2013-04-25 17:55:01,792 INFO
 | |
[org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand]
 | | (pool-3-thread-49) [783c9d00] FINISH,
 | | ValidateStorageServerConnectionVDSCommand, return:
 | | {c925e43f-ff52-45ae-8484-e4ac6b670143=0}, log id: 71197b7a
 | 
 | | 2013-04-25 17:55:01,796 INFO
 | | [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand]
 | | (pool-3-thread-49) [783c9d00] Running command: ConnectStorageToVdsCommand
 | | internal: true. Entities affected : ID:
 | | aaa00000-0000-0000-0000-123456789aaa
 | | Type: System
 | 
 | | 2013-04-25 17:55:01,801 INFO
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]
 | | (pool-3-thread-49) [783c9d00] START,
 | | ConnectStorageServerVDSCommand(HostName
 | | = sbhost-58, HostId = d576e7aa-c2fc-4fee-9125-d8dd61d005be, storagePoolId
 | | =
 | | 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList =
 | | [{
 | | id: c925e43f-ff52-45ae-8484-e4ac6b670143, connection:
 | | storage2.phx.salab.redhat.com:/data/sap/ovirt-domain, iqn: null, vfsType:
 | | null, mountOptions: null, nfsVersion: AUTO, nfsRetrans: null, nfsTimeo:
 | | null
 | | };]), log id: 6a4d78ea
 | 
 | | 2013-04-25 17:55:01,828 INFO
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]
 | | (pool-3-thread-49) [783c9d00] FINISH, ConnectStorageServerVDSCommand,
 | | return: {c925e43f-ff52-45ae-8484-e4ac6b670143=0}, log id: 6a4d78ea
 | 
 | | 2013-04-25 17:55:01,830 INFO
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand]
 | | (pool-3-thread-49) [783c9d00] START, CreateStoragePoolVDSCommand(HostName
 | | =
 | | sbhost-58, HostId = d576e7aa-c2fc-4fee-9125-d8dd61d005be,
 | | storagePoolId=5849b030-626e-47cb-ad90-3ce782d831b3, storageType=NFS,
 | | storagePoolName=Default,
 | | masterDomainId=a7138327-930c-49d7-9f39-c34ee36fc7fb,
 | | domainsIdList=[a7138327-930c-49d7-9f39-c34ee36fc7fb], masterVersion=9),
 | | log
 | | id: 109f1d33
 | 
 | | 2013-04-25 17:55:02,902 WARN
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
 | | (pool-3-thread-49) [783c9d00] Weird return value: StatusForXmlRpc
 | | [mCode=661, mMessage=Cannot acquire host id:
 | | ('a7138327-930c-49d7-9f39-c34ee36fc7fb', SanlockException(19, 'Sanlock
 | | lockspace add failure', 'No such device'))]
 | 
 | | 2013-04-25 17:55:02,908 WARN
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
 | | (pool-3-thread-49) [783c9d00] Weird return value: StatusForXmlRpc
 | | [mCode=661, mMessage=Cannot acquire host id:
 | | ('a7138327-930c-49d7-9f39-c34ee36fc7fb', SanlockException(19, 'Sanlock
 | | lockspace add failure', 'No such device'))]
 | 
 | | 2013-04-25 17:55:02,912 ERROR
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
 | | (pool-3-thread-49) [783c9d00] Failed in CreateStoragePoolVDS method
 | 
 | | 2013-04-25 17:55:02,915 ERROR
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
 | | (pool-3-thread-49) [783c9d00] Error code unexpected and error message
 | | VDSGenericException: VDSErrorException: Failed to CreateStoragePoolVDS,
 | | error = Cannot acquire host id: ('a7138327-930c-49d7-9f39-c34ee36fc7fb',
 | | SanlockException(19, 'Sanlock lockspace add failure', 'No such
device'))
 | 
 | | 2013-04-25 17:55:02,921 INFO
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
 | | (pool-3-thread-49) [783c9d00] Command
 | | org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand
 | | return
 | | value
 | 
 | | StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=661,
 | | mMessage=Cannot acquire host id: ('a7138327-930c-49d7-9f39-c34ee36fc7fb',
 | | SanlockException(19, 'Sanlock lockspace add failure', 'No such
 | | device'))]]
 | 
 | | 2013-04-25 17:55:02,924 INFO
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
 | | (pool-3-thread-49) [783c9d00] HostName = sbhost-58
 | 
 | | 2013-04-25 17:55:02,926 ERROR
 | | [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (pool-3-thread-49)
 | | [783c9d00] Command CreateStoragePoolVDS execution failed. Exception:
 | | VDSErrorException: VDSGenericException: VDSErrorException: Failed to
 | | CreateStoragePoolVDS, error = Cannot acquire host id:
 | | ('a7138327-930c-49d7-9f39-c34ee36fc7fb', SanlockException(19, 'Sanlock
 | | lockspace add failure', 'No such device'))
 | 
 | | 2013-04-25 17:55:02,932 INFO
 | | [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand]
 | | (pool-3-thread-49) [783c9d00] FINISH, CreateStoragePoolVDSCommand, log
 | | id:
 | | 109f1d33
 | 
 | | 2013-04-25 17:55:02,936 ERROR
 | | [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand]
 | | (pool-3-thread-49) [783c9d00] Command
 | | org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand throw
 | | Vdc Bll exception. With error message VdcBLLException:
 | | org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException:
 | | VDSGenericException: VDSErrorException: Failed to CreateStoragePoolVDS,
 | | error = Cannot acquire host id: ('a7138327-930c-49d7-9f39-c34ee36fc7fb',
 | | SanlockException(19, 'Sanlock lockspace add failure', 'No such
device'))
 | 
 | | 2013-04-25 17:55:02,952 INFO
 | | [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand]
 | | (pool-3-thread-49) [783c9d00] Command
 | | [id=c09e2511-3d69-41fd-9a4c-57d4a012d11b]: Compensating CHANGED_ENTITY of
 | | org.ovirt.engine.core.common.businessentities.storage_pool; snapshot:
 | | id=5849b030-626e-47cb-ad90-3ce782d831b3.
 | 
 | | 2013-04-25 17:55:02,961 INFO
 | | [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand]
 | | (pool-3-thread-49) [783c9d00] Command
 | | [id=c09e2511-3d69-41fd-9a4c-57d4a012d11b]: Compensating NEW_ENTITY_ID of
 | | org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap;
 | | snapshot:
 | | storagePoolId = 5849b030-626e-47cb-ad90-3ce782d831b3, storageId =
 | | a7138327-930c-49d7-9f39-c34ee36fc7fb.
 | 
 | | 2013-04-25 17:55:02,973 INFO
 | | [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand]
 | | (pool-3-thread-49) [783c9d00] Command
 | | [id=c09e2511-3d69-41fd-9a4c-57d4a012d11b]: Compensating CHANGED_ENTITY of
 | | org.ovirt.engine.core.common.businessentities.StorageDomainStatic;
 | | snapshot:
 | | id=a7138327-930c-49d7-9f39-c34ee36fc7fb.
 | 
 | | 2013-04-25 17:55:03,017 INFO
 | | [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand]
 | | (pool-3-thread-49) [783c9d00] Lock freed to object EngineLock
 | | [exclusiveLocks= key: 5849b030-626e-47cb-ad90-3ce782d831b3 value: POOL
 | 
 | | , sharedLocks= ]
 | 
 | | 2013-04-25 17:55:16,712 INFO [org.ovirt.engine.core.bll.LoginUserCommand]
 | | (ajp--127.0.0.1-8702-2) Running command: LoginUserCommand internal:
 | | false.
 | 
 | | 2013-04-25 17:55:16,758 WARN
 | | [org.ovirt.engine.core.bll.GetConfigurationValueQuery]
 | | (ajp--127.0.0.1-8702-2) calling GetConfigurationValueQuery
 | | (ApplicationMode)
 | | with null version, using default general for version
 | 
 | | 2013-04-25 17:55:16,766 WARN
 | | [org.ovirt.engine.core.bll.GetConfigurationValueQuery]
 | | (ajp--127.0.0.1-8702-2) calling GetConfigurationValueQuery (VdcVersion)
 | | with
 | | null version, using default general for version
 | 

 | | 2013-04-25 17:56:16,711 INFO [org.ovirt.engine.core.bll.LoginUserCommand]
 | | (ajp--127.0.0.1-8702-8) Running command: LoginUserCommand internal:
 | | false.
 | 
 | | 2013-04-25 17:56:16,757 WARN
 | | [org.ovirt.engine.core.bll.GetConfigurationValueQuery]
 | | (ajp--127.0.0.1-8702-8) calling GetConfigurationValueQuery
 | | (ApplicationMode)
 | | with null version, using default general for version
 | 
 | | 2013-04-25 17:56:16,765 WARN
 | | [org.ovirt.engine.core.bll.GetConfigurationValueQuery]
 | | (ajp--127.0.0.1-8702-8) calling GetConfigurationValueQuery (VdcVersion)
 | | with
 | | null version, using default general for version
 | 

 | | BTW, not sure if this is related, during New Domain, the Advanced
 | | Parameters
 | | has to set to "Auto Negotiation" for NFS version otherwise the creation
 | | would fail (I saw similar behavior in RHEV 3.1).
 | 

 | | Thanks in advance for any input!
 | 

 | | Sherry
 | 
 | | --
 | 
 | | Sherry Yu, RHCE, RHCVA
 | 
 | | Principal Enterprise Architect
 | 
 | | Global Partner Enablement
 | 
 | | Red Hat, Inc (www.redhat.com)
 | 
 | | Mobile: 1-408-832-2160
 | 

 | | _______________________________________________
 | 
 | | Users mailing list
 | 
 | | Users(a)ovirt.org
 | 
 | | http://lists.ovirt.org/mailman/listinfo/users
 | 

 --
 Sherry Yu, RHCE, RHCVA
 Principal Enterprise Architect
 Global Partner Enablement
 Red Hat, Inc (www.redhat.com)
 Mobile: 1-408-832-2160

 _______________________________________________
 Users mailing list
 Users(a)ovirt.org
 http://lists.ovirt.org/mailman/listinfo/users

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

Re: [Users] Error Attaching NFS Data Domain to Data Center - oVirt 3.3