Il 12/02/2015 14:03, Nir Soffer ha scritto:
----- Original Message -----
From: "Sandro Bonazzola" <sbonazzo@redhat.com> To: "Yeela Kaplan" <ykaplan@redhat.com>, "Alon Bar-Lev" <alonbl@redhat.com>, "Allon Mureinik" <amureini@redhat.com>, "Yaniv Dary" <ydary@redhat.com>, "Federico Simoncelli" <fsimonce@redhat.com>, "Sahina Bose" <sabose@redhat.com>, "Yedidyah Bar David" <didi@redhat.com>, "Simone Tiraboschi" <stirabos@redhat.com>, devel@ovirt.org, "Michal Skrivanek" <mskrivan@redhat.com> 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. # 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@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