Bug 1004395 - ISO Domain set-up during run of 'engine-setup' fails to attach to Data Center
ISO Domain set-up during run of 'engine-setup' fails to attach to Data Center
Status: CLOSED CURRENTRELEASE
Product: oVirt
Classification: Community
Component: ovirt-engine-installer (Show other bugs)
3.3
Unspecified Unspecified
urgent Severity high
: ---
: 3.3
Assigned To: Sandro Bonazzola
integration
:
Depends On: 1004005
Blocks:
  Show dependency treegraph
 
Reported: 2013-09-04 10:23 EDT by Sandro Bonazzola
Modified: 2013-10-14 05:55 EDT (History)
11 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 1004005
Environment:
Last Closed: 2013-10-14 05:55:59 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 18899 None None None Never
oVirt gerrit 18901 None None None Never
oVirt gerrit 18902 None None None Never
oVirt gerrit 18975 None None None Never
oVirt gerrit 18978 None None None Never
oVirt gerrit 18982 None None None Never
oVirt gerrit 19038 None None None Never
oVirt gerrit 19039 None None None Never
oVirt gerrit 19043 None None None Never

  None (edit)
Description Sandro Bonazzola 2013-09-04 10:23:22 EDT
+++ This bug was initially created as a clone of Bug #1004005 +++

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:

--- Additional comment from Ayal Baron on 2013-09-04 08:57:53 EDT ---

Alon, are you familiar with how the domain is created during rhevm-setup?
Seems like something there isn't quite right.

--- Additional comment from Sandro Bonazzola on 2013-09-04 09:16:27 EDT ---

from the logs it seems there are 2 issues here:
- wrong permission on created directory tree
- wrong encoding of the uuid of the domain.

--- Additional comment from Rejy M Cyriac on 2013-09-04 09:29:01 EDT ---

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 ?

--- Additional comment from Rejy M Cyriac on 2013-09-04 09:30:33 EDT ---

(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.
...
Comment 1 Sandro Bonazzola 2013-09-05 05:38:51 EDT
> 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.
Comment 2 Sandro Bonazzola 2013-09-05 05:40:14 EDT
> I meant... the set-up does not create the directory for you, unlike the case in RHEVM3.2.

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.
Comment 3 Sandro Bonazzola 2013-09-05 06:49:24 EDT
> - 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 master.
Comment 4 Sandro Bonazzola 2013-09-09 05:19:57 EDT
merged upstream master, pushed on 3.3 branch.
Comment 5 Sandro Bonazzola 2013-09-10 09:02:13 EDT
pushed also on 3.3.0 branch.

Note You need to log in before you can comment on or make changes to this bug.