Automatic redeploy failed

[marcodanti]

I just ran into the following problem in a two nodes cluster:

• on node stw-2, open a deployed .war under standalone/deployments to change a parameter into a web.xml file
• save changed file
• on the server.log file, see this

    15:37:00,982 INFO  [org.jboss.web] (ServerService Thread Pool -- 98) JBAS018224: Unregister web context: /STW

    15:37:00,985 INFO  [org.jboss.modcluster] (ServerService Thread Pool -- 98) MODCLUSTER000021: All pending requests drained from default-host:/STW in 0.0 seconds

This is not normal, because the AS server did not go on and redeploy the updated .war. The same operations repeated on the other node (stw-1) trigger the following log:

    15:40:43,793 INFO  [org.jboss.web] (ServerService Thread Pool -- 101) JBAS018224: Unregister web context: /STW

    15:40:43,796 INFO  [org.jboss.modcluster] (ServerService Thread Pool -- 101) MODCLUSTER000021: All pending requests drained from default-host:/STW in 0.0 seconds

    15:40:44,005 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-1) JBAS015877: Stopped deployment STW.war (runtime-name: STW.war) in 215ms

    15:40:44,006 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-4) JBAS015876: Starting deployment of "STW.war" (runtime-name: "STW.war")

    15:40:47,647 INFO  [org.jboss.web] (ServerService Thread Pool -- 108) JBAS018210: Register web context: /STW

    15:40:49,362 INFO  [org.jboss.as.server] (DeploymentScanner-threads - 1) JBAS018565: Replaced deployment "STW.war" with deployment "STW.war"

which is what was expected. The first node however remained like that. In the mod_cluster-manager page, I see

mod_cluster/1.2.6.Final

start of "httpd.conf" configuration

mod_proxy_cluster.c: OK

mod_sharedmem.c: OK

Protocol supported: http AJP https

mod_advertise.c: OK

Server: stw-1.priv.softeco.it

Server: stweb-cesi1.risorse.enel VirtualHost: *:80

Server: stweb-cesi1.risorse.enel VirtualHost: *:443

Server: stw-1.priv.softeco.it VirtualHost: *:6666 Advertising on Group 224.0.1.105 Port 23364 for http://stw-1.priv.softeco.it:6666 every 10 seconds

end of "httpd.conf" configuration

Auto Refresh show DUMP output show INFO output

