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

From: "Christopher Pereira" <kripper(a)imatronix.cl&gt; To: devel(a)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@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(a)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(a)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(a)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(a)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(a)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.

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.