[ovirt-users] HostedEngine Deployment Woes

Wed Dec 31 04:28:58 EST 2014

----- Original Message -----
> From: "Mikola Rose" <mrose at power-soft.com>
> To: users at ovirt.org
> Sent: Tuesday, December 30, 2014 2:12:52 AM
> Subject: [ovirt-users] HostedEngine Deployment Woes
> 
> 
> Hi List Members;
> 
> I have been struggling with deploying oVirt hosted engine I keep running into
> a timeout during the "Misc Configuration" any suggestion on how I can
> trouble shoot this?
> 
> Redhat 2.6.32-504.3.3.el6.x86_64
> 
> Installed Packages
> ovirt-host-deploy.noarch 1.2.5-1.el6ev @rhel-6-server-rhevm-3.4-rpms
> ovirt-host-deploy-java.noarch 1.2.5-1.el6ev @rhel-6-server-rhevm-3.4-rpms
> ovirt-hosted-engine-ha.noarch 1.1.6-3.el6ev @rhel-6-server-rhevm-3.4-rpms
> ovirt-hosted-engine-setup.noarch 1.1.5-1.el6ev @rhel-6-server-rhevm-3.4-rpms
> rhevm-setup-plugin-ovirt-engine.noarch 3.4.4-2.2.el6ev
> @rhel-6-server-rhevm-3.4-rpms
> rhevm-setup-plugin-ovirt-engine-common.noarch 3.4.4-2.2.el6ev
> @rhel-6-server-rhevm-3.4-rpms

So this is RHEV (3.4) or ovirt?