Node stw-2 (ajp://172.16.0.134:7009):

Enable Contexts Disable Contexts

Balancer: mycluster,LBGroup: ,Flushpackets: Off,Flushwait: 10000,Ping: 10000000,Smax: 26,Ttl: 60000000,Status: OK,Elected: 3820,Read: 105090729,Transferred: 350369,Connected: 0,Load: 96

Virtual Host 1:

Contexts:

/enel-stweb-war, Status: ENABLED Request: 0 Disable

/STCruscotto, Status: ENABLED Request: 0 Disable

/STWebWS, Status: ENABLED Request: 0 Disable

/clusterbench, Status: ENABLED Request: 0 Disable

/STWebAdmin, Status: ENABLED Request: 0 Disable

/PDL, Status: ENABLED Request: 0 Disable

/STMan, Status: ENABLED Request: 0 Disable

/clusterbench-granular, Status: ENABLED Request: 0 Disable

/SchematicaWeb, Status: ENABLED Request: 0 Disable

/STW, Status: STOPPED Request: 0

/PRE_2008, Status: ENABLED Request: 0 Disable

/Clientx, Status: ENABLED Request: 0 Disable

/PRE, Status: ENABLED Request: 0 Disable

/tses, Status: ENABLED Request: 0 Disable

/STWebRegistry-WS, Status: ENABLED Request: 0 Disable

/MAGO, Status: ENABLED Request: 0 Disable

/Aui, Status: ENABLED Request: 0 Disable

/stgeo-war, Status: ENABLED Request: 0 Disable

Aliases:

localhost

stw-2

default-host

Node stw-1 (ajp://172.16.0.133:7009):

Enable Contexts Disable Contexts

Balancer: mycluster,LBGroup: ,Flushpackets: Off,Flushwait: 10000,Ping: 10000000,Smax: 26,Ttl: 60000000,Status: OK,Elected: 7104,Read: 174704448,Transferred: 718980,Connected: 0,Load: 95

Virtual Host 1:

Contexts:

/stgeo-war, Status: ENABLED Request: 0 Disable

/STWebRegistry-WS, Status: ENABLED Request: 0 Disable

/MAGO, Status: ENABLED Request: 0 Disable

/STCruscotto, Status: ENABLED Request: 0 Disable

/PRE, Status: ENABLED Request: 0 Disable

/Clientx, Status: ENABLED Request: 0 Disable

/SchematicaWeb, Status: ENABLED Request: 0 Disable

/clusterbench, Status: ENABLED Request: 0 Disable

/tses, Status: ENABLED Request: 0 Disable

/PDL, Status: ENABLED Request: 0 Disable

/PRE_2008, Status: ENABLED Request: 0 Disable

/STW, Status: ENABLED Request: 0 Disable

/STWebWS, Status: ENABLED Request: 0 Disable

/clusterbench-granular, Status: ENABLED Request: 0 Disable

/STMan, Status: ENABLED Request: 0 Disable

/STWebAdmin, Status: ENABLED Request: 0 Disable

/Aui, Status: ENABLED Request: 0 Disable

/enel-stweb-war, Status: ENABLED Request: 0 Disable

Aliases:

localhost

stw-1

default-host

The setup I am using is: two AS-7.2.0.Final nodes in cluster, behind a httpd-2.4.6 reverse proxy with mod_cluster-1.2.6.Final (on both AS7 and httpd), all running on SLES-11.

I had to restart the node that failed to redeploy

[marcodanti]

Update: I retried this several times; normally it works fine, but once in a while it fails. This time, I did not restart the server and after exactly 10 minutes the log showed the following error:

16:27:00,969 ERROR [org.jboss.as.controller.management-operation] (DeploymentScanner-threads - 2) JBAS014612: Operation ("full-replace-deployment") failed - address: ([]): java.util.concurrent.CancellationException: JBAS014770: Service install was cancelled

    at org.jboss.as.controller.OperationContextImpl$ContextServiceBuilder.install(OperationContextImpl.java:976) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.server.deployment.PathContentServitor.addService(PathContentServitor.java:53) [jboss-as-server-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.server.deployment.DeploymentHandlerUtil.doDeploy(DeploymentHandlerUtil.java:161) [jboss-as-server-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.server.deployment.DeploymentHandlerUtil$4.execute(DeploymentHandlerUtil.java:270) [jboss-as-server-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:440) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.AbstractOperationContext.doCompleteStep(AbstractOperationContext.java:322) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.AbstractOperationContext.completeStepInternal(AbstractOperationContext.java:229) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:224) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.ModelControllerImpl.internalExecute(ModelControllerImpl.java:142) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.ModelControllerImpl.execute(ModelControllerImpl.java:112) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.ModelControllerImpl$2$1.run(ModelControllerImpl.java:399) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_21]

    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.7.0_21]

    at java.util.concurrent.FutureTask.run(FutureTask.java:166) [rt.jar:1.7.0_21]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) [rt.jar:1.7.0_21]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) [rt.jar:1.7.0_21]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_21]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_21]

    at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_21]

    at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.1.0.Final.jar:2.1.0.Final]

16:27:00,974 WARN  [org.jboss.as.controller.management-operation] (DeploymentScanner-threads - 2) JBAS014626: Operation was interrupted before stability could be reached

[rhusar]

So if I understand correctly, the hot-redeployment sometimes fails to redeploy successfully? (you can test to access the app directly, not via reverse proxy)

Or just mod_cluster fails to register the context?

So restart (or reload) fixed the problem?

[marcodanti]

Ops, I forgot to specify in the original post that when I 'restarted' the server that failed to redeploy, that was not a normal restart. I had to hard kill the jboss process (kill -9) because it seemed to be hanged somewhere.

[rhusar]

Could you please replicate the situation and get a thread dump of the java process and attach it here? (jstack)

[rhusar]

Also... can you try to undeploy completely first and then do a deploy? (therefore there will be no "Replaced deployment" log message)

[marcodanti]

OK I got two stack traces: the first was done right after the server locked up after saying "All pernding requests drained...". The I let it alone for 10 minutes, after which it outputs the "Operation ("full-replace-deployment") failed" exception and after that I catched the second trace.

[marcodanti]

And here is the server.log content, to complete the picture, with some comments of mine:

   Trigger auto-redeploy by touching a .war

10:14:01,784 INFO  [org.jboss.web] (ServerService Thread Pool -- 109) JBAS018224: Unregister web context: /STW

10:14:01,787 INFO  [org.jboss.modcluster] (ServerService Thread Pool -- 109) MODCLUSTER000021: All pending requests drained from default-host:/STW in 0.0 seconds

   Redeployment does not take place; at this point the server is stuck somewhere.

   Any attempt to a normal shutdown fails).

   Do first jstack -F here

   After 10 minutes it prints:

