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@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 [email protected]:'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
'[email protected]'
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
'[email protected]'
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 '[email protected]'
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 '[email protected]'.
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.
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.
But because reproducing this kind of things may be time expensive, I
guess this reports could be useful.
Best regards,
Christopher.
_______________________________________________
Devel mailing list
[email protected]
http://lists.ovirt.org/mailman/listinfo/devel
