Bug 1004005 - ISO Domain set-up during run of 'rhevm-setup' fails to attach to Data Center
ISO Domain set-up during run of 'rhevm-setup' fails to attach to Data Center
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine-setup (Show other bugs)
3.3.0
Unspecified Unspecified
high Severity high
: ---
: 3.3.0
Assigned To: Sandro Bonazzola
sefi litmanovich
integration
:
Depends On:
Blocks: 1004395 1019461
  Show dependency treegraph
 
Reported: 2013-09-03 13:10 EDT by Rejy M Cyriac
Modified: 2015-09-22 09 EDT (History)
9 users (show)

See Also:
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 17:11:24 EST
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 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 Rejy M Cyriac 2013-09-03 13:10:37 EDT
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:
Comment 1 Ayal Baron 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.
Comment 2 Sandro Bonazzola 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.
Comment 3 Rejy M Cyriac 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 ?
Comment 4 Rejy M Cyriac 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 5 Sandro Bonazzola 2013-09-05 03:35:26 EDT
(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.
Comment 6 Sandro Bonazzola 2013-09-05 03:59:55 EDT
(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.
Comment 7 Sandro Bonazzola 2013-09-05 04:31:01 EDT
(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 / .
Comment 8 Sandro Bonazzola 2013-09-05 04:56:50 EDT
(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.
Comment 9 Sandro Bonazzola 2013-09-05 05:35:45 EDT
(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.
Comment 10 Sandro Bonazzola 2013-09-05 06:50:18 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 upstream master.
Comment 11 Sandro Bonazzola 2013-09-09 06:02:09 EDT
merged upstream master, pushed on upstream 3.3 branch.
Comment 12 Sandro Bonazzola 2013-09-10 09:04:51 EDT
pushed also to upstream 3.3.0 branch
Comment 13 Sandro Bonazzola 2013-09-11 04:26:03 EDT
All patches merged in master, 3.3 and 3.3.0 upstream branches.
Comment 15 sefi litmanovich 2013-09-16 12:38:23 EDT
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
Comment 16 Itamar Heim 2014-01-21 17:11:24 EST
Closing - RHEV 3.3 Released

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