10:24:01,772 ERROR [org.jboss.as.controller.management-operation] (DeploymentScanner-threads - 1) JBAS014612: Operation ("full-replace-deployment") failed - address: ([]): java.util.concurrent.CancellationException: JBAS014770: Service install was cancelled

    at org.jboss.as.controller.OperationContextImpl$ContextServiceBuilder.install(OperationContextImpl.java:976) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.server.deployment.PathContentServitor.addService(PathContentServitor.java:53) [jboss-as-server-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.server.deployment.DeploymentHandlerUtil.doDeploy(DeploymentHandlerUtil.java:161) [jboss-as-server-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.server.deployment.DeploymentHandlerUtil$4.execute(DeploymentHandlerUtil.java:270) [jboss-as-server-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:440) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.AbstractOperationContext.doCompleteStep(AbstractOperationContext.java:322) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.AbstractOperationContext.completeStepInternal(AbstractOperationContext.java:229) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:224) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.ModelControllerImpl.internalExecute(ModelControllerImpl.java:142) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.ModelControllerImpl.execute(ModelControllerImpl.java:112) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at org.jboss.as.controller.ModelControllerImpl$2$1.run(ModelControllerImpl.java:399) [jboss-as-controller-7.2.0.Final.jar:7.2.0.Final]

    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_21]

    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.7.0_21]

    at java.util.concurrent.FutureTask.run(FutureTask.java:166) [rt.jar:1.7.0_21]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) [rt.jar:1.7.0_21]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) [rt.jar:1.7.0_21]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_21]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_21]

    at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_21]

    at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.1.0.Final.jar:2.1.0.Final]

10:24:01,777 WARN  [org.jboss.as.controller.management-operation] (DeploymentScanner-threads - 1) JBAS014626: Operation was interrupted before stability could be reached

  Do second jstack (with -Fl) here

   After more minutes, the following happens:

10:28:27,506 WARN  [org.jgroups.protocols.FD] (OOB-10,shared=udp) I was suspected by stw-1/stweb; ignoring the SUSPECT message and sending back a HEARTBEAT_ACK

10:28:27,515 WARN  [org.jgroups.protocols.pbcast.GMS] (Incoming-14,shared=udp) stw-2/ejb: not member of view [stw-1/ejb|2]; discarding it

10:28:27,516 WARN  [org.jgroups.protocols.pbcast.GMS] (Incoming-14,shared=udp) stw-2/web: not member of view [stw-1/web|2]; discarding it

10:28:27,517 WARN  [org.jgroups.protocols.pbcast.GMS] (Incoming-14,shared=udp) stw-2/stweb: not member of view [stw-1/stweb|2]; discarding it

10:28:27,509 WARN  [org.jgroups.protocols.FD] (OOB-11,shared=udp) I was suspected by stw-1/web; ignoring the SUSPECT message and sending back a HEARTBEAT_ACK

10:28:27,509 WARN  [org.jgroups.protocols.FD] (OOB-13,shared=udp) I was suspected by stw-1/ejb; ignoring the SUSPECT message and sending back a HEARTBEAT_ACK

10:28:27,563 ERROR [org.jboss.modcluster] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) MODCLUSTER000042: Error MEM sending STATUS command to stw-1.priv.softeco.it/172.16.0.133:6666, configuration will be reset: MEM: Can't read node

10:30:20,143 INFO  [org.jboss.as.clustering] (Incoming-17,shared=udp) JBAS010226: New cluster view for partition ejb: 3 (org.jboss.as.clustering.impl.CoreGroupCommunicationService$GroupView@7b0a6b delta: 0, merge: true)

10:30:20,144 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-17,shared=udp) ISPN000093: Received new, MERGED cluster view: MergeView::[stw-1/ejb|3] [stw-1/ejb, stw-2/ejb], subgroups=[stw-2/ejb|1] [stw-2/ejb], [stw-1/ejb|2] [stw-1/ejb]

10:30:22,018 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,shared=udp) ISPN000093: Received new, MERGED cluster view: MergeView::[stw-1/stweb|3] [stw-1/stweb, stw-2/stweb], subgroups=[stw-2/stweb|1] [stw-2/stweb], [stw-1/stweb|2] [stw-1/stweb]

10:31:07,513 INFO  [org.jboss.as.clustering] (Incoming-12,shared=udp) JBAS010225: New cluster view for partition web (id: 3, delta: 0, merge: true) : [stw-2/web, stw-1/web]

10:31:07,515 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-12,shared=udp) ISPN000093: Received new, MERGED cluster view: MergeView::[stw-2/web|3] [stw-2/web, stw-1/web], subgroups=[stw-2/web|1] [stw-2/web], [stw-1/web|2] [stw-1/web]