Hi, What version of ovirt-engine do you use?
When connection is terminated the sshd on host should kill the process group, very strange that a process is keep running on non existence pipe. What happen if you retry host-deploy? does the issue happens with specific host ar all hosts? Thanks, Alon ----- Original Message ----- > From: "Christopher Pereira" <[email protected]> > To: [email protected] > 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 > [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 _______________________________________________ Devel mailing list [email protected] http://lists.ovirt.org/mailman/listinfo/devel
