[ovirt-devel] Hosted-engine installation failed because of time-out (low prio)

Wed May 6 05:46:11 UTC 2015

----- Original Message -----
> From: "Christopher Pereira" <kripper at imatronix.cl>
> To: devel at ovirt.org
> Sent: Wednesday, May 6, 2015 6:41:45 AM
> Subject: [ovirt-devel] Hosted-engine installation failed because of time-out	(low prio)
> 
> Hi,
> 
> Today a hosted-engine setup timed out during the host installation process.
> We were able to activate the host anyway, so I'm just providing this info in
> case it helps or saves time to anyone.
> 
> It looks like the engine was not piping the right input to the otopi deploy
> process.
> 
> Engine logs:
> 
> 
> 2015-05-05 22:47:13,769 INFO
> [org.ovirt.engine.core.bll.hostdeploy.InstallerMessages] (VdsDeploy)
> [a64986b] Installation 'h5.imatronix.com': Enrolling certificate
> 2015-05-05 22:47:13,875 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [a64986b] Correlation ID: a64986b, Call Stack: null, Custom
> Event ID: -1, Message: Installing Host H5. Enrolling certificate.
> 2015-05-05 22:47:15,222 INFO
> [org.ovirt.engine.core.bll.hostdeploy.InstallerMessages] (VdsDeploy)
> [a64986b] Installation 'h5.imatronix.com': Stage: Transaction commit
> 2015-05-05 22:47:15,317 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [a64986b] Correlation ID: a64986b, Call Stack: null, Custom
> Event ID: -1, Message: Installing Host H5. Stage: Transaction commit.
> 2015-05-05 22:47:15,317 INFO
> [org.ovirt.engine.core.bll.hostdeploy.InstallerMessages] (VdsDeploy)
> [a64986b] Installation 'h5.imatronix.com': Stage: Closing up
> 2015-05-05 22:47:15,433 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [a64986b] Correlation ID: a64986b, Call Stack: null, Custom
> Event ID: -1, Message: Installing Host H5. Stage: Closing up.
> 2015-05-05 22:50:34,791 ERROR
> [org.ovirt.engine.core.utils.servlet.ServletUtils] (ajp--127.0.0.1-8702-3)
> [] Can't read file '/usr/share/ovirt-engine/files/spice/SpiceVersion.txt'
> for request '/ovirt-engine/services/files/spice/SpiceVersion.txt', will send
> a 404 error response.
> 2015-05-05 22:50:34,794 INFO
> [org.ovirt.engine.docs.utils.servlet.ContextSensitiveHelpMappingServlet]
> (ajp--127.0.0.1-8702-7) [] Context-sensitive help is not installed. Manual
> directory doesn't exist: /usr/share/ovirt-engine/manual
> 2015-05-05 22:50:39,608 INFO
> [org.ovirt.engine.core.bll.aaa.LoginAdminUserCommand]
> (ajp--127.0.0.1-8702-9) [] Running command: LoginAdminUserCommand internal:
> false.
> 2015-05-05 22:50:39,675 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (ajp--127.0.0.1-8702-9) [] Correlation ID: null, Call Stack: null, Custom
> Event ID: -1, Message: User admin at internal logged in.
> 
> 
> 2015-05-05 22:56:59,097 ERROR
> [org.ovirt.engine.core.bll.hostdeploy.VdsDeploy] (VdsDeploy) [a64986b] Error
> during deploy dialog: java.io.IOException: Unexpected connection termination
> at
> org.ovirt.otopi.dialog.MachineDialogParser.nextEvent(MachineDialogParser.java:388)
> [otopi.jar:]
> at
> org.ovirt.otopi.dialog.MachineDialogParser.nextEvent(MachineDialogParser.java:405)
> [otopi.jar:]
> at
> org.ovirt.engine.core.bll.hostdeploy.VdsDeploy._threadMain(VdsDeploy.java:841)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.hostdeploy.VdsDeploy.access$2000(VdsDeploy.java:88)
> [bll.jar:]
> at org.ovirt.engine.core.bll.hostdeploy.VdsDeploy$52.run(VdsDeploy.java:989)
> [bll.jar:]
> at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_79]
> 
> 2015-05-05 22:56:59,098 ERROR [org.ovirt.engine.core.uutils.ssh.SSHDialog]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] SSH error running command
> root at h5.imatronix.com :'umask 0077; MYTMP="$(TMPDIR="${OVIRT_TMPDIR}" mktemp
> -d -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null
> 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; tar --warning=no-timestamp -C
> "${MYTMP}" -x && "${MYTMP}"/setup DIALOG/dialect=str:machine
> DIALOG/customization=bool:True': SSH session timeout host '
> root at h5.imatronix.com '
> 2015-05-05 22:56:59,099 ERROR [org.ovirt.engine.core.uutils.ssh.SSHDialog]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] Exception:
> javax.naming.TimeLimitExceededException: SSH session timeout host '
> root at h5.imatronix.com '
> at
> org.ovirt.engine.core.uutils.ssh.SSHClient.executeCommand(SSHClient.java:499)
> [uutils.jar:]
> at
> org.ovirt.engine.core.uutils.ssh.SSHDialog.executeCommand(SSHDialog.java:312)
> [uutils.jar:]
> at
> org.ovirt.engine.core.bll.hostdeploy.VdsDeploy.execute(VdsDeploy.java:1138)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand.installHost(InstallVdsInternalCommand.java:168)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand.executeCommand(InstallVdsInternalCommand.java:94)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1183)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1327)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1931)
> [bll.jar:]
> at
> org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:174)
> [utils.jar:]
> at
> org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:116)
> [utils.jar:]
> at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1351)
> [bll.jar:]
> at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:346)
> [bll.jar:]
> at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:455) [bll.jar:]
> at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:437)
> [bll.jar:]
> at org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:647)
> [bll.jar:]
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> [rt.jar:1.7.0_79]
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> [rt.jar:1.7.0_79]
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> [rt.jar:1.7.0_79]
> at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_79]
> at
> org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:114)
> [jboss-as-weld-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:125)
> [jboss-as-weld-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:135)
> [jboss-as-weld-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:82)
> [jboss-as-weld-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:211)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:363)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:194)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
> org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
> org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view7.runInternalAction(Unknown
> Source) [bll.jar:]
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> [rt.jar:1.7.0_79]
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> [rt.jar:1.7.0_79]
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> [rt.jar:1.7.0_79]
> at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_79]
> at
> org.jboss.weld.util.reflection.SecureReflections$13.work(SecureReflections.java:264)
> [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
> at
> org.jboss.weld.util.reflection.SecureReflectionAccess.run(SecureReflectionAccess.java:52)
> [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
> at
> org.jboss.weld.util.reflection.SecureReflectionAccess.runAsInvocation(SecureReflectionAccess.java:137)
> [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
> at
> org.jboss.weld.util.reflection.SecureReflections.invoke(SecureReflections.java:260)
> [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
> at
> org.jboss.weld.bean.proxy.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:111)
> [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
> at
> org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56)
> [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
> at
> org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:105)
> [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
> at
> org.ovirt.engine.core.bll.BackendCommandObjectsHandler$BackendInternal$BackendLocal$1808883726$Proxy$_$$_Weld$Proxy$.runInternalAction(BackendCommandObjectsHandler$BackendInternal$BackendLocal$1808883726$Proxy$_$$_Weld$Proxy$.java)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.CommandBase.runInternalAction(CommandBase.java:2264)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.hostdeploy.AddVdsCommand.access$800(AddVdsCommand.java:67)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.hostdeploy.AddVdsCommand$3.run(AddVdsCommand.java:203)
> [bll.jar:]
> at
> org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:92)
> [utils.jar:]
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> [rt.jar:1.7.0_79]
> at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_79]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> [rt.jar:1.7.0_79]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> [rt.jar:1.7.0_79]
> at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_79]
> 
> 2015-05-05 22:56:59,114 ERROR
> [org.ovirt.engine.core.bll.hostdeploy.VdsDeploy]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] Timeout during host
> h5.imatronix.com install
> 2015-05-05 22:56:59,114 ERROR
> [org.ovirt.engine.core.bll.hostdeploy.InstallerMessages]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] Installation
> 'h5.imatronix.com': Processing stopped due to timeout
> 2015-05-05 22:56:59,171 ERROR
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] Correlation ID: a64986b, Call
> Stack: null, Custom Event ID: -1, Message: Failed to install Host H5.
> Processing stopped due to timeout.
> 2015-05-05 22:56:59,175 ERROR
> [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] Host installation failed for
> host '2eee855b-599a-486c-9ab3-99fa03d2f9ab', 'H5': SSH session timeout host
> ' root at h5.imatronix.com '
> 2015-05-05 22:56:59,180 INFO
> [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] START,
> SetVdsStatusVDSCommand(HostName = H5,
> SetVdsStatusVDSCommandParameters:{runAsync='true',
> hostId='2eee855b-599a-486c-9ab3-99fa03d2f9ab', status='InstallFailed',
> nonOperationalReason='NONE', stopSpmFailureLogged='false',
> maintenanceReason='null'}), log id: 5cf95514
> 2015-05-05 22:56:59,246 INFO
> [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] FINISH,
> SetVdsStatusVDSCommand, log id: 5cf95514
> 2015-05-05 22:56:59,321 ERROR
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] Correlation ID: a64986b, Job
> ID: 54880a3a-1424-4231-94fc-654922ca3436, Call Stack: null, Custom Event ID:
> -1, Message: Host H5 installation failed. SSH session timeout host '
> root at h5.imatronix.com '.
> 2015-05-05 22:56:59,388 INFO
> [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand]
> (org.ovirt.thread.pool-12-thread-3) [a64986b] Lock freed to object
> 'EngineLock:{exclusiveLocks='[2eee855b-599a-486c-9ab3-99fa03d2f9ab=<VDS,
> ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}'
> === On the Host ===
> 
> After SSH timed out, this process was still running:
> 
> /bin/python -B -m otopi.__main__
> "BASE/pluginPath=str:/tmp/ovirt-D4qxGz4W1I/otopi-plugins"
> APPEND:BASE/pluginGroups=str:ovirt-host-deploy DIALOG/dialect=str:machine
> DIALOG/customization=bool:True
> 
> It was waiting for FD 7...
> 
> strace -p 23736
> Process 23736 attached
> read(7,
> 
> This FD belongs to this pipe:
> 7 -> pipe:[535838]
> 
> Which is reading input from the SSH connection initiated by engine:
> sshd 23728 root 9w FIFO 0,8 0t0 535838 pipe
> bash 23730 root 0r FIFO 0,8 0t0 535838 pipe
> python 23736 root 4r FIFO 0,8 0t0 535838 pipe
> python 23736 root 7r FIFO 0,8 0t0 535838 pipe
> 
> It looks like engine is not piping the right input to this process so it
> keeps reading.
> 
> During the engine-setup process, it updated to last version, so it could be
> just a protocol version mismatch.
> 
> Please let me know if you want me to continue reporting issues like this one.

We do!

> I prefer not to fill a BZ report since I guess that this kind of things are
> generally detected and fixed by the developers without the need of feedback
> or tracking.

Most probably, but not always.

> But because reproducing this kind of things may be time expensive, I guess
> this reports could be useful.

Indeed.

Which OS is on engine machine?

Adding Alon.

It might be an apache-ssh issue, not sure.

Best,
-- 
Didi