Re: [ovirt-devel] [HC] Weird issue while deploying hosted-engine

----- Original Message ----- > From: "Sandro Bonazzola" <sbonazzo(a)redhat.com&gt; > To: "Nir Soffer" <nsoffer(a)redhat.com&gt; > Cc: "Yeela Kaplan" <ykaplan(a)redhat.com&gt;, "Alon Bar-Lev" <alonbl(a)redhat.com&gt;, "Allon Mureinik" <amureini(a)redhat.com&gt;, > "Yaniv Dary" <ydary(a)redhat.com&gt;, "Federico Simoncelli" <fsimonce(a)redhat.com&gt;, "Sahina Bose" <sabose(a)redhat.com&gt;, > "Yedidyah Bar David" <didi(a)redhat.com&gt;, "Simone Tiraboschi" <stirabos(a)redhat.com&gt;, devel(a)ovirt.org, "Michal > Skrivanek" <mskrivan(a)redhat.com&gt;, "David Teigland" <teigland(a)redhat.com&gt; > Sent: Thursday, February 12, 2015 4:24:55 PM > Subject: Re: [ovirt-devel] [HC] Weird issue while deploying hosted-engine > > Il 12/02/2015 14:03, Nir Soffer ha scritto: >> ----- Original Message ----- >>> From: "Sandro Bonazzola" <sbonazzo(a)redhat.com&gt; >>> To: "Yeela Kaplan" <ykaplan(a)redhat.com&gt;, "Alon Bar-Lev" >>> <alonbl(a)redhat.com&gt;, "Allon Mureinik" <amureini(a)redhat.com&gt;, >>> "Yaniv Dary" <ydary(a)redhat.com&gt;, "Federico Simoncelli" >>> <fsimonce(a)redhat.com&gt;, "Sahina Bose" <sabose(a)redhat.com&gt;, >>> "Yedidyah Bar David" <didi(a)redhat.com&gt;, "Simone Tiraboschi" >>> <stirabos(a)redhat.com&gt;, devel(a)ovirt.org, "Michal >>> Skrivanek" <mskrivan(a)redhat.com&gt; >>> Sent: Thursday, February 12, 2015 2:55:57 PM >>> Subject: [ovirt-devel] [HC] Weird issue while deploying hosted-engine >>> >>> While deploying Hosted Engine on Hyper Converged Gluster Storage I've hit >>> the >>> following issue. >>> >>> ovirt-hosted-engine-setup: >>> >>> [ INFO ] Engine replied: DB Up!Welcome to Health Status! >>> Enter the name of the cluster to which you want to add the host >>> (Default) [Default]: >>> [ INFO ] Waiting for the host to become operational in the engine. This >>> may >>> take several minutes... >>> [ INFO ] Still waiting for VDSM host to become operational... >>> >>> Accessed to the engine, VM and engine working correctly, installed using >>> 3.5 >>> snapshot repositories. >>> host-deploy started on the host (see attached logs) and got stuck at: >>> >>> 2015-02-12 13:08:33 DEBUG otopi.plugins.otopi.dialog.machine >>> dialog.__logString:215 DIALOG:SEND ### Response is VALUE >>> TIME=type:value or ABORT TIME >>> >>> until several minutes later when: >>> 2015-02-12 13:24:31 DEBUG otopi.context context._executeMethod:152 method >>> exception >>> Traceback (most recent call last): >>> File "/tmp/ovirt-ePMfjwrlpe/pythonlib/otopi/context.py", line 142, in >>> _executeMethod >>> method['method']() >>> File "/tmp/ovirt-ePMfjwrlpe/otopi-plugins/otopi/system/clock.py", line >>> 111, >>> in _set_clock >>> format="YYYYmmddHHMMSS+0000" >>> File "/tmp/ovirt-ePMfjwrlpe/otopi-plugins/otopi/dialog/machine.py", line >>> 235, in queryValue >>> opcode, variable = self._readline().split(' ', 1) >>> File "/tmp/ovirt-ePMfjwrlpe/pythonlib/otopi/dialog.py", line 259, in >>> _readline >>> raise IOError(_('End of file')) >>> IOError: End of file >>> >>> resumed the process. >>> >>> Around the time when host-deploy got stucked I see in sanlock logs: >>> >>> 2015-02-12 13:08:25+0100 7254 [683]: open error -1 >>> /rhev/data-center/mnt/glusterSD/minidell.home:_hosted__engine__glusterfs/a7dba6e3-09ac-430a-8d6e-eea17cf18b8f/images/51156c24-5ea1-42df-bf33-daebf2c4780c/3719b0 >>> 06-68a2-4742-964c-413a3f77c0b4.lease >>> 2015-02-12 13:08:25+0100 7254 [683]: r4 release_token open error -2 >>> 2015-02-12 13:08:31+0100 7260 [16910]: a7dba6e3 aio collect 0 >>> 0x7f1d640008c0:0x7f1d640008d0:0x7f1d7ec52000 result -107:0 match res >>> 2015-02-12 13:08:31+0100 7260 [16910]: s3 delta_renew read rv -107 offset >>> 0 >>> /rhev/data-center/mnt/glusterSD/minidell.home:_hosted__engine__glusterfs/a7dba6e3-09ac-430a-8d6e-eea17cf18b8f/dom_md/ids >>> 2015-02-12 13:08:31+0100 7260 [16910]: s3 renewal error -107 delta_length >>> 0 >>> last_success 7239 >>> 2015-02-12 13:08:31+0100 7260 [16910]: a7dba6e3 aio collect 0 >>> 0x7f1d640008c0:0x7f1d640008d0:0x7f1d7ec52000 result -107:0 match res >>> 2015-02-12 13:08:31+0100 7260 [16910]: s3 delta_renew read rv -107 offset >>> 0 >>> /rhev/data-center/mnt/glusterSD/minidell.home:_hosted__engine__glusterfs/a7dba6e3-09ac-430a-8d6e-eea17cf18b8f/dom_md/ids >>> 2015-02-12 13:08:31+0100 7260 [16910]: s3 renewal error -107 delta_length >>> 0 >>> last_success 7239 >>> 2015-02-12 13:08:32+0100 7261 [16910]: a7dba6e3 aio collect 0 >>> 0x7f1d640008c0:0x7f1d640008d0:0x7f1d7ec52000 result -107:0 match res >>> 2015-02-12 13:08:32+0100 7261 [16910]: s3 delta_renew read rv -107 offset >>> 0 >>> /rhev/data-center/mnt/glusterSD/minidell.home:_hosted__engine__glusterfs/a7dba6e3-09ac-430a-8d6e-eea17cf18b8f/dom_md/ids >>> 2015-02-12 13:08:32+0100 7261 [16910]: s3 renewal error -107 delta_length >>> 0 >>> last_success 7239 >> >> Sanlock cannot access your storage. The rest of the errors are less >> interesting, >> as nothing will work without storage. >> >> While sanlock is failing, can you access that storage from another host or >> from the host running sanlock? >> >> Adding David for helping with debugging the sanlock errors. > > > If you mean something like: > # mount -t glusterfs minidell.home:/hosted_engine_glusterfs /tmp/test > # # ll /tmp/test/ > totale 4 > drwxr-xr-x. 6 vdsm kvm 4096 12 feb 11.49 a7dba6e3-09ac-430a-8d6e-eea17cf18b8f > -rwxr-xr-x. 1 vdsm kvm 0 12 feb 13.04 __DIRECT_IO_TEST__ > > yes, I can still access the gluster volume. While sanlock fail to update the lease or now? Try also to write to this storage.

