<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=utf-8">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hi,<br>
<br>
Today a hosted-engine setup timed out during the host installation
process.<br>
We were able to activate the host anyway, so I'm just providing this
info in case it helps or saves time to anyone.<br>
<br>
It looks like the engine was not piping the right input to the otopi
deploy process.<br>
<br>
Engine logs:<br>
<blockquote>2015-05-05 22:47:13,769 INFO
[org.ovirt.engine.core.bll.hostdeploy.InstallerMessages]
(VdsDeploy) [a64986b] Installation 'h5.imatronix.com': Enrolling
certificate<br>
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.<br>
2015-05-05 22:47:15,222 INFO
[org.ovirt.engine.core.bll.hostdeploy.InstallerMessages]
(VdsDeploy) [a64986b] Installation 'h5.imatronix.com': Stage:
Transaction commit<br>
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.<br>
2015-05-05 22:47:15,317 INFO
[org.ovirt.engine.core.bll.hostdeploy.InstallerMessages]
(VdsDeploy) [a64986b] Installation 'h5.imatronix.com': Stage:
Closing up<br>
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.<br>
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.<br>
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<br>
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.<br>
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@internal logged in.<br>
</blockquote>
<blockquote>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<br>
at
org.ovirt.otopi.dialog.MachineDialogParser.nextEvent(MachineDialogParser.java:388)
[otopi.jar:]<br>
at
org.ovirt.otopi.dialog.MachineDialogParser.nextEvent(MachineDialogParser.java:405)
[otopi.jar:]<br>
at
org.ovirt.engine.core.bll.hostdeploy.VdsDeploy._threadMain(VdsDeploy.java:841)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.hostdeploy.VdsDeploy.access$2000(VdsDeploy.java:88)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.hostdeploy.VdsDeploy$52.run(VdsDeploy.java:989)
[bll.jar:]<br>
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_79]<br>
<br>
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 <a class="moz-txt-link-abbreviated" href="mailto:root@h5.imatronix.com">root@h5.imatronix.com</a>:'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
'<a class="moz-txt-link-abbreviated" href="mailto:root@h5.imatronix.com">root@h5.imatronix.com</a>'<br>
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
'<a class="moz-txt-link-abbreviated" href="mailto:root@h5.imatronix.com">root@h5.imatronix.com</a>'<br>
at
org.ovirt.engine.core.uutils.ssh.SSHClient.executeCommand(SSHClient.java:499)
[uutils.jar:]<br>
at
org.ovirt.engine.core.uutils.ssh.SSHDialog.executeCommand(SSHDialog.java:312)
[uutils.jar:]<br>
at
org.ovirt.engine.core.bll.hostdeploy.VdsDeploy.execute(VdsDeploy.java:1138)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand.installHost(InstallVdsInternalCommand.java:168)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand.executeCommand(InstallVdsInternalCommand.java:94)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1183)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1327)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1931)
[bll.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:174)
[utils.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:116)
[utils.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1351)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:346)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.Backend.runAction(Backend.java:455)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:437)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:647)
[bll.jar:]<br>
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method) [rt.jar:1.7.0_79]<br>
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[rt.jar:1.7.0_79]<br>
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.7.0_79]<br>
at java.lang.reflect.Method.invoke(Method.java:606)
[rt.jar:1.7.0_79]<br>
at
org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72)
[jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:114)
[jboss-as-weld-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:125)
[jboss-as-weld-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:135)
[jboss-as-weld-7.1.1.Final.jar:7.1.1.Final]<br>
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]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
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]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:82)
[jboss-as-weld-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
[jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53)
[jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:211)
[jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:363)
[jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:194)
[jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
[jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
[jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
[jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
[jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)
[jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173)
[jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
[jboss-invocation-1.1.1.Final.jar:1.1.1.Final]<br>
at
org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72)
[jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]<br>
at
org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view7.runInternalAction(Unknown
Source) [bll.jar:]<br>
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method) [rt.jar:1.7.0_79]<br>
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[rt.jar:1.7.0_79]<br>
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.7.0_79]<br>
at java.lang.reflect.Method.invoke(Method.java:606)
[rt.jar:1.7.0_79]<br>
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]<br>
at
org.jboss.weld.util.reflection.SecureReflectionAccess.run(SecureReflectionAccess.java:52)
[weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]<br>
at
org.jboss.weld.util.reflection.SecureReflectionAccess.runAsInvocation(SecureReflectionAccess.java:137)
[weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]<br>
at
org.jboss.weld.util.reflection.SecureReflections.invoke(SecureReflections.java:260)
[weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]<br>
at
org.jboss.weld.bean.proxy.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:111)
[weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]<br>
at
org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56)
[weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]<br>
at
org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:105)
[weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]<br>
at
org.ovirt.engine.core.bll.BackendCommandObjectsHandler$BackendInternal$BackendLocal$1808883726$Proxy$_$$_Weld$Proxy$.runInternalAction(BackendCommandObjectsHandler$BackendInternal$BackendLocal$1808883726$Proxy$_$$_Weld$Proxy$.java)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.runInternalAction(CommandBase.java:2264)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.hostdeploy.AddVdsCommand.access$800(AddVdsCommand.java:67)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.hostdeploy.AddVdsCommand$3.run(AddVdsCommand.java:203)
[bll.jar:]<br>
at
org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:92)
[utils.jar:]<br>
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[rt.jar:1.7.0_79]<br>
at
java.util.concurrent.FutureTask.run(FutureTask.java:262)
[rt.jar:1.7.0_79]<br>
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[rt.jar:1.7.0_79]<br>
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[rt.jar:1.7.0_79]<br>
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_79]<br>
<br>
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<br>
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<br>
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.<br>
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 '<a class="moz-txt-link-abbreviated" href="mailto:root@h5.imatronix.com">root@h5.imatronix.com</a>'<br>
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<br>
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<br>
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 '<a class="moz-txt-link-abbreviated" href="mailto:root@h5.imatronix.com">root@h5.imatronix.com</a>'.<br>
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'}'<br>
</blockquote>
=== On the Host ===<br>
<br>
After SSH timed out, this process was still running:<br>
<br>
/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<br>
<br>
It was waiting for FD 7...<br>
<br>
strace -p 23736<br>
Process 23736 attached<br>
read(7,<br>
<br>
This FD belongs to this pipe:<br>
7 -> pipe:[535838]<br>
<br>
Which is reading input from the SSH connection initiated by engine:<br>
sshd 23728 root 9w FIFO
0,8 0t0 535838 pipe<br>
bash 23730 root 0r FIFO
0,8 0t0 535838 pipe<br>
python 23736 root 4r FIFO
0,8 0t0 535838 pipe<br>
python 23736 root 7r FIFO
0,8 0t0 535838 pipe<br>
<br>
It looks like engine is not piping the right input to this process
so it keeps reading.<br>
<br>
During the engine-setup process, it updated to last version, so it
could be just a protocol version mismatch.<br>
<br>
Please let me know if you want me to continue reporting issues like
this one.<br>
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.<br>
But because reproducing this kind of things may be time expensive, I
guess this reports could be useful.<br>
<br>
Best regards,<br>
Christopher.<br>
</body>
</html>