10:41 p.m.
This is a multi-part message in MIME format.
--------------020900070407030402010704
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
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@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.
Best regards,
Christopher.
--------------020900070407030402010704
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 8bit
<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>
--------------020900070407030402010704--
12:46 a.m.
New subject: Hosted-engine installation failed because of time-out (low prio)
----- Original Message -----
From: "Christopher Pereira" <kripper(a)imatronix.cl>
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.
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
1:39 a.m.
On 06-05-2015 2:46, Yedidyah Bar David wrote:
----- Original Message -----
> From: "Christopher Pereira" <kripper(a)imatronix.cl>
> 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 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.
Which OS is on engine machine? Adding Alon. It might be an apache-ssh
issue, not sure. Best,
Hi Yedi,
Host is CentOS Linux release 7.1.1503 (Core).
I was using VDSM build from Gerrit today.
Anyway, I just installed a second host and didn't have any issues.
1:39 a.m.
New subject: Hosted-engine installation failed because of time-out (low prio)
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" <kripper(a)imatronix.cl>
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.
Best regards,
Christopher.
_______________________________________________
Devel mailing list
Devel(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel
1:49 a.m.
On 06-05-2015 3:39, Alon Bar-Lev wrote:
Hi,
What version of ovirt-engine do you use?
Latest night build.
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.
This was Gerrit
patched with [1], which avoids glusterfs running and
dying inside VDSM's cgroup.
[1] https://gerrit.ovirt.org/#/c/40240/
What happen if you retry host-deploy? does the issue happens with
specific host ar all hosts?
Yes, multiple times.
I finally tried "Activate" and the host works fine.
I didn't have problems installing and activating a second host (after
adding the required repo).
BTW, shouldn't the repo be added by the installation process?
2:01 a.m.
----- Original Message -----
From: "Christopher Pereira" <kripper(a)imatronix.cl>
To: "Alon Bar-Lev" <alonbl(a)redhat.com>
Cc: devel(a)ovirt.org
Sent: Wednesday, May 6, 2015 9:49:43 AM
Subject: Re: [ovirt-devel] Hosted-engine installation failed because of time-out (low
prio)
On 06-05-2015 3:39, Alon Bar-Lev wrote:
> Hi,
>
> What version of ovirt-engine do you use?
Latest night build.
>
> 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.
This was Gerrit patched with [1], which avoids glusterfs running and
dying inside VDSM's cgroup.
[1] https://gerrit.ovirt.org/#/c/40240/
this is a different issue, the python process should die when connection is terminated.
> What happen if you retry host-deploy? does the issue happens
with specific
> host ar all hosts?
Yes, multiple times.
I finally tried "Activate" and the host works fine.
I didn't have problems installing and activating a second host (after
adding the required repo).
and a third? I would like to know if this is specific to single host, as the last report
of these kind of failures were long ago.
BTW, shouldn't the repo be added by the installation process?
No, it is sysadmin task to configure the right repo, we cannot guess where it is within
enterprise.
3276
days inactive
3276
days old
5 comments
3 participants
participants (3)
-
Alon Bar-Lev -
Christopher Pereira -
Yedidyah Bar David