> 
> 
> Please confirm installation settings (Yes, No)[No]: Yes
> [ INFO ] Stage: Transaction setup
> [ INFO ] Stage: Misc configuration
> [ INFO ] Stage: Package installation
> [ INFO ] Stage: Misc configuration
> [ INFO ] Configuring libvirt
> [ INFO ] Configuring VDSM
> [ INFO ] Starting vdsmd
> [ INFO ] Waiting for VDSM hardware info
> [ INFO ] Waiting for VDSM hardware info
> [ INFO ] Connecting Storage Domain
> [ INFO ] Connecting Storage Pool
> [ INFO ] Verifying sanlock lockspace initialization
> [ INFO ] sanlock lockspace already initialized
> [ INFO ] sanlock metadata already initialized
> [ INFO ] Creating VM Image
> [ INFO ] Disconnecting Storage Pool
> [ INFO ] Start monitoring domain
> [ ERROR ] Failed to execute stage 'Misc configuration': The read operation
> timed out
> [ INFO ] Stage: Clean up
> [ INFO ] Generating answer file '/etc/ovirt-hosted-engine/answers.conf'
> [ INFO ] Stage: Pre-termination
> [ INFO ] Stage: Termination
> 
> 
> 
> 2014-12-29 14:53:41 DEBUG
> otopi.plugins.ovirt_hosted_engine_setup.sanlock.lockspace
> lockspace._misc:133 Ensuring lease for lockspace hosted-engine, host id 1 is
> acquired (file:
> /rhev/data-center/mnt/192.168.0.75:_Volumes_Raid1/8094d528-7aa2-4c28-839f-73d7c8bcfebb/ha_agent/hosted-engine.lockspace)
> 2014-12-29 14:53:41 INFO
> otopi.plugins.ovirt_hosted_engine_setup.sanlock.lockspace
> lockspace._misc:144 sanlock lockspace already initialized
> 2014-12-29 14:53:41 INFO
> otopi.plugins.ovirt_hosted_engine_setup.sanlock.lockspace
> lockspace._misc:157 sanlock metadata already initialized
> 2014-12-29 14:53:41 DEBUG otopi.context context._executeMethod:138 Stage misc
> METHOD otopi.plugins.ovirt_hosted_engine_setup.vm.image.Plugin._misc
> 2014-12-29 14:53:41 INFO otopi.plugins.ovirt_hosted_engine_setup.vm.image
> image._misc:162 Creating VM Image
> 2014-12-29 14:53:41 DEBUG otopi.plugins.ovirt_hosted_engine_setup.vm.image
> image._misc:163 createVolume
> 2014-12-29 14:53:42 DEBUG otopi.plugins.ovirt_hosted_engine_setup.vm.image
> image._misc:184 Created volume d8e7eed4-c763-4b3d-8a71-35f2d692a73d, request
> was:
> - image: 9043e535-ea94-41f8-98df-6fdbfeb107c3
> - volume: e6a9291d-ac21-4a95-b43c-0d6e552baaa2
> 2014-12-29 14:53:42 DEBUG otopi.ovirt_hosted_engine_setup.tasks tasks.wait:48
> Waiting for existing tasks to complete
> 2014-12-29 14:53:43 DEBUG otopi.ovirt_hosted_engine_setup.tasks tasks.wait:48
> Waiting for existing tasks to complete
> 2014-12-29 14:53:43 DEBUG otopi.context context._executeMethod:138 Stage misc
> METHOD otopi.plugins.ovirt_hosted_engine_setup.vm.boot_disk.Plugin._misc
> 2014-12-29 14:53:43 DEBUG otopi.context context._executeMethod:144 condition
> False
> 2014-12-29 14:53:43 DEBUG otopi.context context._executeMethod:138 Stage misc
> METHOD
> otopi.plugins.ovirt_hosted_engine_setup.storage.storage.Plugin._disconnect_pool
> 2014-12-29 14:53:43 INFO
> otopi.plugins.ovirt_hosted_engine_setup.storage.storage
> storage._disconnect_pool:971 Disconnecting Storage Pool
> 2014-12-29 14:53:43 DEBUG otopi.ovirt_hosted_engine_setup.tasks tasks.wait:48
> Waiting for existing tasks to complete
> 2014-12-29 14:53:43 DEBUG
> otopi.plugins.ovirt_hosted_engine_setup.storage.storage storage._spmStop:602
> spmStop
> 2014-12-29 14:53:43 DEBUG
> otopi.plugins.ovirt_hosted_engine_setup.storage.storage storage._spmStop:611
> 2014-12-29 14:53:43 DEBUG
> otopi.plugins.ovirt_hosted_engine_setup.storage.storage
> storage._storagePoolConnection:573 disconnectStoragePool
> 2014-12-29 14:53:45 INFO
> otopi.plugins.ovirt_hosted_engine_setup.storage.storage
> storage._disconnect_pool:975 Start monitoring domain
> 2014-12-29 14:53:45 DEBUG
> otopi.plugins.ovirt_hosted_engine_setup.storage.storage
> storage._startMonitoringDomain:529 _startMonitoringDomain
> 2014-12-29 14:53:46 DEBUG
> otopi.plugins.ovirt_hosted_engine_setup.storage.storage
> storage._startMonitoringDomain:534 {'status': {'message': 'OK', 'code': 0}}
> 2014-12-29 14:53:51 DEBUG otopi.ovirt_hosted_engine_setup.tasks
> tasks.wait:127 Waiting for domain monitor
> 2014-12-29 14:54:51 DEBUG otopi.context context._executeMethod:152 method
> exception
> Traceback (most recent call last):
> File "/usr/lib/python2.6/site-packages/otopi/context.py", line 142, in
> _executeMethod
> method['method']()
> File
> "/usr/share/ovirt-hosted-engine-setup/scripts/../plugins/ovirt-hosted-engine-setup/storage/storage.py",
> line 976, in _disconnect_pool
> self._startMonitoringDomain()
> File
> "/usr/share/ovirt-hosted-engine-setup/scripts/../plugins/ovirt-hosted-engine-setup/storage/storage.py",
> line 539, in _startMonitoringDomain
> waiter.wait(self.environment[ohostedcons.StorageEnv.SD_UUID])
> File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_setup/tasks.py",
> line 128, in wait
> response = serv.s.getVdsStats()
> File "/usr/lib64/python2.6/xmlrpclib.py", line 1199, in __call__
> return self.__send(self.__name, args)
> File "/usr/lib64/python2.6/xmlrpclib.py", line 1489, in __request
> verbose=self.__verbose
> File "/usr/lib64/python2.6/xmlrpclib.py", line 1237, in request
> errcode, errmsg, headers = h.getreply()
> File "/usr/lib64/python2.6/httplib.py", line 1064, in getreply
> response = self._conn.getresponse()
> File "/usr/lib64/python2.6/httplib.py", line 990, in getresponse
> response.begin()
> File "/usr/lib64/python2.6/httplib.py", line 391, in begin
> version, status, reason = self._read_status()
> File "/usr/lib64/python2.6/httplib.py", line 349, in _read_status
> line = self.fp.readline()
> File "/usr/lib64/python2.6/socket.py", line 433, in readline
> data = recv(1)
> File "/usr/lib64/python2.6/ssl.py", line 215, in recv
> return self.read(buflen)
> File "/usr/lib64/python2.6/ssl.py", line 136, in read
> return self._sslobj.read(len)
> SSLError: The read operation timed out

We had several similar cases in the past [1] [2] but never managed
to reproduce on clean systems. Might it be some "dirt"? E.g. repeated
attempts using same storage, or storage used for something else,
some other host accessing it, host left unclean after previous
attempts to deploy (failed or successful), something like that?

If you reproduce on completely clean systems, both host(s) and storage,
please post more relevant logs, including:

>From host(s):
/var/log/vdsm/*
/var/log/ovirt-hosted-engine-setup/*
/var/log/ovirt-hosted-engine-ha/*
output of 'sanlock status'
output of 'rpm -qa'

>From engine vm:
/var/log/ovirt-engine/*

[1] https://bugzilla.redhat.com/show_bug.cgi?id=1152564
[2] https://bugzilla.redhat.com/show_bug.cgi?id=1099874

Thanks,
-- 
Didi