Bug 1004005
| Summary: | ISO Domain set-up during run of 'rhevm-setup' fails to attach to Data Center | |||
|---|---|---|---|---|
| Product: | Red Hat Enterprise Virtualization Manager | Reporter: | Rejy M Cyriac <rcyriac> | |
| Component: | ovirt-engine-setup | Assignee: | Sandro Bonazzola <sbonazzo> | |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | sefi litmanovich <slitmano> | |
| Severity: | high | Docs Contact: | ||
| Priority: | high | |||
| Version: | 3.3.0 | CC: | acathrow, alonbl, bazulay, ecohen, iheim, oschreib, Rhev-m-bugs, scohen, yeylon | |
| Target Milestone: | --- | |||
| Target Release: | 3.3.0 | |||
| Hardware: | Unspecified | |||
| OS: | Unspecified | |||
| Whiteboard: | integration | |||
| Fixed In Version: | is14 | Doc Type: | Bug Fix | |
| Doc Text: | Story Points: | --- | ||
| Clone Of: | ||||
| : | 1004395 (view as bug list) | Environment: | ||
| Last Closed: | 2014-01-21 22:11:24 UTC | Type: | Bug | |
| Regression: | --- | Mount Type: | --- | |
| Documentation: | --- | CRM: | ||
| Verified Versions: | Category: | --- | ||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | ||
| Cloudforms Team: | --- | Target Upstream Version: | ||
| Embargoed: | ||||
| Bug Depends On: | ||||
| Bug Blocks: | 1004395, 1019461 | |||
Alon, are you familiar with how the domain is created during rhevm-setup? Seems like something there isn't quite right. from the logs it seems there are 2 issues here: - wrong permission on created directory tree - wrong encoding of the uuid of the domain. A little history regarding the wrong ownerships at the root directory of the ISO Domain. During the run of 'rhevm-setup' in RHEVM3.3, if a non-existing directory path is given for the ISO Domain, the set-up does not create the directory for you, as it is in RHEVM3.2. The setup gives out an error, and waits again for the input of an existing directory path. So the directory for the ISO Domain was manually created, and provided to setup, which accepted it, but did not change the ownerships of the root directory of the ISO Domain to vdsm:kvm, as expected. I think that the earlier process was better in which the setup created the directory for you, and ensured right ownerships. Should I create a separate BZ for that ? (In reply to Rejy M Cyriac from comment #3) > A little history regarding the wrong ownerships at the root directory of the > ISO Domain. > > During the run of 'rhevm-setup' in RHEVM3.3, if a non-existing directory > path is given for the ISO Domain, the set-up does not create the directory > for you, as it is in RHEVM3.2. I meant... the set-up does not create the directory for you, unlike the case in RHEVM3.2. ... (In reply to Rejy M Cyriac from comment #3) > I think that the earlier process was better in which the setup created the > directory for you, and ensured right ownerships. Should I create a separate > BZ for that ? I think it can be addressed solving this bug. (In reply to Sandro Bonazzola from comment #5) > (In reply to Rejy M Cyriac from comment #3) > > I think that the earlier process was better in which the setup created the > > directory for you, and ensured right ownerships. Should I create a separate > > BZ for that ? > > I think it can be addressed solving this bug. looking at the code it seems that setup should already create that directory for you with the right permissions. It seems that the only thing missing is ensuring that the specified path, if exists, has the right ownership. So maybe it's better to open a new bug about the failure in creating the directory if you're able to reproduce it. In this case please also attach the setup logs to the new bug. (In reply to Sandro Bonazzola from comment #6) > So maybe it's better to open a new bug about the failure in creating the > directory if you're able to reproduce it. In this case please also attach > the setup logs to the new bug. I reproduced this issue: Configure an NFS share on this server to be used as an ISO Domain? (Yes, No) [Yes]: Local ISO domain path [/var/lib/exports/iso-20130905082803]: /ISOstore [ ERROR ] Cannot access mount point /ISOstore: Error: mount point /ISOstore is not writable Local ISO domain path [/var/lib/exports/iso-20130905082814]: /var/ISOstore Local ISO domain name [ISO_DOMAIN]: So it fails only specifying a non existent directory on / . (In reply to Sandro Bonazzola from comment #7) > I reproduced this issue: > Configure an NFS share on this server to be used as an ISO Domain? (Yes, > No) [Yes]: > Local ISO domain path [/var/lib/exports/iso-20130905082803]: /ISOstore > [ ERROR ] Cannot access mount point /ISOstore: Error: mount point /ISOstore > is not writable > Local ISO domain path [/var/lib/exports/iso-20130905082814]: /var/ISOstore > Local ISO domain name [ISO_DOMAIN]: > > So it fails only specifying a non existent directory on / . upstream patch 18899 should fix this specific issue. (In reply to Sandro Bonazzola from comment #2) > from the logs it seems there are 2 issues here: > - wrong permission on created directory tree upstream patch 18901 should fix this specific issue: previously if an existing directory was specified for using it as iso domain its ownership and access bits where untouched. Now ownership and access bits are enforced. > - wrong encoding of the uuid of the domain. I'm still trying to reproduce this. > - wrong encoding of the uuid of the domain.
upstream patch 18902 should fix this specific issue.
Moving the bug to post, patch under review on upstream master.
merged upstream master, pushed on upstream 3.3 branch. pushed also to upstream 3.3.0 branch All patches merged in master, 3.3 and 3.3.0 upstream branches. Verified- ran engine-setup on vm with RHEL6.4 after installing rhevm is14. 1.Local ISO domain path [/var/lib/exports/iso-20130905082803]: /ISOstore worked fine 2. created POSIX complaint FS Data Center of 3.2 compatibility version, and cluster accordingly. 3. added host, added storge: POSIX complaint FS. 4. after data center went up, attached the ISO_DOMAIN successfully Closing - RHEV 3.3 Released |
Description of problem: On RHEVM3.3 IS12 build (3.3.0-0.18.master.el6ev), an ISO Domain was configured locally during the run of the 'rhevm-setup' tool. This ISO Domain was visible as an un-attached ISO Domain in the RHEVM admin portal, as expected. However, on trying to attach this ISO Domain to an up and running POSIX compliant FS Data Center of 3.2 compatibility version, the process fails. The message at the RHEVM admin portal log interface was as given below. -------------------------------------- 2013-Sep-03, 19:38 Failed to attach Storage Domain ISO_DOMAIN to Data Center GOLDDataCenter. (User: admin@internal) -------------------------------------- The ovirt-engine log conatined the following entries. -------------------------------------- 2013-09-03 19:37:59,934 INFO [org.ovirt.engine.core.bll.storage.AttachStorageDomainToPoolCommand] (pool-5-thread-50) [51407b5] Running command: AttachStorageDomainToPoolCommand internal: false. Entities affecte d : ID: 71d9c6b0-2080-4764-a86a-408d6c595f0b Type: Storage 2013-09-03 19:37:59,944 INFO [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (pool-5-thread-10) Running command: ConnectStorageToVdsCommand internal: true. Entities affected : ID: aaa00000-0000- 0000-0000-123456789aaa Type: System 2013-09-03 19:37:59,946 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-5-thread-10) START, ConnectStorageServerVDSCommand(HostName = rhs-gp-srv12-RHEL-6.4, HostId = d63c60 b5-07e4-4781-83c1-e2f17840702a, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: 9956228d-80af-41f4-8d2a-7969297fc86e, connection: snow.lab.eng.blr.redhat.com:/ISO store, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 281e5a90 2013-09-03 19:37:59,980 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-9) START, GlusterServersListVDSCommand(HostName = sally, HostId = 9c6574f3-9251 -48d9-8400-b07bf087e3cf), log id: 491345fa 2013-09-03 19:38:00,368 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-9) FINISH, GlusterServersListVDSCommand, return: [10.70.34.113:CONNECTED, red.l ab.eng.blr.redhat.com:CONNECTED, 10.70.34.111:CONNECTED], log id: 491345fa 2013-09-03 19:38:00,373 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-9) START, GlusterVolumesListVDSCommand(HostName = sally, HostId = 9c6574f3-9251 -48d9-8400-b07bf087e3cf), log id: 7e00f142 2013-09-03 19:38:00,397 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-10) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Failed to connect Hos t rhs-gp-srv12-RHEL-6.4 to the Storage Domains ISO_DOMAIN. 2013-09-03 19:38:00,397 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-5-thread-10) FINISH, ConnectStorageServerVDSCommand, return: {9956228d-80af-41f4-8d2a-7969297fc86e=4 69}, log id: 281e5a90 2013-09-03 19:38:00,398 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-10) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: The error message for connection snow.lab.eng.blr.redhat.com:/ISOstore returned by VDSM was: Permission settings on the specified path do not allow access to the storage. Verify permission settings on the specified storage path. 2013-09-03 19:38:00,399 ERROR [org.ovirt.engine.core.bll.storage.NFSStorageHelper] (pool-5-thread-10) The connection with details snow.lab.eng.blr.redhat.com:/ISOstore failed because of error code 469 and error message is: permission settings on the specified path do not allow access to the storage. verify permission settings on the specified storage path. -------------------------------------- The vdsm log at the Hypervisor conatained the following entries. -------------------------------------- Thread-37437::DEBUG::2013-09-03 19:43:03,080::task::579::TaskManager.Task::(_updateState) Task=`1a3ae651-a354-4d22-b4e7-ce56fb7e2c57`::moving from state init -> state preparing Thread-37437::INFO::2013-09-03 19:43:03,081::logUtils::40::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'snow.lab.eng.blr.redhat.com:/ISOstore', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '9956228d-80af-41f4-8d2a-7969297fc86e', 'port': ''}], options=None) Thread-37437::DEBUG::2013-09-03 19:43:03,083::misc::83::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 snow.lab.eng.blr.redhat.com:/ISOstore /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore' (cwd None) Thread-37437::DEBUG::2013-09-03 19:43:03,145::hsm::2237::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore Thread-37437::DEBUG::2013-09-03 19:43:03,148::hsm::2261::Storage.HSM::(__prefetchDomains) Found SD uuids: ('71d9c6b0-2080-4764-a86a-408d6c595f0b',) Thread-37437::DEBUG::2013-09-03 19:43:03,148::hsm::2310::Storage.HSM::(connectStorageServer) knownSDs: {'71d9c6b0-2080-4764-a86a-408d6c595f0b': <function findDomain at 0x7f221f7432a8>, '4f4297d3-a067-4ce1-9a86-11871a07cbbd': <function findDomain at 0x7f221f7432a8>, 'ce692787-dc4e-49ce-859f-a3569aad4049': <function findDomain at 0x7f221f7432a8>} Thread-37437::INFO::2013-09-03 19:43:03,148::logUtils::42::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '9956228d-80af-41f4-8d2a-7969297fc86e'}]} Thread-37437::DEBUG::2013-09-03 19:43:03,148::task::1168::TaskManager.Task::(prepare) Task=`1a3ae651-a354-4d22-b4e7-ce56fb7e2c57`::finished: {'statuslist': [{'status': 0, 'id': '9956228d-80af-41f4-8d2a-7969297fc86e'}]} Thread-37437::DEBUG::2013-09-03 19:43:03,148::task::579::TaskManager.Task::(_updateState) Task=`1a3ae651-a354-4d22-b4e7-ce56fb7e2c57`::moving from state preparing -> state finished -------------------------------------- The permissions on the ISO Domain directory were as follows -------------------------------------- [root@snow ~]# ls -ld /ISOstore/ drwxr-xr-x. 3 root root 4096 Sep 2 11:05 /ISOstore/ [root@snow ~]# ls -lR /ISOstore/ /ISOstore/: total 4 drwxr-xr-x. 4 vdsm kvm 4096 Sep 2 11:05 71d9c6b0-2080-4764-a86a-408d6c595f0b /ISOstore/71d9c6b0-2080-4764-a86a-408d6c595f0b: total 8 drwxr-xr-x. 2 vdsm kvm 4096 Sep 2 11:05 dom_md drwxr-xr-x. 3 vdsm kvm 4096 Sep 2 11:05 images /ISOstore/71d9c6b0-2080-4764-a86a-408d6c595f0b/dom_md: total 20 -rw-r--r--. 1 vdsm kvm 1 Sep 2 11:05 ids -rw-r--r--. 1 vdsm kvm 1 Sep 2 11:05 inbox -rw-r--r--. 1 vdsm kvm 1 Sep 2 11:05 leases -rwxr-xr-x. 1 vdsm kvm 299 Sep 2 11:05 metadata -rw-r--r--. 1 vdsm kvm 1 Sep 2 11:05 outbox /ISOstore/71d9c6b0-2080-4764-a86a-408d6c595f0b/images: total 4 drwxr-xr-x. 2 vdsm kvm 4096 Sep 2 11:19 11111111-1111-1111-1111-111111111111 /ISOstore/71d9c6b0-2080-4764-a86a-408d6c595f0b/images/11111111-1111-1111-1111-111111111111: total 10464460 -rw-r--r--. 1 vdsm kvm 654055424 Sep 2 11:15 en_win_srv_2003_r2_enterprise_x64_with_sp2_vl_cd1_x13-48614.iso -rw-r--r--. 1 vdsm kvm 4298059776 Sep 2 11:16 RHEL5.9-Server-20121129.0-x86_64-DVD.iso -rw-r--r--. 1 vdsm kvm 3720347648 Sep 2 11:18 RHEL6.4-20130130.0-Server-x86_64-DVD1.iso -rw-r--r--. 1 vdsm kvm 264644608 Sep 2 11:18 RHEV-toolsSetup_3.2_12.iso -rw-r--r--. 1 vdsm kvm 1682057216 Sep 2 11:19 RHS-2.0-20130715.2-RHS-x86_64-DVD1.iso -rw-r--r--. 1 vdsm kvm 2949120 Sep 2 11:19 virtio-win-1.6.5_amd64.vfd -rw-r--r--. 1 vdsm kvm 90521600 Sep 2 11:19 virtio-win-1.6.5.iso -rw-r--r--. 1 vdsm kvm 2949120 Sep 2 11:19 virtio-win-1.6.5_x86.vfd -------------------------------------- The nfs entries and outputs, and firewall rules: -------------------------------------- [root@snow ~]# cat /etc/exports /ISOstore 0.0.0.0/0.0.0.0(rw) [root@snow ~]# showmount -e Export list for snow.lab.eng.blr.redhat.com: /ISOstore 0.0.0.0/0.0.0.0 [root@snow ~]# iptables -nvL Chain INPUT (policy ACCEPT 0 packets, 0 bytes) pkts bytes target prot opt in out source destination 1144K 421M ACCEPT all -- lo * 0.0.0.0/0 0.0.0.0/0 2 168 ACCEPT icmp -- * * 0.0.0.0/0 0.0.0.0/0 icmp type 255 693K 276M ACCEPT all -- * * 0.0.0.0/0 0.0.0.0/0 state RELATED,ESTABLISHED 7 420 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:22 0 0 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:5432 0 0 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:5432 10389 623K ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:443 8 480 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:111 6 504 ACCEPT udp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW udp dpt:111 0 0 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:662 0 0 ACCEPT udp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW udp dpt:662 0 0 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:875 0 0 ACCEPT udp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW udp dpt:875 0 0 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:892 12 816 ACCEPT udp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW udp dpt:892 12 720 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:2049 0 0 ACCEPT udp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW udp dpt:32769 0 0 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:32803 0 0 ACCEPT tcp -- * * 0.0.0.0/0 0.0.0.0/0 state NEW tcp dpt:80 11599 1677K REJECT all -- * * 0.0.0.0/0 0.0.0.0/0 reject-with icmp-host-prohibited Chain FORWARD (policy ACCEPT 0 packets, 0 bytes) pkts bytes target prot opt in out source destination Chain OUTPUT (policy ACCEPT 2033K packets, 536M bytes) pkts bytes target prot opt in out source destination -------------------------------------- I changed the ownerships of the root directory (/ISOstore/) from the current root:root to vdsm:kvm , and tried again. Different error came up now in the ovirt-engine log, and Hypervisor vdsm log: -------------------------------------- ovirt-engine log: 2013-09-03 19:43:01,925 INFO [org.ovirt.engine.core.bll.storage.AttachStorageDomainToPoolCommand] (pool-5-thread-50) [426f79ee] Running command: AttachStorageDomainToPoolCommand internal: false. Entities affected : ID: 71d9c6b0-2080-4764-a86a-408d6c595f0b Type: Storage 2013-09-03 19:43:01,931 INFO [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (pool-5-thread-24) Running command: ConnectStorageToVdsCommand internal: true. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2013-09-03 19:43:01,933 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-5-thread-24) START, ConnectStorageServerVDSCommand(HostName = rhs-gp-srv12-RHEL-6.4, HostId = d63c60b5-07e4-4781-83c1-e2f17840702a, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: 9956228d-80af-41f4-8d2a-7969297fc86e, connection: snow.lab.eng.blr.redhat.com:/ISOstore, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 31a497c2 2013-09-03 19:43:02,008 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-5-thread-24) FINISH, ConnectStorageServerVDSCommand, return: {9956228d-80af-41f4-8d2a-7969297fc86e=0}, log id: 31a497c2 2013-09-03 19:43:02,009 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.AttachStorageDomainVDSCommand] (pool-5-thread-50) [426f79ee] START, AttachStorageDomainVDSCommand( storagePoolId = 71e449b7-2066-4de8-80aa-92b9018bb00c, ignoreFailoverLimit = false, storageDomainId = 71d9c6b0-2080-4764-a86a-408d6c595f0b), log id: 158f4efe 2013-09-03 19:43:02,792 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-22) START, GlusterServersListVDSCommand(HostName = hamm, HostId = 61332701-40bd-4ed0-bfd7-54d449651398), log id: 731b86bd 2013-09-03 19:43:03,178 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-22) FINISH, GlusterServersListVDSCommand, return: [10.70.34.111:CONNECTED, red.lab.eng.blr.redhat.com:CONNECTED, sally.lab.eng.blr.redhat.com:CONNECTED], log id: 731b86bd 2013-09-03 19:43:03,183 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-22) START, GlusterVolumesListVDSCommand(HostName = hamm, HostId = 61332701-40bd-4ed0-bfd7-54d449651398), log id: 76d6779e 2013-09-03 19:43:03,385 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-22) FINISH, GlusterVolumesListVDSCommand, return: {82f6bd66-d846-4282-b8c7-612b49faefb6=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@8b3c39b9, b316c3c7-c221-40df-a5a2-9aece34365c7=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@8942a8e7}, log id: 76d6779e 2013-09-03 19:43:04,464 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.AttachStorageDomainVDSCommand] (pool-5-thread-50) [426f79ee] Failed in AttachStorageDomainVDS method 2013-09-03 19:43:04,469 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.AttachStorageDomainVDSCommand] (pool-5-thread-50) [426f79ee] Error code AcquireLockFailure and error message IRSGenericException: IRSErrorException: Failed to AttachStorageDomainVDS, error = Cannot obtain lock: 'id=(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',), rc=1, out=[], err=["sh: -c: line 0: syntax error near unexpected token `(\'", "sh: -c: line 0: `/usr/libexec/vdsm/spmprotect.sh start (\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',) 1 5 /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore/(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',)/dom_md/leases 60000 10000 3\'"]' 2013-09-03 19:43:04,469 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (pool-5-thread-50) [426f79ee] IrsBroker::Failed::AttachStorageDomainVDS due to: IRSErrorException: IRSGenericException: IRSErrorException: Failed to AttachStorageDomainVDS, error = Cannot obtain lock: 'id=(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',), rc=1, out=[], err=["sh: -c: line 0: syntax error near unexpected token `(\'", "sh: -c: line 0: `/usr/libexec/vdsm/spmprotect.sh start (\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',) 1 5 /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore/(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',)/dom_md/leases 60000 10000 3\'"]' 2013-09-03 19:43:04,477 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.AttachStorageDomainVDSCommand] (pool-5-thread-50) [426f79ee] FINISH, AttachStorageDomainVDSCommand, log id: 158f4efe 2013-09-03 19:43:04,477 ERROR [org.ovirt.engine.core.bll.storage.AttachStorageDomainToPoolCommand] (pool-5-thread-50) [426f79ee] Command org.ovirt.engine.core.bll.storage.AttachStorageDomainToPoolCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IRSErrorException: IRSGenericException: IRSErrorException: Failed to AttachStorageDomainVDS, error = Cannot obtain lock: 'id=(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',), rc=1, out=[], err=["sh: -c: line 0: syntax error near unexpected token `(\'", "sh: -c: line 0: `/usr/libexec/vdsm/spmprotect.sh start (\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',) 1 5 /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore/(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',)/dom_md/leases 60000 10000 3\'"]' (Failed with error AcquireLockFailure and code 651) 2013-09-03 19:43:04,478 INFO [org.ovirt.engine.core.bll.storage.AttachStorageDomainToPoolCommand] (pool-5-thread-50) [426f79ee] Command [id=4f668635-838e-486b-b999-80f23e7cc416]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap; snapshot: storagePoolId = 71e449b7-2066-4de8-80aa-92b9018bb00c, storageId = 71d9c6b0-2080-4764-a86a-408d6c595f0b. 2013-09-03 19:43:04,483 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-50) [426f79ee] Correlation ID: 426f79ee, Job ID: dd839f0e-976e-461f-9e2a-aca5de71100f, Call Stack: null, Custom Event ID: -1, Message: Failed to attach Storage Domain ISO_DOMAIN to Data Center GOLDDataCenter. (User: admin@internal) 2013-09-03 19:43:08,400 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-48) START, GlusterServersListVDSCommand(HostName = sally, HostId = 9c6574f3-9251-48d9-8400-b07bf087e3cf), log id: 1b28110c 2013-09-03 19:43:08,782 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-48) FINISH, GlusterServersListVDSCommand, return: [10.70.34.113:CONNECTED, red.lab.eng.blr.redhat.com:CONNECTED, 10.70.34.111:CONNECTED], log id: 1b28110c 2013-09-03 19:43:08,787 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-48) START, GlusterVolumesListVDSCommand(HostName = sally, HostId = 9c6574f3-9251-48d9-8400-b07bf087e3cf), log id: 3dca56ef 2013-09-03 19:43:08,989 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-48) FINISH, GlusterVolumesListVDSCommand, return: {82f6bd66-d846-4282-b8c7-612b49faefb6=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@3d8e3139, b316c3c7-c221-40df-a5a2-9aece34365c7=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@afd5606a}, log id: 3dca56ef 2013-09-03 19:43:14,007 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-56) START, GlusterServersListVDSCommand(HostName = red, HostId = 0060bfdb-b83b-4459-89ec-9c8933b2543f), log id: 68eca32b 2013-09-03 19:43:14,389 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-56) FINISH, GlusterServersListVDSCommand, return: [10.70.34.112:CONNECTED, 10.70.34.111:CONNECTED, sally.lab.eng.blr.redhat.com:CONNECTED], log id: 68eca32b 2013-09-03 19:43:14,394 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-56) START, GlusterVolumesListVDSCommand(HostName = red, HostId = 0060bfdb-b83b-4459-89ec-9c8933b2543f), log id: 38d40f35 2013-09-03 19:43:14,600 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-56) FINISH, GlusterVolumesListVDSCommand, return: {82f6bd66-d846-4282-b8c7-612b49faefb6=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@f0dfffef, b316c3c7-c221-40df-a5a2-9aece34365c7=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@8883b0e5}, log id: 38d40f35 2013-09-03 19:43:19,615 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-85) START, GlusterServersListVDSCommand(HostName = hamm, HostId = 61332701-40bd-4ed0-bfd7-54d449651398), log id: 6e9edfe6 2013-09-03 19:43:19,993 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-85) FINISH, GlusterServersListVDSCommand, return: [10.70.34.111:CONNECTED, red.lab.eng.blr.redhat.com:CONNECTED, sally.lab.eng.blr.redhat.com:CONNECTED], log id: 6e9edfe6 2013-09-03 19:43:19,997 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-85) START, GlusterVolumesListVDSCommand(HostName = hamm, HostId = 61332701-40bd-4ed0-bfd7-54d449651398), log id: 191a9ea9 2013-09-03 19:43:20,198 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-85) FINISH, GlusterVolumesListVDSCommand, return: {82f6bd66-d846-4282-b8c7-612b49faefb6=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@e17f0994, b316c3c7-c221-40df-a5a2-9aece34365c7=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@dfc2c7f0}, log id: 191a9ea9 2013-09-03 19:43:25,215 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-87) START, GlusterServersListVDSCommand(HostName = red, HostId = 0060bfdb-b83b-4459-89ec-9c8933b2543f), log id: 3e7b4d23 2013-09-03 19:43:25,593 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-87) FINISH, GlusterServersListVDSCommand, return: [10.70.34.112:CONNECTED, 10.70.34.111:CONNECTED, sally.lab.eng.blr.redhat.com:CONNECTED], log id: 3e7b4d23 2013-09-03 19:43:25,598 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-87) START, GlusterVolumesListVDSCommand(HostName = red, HostId = 0060bfdb-b83b-4459-89ec-9c8933b2543f), log id: 7534ed05 2013-09-03 19:43:25,799 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-87) FINISH, GlusterVolumesListVDSCommand, return: {82f6bd66-d846-4282-b8c7-612b49faefb6=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@74ec156d, b316c3c7-c221-40df-a5a2-9aece34365c7=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@685dbadc}, log id: 7534ed05 2013-09-03 19:43:30,812 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-90) START, GlusterServersListVDSCommand(HostName = hamm, HostId = 61332701-40bd-4ed0-bfd7-54d449651398), log id: 25c4c259 2013-09-03 19:43:31,196 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand] (DefaultQuartzScheduler_Worker-90) FINISH, GlusterServersListVDSCommand, return: [10.70.34.111:CONNECTED, red.lab.eng.blr.redhat.com:CONNECTED, sally.lab.eng.blr.redhat.com:CONNECTED], log id: 25c4c259 2013-09-03 19:43:31,200 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-90) START, GlusterVolumesListVDSCommand(HostName = hamm, HostId = 61332701-40bd-4ed0-bfd7-54d449651398), log id: 10fbf20c 2013-09-03 19:43:31,405 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-90) FINISH, GlusterVolumesListVDSCommand, return: {82f6bd66-d846-4282-b8c7-612b49faefb6=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@df49f3a7, b316c3c7-c221-40df-a5a2-9aece34365c7=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@2734da6b}, log id: 10fbf20c Hypervisor vdsm log: Thread-37438::DEBUG::2013-09-03 19:43:05,423::fileSD::134::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore/71d9c6b0-2080-4764-a86a-408d6c595f0 b Thread-37438::DEBUG::2013-09-03 19:43:05,423::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-37438::DEBUG::2013-09-03 19:43:05,486::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=ISO_DOMAIN', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=no.one.reads.this:/rhev', 'ROLE=Regular', "SDUUID=('71d9c6b0-2080-4764-a86a-408d6c595f0b',)", 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=4a4e7b0a44ac5d0ef5efff81912ed5352bf04068'] Thread-37438::DEBUG::2013-09-03 19:43:05,534::fileSD::526::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images [] Thread-37438::WARNING::2013-09-03 19:43:05,534::sd::370::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace ('71d9c6b0-2080-4764-a86a-408d6c595f0b',)_imageNS already registered Thread-37438::WARNING::2013-09-03 19:43:05,534::sd::378::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace ('71d9c6b0-2080-4764-a86a-408d6c595f0b',)_volumeNS already registered Thread-37438::DEBUG::2013-09-03 19:43:05,534::clusterlock::81::SafeLease::(acquireHostId) Host id for domain ('71d9c6b0-2080-4764-a86a-408d6c595f0b',) successfully acquired (id: 1) Thread-37438::DEBUG::2013-09-03 19:43:05,535::clusterlock::95::SafeLease::(acquire) Acquiring cluster lock for domain ('71d9c6b0-2080-4764-a86a-408d6c595f0b',) Thread-37438::DEBUG::2013-09-03 19:43:05,535::misc::83::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /usr/bin/setsid /usr/bin/ionice -c 1 -n 0 /bin/su vdsm -s /bin/sh -c "/usr/libexec/vdsm/spmprotect.sh start (\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',) 1 5 /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore/(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',)/dom_md/leases 60000 10000 3"' (cwd /usr/libexec/vdsm) Thread-37438::DEBUG::2013-09-03 19:43:05,597::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = "sh: -c: line 0: syntax error near unexpected token `('\nsh: -c: line 0: `/usr/libexec/vdsm/spmprotect.sh start ('71d9c6b0-2080-4764-a86a-408d6c595f0b',) 1 5 /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore/('71d9c6b0-2080-4764-a86a-408d6c595f0b',)/dom_md/leases 60000 10000 3'\n"; <rc> = 1 Thread-37438::DEBUG::2013-09-03 19:43:05,597::clusterlock::85::SafeLease::(releaseHostId) Host id for domain ('71d9c6b0-2080-4764-a86a-408d6c595f0b',) released successfully (id: 1) Thread-37438::ERROR::2013-09-03 19:43:05,601::task::850::TaskManager.Task::(_setError) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 857, in _run return fn(*args, **kargs) File "/usr/share/vdsm/logUtils.py", line 41, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 1098, in attachStorageDomain pool.attachSD(sdUUID) File "/usr/share/vdsm/storage/securable.py", line 68, in wrapper return f(self, *args, **kwargs) File "/usr/share/vdsm/storage/sp.py", line 935, in attachSD dom.acquireClusterLock(self.id) File "/usr/share/vdsm/storage/sd.py", line 474, in acquireClusterLock self._clusterLock.acquire(hostID) File "/usr/share/vdsm/storage/clusterlock.py", line 111, in acquire raise se.AcquireLockFailure(self._sdUUID, rc, out, err) AcquireLockFailure: Cannot obtain lock: 'id=(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',), rc=1, out=[], err=["sh: -c: line 0: syntax error near unexpected token `(\'", "sh: -c: line 0: `/usr/libexec/vdsm/spmprotect.sh start (\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',) 1 5 /rhev/data-center/mnt/snow.lab.eng.blr.redhat.com:_ISOstore/(\'71d9c6b0-2080-4764-a86a-408d6c595f0b\',)/dom_md/leases 60000 10000 3\'"]' Thread-37438::DEBUG::2013-09-03 19:43:05,602::task::869::TaskManager.Task::(_run) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::Task._run: 81723ccd-beee-4301-b8de-9051f4744a17 ('71d9c6b0-2080-4764-a86a-408d6c595f0b', '71e449b7-2066-4de8-80aa-92b9018bb00c') {} failed - stopping task Thread-37438::DEBUG::2013-09-03 19:43:05,602::task::1194::TaskManager.Task::(stop) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::stopping in state preparing (force False) Thread-37438::DEBUG::2013-09-03 19:43:05,602::task::974::TaskManager.Task::(_decref) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::ref 1 aborting True Thread-37438::INFO::2013-09-03 19:43:05,602::task::1151::TaskManager.Task::(prepare) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::aborting: Task is aborted: 'Cannot obtain lock' - code 651 Thread-37438::DEBUG::2013-09-03 19:43:05,602::task::1156::TaskManager.Task::(prepare) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::Prepare: aborted: Cannot obtain lock Thread-37438::DEBUG::2013-09-03 19:43:05,602::task::974::TaskManager.Task::(_decref) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::ref 0 aborting True Thread-37438::DEBUG::2013-09-03 19:43:05,603::task::909::TaskManager.Task::(_doAbort) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::Task._doAbort: force False Thread-37438::DEBUG::2013-09-03 19:43:05,603::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-37438::DEBUG::2013-09-03 19:43:05,603::task::579::TaskManager.Task::(_updateState) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::moving from state preparing -> state aborting Thread-37438::DEBUG::2013-09-03 19:43:05,603::task::534::TaskManager.Task::(__state_aborting) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::_aborting: recover policy none Thread-37438::DEBUG::2013-09-03 19:43:05,603::task::579::TaskManager.Task::(_updateState) Task=`81723ccd-beee-4301-b8de-9051f4744a17`::moving from state aborting -> state failed Thread-37438::DEBUG::2013-09-03 19:43:05,603::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.71e449b7-2066-4de8-80aa-92b9018bb00c': < ResourceRef 'Storage.71e449b7-2066-4de8-80aa-92b9018bb00c', isValid: 'True' obj: 'None'>, 'Storage.71d9c6b0-2080-4764-a86a-408d6c595f0b': < ResourceRef 'Storage.71d9c6b0-2080-4764-a86a-408d6c595f0b', isValid: 'True' obj: 'None'>} -------------------------------------- Created another NFS share on the same system manually, and tried adding as ISO Domain. That worked perfectly. Looking at the permissions on the newly added ISO Domain, I have noticed differences of permissions at contents of 'dom_md' directory inside the ISO Domain directory of newly created one, and automatically created one. The newly created one has the following.(The automatically created one's permissions are given in an output pasted above) -------------------------------------- /ISOnewstore/66335a5a-e11b-43bd-8ae6-898f74531f2b/dom_md: total 8 -rw-rw----. 1 vdsm kvm 0 Sep 3 21:18 ids -rw-rw----. 1 vdsm kvm 0 Sep 3 21:18 inbox -rw-rw----. 1 vdsm kvm 512 Sep 3 21:18 leases -rw-r--r--. 1 vdsm kvm 327 Sep 3 21:18 metadata -rw-rw----. 1 vdsm kvm 0 Sep 3 21:18 outbox -------------------------------------- Tried changing the permissions of the contents of 'dom_md' in the automatically created ISO Domain to match this. But still failed to attach. Then removed automatically created ISO Domain from RHEVM admin portal, cleaned its contents, and tried attaching it as new ISO Domain. Worked Perfectly, just like the earlier manually created one. Version-Release number of selected component (if applicable): RHEVM3.3 IS12 build (3.3.0-0.18.master.el6ev) How reproducible: Steps to Reproduce: 1.Confihure ISO Domain locally during run of 'rhevm-setup' 2.Create and activate POSIX complaint FS Data Center of 3.2 compatibility version 3.Try to attach ISO Domain to Data Center Actual results: Attaching the automatically configured ISO Domain(through rhevm-setup), to active Data Center fails. Expected results: Attaching the automatically configured ISO Domain(through rhevm-setup), to active Data Center should be successful. Additional info: