jcliff sometimes doesn't wait for WildFly long enough
Closed this issue · 2 comments
Ucidbuild commented
Sometimes (about once out of four tries), jcliff doesn't wait for WildFly long enough after reloading it.
This is the verbose jcliff log:
...
2015-10-27 13:46:48:0398: cmds:/subsystem=datasources/data-source=PasseportWriteDS:write-attribute(name=blocking-timeout-wait-millis,value="1000")
2015-10-27 13:46:48:0398: cmds:/subsystem=datasources/data-source=PasseportWriteDS:write-attribute(name=idle-timeout-minutes,value="5")
2015-10-27 13:46:48:0398: cmds:/subsystem=datasources/data-source=PasseportWriteDS:write-attribute(name=query-timeout,value="0")
2015-10-27 13:46:48:0398: cmds:/subsystem=datasources/data-source=PasseportWriteDS:write-attribute(name=set-tx-query-timeout,value="false")
2015-10-27 13:46:48:0398: cmds:/subsystem=datasources/data-source=PasseportWriteDS:write-attribute(name=share-prepared-statements,value="false")
2015-10-27 13:46:48:0398: cmds:/subsystem=datasources/data-source=PasseportWriteDS:write-attribute(name=use-try-lock,value="0")
2015-10-27 13:46:48:0398: cmds:/subsystem=datasources/data-source=PasseportWriteDS:write-attribute(name=validate-on-match,value="true")
2015-10-27 13:46:48:0398: cmds:run-batch
2015-10-27 13:46:48:0398: Script file:/tmp/jcliff-script2373698895087090811.tmp true
2015-10-27 13:46:48:0398: In file:/tmp/jcliff-in2076208699409391012.tmp true
2015-10-27 13:46:49:0564: return Code has :0
2015-10-27 13:46:49:0568: stderr:
2015-10-27 13:46:49:0568: stdout:The batch executed successfully
process-state: reload-required
2015-10-27 13:46:49:0568: Return:The batch executed successfully
process-state: reload-required
2015-10-27 13:46:49:0569: in file:/tmp/jcliff-in2216300268130915430.tmp true
2015-10-27 13:46:49:0569: out file:/tmp/jcliff-out2224194031294791864.tmp true
2015-10-27 13:46:49:0569: err file:/tmp/jcliff-err3305043549566407063.tmp true
2015-10-27 13:46:49:0569: script file:/tmp/jcliff-script6048437213908135456.tmp true
2015-10-27 13:46:49:0569: args:/opt/wildfly/bin/jboss-cli.sh
2015-10-27 13:46:49:0569: args:--controller=127.0.0.1:9990
2015-10-27 13:46:49:0569: args:--connect
2015-10-27 13:46:49:0569: args:--file=/tmp/jcliff-in2216300268130915430.tmp
2015-10-27 13:46:49:0569: args:--user=admin-myhostname
2015-10-27 13:46:49:0569: args:--password=*****
2015-10-27 13:46:49:0569: args:--timeout=5000
2015-10-27 13:46:49:0569: cmds:ls
2015-10-27 13:46:49:0569: Script file:/tmp/jcliff-script6048437213908135456.tmp true
2015-10-27 13:46:49:0569: In file:/tmp/jcliff-in2216300268130915430.tmp true
2015-10-27 13:46:50:0679: return Code has :0
2015-10-27 13:46:50:0679: stderr:
2015-10-27 13:46:50:0679: stdout:core-service
deployment
deployment-overlay
extension
interface
path
socket-binding-group
subsystem
system-property
launch-type=STANDALONE
management-major-version=2
management-micro-version=0
management-minor-version=2
name=myhostname
namespaces=[]
process-type=Server
product-name=undefined
product-version=undefined
profile-name=undefined
release-codename=Tweek
release-version=8.2.0.Final
running-mode=NORMAL
schema-locations=[]
server-state=reload-required
2015-10-27 13:46:50:0679: Return:core-service
deployment
deployment-overlay
extension
interface
path
socket-binding-group
subsystem
system-property
launch-type=STANDALONE
management-major-version=2
management-micro-version=0
management-minor-version=2
name=myhostname
namespaces=[]
process-type=Server
product-name=undefined
product-version=undefined
profile-name=undefined
release-codename=Tweek
release-version=8.2.0.Final
running-mode=NORMAL
schema-locations=[]
server-state=reload-required
2015-10-27 13:46:50:0680: in file:/tmp/jcliff-in2920145061752891963.tmp true
2015-10-27 13:46:50:0680: out file:/tmp/jcliff-out3146731002401624511.tmp true
2015-10-27 13:46:50:0680: err file:/tmp/jcliff-err2672618051574195629.tmp true
2015-10-27 13:46:50:0680: script file:/tmp/jcliff-script2630814811893108199.tmp true
2015-10-27 13:46:50:0680: args:/opt/wildfly/bin/jboss-cli.sh
2015-10-27 13:46:50:0680: args:--controller=127.0.0.1:9990
2015-10-27 13:46:50:0680: args:--connect
2015-10-27 13:46:50:0680: args:--file=/tmp/jcliff-in2920145061752891963.tmp
2015-10-27 13:46:50:0680: args:--user=admin-myhostname
2015-10-27 13:46:50:0680: args:--password=*****
2015-10-27 13:46:50:0680: args:--timeout=5000
2015-10-27 13:46:50:0680: cmds::reload
2015-10-27 13:46:50:0680: Script file:/tmp/jcliff-script2630814811893108199.tmp true
2015-10-27 13:46:50:0680: In file:/tmp/jcliff-in2920145061752891963.tmp true
2015-10-27 13:46:51:0922: return Code has :0
2015-10-27 13:46:51:0922: stderr:
2015-10-27 13:46:51:0922: stdout:{
"outcome" => "success",
"result" => undefined
}
2015-10-27 13:46:51:0922: Return:{
"outcome" => "success",
"result" => undefined
}
2015-10-27 13:46:51:0923: in file:/tmp/jcliff-in3244564751908510918.tmp true
2015-10-27 13:46:51:0923: out file:/tmp/jcliff-out7030680984186590786.tmp true
2015-10-27 13:46:51:0923: err file:/tmp/jcliff-err9033155621287357853.tmp true
2015-10-27 13:46:51:0923: script file:/tmp/jcliff-script5147996763721763743.tmp true
2015-10-27 13:46:51:0923: args:/opt/wildfly/bin/jboss-cli.sh
2015-10-27 13:46:51:0923: args:--controller=127.0.0.1:9990
2015-10-27 13:46:51:0923: args:--connect
2015-10-27 13:46:51:0923: args:--file=/tmp/jcliff-in3244564751908510918.tmp
2015-10-27 13:46:51:0923: args:--user=admin-myhostname
2015-10-27 13:46:51:0923: args:--password=*****
2015-10-27 13:46:51:0923: args:--timeout=5000
2015-10-27 13:46:51:0923: cmds:ls
2015-10-27 13:46:51:0923: Script file:/tmp/jcliff-script5147996763721763743.tmp true
2015-10-27 13:46:51:0923: In file:/tmp/jcliff-in3244564751908510918.tmp true
2015-10-27 13:46:54:0254: return Code has :0
2015-10-27 13:46:54:0255: stderr:
2015-10-27 13:46:54:0255: stdout:core-service
deployment
deployment-overlay
extension
interface
path
socket-binding-group
subsystem
system-property
launch-type=STANDALONE
management-major-version=2
management-micro-version=0
management-minor-version=2
name=myhostname
namespaces=[]
process-type=Server
product-name=undefined
product-version=undefined
profile-name=undefined
release-codename=Tweek
release-version=8.2.0.Final
running-mode=NORMAL
schema-locations=[]
server-state=starting
2015-10-27 13:46:54:0255: Return:core-service
deployment
deployment-overlay
extension
interface
path
socket-binding-group
subsystem
system-property
launch-type=STANDALONE
management-major-version=2
management-micro-version=0
management-minor-version=2
name=myhostname
namespaces=[]
process-type=Server
product-name=undefined
product-version=undefined
profile-name=undefined
release-codename=Tweek
release-version=8.2.0.Final
running-mode=NORMAL
schema-locations=[]
server-state=starting
2015-10-27 13:46:54:0256: in file:/tmp/jcliff-in8261434089074670813.tmp true
2015-10-27 13:46:54:0256: out file:/tmp/jcliff-out2921501971237476451.tmp true
2015-10-27 13:46:54:0256: err file:/tmp/jcliff-err1345454118171290641.tmp true
2015-10-27 13:46:54:0256: script file:/tmp/jcliff-script5533378880105915110.tmp true
2015-10-27 13:46:54:0256: args:/opt/wildfly/bin/jboss-cli.sh
2015-10-27 13:46:54:0256: args:--controller=127.0.0.1:9990
2015-10-27 13:46:54:0256: args:--connect
2015-10-27 13:46:54:0256: args:--file=/tmp/jcliff-in8261434089074670813.tmp
2015-10-27 13:46:54:0256: args:--user=admin-myhostname
2015-10-27 13:46:54:0256: args:--password=*****
2015-10-27 13:46:54:0256: args:--timeout=5000
2015-10-27 13:46:54:0256: cmds:ls
2015-10-27 13:46:54:0256: Script file:/tmp/jcliff-script5533378880105915110.tmp true
2015-10-27 13:46:54:0256: In file:/tmp/jcliff-in8261434089074670813.tmp true
2015-10-27 13:47:06:0785: return Code has :1
2015-10-27 13:47:06:0793: stderr:org.jboss.as.cli.CliInitializationException: Failed to connect to the controller
at org.jboss.as.cli.impl.CliLauncher.initCommandContext(CliLauncher.java:278)
at org.jboss.as.cli.impl.CliLauncher.main(CliLauncher.java:235)
at org.jboss.as.cli.CommandLineMain.main(CommandLineMain.java:34)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.jboss.modules.Module.run(Module.java:312)
at org.jboss.modules.Main.main(Main.java:460)
Caused by: org.jboss.as.cli.CommandLineException: The controller is not available at 127.0.0.1:9990
at org.jboss.as.cli.impl.CommandContextImpl.tryConnection(CommandContextImpl.java:1028)
at org.jboss.as.cli.impl.CommandContextImpl.connectController(CommandContextImpl.java:840)
at org.jboss.as.cli.impl.CommandContextImpl.connectController(CommandContextImpl.java:819)
at org.jboss.as.cli.impl.CliLauncher.initCommandContext(CliLauncher.java:276)
... 8 more
Caused by: java.io.IOException: java.net.ConnectException: JBAS012144: Could not connect to http-remoting://127.0.0.1:9990. The connection timed out
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeForResult(AbstractModelControllerClient.java:129)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.execute(AbstractModelControllerClient.java:71)
at org.jboss.as.cli.impl.CommandContextImpl.tryConnection(CommandContextImpl.java:1005)
... 11 more
Caused by: java.net.ConnectException: JBAS012144: Could not connect to http-remoting://127.0.0.1:9990. The connection timed out
at org.jboss.as.protocol.ProtocolConnectionUtils.connectSync(ProtocolConnectionUtils.java:119)
at org.jboss.as.protocol.ProtocolConnectionManager$EstablishingConnection.connect(ProtocolConnectionManager.java:256)
at org.jboss.as.protocol.ProtocolConnectionManager.connect(ProtocolConnectionManager.java:70)
at org.jboss.as.protocol.mgmt.FutureManagementChannel$Establishing.getChannel(FutureManagementChannel.java:204)
at org.jboss.as.cli.impl.CLIModelControllerClient.getOrCreateChannel(CLIModelControllerClient.java:169)
at org.jboss.as.cli.impl.CLIModelControllerClient$2.getChannel(CLIModelControllerClient.java:129)
at org.jboss.as.protocol.mgmt.ManagementChannelHandler.executeRequest(ManagementChannelHandler.java:117)
at org.jboss.as.protocol.mgmt.ManagementChannelHandler.executeRequest(ManagementChannelHandler.java:92)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeRequest(AbstractModelControllerClient.java:236)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.execute(AbstractModelControllerClient.java:141)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeForResult(AbstractModelControllerClient.java:127)
... 13 more
2015-10-27 13:47:06:0793: stdout:
2015-10-27 13:47:06:0813: java.lang.RuntimeException: java.lang.RuntimeException: org.jboss.as.cli.CliInitializationException: Failed to connect to the controller
at org.jboss.as.cli.impl.CliLauncher.initCommandContext(CliLauncher.java:278)
at org.jboss.as.cli.impl.CliLauncher.main(CliLauncher.java:235)
at org.jboss.as.cli.CommandLineMain.main(CommandLineMain.java:34)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.jboss.modules.Module.run(Module.java:312)
at org.jboss.modules.Main.main(Main.java:460)
Caused by: org.jboss.as.cli.CommandLineException: The controller is not available at 127.0.0.1:9990
at org.jboss.as.cli.impl.CommandContextImpl.tryConnection(CommandContextImpl.java:1028)
at org.jboss.as.cli.impl.CommandContextImpl.connectController(CommandContextImpl.java:840)
at org.jboss.as.cli.impl.CommandContextImpl.connectController(CommandContextImpl.java:819)
at org.jboss.as.cli.impl.CliLauncher.initCommandContext(CliLauncher.java:276)
... 8 more
Caused by: java.io.IOException: java.net.ConnectException: JBAS012144: Could not connect to http-remoting://127.0.0.1:9990. The connection timed out
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeForResult(AbstractModelControllerClient.java:129)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.execute(AbstractModelControllerClient.java:71)
at org.jboss.as.cli.impl.CommandContextImpl.tryConnection(CommandContextImpl.java:1005)
... 11 more
Caused by: java.net.ConnectException: JBAS012144: Could not connect to http-remoting://127.0.0.1:9990. The connection timed out
at org.jboss.as.protocol.ProtocolConnectionUtils.connectSync(ProtocolConnectionUtils.java:119)
at org.jboss.as.protocol.ProtocolConnectionManager$EstablishingConnection.connect(ProtocolConnectionManager.java:256)
at org.jboss.as.protocol.ProtocolConnectionManager.connect(ProtocolConnectionManager.java:70)
at org.jboss.as.protocol.mgmt.FutureManagementChannel$Establishing.getChannel(FutureManagementChannel.java:204)
at org.jboss.as.cli.impl.CLIModelControllerClient.getOrCreateChannel(CLIModelControllerClient.java:169)
at org.jboss.as.cli.impl.CLIModelControllerClient$2.getChannel(CLIModelControllerClient.java:129)
at org.jboss.as.protocol.mgmt.ManagementChannelHandler.executeRequest(ManagementChannelHandler.java:117)
at org.jboss.as.protocol.mgmt.ManagementChannelHandler.executeRequest(ManagementChannelHandler.java:92)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeRequest(AbstractModelControllerClient.java:236)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.execute(AbstractModelControllerClient.java:141)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeForResult(AbstractModelControllerClient.java:127)
... 13 more
at com.redhat.jcliff.Cli.run(Cli.java:193)
at com.redhat.jcliff.Cli.run(Cli.java:105)
at com.redhat.jcliff.Cli.run(Cli.java:60)
at com.redhat.jcliff.Main.reloadRequired(Main.java:322)
at com.redhat.jcliff.Main.main(Main.java:254)
Caused by: java.lang.RuntimeException: org.jboss.as.cli.CliInitializationException: Failed to connect to the controller
at org.jboss.as.cli.impl.CliLauncher.initCommandContext(CliLauncher.java:278)
at org.jboss.as.cli.impl.CliLauncher.main(CliLauncher.java:235)
at org.jboss.as.cli.CommandLineMain.main(CommandLineMain.java:34)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.jboss.modules.Module.run(Module.java:312)
at org.jboss.modules.Main.main(Main.java:460)
Caused by: org.jboss.as.cli.CommandLineException: The controller is not available at 127.0.0.1:9990
at org.jboss.as.cli.impl.CommandContextImpl.tryConnection(CommandContextImpl.java:1028)
at org.jboss.as.cli.impl.CommandContextImpl.connectController(CommandContextImpl.java:840)
at org.jboss.as.cli.impl.CommandContextImpl.connectController(CommandContextImpl.java:819)
at org.jboss.as.cli.impl.CliLauncher.initCommandContext(CliLauncher.java:276)
... 8 more
Caused by: java.io.IOException: java.net.ConnectException: JBAS012144: Could not connect to http-remoting://127.0.0.1:9990. The connection timed out
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeForResult(AbstractModelControllerClient.java:129)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.execute(AbstractModelControllerClient.java:71)
at org.jboss.as.cli.impl.CommandContextImpl.tryConnection(CommandContextImpl.java:1005)
... 11 more
Caused by: java.net.ConnectException: JBAS012144: Could not connect to http-remoting://127.0.0.1:9990. The connection timed out
at org.jboss.as.protocol.ProtocolConnectionUtils.connectSync(ProtocolConnectionUtils.java:119)
at org.jboss.as.protocol.ProtocolConnectionManager$EstablishingConnection.connect(ProtocolConnectionManager.java:256)
at org.jboss.as.protocol.ProtocolConnectionManager.connect(ProtocolConnectionManager.java:70)
at org.jboss.as.protocol.mgmt.FutureManagementChannel$Establishing.getChannel(FutureManagementChannel.java:204)
at org.jboss.as.cli.impl.CLIModelControllerClient.getOrCreateChannel(CLIModelControllerClient.java:169)
at org.jboss.as.cli.impl.CLIModelControllerClient$2.getChannel(CLIModelControllerClient.java:129)
at org.jboss.as.protocol.mgmt.ManagementChannelHandler.executeRequest(ManagementChannelHandler.java:117)
at org.jboss.as.protocol.mgmt.ManagementChannelHandler.executeRequest(ManagementChannelHandler.java:92)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeRequest(AbstractModelControllerClient.java:236)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.execute(AbstractModelControllerClient.java:141)
at org.jboss.as.controller.client.impl.AbstractModelControllerClient.executeForResult(AbstractModelControllerClient.java:127)
... 13 more
at com.redhat.jcliff.Cli.run(Cli.java:184)
... 4 more
==> /var/log/messages <==
Oct 27 13:47:07 myhostname puppet-agent[2545]: (/Stage[main]/Wildfly::Jcliff::Execution/Exec[wildfly-jcliff-execution]) Failed to call refresh: /usr/bin/jcliff --cli=/opt/wildfly/bin/jboss-cli.sh -v -- controller=127.0.0.1:9990 --output=/var/log/jcliff/jcliff.log --reload --user=admin-myhostname --password=***** /etc/jcliff/* returned 1 instead of one of [0]
Oct 27 13:47:07 myhostname puppet-agent[2545]: (/Stage[main]/Wildfly::Jcliff::Execution/Exec[wildfly-jcliff-execution]) /usr/bin/jcliff --cli=/opt/wildfly/bin/jboss-cli.sh -v --controller=127.0.0.1:9990 -- output=/var/log/jcliff/jcliff.log --reload --user=admin-myhostname --password=***** /etc/jcliff/* returned 1 instead of one of [0]
Oct 27 13:47:07 myhostname puppet-agent[2545]: Finished catalog run in 59.95 seconds
WildFly was back available at 2015-10-27 13:47:11,424:
INFO [org.jboss.as] (Controller Boot Thread) JBAS015874: WildFly 8.2.0.Final "Tweek" started in 18730ms - Started 491 of 676 services (273 services are lazy, passive or on-demand)
Summary:
2015-10-27 13:46:50:0680: cmds::reload
2015-10-27 13:47:06:0793: stderr:org.jboss.as.cli.CliInitializationException: Failed to connect to the controller
2015-10-27 13:47:11,424 WildFly is available again
Shouldn't jcliff wait at least 5 seconds (args:--timeout=5000)?
bserdar commented
--timeout option is passed to jboss-cli, and based on this log and the description, I think it doesn't affect the first connection timeout.
I'll add a sleep after :reload.
bserdar commented
There was already a 20sec delay, apparently that's not enough. Added a new command line flag:
--reconnect-delay=delayMsecs
Pass a larger millisecond delay value to make this work.