7 Replies Latest reply on Feb 2, 2009 8:39 AM by Manuel Aznar Pérez

    Strange behavior replicated session (Error)

    Manuel Aznar Pérez Newbie

      My enviroment is 1 apache (load balancer - mod_proxy) and 3 JBoss 5.0.0.GA-jdk6 (in cluster with session replication).

      Deploy "Counter.war" application.

      1.- 3 servers up. All works fine. session xxxxxxxxxxxxxxxxx.node1 - counter: 1,2,3,4
      2.- node1 down. All works fine. session xxxxxxxxxxxxxxxxx.node2 - counter: 5,6
      3.- node2 down. All works fine. session xxxxxxxxxxxxxxxxx.node3 - counter: 7,8,9,10
      4.- node1 up
      5.- node3 down. Don't work correctly!!!!!! session yyyyyyyyyyyyyyyyy.node1 - counter: 1

      A random sequence is the same result. Finally it creates a new session id.

      I test this enviroment in JBoss 4.2.3.GA-jdk6 and it works fine.

      One difference is that session always is xxxxxxxxxxxxxxxxx.node1. Don't change name node.

      This isn't correctly behaviour.

      Is a bug in JBoss 5.0.0.GA?

        • 1. Re: Strange behavior replicated session (Error)
          Brian Stansberry Master

           

          "rengar" wrote:
          One difference is that session always is xxxxxxxxxxxxxxxxx.node1. Don't change name node.


          Do you mean with AS 4.2.3 it's always xxxxxxxxxxxx.node1? Even after you shut down node1?

          If so, do you have "UseJK" set to "true" in your 4.2.3 deploy/jboss-web-deployer/META-INF/jboss-service.xml file? You should.

          I want to start with this issue because always keeping .node1 is not the expected behavior; it should change after failover like it did with AS 5 in your steps 1, 2, 3. If you can make that happen in 4.2.3 and then you see the same "bad" behavior that tells me it is an issue with how mod_proxy deals with the jvmRoute suffix.

          • 2. Re: Strange behavior replicated session (Error)
            Manuel Aznar Pérez Newbie

             

            Do you mean with AS 4.2.3 it's always xxxxxxxxxxxx.node1? Even after you shut down node1?


            Yes


            If so, do you have "UseJK" set to "true" in your 4.2.3 deploy/jboss-web-deployer/META-INF/jboss-service.xml file? You should.


            I have useJK="true".


            If you can make that happen in 4.2.3 and then you see the same "bad" behavior that tells me it is an issue with how mod_proxy deals with the jvmRoute suffix.


            I use the same apache-mod_proxy at 4.2.3 and 5.0.0.

            My configuration:

            1.- Apache

            <VirtualHost *:80>
            
             <Proxy balancer://portalcluster>
             Order deny,allow
             Allow from all
            
             BalancerMember ajp://10.20.2.110:8009 route=node1
             BalancerMember ajp://10.20.2.111:8009 route=node2
             BalancerMember ajp://10.20.2.112:8009 route=node3
             </Proxy>
            
             ProxyPass / balancer://portalcluster/ stickysession=JSESSIONID nofailover=Off
            </VirtualHost>
            


            2.- JBoss web (at 3 nodes - node1,node2,node3)

            -"/opt/java/jboss/server/all/deploy/jboss-web.deployer/server.xml"

             <Engine .... jvmRoute="node1">
            

             <Engine .... jvmRoute="node2">
            

             <Engine .... jvmRoute="node3">
            


            -"/opt/java/jboss/server/all/deploy/jboss-web.deployer/META-INF/jboss-service.xml" (this step only 4.2.3, not at 5.0.0 (don't necessary))

            <attribute name="UseJK">true</attribute>
            


            At 5.0.0 have a strange behaviour when it returns node1 because change session to yyyyyyyyyyyyyyy.node1 (New session). Before session were xxxxxxxxxxxxxxx.node1. Don't reused the same session.

            Thanks.



            • 3. Re: Strange behavior replicated session (Error)
              Manuel Aznar Pérez Newbie

              Also I tested mod_cluster project at 5.0.0 getting the same result. It generate a new session when return node1.

              • 4. Re: Strange behavior replicated session (Error)
                Brian Stansberry Master

                Do you have buddy replication enabled? (Not enabled by default.)

                The bit about the session id always remaining xxxxxxx.node1 in 4.2.3 is mysterious to me, as it shouldn't work that way. But I'll put that aside for now since you've got the "UseJK" flag set.

                • 5. Re: Strange behavior replicated session (Error)
                  Brian Stansberry Master

                  I just tried reproducing this with mod_jk and it worked fine. It will probably be a couple days before I can try with mod_cluster. If you have mod_jk available and can try with that, let me know.

                  • 6. Re: Strange behavior replicated session (Error)
                    Paul Ferraro Master

                    Seems to me the newly restarted node is not receiving the session cache state upon startup (do you see any errors/warnings from jgroups in your logs after restarting node1?), or has already begun accepting requests before the receiving the session cache state. How long did you wait between steps 4 and 5? Can you try waiting a bit and see if the observed behavior is different?

                    • 7. Re: Strange behavior replicated session (Error)
                      Manuel Aznar Pérez Newbie

                      I haven't Buddy Replication.

                      I wait 5 min.

                      Node2: 10.20.2.111 (jvmRoute = PilotoCluster111)
                      Node3: 10.20.2.112 (jvmRoute = PilotoCluster112)

                      Log node3:

                      2009-02-02 16:14:37,087 INFO [org.jboss.example.counter.CounterServlet] *****************
                      2009-02-02 16:14:37,087 INFO [org.jboss.example.counter.CounterServlet] Counter = 14
                      2009-02-02 16:14:37,088 INFO [org.jboss.example.counter.CounterServlet] sessionID = 3U2iibVx7mu85jziAqt-eQ__.PilotoCluster112
                      2009-02-02 16:14:37,088 INFO [org.jboss.example.counter.CounterServlet] *****************
                      2009-02-02 16:14:37,089 INFO [org.jboss.example.counter.Counter] ****************************
                      2009-02-02 16:14:37,089 INFO [org.jboss.example.counter.Counter] Serialization is under way.
                      2009-02-02 16:14:37,089 INFO [org.jboss.example.counter.Counter] Counter = 14
                      2009-02-02 16:14:37,089 INFO [org.jboss.example.counter.Counter] ****************************
                      2009-02-02 16:14:38,263 INFO [org.jboss.example.counter.CounterServlet] *****************
                      2009-02-02 16:14:38,263 INFO [org.jboss.example.counter.CounterServlet] Counter = 15
                      2009-02-02 16:14:38,263 INFO [org.jboss.example.counter.CounterServlet] sessionID = 3U2iibVx7mu85jziAqt-eQ__.PilotoCluster112
                      2009-02-02 16:14:38,263 INFO [org.jboss.example.counter.CounterServlet] *****************
                      2009-02-02 16:14:38,265 INFO [org.jboss.example.counter.Counter] ****************************
                      2009-02-02 16:14:38,265 INFO [org.jboss.example.counter.Counter] Serialization is under way.
                      2009-02-02 16:14:38,265 INFO [org.jboss.example.counter.Counter] Counter = 15
                      2009-02-02 16:14:38,265 INFO [org.jboss.example.counter.Counter] ****************************
                      2009-02-02 16:14:42,673 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:14:42,693 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=true, isMasterNode=true, viewID=820930537
                      2009-02-02 16:14:52,697 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:14:52,733 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=true, isMasterNode=true, viewID=820930537
                      2009-02-02 16:15:02,737 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:15:02,759 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=true, isMasterNode=true, viewID=820930537
                      2009-02-02 16:15:12,763 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:15:12,784 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=true, isMasterNode=true, viewID=820930537
                      2009-02-02 16:15:13,688 INFO [org.jboss.bootstrap.microcontainer.ServerImpl] Runtime shutdown hook called, forceHalt: true
                      2009-02-02 16:15:13,688 DEBUG [org.jboss.web.tomcat.service.deployers.TomcatService] Saw org.jboss.system.server.stopped notification, stopping connectors
                      2009-02-02 16:15:13,691 INFO [org.apache.coyote.http11.Http11Protocol] Pausing Coyote HTTP/1.1 on http-PilotoClusterLocal%2F10.20.2.112-8080
                      2009-02-02 16:15:13,719 INFO [org.apache.coyote.http11.Http11Protocol] Stopping Coyote HTTP/1.1 on http-PilotoClusterLocal%2F10.20.2.112-8080
                      


                      Log node2:
                      2009-02-02 16:15:13,300 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:15:18,390 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:15:22,985 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <Mon, 2 Feb 2009 16:15:22>
                      2009-02-02 16:15:22,985 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass
                      2009-02-02 16:15:22,985 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
                      2009-02-02 16:15:22,986 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
                      2009-02-02 16:15:23,303 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:15:28,415 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:15:32,987 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <Mon, 2 Feb 2009 16:15:32>
                      2009-02-02 16:15:32,987 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass
                      2009-02-02 16:15:32,987 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass
                      2009-02-02 16:15:32,987 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
                      2009-02-02 16:15:33,305 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:15:38,447 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:15:43,308 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:15:48,472 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:15:53,310 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:15:58,495 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:16:03,313 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:16:08,519 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:16:13,315 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:16:18,543 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:16:23,318 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:17:32,989 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <Mon, 2 Feb 2009 16:17:32>
                      2009-02-02 16:17:32,989 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass
                      2009-02-02 16:17:32,989 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
                      2009-02-02 16:17:32,990 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
                      2009-02-02 16:17:33,338 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:17:38,764 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:17:42,990 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <Mon, 2 Feb 2009 16:17:42>
                      2009-02-02 16:17:42,991 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass
                      2009-02-02 16:17:42,991 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass
                      2009-02-02 16:17:42,991 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
                      2009-02-02 16:17:43,340 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:17:48,787 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=false, isMasterNode=false, viewID=820930537
                      2009-02-02 16:17:49,840 DEBUG [org.jboss.cache.invalidation.bridges.JGCacheInvalidationBridge] The list of replicants for the JG bridge has changed, computing and updating local info...
                      2009-02-02 16:17:49,841 DEBUG [org.jboss.cache.invalidation.bridges.JGCacheInvalidationBridge] ... No bridge info was associated with this node
                      2009-02-02 16:17:50,199 DEBUG [org.jboss.ha.framework.server.HARMIServerImpl$RefreshProxiesHATarget] replicantsChanged 'HAJNDI' to 1 (intra-view id: 396150693)
                      2009-02-02 16:17:50,301 DEBUG [org.jboss.cache.RPCManagerImpl] Block received at 10.20.2.111:43345
                      2009-02-02 16:17:50,301 DEBUG [org.jboss.cache.RPCManagerImpl] Block processed at 10.20.2.111:43345
                      2009-02-02 16:17:50,309 WARN [org.jgroups.protocols.pbcast.NAKACK] 10.20.2.111:43345] discarded message from non-member 10.20.2.112:56373, myview is [10.20.2.112:56373|6] [10.20.2.111:43345]
                      2009-02-02 16:17:50,310 INFO [org.jboss.cache.RPCManagerImpl] Received new cluster view: [10.20.2.112:56373|6] [10.20.2.111:43345]
                      2009-02-02 16:17:50,310 DEBUG [org.jboss.cache.RPCManagerImpl] UnBlock received at 10.20.2.111:43345
                      2009-02-02 16:17:50,310 DEBUG [org.jboss.cache.RPCManagerImpl] UnBlock processed at 10.20.2.111:43345
                      2009-02-02 16:17:50,367 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=true, isMasterNode=false, viewID=820930537
                      2009-02-02 16:17:50,368 DEBUG [org.jboss.modcluster.ha.HAModClusterService] startNewMaster, isMasterNode=false
                      2009-02-02 16:17:50,382 DEBUG [org.jboss.modcluster.ha.HAModClusterService] partitionTopologyChanged, isElectedNewMaster=true, isMasterNode=true, viewID=396150693
                      2009-02-02 16:17:50,393 DEBUG [org.jboss.ha.framework.server.HASingletonImpl] partitionTopologyChanged, isElectedNewMaster=true, isMasterNode=false, viewID=396150693
                      2009-02-02 16:17:50,393 DEBUG [org.jboss.ha.framework.server.HASingletonImpl] startNewMaster, isMasterNode=false
                      2009-02-02 16:17:50,393 DEBUG [org.jboss.ha.framework.server.HASingletonImpl] startSingleton() : elected for master singleton node
                      2009-02-02 16:17:50,394 DEBUG [org.jboss.ha.singleton.HASingletonController] Calling operation: deploySingletons(file:/usr/java/jboss-5.0.0.GA/server/default/deploy-hasingleton), on target: 'HASingletonDeploymentScanner@3a70dd47{}'
                      2009-02-02 16:17:50,394 DEBUG [org.jboss.ha.singleton.HASingletonDeploymentScanner] Added URI: file:/usr/java/jboss-5.0.0.GA/server/default/deploy-hasingleton
                      2009-02-02 16:17:50,394 DEBUG [org.jboss.deployers.plugins.main.MainDeployerImpl] Asked to process() when there is nothing to do.
                      2009-02-02 16:17:50,430 DEBUG [org.jboss.cache.RPCManagerImpl] Block received at 10.20.2.111:43345
                      2009-02-02 16:17:50,430 DEBUG [org.jboss.cache.RPCManagerImpl] Block processed at 10.20.2.111:43345
                      2009-02-02 16:17:50,433 INFO [org.jboss.cache.RPCManagerImpl] Received new cluster view: [10.20.2.112:56373|6] [10.20.2.111:43345]
                      2009-02-02 16:17:50,434 DEBUG [org.jboss.web.tomcat.service.sso.jbc.JBossCacheSSOClusterManager] Received ViewChangedEvent EventImpl{type=VIEW_CHANGED,pre=false, cache=org.jboss.cache.DataContainerImpl [1 nodes, 0 locks], modificationType=null, data=null, fqn=null, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=[10.20.2.112:56373|6] [10.20.2.111:43345], buddyGroup=null}
                      2009-02-02 16:17:50,434 DEBUG [org.jboss.web.tomcat.service.sso.jbc.JBossCacheSSOClusterManager] Members have been removed; will launch cleanup task. Dead members: [10.20.2.112:56373]
                      2009-02-02 16:17:50,434 DEBUG [org.jboss.cache.RPCManagerImpl] UnBlock received at 10.20.2.111:43345
                      2009-02-02 16:17:50,434 DEBUG [org.jboss.cache.RPCManagerImpl] UnBlock processed at 10.20.2.111:43345
                      2009-02-02 16:17:50,435 WARN [org.jgroups.protocols.pbcast.NAKACK] 10.20.2.111:43345] discarded message from non-member 10.20.2.112:56373, myview is [10.20.2.112:56373|6] [10.20.2.111:43345]
                      2009-02-02 16:17:50,479 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.JBOSS_PRUEBAS] Block processed at 10.20.2.111:1099
                      2009-02-02 16:17:50,493 INFO [org.jboss.ha.framework.interfaces.HAPartition.lifecycle.JBOSS_PRUEBAS] New cluster view for partition JBOSS_PRUEBAS (id: 6, delta: -1) : [10.20.2.111:1099]
                      2009-02-02 16:17:50,494 WARN [org.jgroups.protocols.pbcast.NAKACK] 10.20.2.111:43345] discarded message from non-member 10.20.2.112:56373, myview is [10.20.2.112:56373|6] [10.20.2.111:43345]
                      2009-02-02 16:17:50,495 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.JBOSS_PRUEBAS] dead members: [10.20.2.112:1099]
                      2009-02-02 16:17:50,496 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.JBOSS_PRUEBAS] membership changed from 2 to 1
                      2009-02-02 16:17:50,496 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.JBOSS_PRUEBAS] Unblock processed at 10.20.2.111:1099
                      2009-02-02 16:17:50,496 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.JBOSS_PRUEBAS] Begin notifyListeners, viewID: 6
                      2009-02-02 16:17:50,496 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.JBOSS_PRUEBAS] I am (10.20.2.111:1099) received membershipChanged event:
                      2009-02-02 16:17:50,496 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.JBOSS_PRUEBAS] Dead members: 1 ([10.20.2.112:1099])
                      2009-02-02 16:17:50,496 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.JBOSS_PRUEBAS] New Members : 0 ([])
                      2009-02-02 16:17:50,496 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.JBOSS_PRUEBAS] All Members : 1 ([10.20.2.111:1099])
                      2009-02-02 16:17:50,496 DEBUG [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.JBOSS_PRUEBAS] purgeDeadMembers, [10.20.2.112:1099]
                      2009-02-02 16:17:50,496 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.JBOSS_PRUEBAS] End notifyListeners, viewID: 6
                      2009-02-02 16:17:53,343 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:18:03,350 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:18:13,354 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:18:23,357 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:18:33,361 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:18:43,363 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:18:53,366 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:19:03,369 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:19:13,372 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:19:23,376 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:19:33,379 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:19:42,993 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <Mon, 2 Feb 2009 16:19:42>
                      2009-02-02 16:19:42,993 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass
                      2009-02-02 16:19:42,993 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
                      2009-02-02 16:19:42,993 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
                      2009-02-02 16:19:43,382 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:19:52,995 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <Mon, 2 Feb 2009 16:19:52>
                      2009-02-02 16:19:52,995 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass
                      2009-02-02 16:19:52,995 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass
                      2009-02-02 16:19:52,995 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
                      2009-02-02 16:19:53,385 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:20:03,387 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:20:13,391 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:20:21,318 INFO [org.jboss.example.counter.Counter] ************************
                      2009-02-02 16:20:21,319 INFO [org.jboss.example.counter.Counter] Counter is being created
                      2009-02-02 16:20:21,319 INFO [org.jboss.example.counter.Counter] ************************
                      2009-02-02 16:20:21,322 INFO [org.jboss.example.counter.CounterServlet] *****************
                      2009-02-02 16:20:21,322 INFO [org.jboss.example.counter.CounterServlet] Counter = 1
                      2009-02-02 16:20:21,322 INFO [org.jboss.example.counter.CounterServlet] sessionID = Wb7XLjglpDtd7dyl4CbZDw__.PilotoCluster111
                      2009-02-02 16:20:21,322 INFO [org.jboss.example.counter.CounterServlet] *****************
                      2009-02-02 16:20:21,349 INFO [org.jboss.example.counter.Counter] ****************************
                      2009-02-02 16:20:21,349 INFO [org.jboss.example.counter.Counter] Serialization is under way.
                      2009-02-02 16:20:21,350 INFO [org.jboss.example.counter.Counter] Counter = 1
                      2009-02-02 16:20:21,350 INFO [org.jboss.example.counter.Counter] ****************************
                      2009-02-02 16:20:23,394 DEBUG [org.jboss.modcluster.ha.HAModClusterService] Check status for engine [jboss.web]
                      2009-02-02 16:20:25,091 INFO [org.jboss.example.counter.CounterServlet] *****************
                      2009-02-02 16:20:25,091 INFO [org.jboss.example.counter.CounterServlet] Counter = 2
                      2009-02-02 16:20:25,091 INFO [org.jboss.example.counter.CounterServlet] sessionID = Wb7XLjglpDtd7dyl4CbZDw__.PilotoCluster111
                      2009-02-02 16:20:25,091 INFO [org.jboss.example.counter.CounterServlet] *****************
                      2009-02-02 16:20:25,092 INFO [org.jboss.example.counter.Counter] ****************************
                      2009-02-02 16:20:25,092 INFO [org.jboss.example.counter.Counter] Serialization is under way.
                      2009-02-02 16:20:25,092 INFO [org.jboss.example.counter.Counter] Counter = 2
                      2009-02-02 16:20:25,092 INFO [org.jboss.example.counter.Counter] ****************************