> > # gluster volume info hosted_engine_glusterfs > > Volume Name: hosted_engine_glusterfs > Type: Distribute > Volume ID: 8d78571d-69ef-41fb-bc0a-34dc7d903df5 > Status: Started > Number of Bricks: 1 > Transport-type: tcp > Bricks: > Brick1: minidell.home:/path1 > Options Reconfigured: > nfs.disable: on > storage.owner-gid: 36 > storage.owner-uid: 36 > network.ping-timeout: 10 > auth.allow: * > cluster.server-quorum-type: server > cluster.quorum-type: auto > network.remote-dio: enable > cluster.eager-lock: enable > performance.stat-prefetch: off > performance.io-cache: off > performance.read-ahead: off > performance.quick-read: off > server.allow-insecure: on > user.cifs: disable > > # gluster volume status hosted_engine_glusterfs > Status of volume: hosted_engine_glusterfs > Gluster process Port Online Pid > ------------------------------------------------------------------------------ > Brick minidell.home:/path1 49217 Y 16660 > > Task Status of Volume hosted_engine_glusterfs > ------------------------------------------------------------------------------ > There are no active volume tasks > > > >> >>> >>> >>> And in VDSM logs: >>> >>> MainThread::DEBUG::2015-02-12 >>> 13:08:25,529::vdsm::58::vds::(sigtermHandler) >>> Received signal 15 >>> MainThread::DEBUG::2015-02-12 >>> 13:08:25,529::protocoldetector::144::vds.MultiProtocolAcceptor::(stop) >>> Stopping Acceptor >>> MainThread::INFO::2015-02-12 >>> 13:08:25,530::__init__::565::jsonrpc.JsonRpcServer::(stop) Stopping >>> JsonRPC >>> Server >>> Detector thread::DEBUG::2015-02-12 >>> 13:08:25,530::protocoldetector::115::vds.MultiProtocolAcceptor::(_cleanup) >>> Cleaning Acceptor >>> MainThread::INFO::2015-02-12 13:08:25,531::vmchannels::188::vds::(stop) VM >>> channels listener was stopped. >>> MainThread::INFO::2015-02-12 13:08:25,535::momIF::91::MOM::(stop) Shutting >>> down MOM >>> MainThread::DEBUG::2015-02-12 >>> 13:08:25,535::task::595::Storage.TaskManager.Task::(_updateState) >>> Task=`c52bd13a-24f0-4d8a-97d8-f6c53ca8bddc`::moving >>> from state init -> state preparing >>> MainThread::INFO::2015-02-12 >>> 13:08:25,535::logUtils::44::dispatcher::(wrapper) Run and protect: >>> prepareForShutdown(options=None) >>> Thread-11::DEBUG::2015-02-12 >>> 13:08:25,535::storageServer::706::Storage.ConnectionMonitor::(_monitorConnections) >>> Monitoring stopped >>> ioprocess communication (16795)::ERROR::2015-02-12 >>> 13:08:25,530::__init__::152::IOProcessClient::(_communicate) IOProcess >>> failure >>> Traceback (most recent call last): >>> File "/usr/lib/python2.7/site-packages/ioprocess/__init__.py", line 107, >>> in >>> _communicate >>> raise Exception("FD closed") >>> Exception: FD closed >>> ioprocess communication (16795)::DEBUG::2015-02-12 >>> 13:08:25,537::__init__::298::IOProcessClient::(_run) Starting IOProcess... >>> >>> >>> Followed by: >>> >>> MainThread::INFO::2015-02-12 >>> 13:08:25,548::domainMonitor::137::Storage.DomainMonitor::(close) Stopping >>> domain monitors >>> MainThread::INFO::2015-02-12 >>> 13:08:25,549::domainMonitor::114::Storage.DomainMonitor::(stopMonitoring) >>> Stop monitoring >>> a7dba6e3-09ac-430a-8d6e-eea17cf18b8f >>> Thread-94::DEBUG::2015-02-12 >>> 13:08:25,549::domainMonitor::192::Storage.DomainMonitorThread::(_monitorLoop) >>> Stopping domain monitor for >>> a7dba6e3-09ac-430a-8d6e-eea17cf18b8f >>> Thread-94::INFO::2015-02-12 >>> 13:08:25,549::clusterlock::245::Storage.SANLock::(releaseHostId) Releasing >>> host id for domain >>> a7dba6e3-09ac-430a-8d6e-eea17cf18b8f (id: 1) >>> Thread-94::DEBUG::2015-02-12 >>> 13:08:25,549::domainMonitor::201::Storage.DomainMonitorThread::(_monitorLoop) >>> Unable to release the host id 1 for domain >>> a7dba6e3-09ac-430a-8d6e-eea17cf18b8f >>> Traceback (most recent call last): >>> File "/usr/share/vdsm/storage/domainMonitor.py", line 198, in >>> _monitorLoop >>> self.domain.releaseHostId(self.hostId, unused=True) >>> File "/usr/share/vdsm/storage/sd.py", line 480, in releaseHostId >>> self._clusterLock.releaseHostId(hostId, async, unused) >>> File "/usr/share/vdsm/storage/clusterlock.py", line 252, in >>> releaseHostId >>> raise se.ReleaseHostIdFailure(self._sdUUID, e) >>> ReleaseHostIdFailure: Cannot release host id: >>> (u'a7dba6e3-09ac-430a-8d6e-eea17cf18b8f', SanlockException(16, 'Sanlock >>> lockspace remove failure', >>> 'Device or resource busy')) >>> >>> supervdsm logs doesn't show anything interesting but: >>> >>> # service supervdsmd status >>> Redirecting to /bin/systemctl status supervdsmd.service >>> supervdsmd.service - "Auxiliary vdsm service for running helper functions >>> as >>> root" >>> Loaded: loaded (/usr/lib/systemd/system/supervdsmd.service; static) >>> Active: inactive (dead) since gio 2015-02-12 13:08:30 CET; 27min ago >>> Main PID: 15859 (code=exited, status=0/SUCCESS) >>> CGroup: /system.slice/supervdsmd.service >>> >>> feb 12 13:08:30 minidell.home systemd[1]: Stopping "Auxiliary vdsm service >>> for running helper functions as root"... >>> feb 12 13:08:30 minidell.home daemonAdapter[15859]: Traceback (most recent >>> call last): >>> feb 12 13:08:30 minidell.home daemonAdapter[15859]: File >>> "/usr/lib64/python2.7/multiprocessing/util.py", line 268, in >>> _run_finalizers >>> feb 12 13:08:30 minidell.home daemonAdapter[15859]: finalizer() >>> feb 12 13:08:30 minidell.home daemonAdapter[15859]: File >>> "/usr/lib64/python2.7/multiprocessing/util.py", line 201, in __call__ >>> feb 12 13:08:30 minidell.home daemonAdapter[15859]: res = >>> self._callback(*self._args, **self._kwargs) >>> feb 12 13:08:30 minidell.home daemonAdapter[15859]: OSError: [Errno 2] No >>> such file or directory: '/var/run/vdsm/svdsm.sock' >>> feb 12 13:08:30 minidell.home python[15859]: DIGEST-MD5 client mech >>> dispose >>> feb 12 13:08:30 minidell.home python[15859]: DIGEST-MD5 common mech >>> dispose >>> feb 12 13:08:30 minidell.home systemd[1]: Stopped "Auxiliary vdsm service >>> for >>> running helper functions as root". >>> >>> >>> >>> After a while the VM became unreachable as ovirt-hosted-engine-setup >>> shows: >>> >>> 2015-02-12 13:10:33 DEBUG >>> otopi.plugins.ovirt_hosted_engine_setup.engine.add_host >>> add_host._wait_host_ready:183 Error fetching host state: >>> [ERROR]::oVirt API connection failure, [Errno 110] Connection timed out >>> 2015-02-12 13:10:33 DEBUG >>> otopi.plugins.ovirt_hosted_engine_setup.engine.add_host >>> add_host._wait_host_ready:189 VDSM host in state >>> >>> >>> Gluster logs don't show anything special. >>> >>> I'm guessing that the 15 minutes of host-deploy being stuck caused the >>> issue >>> here, but I don't see any relevant change that may have caused it. >>> >>> Attaching the tar.gz with the code used for ovirt-hosted-engine-setup; the >>> rest is 3.5-snapshot over RHEL 7.1 >>> >>> Any hint is welcome. >>> >>> -- >>> Sandro Bonazzola >>> Better technology. Faster innovation. Powered by community collaboration. >>> See how it works at redhat.com >>> >>> _______________________________________________ >>> Devel mailing list >>> Devel(a)ovirt.org >>> http://lists.ovirt.org/mailman/listinfo/devel > > > -- > Sandro Bonazzola > Better technology. Faster innovation. Powered by community collaboration. > See how it works at redhat.com >