Aled Sage created BROOKLYN-347:
----------------------------------
Summary: ssh gives " Execution failed, invalid result -1" (though
command on VM succeeded)
Key: BROOKLYN-347
URL: https://issues.apache.org/jira/browse/BROOKLYN-347
Project: Brooklyn
Issue Type: Bug
Reporter: Aled Sage
When deploying an app to an OpenStack environment (behind a slow VPN), one of
the VanillaSoftwareProcess entities failed to execute the "customize" command
with the error shown below.
TL;DR the logging of stdout shows the actual command gave exit code {{0}}. The
{{-1}} implies it is an exception in the {{SshjTool}} (or sshj library), but
nothing logged to give us a clue about it.
{noformat}
Failed after 10.29s
STDOUT
Executed
/tmp/brooklyn-20160914-102321520-StEE-customizing_VanillaSoftwarePro.sh, result
0: Execution failed, invalid result -1 for customizing
VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
java.lang.IllegalStateException: Execution failed, invalid result -1 for
customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper.logWithDetailsAndThrow(ScriptHelper.java:388)
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper.executeInternal(ScriptHelper.java:377)
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper$8.call(ScriptHelper.java:287)
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper$8.call(ScriptHelper.java:285)
at
org.apache.brooklyn.util.core.task.DynamicSequentialTask$DstJob.call(DynamicSequentialTask.java:359)
at
org.apache.brooklyn.util.core.task.BasicExecutionManager$SubmissionCallable.call(BasicExecutionManager.java:519)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
{noformat}
The full exception subsequently logged is:
{noformat}
2016-09-14 10:23:31,812 WARN o.a.b.c.m.i.EffectorUtils
[brooklyn-execmanager-lUyvzrEP-282]: Error invoking start at
VanillaSoftwareProcessImpl{id=tk2yqo7f7y}: Execution failed, invalid result -1
for customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
2016-09-14 10:23:31,818 DEBUG o.a.b.c.m.i.EffectorUtils
[brooklyn-execmanager-lUyvzrEP-282]: Error invoking start at
VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
org.apache.brooklyn.util.exceptions.PropagatedRuntimeException:
at
org.apache.brooklyn.util.exceptions.Exceptions.propagate(Exceptions.java:129)
~[brooklyn-utils-common-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicTask.getUnchecked(BasicTask.java:372)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.DynamicSequentialTask.drain(DynamicSequentialTask.java:492)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.DynamicTasks.drain(DynamicTasks.java:314)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.DynamicTasks.waitForLast(DynamicTasks.java:303)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks.start(MachineLifecycleEffectorTasks.java:357)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks$StartEffectorBody.call(MachineLifecycleEffectorTasks.java:257)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.lifecycle.MachineLifecycleEffectorTasks$StartEffectorBody.call(MachineLifecycleEffectorTasks.java:244)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.core.effector.EffectorTasks$EffectorBodyTaskFactory$1.call(EffectorTasks.java:82)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.DynamicSequentialTask$DstJob.call(DynamicSequentialTask.java:359)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicExecutionManager$SubmissionCallable.call(BasicExecutionManager.java:519)
[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[na:1.7.0_71]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_71]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_71]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_71]
Caused by: java.util.concurrent.ExecutionException:
org.apache.brooklyn.util.exceptions.PropagatedRuntimeException: Execution
failed, invalid result -1 for customizing
VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
[na:1.7.0_71]
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
[na:1.7.0_71]
at
com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
~[guava-16.0.1.jar:na]
at org.apache.brooklyn.util.core.task.BasicTask.get(BasicTask.java:361)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicTask.getUnchecked(BasicTask.java:370)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
... 13 common frames omitted
Caused by: org.apache.brooklyn.util.exceptions.PropagatedRuntimeException:
at
org.apache.brooklyn.util.exceptions.Exceptions.propagate(Exceptions.java:129)
~[brooklyn-utils-common-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicTask.getUnchecked(BasicTask.java:372)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.DynamicSequentialTask.drain(DynamicSequentialTask.java:492)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.DynamicTasks.drain(DynamicTasks.java:314)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.DynamicTasks.waitForLast(DynamicTasks.java:303)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.DynamicSequentialTask$DstJob.call(DynamicSequentialTask.java:400)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
... 5 common frames omitted
Caused by: java.util.concurrent.ExecutionException:
org.apache.brooklyn.util.exceptions.PropagatedRuntimeException: Execution
failed, invalid result -1 for customizing
VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
[na:1.7.0_71]
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
[na:1.7.0_71]
at
com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
~[guava-16.0.1.jar:na]
at org.apache.brooklyn.util.core.task.BasicTask.get(BasicTask.java:361)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicTask.getUnchecked(BasicTask.java:370)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
... 9 common frames omitted
Caused by: org.apache.brooklyn.util.exceptions.PropagatedRuntimeException:
at
org.apache.brooklyn.util.exceptions.Exceptions.propagate(Exceptions.java:129)
~[brooklyn-utils-common-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicTask.getUnchecked(BasicTask.java:372)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
... 9 common frames omitted
Caused by: java.util.concurrent.ExecutionException:
org.apache.brooklyn.util.exceptions.PropagatedRuntimeException: Execution
failed, invalid result -1 for customizing
VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
[na:1.7.0_71]
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
[na:1.7.0_71]
at
com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
~[guava-16.0.1.jar:na]
at org.apache.brooklyn.util.core.task.BasicTask.get(BasicTask.java:361)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicTask.getUnchecked(BasicTask.java:370)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
... 9 common frames omitted
Caused by: org.apache.brooklyn.util.exceptions.PropagatedRuntimeException:
at
org.apache.brooklyn.util.exceptions.Exceptions.propagate(Exceptions.java:129)
~[brooklyn-utils-common-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicTask.getUnchecked(BasicTask.java:372)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper.execute(ScriptHelper.java:337)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.VanillaSoftwareProcessSshDriver.customize(VanillaSoftwareProcessSshDriver.java:128)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.AbstractSoftwareProcessDriver$3$2.run(AbstractSoftwareProcessDriver.java:175)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
~[na:1.7.0_71]
at
org.apache.brooklyn.util.core.task.DynamicSequentialTask$DstJob.call(DynamicSequentialTask.java:359)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
... 5 common frames omitted
Caused by: java.util.concurrent.ExecutionException:
java.lang.IllegalStateException: Execution failed, invalid result -1 for
customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
[na:1.7.0_71]
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
[na:1.7.0_71]
at
com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
~[guava-16.0.1.jar:na]
at org.apache.brooklyn.util.core.task.BasicTask.get(BasicTask.java:361)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.util.core.task.BasicTask.getUnchecked(BasicTask.java:370)
~[brooklyn-core-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
... 10 common frames omitted
Caused by: java.lang.IllegalStateException: Execution failed, invalid result -1
for customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper.logWithDetailsAndThrow(ScriptHelper.java:388)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper.executeInternal(ScriptHelper.java:377)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper$8.call(ScriptHelper.java:287)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
at
org.apache.brooklyn.entity.software.base.lifecycle.ScriptHelper$8.call(ScriptHelper.java:285)
~[brooklyn-software-base-0.10.0-20160908.1322.jar:0.10.0-20160908.1322]
... 6 common frames omitted
{noformat}
The debug logs contained the following:
{noformat}
2016-09-14 10:23:21,520 DEBUG brooklyn.SSH [brooklyn-execmanager-lUyvzrEP-234]:
customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y}, initiating ssh on
machine
SshMachineLocation[10.104.0.115:[email protected]/10.104.0.115:22(id=o3fvyriymw)]:
#!/bin/bash -e
; export
INSTALL_DIR="/home/users/amp/brooklyn-managed-processes/installs/VanillaSoftwareProcess_0.0.0_PUZrn"
; export
RUN_DIR="/home/users/amp/brooklyn-managed-processes/apps/c5f14ojgpk/entities/VanillaSoftwareProcess_tk2yqo7f7y"
; mkdir -p $RUN_DIR ; cd $RUN_DIR ; cd . ; cp
/home/users/amp/brooklyn-managed-processes/installs/VanillaSoftwareProcess_0.0.0_PUZrn/metering-microservice-1.1.jar
.
2016-09-14 10:23:31,809 DEBUG brooklyn.SSH [brooklyn-execmanager-lUyvzrEP-234]:
customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y}, on machine
SshMachineLocation[10.104.0.115:[email protected]/10.104.0.115:22(id=o3fvyriymw)],
completed: return status -1
2016-09-14 10:23:31,810 WARN o.a.b.e.s.b.l.ScriptHelper
[brooklyn-execmanager-lUyvzrEP-234]: Execution failed, invalid result -1 for
customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y} (throwing)
2016-09-14 10:23:31,810 INFO o.a.b.e.s.b.l.ScriptHelper
[brooklyn-execmanager-lUyvzrEP-234]: STDOUT of problem in Task[ssh: customizing
VanillaSoftwareProcessImpl{id=tk2yqo7f7y}]@n5FcZqp2:
Executed
/tmp/brooklyn-20160914-102321520-StEE-customizing_VanillaSoftwarePro.sh, result 0
2016-09-14 10:23:31,810 INFO o.a.b.e.s.b.l.ScriptHelper
[brooklyn-execmanager-lUyvzrEP-234]: STDIN of problem in Task[ssh: customizing
VanillaSoftwareProcessImpl{id=tk2yqo7f7y}]@n5FcZqp2:
export
INSTALL_DIR="/home/users/amp/brooklyn-managed-processes/installs/VanillaSoftwareProcess_0.0.0_PUZrn"
export
RUN_DIR="/home/users/amp/brooklyn-managed-processes/apps/c5f14ojgpk/entities/VanillaSoftwareProcess_tk2yqo7f7y"
mkdir -p $RUN_DIR
cd $RUN_DIR
cd .
cp
/home/users/amp/brooklyn-managed-processes/installs/VanillaSoftwareProcess_0.0.0_PUZrn/metering-microservice-1.1.jar
.
2016-09-14 10:23:31,810 DEBUG o.a.b.u.c.t.BasicExecutionManager
[brooklyn-execmanager-lUyvzrEP-234]: Exception running task Task[ssh:
customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y}]@n5FcZqp2 (rethrowing):
java.lang.IllegalStateException: Execution failed, invalid result -1 for
customizing VanillaSoftwareProcessImpl{id=tk2yqo7f7y}
{noformat}
The previous commands (e.g. install etc) had executed successfully.
Grep'ing for sshj logs from around that time ({{grep -E "n\.s\.s|sshj"}}, I see
the exception below a few times (from a different thread), but I believe that
is unrelated because we successfully finished executing the install command at
{{2016-09-14 10:23:21,516}}:
{noformat}
2016-09-14 10:14:31,867 ERROR n.s.s.transport.TransportImpl [reader]: Dying
because - net.schmizz.sshj.transport.TransportException: Broken transport;
encountered EOF
2016-09-14 10:23:02,856 ERROR n.s.s.transport.TransportImpl [reader]: Dying
because - java.net.SocketTimeoutException: Read timed out
2016-09-14 10:24:33,859 ERROR n.s.s.transport.TransportImpl [reader]: Dying
because - java.net.SocketTimeoutException: Read timed out
2016-09-14 10:25:56,151 ERROR n.s.s.transport.TransportImpl [reader]: Dying
because - java.net.SocketTimeoutException: Read timed out
{noformat}
The {{result -1}} suggests that SshjTool.execScript returned {{-1}}. I presume
{{SshjTool.ShellAction.create()}} returned null, which implies
{{net.schmizz.sshj.connection.channel.direct.ShellChannel.exitStatus}} was null.
Prior to returning, we checked {{shell.isOpen() &&
((SessionChannel)session).getExitStatus()==null}} (and would have log.debug if
that was true), so presumably the shell was closed and exit status was null.
I'm surprised we can get into that state without further logging of exceptions
in {{net.schmizz.sshj}} (or propagated and logged in {{SshjTool}}.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
