7 Replies Latest reply on Oct 10, 2013 4:57 AM by marcodanti

    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

       

        • 1. Re: Automatic redeploy failed
          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

          • 2. Re: Automatic redeploy failed
            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?

            • 3. Re: Automatic redeploy failed
              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.

              • 4. Re: Automatic redeploy failed
                rhusar

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

                • 5. Re: Re: Automatic redeploy failed
                  rhusar

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

                  • 6. Re: Re: Re: Automatic redeploy failed
                    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.

                    • 7. Re: Re: Re: Re: Automatic redeploy failed
                      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]