Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

jcliff sometimes doesn't wait for WildFly long enough #59

Closed
Ucidbuild opened this issue Oct 27, 2015 · 2 comments
Closed

jcliff sometimes doesn't wait for WildFly long enough #59

Ucidbuild opened this issue Oct 27, 2015 · 2 comments

Comments

@Ucidbuild
Copy link

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
Copy link
Owner

bserdar commented Oct 27, 2015

--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
Copy link
Owner

bserdar commented Oct 27, 2015

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.

@bserdar bserdar closed this as completed Oct 27, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bserdar @Ucidbuild