StatefulWithXPCFailoverTestCase intermittently fails

org.jboss.as.test.clustering.cluster.ejb3.xpc.StatefulWithXPCFailoverTestCase(UDP).testBasicXPC

Failing for the past 1 build (Since #4179 )
Took 3 min 54 sec.
Error Message

assertExecuteUrlWithResult Timed out trying to execute url=http://127.0.0.1:8180/stateful/count?command=getEmployee, 2. started node2, xpc on node1, node1 should be able to read entity on node1
Stacktrace

java.lang.AssertionError: assertExecuteUrlWithResult Timed out trying to execute url=http://127.0.0.1:8180/stateful/count?command=getEmployee, 2. started node2, xpc on node1, node1 should be able to read entity on node1
at org.jboss.as.test.clustering.cluster.ejb3.xpc.StatefulWithXPCFailoverTestCase.executeUrlWithAnswer(StatefulWithXPCFailoverTestCase.java:313)
at org.jboss.as.test.clustering.cluster.ejb3.xpc.StatefulWithXPCFailoverTestCase.testBasicXPC(StatefulWithXPCFailoverTestCase.java:172)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at org.jboss.arquillian.junit.Arquillian$6$1.invoke(Arquillian.java:270)
at org.jboss.arquillian.container.test.impl.execution.LocalTestExecuter.execute(LocalTestExecuter.java:60)
at sun.reflect.GeneratedMethodAccessor12.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:90)
at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99)
at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81)
at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:135)
at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:115)
at org.jboss.arquillian.core.impl.EventImpl.fire(EventImpl.java:67)
at org.jboss.arquillian.container.test.impl.execution.ClientTestExecuter.execute(ClientTestExecuter.java:53)
at sun.reflect.GeneratedMethodAccessor11.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:90)
at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99)
at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81)
at org.jboss.arquillian.container.test.impl.client.ContainerEventController.createContext(ContainerEventController.java:142)
at org.jboss.arquillian.container.test.impl.client.ContainerEventController.createTestContext(ContainerEventController.java:129)
at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:90)
at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88)
at org.jboss.arquillian.test.impl.TestContextHandler.createTestContext(TestContextHandler.java:89)
at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:90)
at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88)
at org.jboss.arquillian.test.impl.TestContextHandler.createClassContext(TestContextHandler.java:75)
at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:90)
at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88)
at org.jboss.arquillian.test.impl.TestContextHandler.createSuiteContext(TestContextHandler.java:60)
at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:90)
at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88)
at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:135)
at org.jboss.arquillian.test.impl.EventTestRunnerAdaptor.test(EventTestRunnerAdaptor.java:111)
at org.jboss.arquillian.junit.Arquillian$6.evaluate(Arquillian.java:263)
at org.jboss.arquillian.junit.Arquillian$4.evaluate(Arquillian.java:226)
at org.jboss.arquillian.junit.Arquillian.multiExecute(Arquillian.java:314)
at org.jboss.arquillian.junit.Arquillian.access$100(Arquillian.java:46)
at org.jboss.arquillian.junit.Arquillian$5.evaluate(Arquillian.java:240)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
at org.jboss.arquillian.junit.Arquillian$2.evaluate(Arquillian.java:185)
at org.jboss.arquillian.junit.Arquillian.multiExecute(Arquillian.java:314)
at org.jboss.arquillian.junit.Arquillian.access$100(Arquillian.java:46)
at org.jboss.arquillian.junit.Arquillian$3.evaluate(Arquillian.java:199)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at org.jboss.arquillian.junit.Arquillian.run(Arquillian.java:147)
at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:234)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:133)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:114)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:188)
at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:166)
at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:86)
at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:101)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74)
Standard Output

Wed Jul 18 09:07:21 EDT 2012stopping deployment=deployment-1, container=container-1
09:07:21,763 INFO [org.jboss.web] (MSC service thread 1-4) JBAS018224: Unregister web context: /stateful
09:07:21,788 INFO [org.infinispan.eviction.PassivationManagerImpl] (ServerService Thread Pool – 25) ISPN000029: Passivating all entries to disk
09:07:21,791 INFO [org.infinispan.eviction.PassivationManagerImpl] (ServerService Thread Pool – 25) ISPN000030: Passivated 0 entries in 1 milliseconds
09:07:21,791 INFO [org.infinispan.eviction.PassivationManagerImpl] (ServerService Thread Pool – 27) ISPN000029: Passivating all entries to disk
09:07:21,794 INFO [org.infinispan.eviction.PassivationManagerImpl] (ServerService Thread Pool – 27) ISPN000030: Passivated 0 entries in 3 milliseconds
09:07:21,796 INFO [org.infinispan.eviction.PassivationManagerImpl] (MSC service thread 1-6) ISPN000029: Passivating all entries to disk
09:07:21,797 INFO [org.infinispan.eviction.PassivationManagerImpl] (MSC service thread 1-6) ISPN000030: Passivated 0 entries in 1 milliseconds
09:07:21,803 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 27) JBAS010282: Stopped org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulBean cache from ejb container
09:07:21,811 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-6) JBAS010282: Stopped default-host/stateful cache from web container
09:07:21,811 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 25) JBAS010282: Stopped org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.SecondBean cache from ejb container
09:07:21,819 INFO [org.jboss.as.jpa] (ServerService Thread Pool – 25) JBAS011403: Stopping Persistence Unit Service 'stateful.war#mypc'
09:07:21,832 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 25) JBAS010282: Stopped stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee cache from hibernate container
09:07:21,867 INFO [org.infinispan.jmx.CacheJmxRegistration] (ServerService Thread Pool – 25) ISPN000031: MBeans were successfully registered to the platform mbean server.
09:07:21,869 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 25) JBAS010281: Started local-query cache from hibernate container
09:07:21,870 INFO [org.hibernate.tool.hbm2ddl.SchemaExport] (ServerService Thread Pool – 25) HHH000227: Running hbm2ddl schema export
09:07:21,873 INFO [stdout] (ServerService Thread Pool – 25) Hibernate: drop table Employee if exists
09:07:21,881 INFO [org.hibernate.tool.hbm2ddl.SchemaExport] (ServerService Thread Pool – 25) HHH000230: Schema export complete
09:07:21,924 INFO [org.infinispan.eviction.PassivationManagerImpl] (MSC service thread 1-2) ISPN000029: Passivating all entries to disk
09:07:21,926 INFO [org.infinispan.eviction.PassivationManagerImpl] (MSC service thread 1-2) ISPN000030: Passivated 0 entries in 1 milliseconds
09:07:21,951 INFO [org.infinispan.eviction.PassivationManagerImpl] (MSC service thread 1-1) ISPN000029: Passivating all entries to disk
09:07:21,953 INFO [org.infinispan.eviction.PassivationManagerImpl] (MSC service thread 1-1) ISPN000030: Passivated 0 entries in 1 milliseconds
09:07:21,953 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-5) JBAS010282: Stopped remote-connector-client-mappings cache from ejb container
09:07:21,962 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-2) JBAS010282: Stopped repl cache from web container
09:07:21,980 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) JBAS010282: Stopped repl cache from ejb container
09:07:21,997 INFO [org.infinispan.cacheviews.CacheViewsManagerImpl] (OOB-19,null) ISPN000170: Our last committed view (CacheView

{viewId=2, members=[node-0/web, node-1/web]}) is not the same as the coordinator's last committed view (CacheView{viewId=3, members=[node-0/web]}). This is normal during a merge
09:07:22,003 WARN [org.infinispan.commands.control.CacheViewControlCommand] (OOB-19,null) ISPN000071: Caught exception when handling command CacheViewControlCommand{cache=default-host/stateful, type=PREPARE_VIEW, sender=node-0/web, newViewId=4, newMembers=[node-0/web, node-1/web], oldViewId=3, oldMembers=[node-0/web]}: java.lang.IllegalStateException: default-host/stateful: Received cache view prepare request after the local node has already shut down
at org.infinispan.cacheviews.CacheViewsManagerImpl.handlePrepareView(CacheViewsManagerImpl.java:487)
at org.infinispan.commands.control.CacheViewControlCommand.perform(CacheViewControlCommand.java:126)
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:95)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:226)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:203)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:465)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:372)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:247)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:601)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130)
at org.jgroups.JChannel.up(JChannel.java:715)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1020)
at org.jgroups.protocols.RSVP.up(RSVP.java:179)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:899)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:744)
at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:414)
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:572)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:102)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143)
at org.jgroups.protocols.FD.up(FD.java:273)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
at org.jgroups.protocols.Discovery.up(Discovery.java:359)
at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2568)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1211)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1775)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1748)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_29]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:07:22,036 INFO [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment stateful.war in 299ms
09:07:22,005 WARN [org.infinispan.commands.control.CacheViewControlCommand] (OOB-18,null) ISPN000071: Caught exception when handling command CacheViewControlCommand{cache=repl, type=PREPARE_VIEW, sender=node-0/web, newViewId=3, newMembers=[node-0/web, node-1/web, node-1/web], oldViewId=2, oldMembers=[node-0/web, node-1/web]}: java.lang.IllegalStateException: repl: Received cache view prepare request after the local node has already shut down
at org.infinispan.cacheviews.CacheViewsManagerImpl.handlePrepareView(CacheViewsManagerImpl.java:487)
at org.infinispan.commands.control.CacheViewControlCommand.perform(CacheViewControlCommand.java:126)
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:95)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:226)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:203)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:465)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:372)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:247)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:601)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130)
at org.jgroups.JChannel.up(JChannel.java:715)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1020)
at org.jgroups.protocols.RSVP.up(RSVP.java:179)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:899)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:744)
at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:414)
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:572)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:102)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143)
at org.jgroups.protocols.FD.up(FD.java:273)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
at org.jgroups.protocols.Discovery.up(Discovery.java:359)
at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2568)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1211)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1775)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1748)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_29]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:07:22,229 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ViewHandler,hibernate,node-0/hibernate) ISPN000094: Received new cluster view: [node-0/hibernate|2] [node-0/hibernate]
09:07:22,273 INFO [org.jboss.as.clustering] (ViewHandler,web,node-0/web) JBAS010225: New cluster view for partition web (id: 2, delta: -1, merge: false) : [node-0/web]
09:07:22,273 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ViewHandler,web,node-0/web) ISPN000094: Received new cluster view: [node-0/web|2] [node-0/web]
09:07:22,314 INFO [org.jboss.as.clustering] (ViewHandler,ejb,node-0/ejb) JBAS010225: New cluster view for partition ejb (id: 2, delta: -1, merge: false) : [node-0/ejb]
09:07:22,315 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ViewHandler,ejb,node-0/ejb) ISPN000094: Received new cluster view: [node-0/ejb|2] [node-0/ejb]
09:07:22,330 INFO [org.jboss.as.clustering] (ViewHandler,web,node-0/web) JBAS010225: New cluster view for partition web (id: 3, delta: 1, merge: false) : [node-0/web, node-1/web]
09:07:22,332 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ViewHandler,web,node-0/web) ISPN000094: Received new cluster view: [node-0/web|3] [node-0/web, node-1/web]
09:07:22,445 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-3) JBAS010282: Stopped local-query cache from hibernate container
09:07:22,676 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-2) ISPN000082: Stopping the RpcDispatcher
09:07:22,687 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-3) ISPN000082: Stopping the RpcDispatcher
09:07:22,711 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-4) ISPN000082: Stopping the RpcDispatcher
09:07:22,740 INFO [org.jboss.as.repository] (management-handler-thread - 3) JBAS014901: Content removed from location /home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/target/jbossas-clustering-udp-1/standalone/data/content/86/6f7577e378f4b33c5425fc3bc244363c57d2c2/content
09:07:22,741 INFO [org.jboss.as.server] (management-handler-thread - 3) JBAS018558: Undeployed "stateful.war"
09:07:22,743 INFO [org.jboss.arquillian.container.test.impl.client.container.ClientContainerController] (main) Manual stopping of a server instance
Wed Jul 18 09:07:22 EDT 2012stopped deployment=deployment-1, container=container-1
Wed Jul 18 09:07:22 EDT 2012create employee entity
09:07:23,236 INFO [stdout] (http-/127.0.0.1:8080-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = createEmployee
09:07:23,266 INFO [stdout] (http-/127.0.0.1:8080-1) createEmployee(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=EntityKey[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1],collectionKeys=[]];ActionQueue[insertions=EntityInsertAction[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:07:23,266 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000161: Logging statistics....
09:07:23,267 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000251: Start time: 1342616826811
09:07:23,267 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000242: Sessions opened: 1
09:07:23,268 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000241: Sessions closed: 0
09:07:23,268 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000266: Transactions: 0
09:07:23,268 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000258: Successful transactions: 0
09:07:23,269 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000187: Optimistic lock failures: 0
09:07:23,269 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000105: Flushes: 0
09:07:23,269 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000048: Connections obtained: 0
09:07:23,270 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000253: Statements prepared: 0
09:07:23,270 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000252: Statements closed: 0
09:07:23,271 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000239: Second level cache puts: 0
09:07:23,271 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000237: Second level cache hits: 0
09:07:23,271 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000238: Second level cache misses: 0
09:07:23,272 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000079: Entities loaded: 0
09:07:23,272 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000080: Entities updated: 0
09:07:23,272 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000078: Entities inserted: 0
09:07:23,273 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000076: Entities deleted: 0
09:07:23,273 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000077: Entities fetched (minimize this): 0
09:07:23,273 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000033: Collections loaded: 0
09:07:23,274 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000036: Collections updated: 0
09:07:23,274 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000035: Collections removed: 0
09:07:23,275 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000034: Collections recreated: 0
09:07:23,275 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000032: Collections fetched (minimize this): 0
09:07:23,275 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000438: NaturalId cache puts: 0
09:07:23,276 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000439: NaturalId cache hits: 0
09:07:23,276 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000440: NaturalId cache misses: 0
09:07:23,276 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000441: Max NaturalId query time: 0ms
09:07:23,277 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000442: NaturalId queries executed to database: 0
09:07:23,277 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000210: Queries executed to database: 0
09:07:23,277 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000215: Query cache puts: 0
09:07:23,278 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000433: update timestamps cache puts: 0
09:07:23,278 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000434: update timestamps cache hits: 0
09:07:23,278 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000435: update timestamps cache misses: 0
09:07:23,279 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000213: Query cache hits: 0
09:07:23,279 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000214: Query cache misses: 0
09:07:23,279 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000173: Max query time: 0ms
09:07:23,280 INFO [stdout] (http-/127.0.0.1:8080-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:07:23,281 INFO [stdout] (http-/127.0.0.1:8080-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:07:23,287 INFO [stdout] (http-/127.0.0.1:8080-1) getEmployee 1(version=created, HashMap version=created) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=EntityKey[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1],collectionKeys=[]];ActionQueue[insertions=EntityInsertAction[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:07:23,288 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000161: Logging statistics....
09:07:23,288 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000251: Start time: 1342616826811
09:07:23,288 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000242: Sessions opened: 1
09:07:23,289 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000241: Sessions closed: 0
09:07:23,289 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000266: Transactions: 0
09:07:23,289 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000258: Successful transactions: 0
09:07:23,290 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000187: Optimistic lock failures: 0
09:07:23,290 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000105: Flushes: 0
09:07:23,290 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000048: Connections obtained: 0
09:07:23,291 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000253: Statements prepared: 0
09:07:23,291 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000252: Statements closed: 0
09:07:23,291 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000239: Second level cache puts: 0
09:07:23,291 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000237: Second level cache hits: 0
09:07:23,292 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000238: Second level cache misses: 0
09:07:23,292 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000079: Entities loaded: 0
09:07:23,292 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000080: Entities updated: 0
09:07:23,293 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000078: Entities inserted: 0
09:07:23,293 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000076: Entities deleted: 0
09:07:23,293 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000077: Entities fetched (minimize this): 0
09:07:23,294 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000033: Collections loaded: 0
09:07:23,294 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000036: Collections updated: 0
09:07:23,294 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000035: Collections removed: 0
09:07:23,295 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000034: Collections recreated: 0
09:07:23,295 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000032: Collections fetched (minimize this): 0
09:07:23,295 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000438: NaturalId cache puts: 0
09:07:23,296 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000439: NaturalId cache hits: 0
09:07:23,296 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000440: NaturalId cache misses: 0
09:07:23,296 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000441: Max NaturalId query time: 0ms
09:07:23,297 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000442: NaturalId queries executed to database: 0
09:07:23,297 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000210: Queries executed to database: 0
09:07:23,297 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000215: Query cache puts: 0
09:07:23,298 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000433: update timestamps cache puts: 0
09:07:23,298 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000434: update timestamps cache hits: 0
09:07:23,298 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000435: update timestamps cache misses: 0
09:07:23,299 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000213: Query cache hits: 0
09:07:23,299 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000214: Query cache misses: 0
09:07:23,299 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000173: Max query time: 0ms
09:07:23,300 INFO [stdout] (http-/127.0.0.1:8080-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:07:23,300 INFO [stdout] (http-/127.0.0.1:8080-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:07:23,307 INFO [stdout] (http-/127.0.0.1:8080-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = createEmployee finished
09:07:27,336 WARN [org.jgroups.protocols.pbcast.GMS] (ViewHandler,web,node-0/web) node-0/web: failed to collect all ACKs (expected=1) for unicast view [node-0/web|3] [node-0/web, node-1/web] after 5000ms, missing ACKs from [node-1/web]
09:08:05,844 INFO [org.jboss.as.clustering] (VERIFY_SUSPECT.TimerThread,web,node-0/web) JBAS010232: Suspected member: node-1/web
09:08:06,201 INFO [org.jboss.as.clustering] (ViewHandler,web,node-0/web) JBAS010225: New cluster view for partition web (id: 4, delta: -1, merge: false) : [node-0/web]
09:08:06,204 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ViewHandler,web,node-0/web) ISPN000094: Received new cluster view: [node-0/web|4] [node-0/web]
09:08:22,001 ERROR [org.infinispan.cacheviews.CacheViewsManagerImpl] (CacheViewInstaller-1,node-0/web) ISPN000172: Failed to prepare view CacheView{viewId=4, members=[node-0/web, node-1/web]} for cache default-host/stateful, rolling back to view CacheView{viewId=3, members=[node-0/web]}: java.util.concurrent.ExecutionException: org.infinispan.CacheException: org.jgroups.TimeoutException: TimeoutException
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:232) [rt.jar:1.6.0_29]
at java.util.concurrent.FutureTask.get(FutureTask.java:91) [rt.jar:1.6.0_29]
at org.infinispan.cacheviews.CacheViewsManagerImpl.clusterPrepareView(CacheViewsManagerImpl.java:318) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.cacheviews.CacheViewsManagerImpl.clusterInstallView(CacheViewsManagerImpl.java:249) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.cacheviews.CacheViewsManagerImpl$ViewInstallationTask.call(CacheViewsManagerImpl.java:875) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [rt.jar:1.6.0_29]
at java.util.concurrent.FutureTask.run(FutureTask.java:138) [rt.jar:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_29]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]
Caused by: org.infinispan.CacheException: org.jgroups.TimeoutException: TimeoutException
at org.infinispan.util.Util.rewrapAsCacheException(Util.java:526) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:172) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:489) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.cacheviews.CacheViewsManagerImpl$2.call(CacheViewsManagerImpl.java:302) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.cacheviews.CacheViewsManagerImpl$2.call(CacheViewsManagerImpl.java:299) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
... 5 more
Caused by: org.jgroups.TimeoutException: TimeoutException
at org.jgroups.util.Promise._getResultWithTimeout(Promise.java:145) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.util.Promise.getResultWithTimeout(Promise.java:40) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.util.AckCollector.waitForAllAcks(AckCollector.java:93) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.protocols.RSVP$Entry.block(RSVP.java:275) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.protocols.RSVP.down(RSVP.java:114) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.stack.ProtocolStack.down(ProtocolStack.java:1025) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.JChannel.down(JChannel.java:729) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.down(MessageDispatcher.java:617) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.RequestCorrelator.sendUnicastRequest(RequestCorrelator.java:202) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.UnicastRequest.sendRequest(UnicastRequest.java:44) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.Request.execute(Request.java:83) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.MessageDispatcher.sendMessage(MessageDispatcher.java:366) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:275) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:165) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
... 8 more

09:08:22,005 ERROR [org.infinispan.cacheviews.CacheViewsManagerImpl] (CacheViewInstaller-2,node-0/web) ISPN000172: Failed to prepare view CacheView{viewId=3, members=[node-0/web, node-1/web, node-1/web]} for cache repl, rolling back to view CacheView{viewId=2, members=[node-0/web, node-1/web]}

: java.util.concurrent.ExecutionException: org.infinispan.CacheException: org.jgroups.TimeoutException: TimeoutException
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:232) [rt.jar:1.6.0_29]
at java.util.concurrent.FutureTask.get(FutureTask.java:91) [rt.jar:1.6.0_29]
at org.infinispan.cacheviews.CacheViewsManagerImpl.clusterPrepareView(CacheViewsManagerImpl.java:318) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.cacheviews.CacheViewsManagerImpl.clusterInstallView(CacheViewsManagerImpl.java:249) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.cacheviews.CacheViewsManagerImpl$ViewInstallationTask.call(CacheViewsManagerImpl.java:875) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [rt.jar:1.6.0_29]
at java.util.concurrent.FutureTask.run(FutureTask.java:138) [rt.jar:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_29]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]
Caused by: org.infinispan.CacheException: org.jgroups.TimeoutException: TimeoutException
at org.infinispan.util.Util.rewrapAsCacheException(Util.java:526) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommands(CommandAwareRpcDispatcher.java:139) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:492) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.cacheviews.CacheViewsManagerImpl$2.call(CacheViewsManagerImpl.java:302) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.cacheviews.CacheViewsManagerImpl$2.call(CacheViewsManagerImpl.java:299) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
... 5 more
Caused by: org.jgroups.TimeoutException: TimeoutException
at org.jgroups.util.Promise._getResultWithTimeout(Promise.java:145) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.util.Promise.getResultWithTimeout(Promise.java:40) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.util.AckCollector.waitForAllAcks(AckCollector.java:93) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.protocols.RSVP$Entry.block(RSVP.java:275) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.protocols.RSVP.down(RSVP.java:114) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.stack.ProtocolStack.down(ProtocolStack.java:1025) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.JChannel.down(JChannel.java:729) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.down(MessageDispatcher.java:617) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.RequestCorrelator.sendUnicastRequest(RequestCorrelator.java:202) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.UnicastRequest.sendRequest(UnicastRequest.java:44) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.Request.execute(Request.java:83) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.jgroups.blocks.MessageDispatcher.sendMessageWithFuture(MessageDispatcher.java:418) [jgroups-3.1.0.Final.jar:3.1.0.Final]
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processCalls(CommandAwareRpcDispatcher.java:329) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommands(CommandAwareRpcDispatcher.java:132) [infinispan-core-5.1.5.FINAL.jar:5.1.5.FINAL]
... 8 more

09:08:23,320 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (http-/127.0.0.1:8080-1) ISPN000136: Execution error: org.infinispan.statetransfer.StateTransferInProgressException: Timed out waiting for the state transfer lock, state transfer in progress for view 4
at org.infinispan.interceptors.StateTransferLockInterceptor.signalStateTransferInProgress(StateTransferLockInterceptor.java:201)
at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:81)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:132)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:91)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:86)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:174)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:08:23,332 ERROR [org.infinispan.transaction.TransactionCoordinator] (http-/127.0.0.1:8080-1) ISPN000097: Error while processing a prepare in a single-phase transaction: org.infinispan.statetransfer.StateTransferInProgressException: Timed out waiting for the state transfer lock, state transfer in progress for view 4
at org.infinispan.interceptors.StateTransferLockInterceptor.signalStateTransferInProgress(StateTransferLockInterceptor.java:201)
at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:81)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:132)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:91)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:86)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:174)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:08:23,342 ERROR [org.infinispan.transaction.tm.DummyTransaction] (http-/127.0.0.1:8080-1) ISPN000111: afterCompletion() failed for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=DummyTransaction{xid=DummyXid

{id=13}

, status=3}, lockedKeys=null, backupKeyLocks=null, viewId=2} org.infinispan.transaction.synchronization.SyncLocalTransaction@b} org.infinispan.transaction.synchronization.SynchronizationAdapter@2a: org.infinispan.CacheException: Could not commit.
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:83)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]
Caused by: javax.transaction.xa.XAException
at org.infinispan.transaction.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:223)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:176)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
... 23 more

Wed Jul 18 09:08:23 EDT 20121. about to read entity on node1
09:08:23,369 INFO [stdout] (http-/127.0.0.1:8080-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:08:23,373 INFO [stdout] (http-/127.0.0.1:8080-1) getEmployee 1(version=created, HashMap version=created) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=EntityKey[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1],collectionKeys=[]];ActionQueue[insertions=EntityInsertAction[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:08:23,375 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000161: Logging statistics....
09:08:23,376 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000251: Start time: 1342616826811
09:08:23,378 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000242: Sessions opened: 1
09:08:23,379 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000241: Sessions closed: 0
09:08:23,380 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000266: Transactions: 0
09:08:23,381 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000258: Successful transactions: 0
09:08:23,382 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000187: Optimistic lock failures: 0
09:08:23,382 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000105: Flushes: 0
09:08:23,383 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000048: Connections obtained: 0
09:08:23,383 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000253: Statements prepared: 0
09:08:23,384 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000252: Statements closed: 0
09:08:23,384 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000239: Second level cache puts: 0
09:08:23,385 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000237: Second level cache hits: 0
09:08:23,385 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000238: Second level cache misses: 0
09:08:23,386 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000079: Entities loaded: 0
09:08:23,386 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000080: Entities updated: 0
09:08:23,387 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000078: Entities inserted: 0
09:08:23,388 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000076: Entities deleted: 0
09:08:23,388 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000077: Entities fetched (minimize this): 0
09:08:23,389 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000033: Collections loaded: 0
09:08:23,389 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000036: Collections updated: 0
09:08:23,390 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000035: Collections removed: 0
09:08:23,390 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000034: Collections recreated: 0
09:08:23,391 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000032: Collections fetched (minimize this): 0
09:08:23,391 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000438: NaturalId cache puts: 0
09:08:23,392 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000439: NaturalId cache hits: 0
09:08:23,393 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000440: NaturalId cache misses: 0
09:08:23,393 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000441: Max NaturalId query time: 0ms
09:08:23,394 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000442: NaturalId queries executed to database: 0
09:08:23,394 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000210: Queries executed to database: 0
09:08:23,395 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000215: Query cache puts: 0
09:08:23,395 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000433: update timestamps cache puts: 0
09:08:23,396 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000434: update timestamps cache hits: 0
09:08:23,396 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000435: update timestamps cache misses: 0
09:08:23,397 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000213: Query cache hits: 0
09:08:23,398 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000214: Query cache misses: 0
09:08:23,398 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000173: Max query time: 0ms
09:08:23,399 INFO [stdout] (http-/127.0.0.1:8080-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:08:23,400 INFO [stdout] (http-/127.0.0.1:8080-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:08:23,403 INFO [stdout] (http-/127.0.0.1:8080-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee finished
09:09:23,406 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (http-/127.0.0.1:8080-1) ISPN000136: Execution error: org.infinispan.statetransfer.StateTransferInProgressException: Timed out waiting for the state transfer lock, state transfer in progress for view 4
at org.infinispan.interceptors.StateTransferLockInterceptor.signalStateTransferInProgress(StateTransferLockInterceptor.java:201)
at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:81)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:132)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:91)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:86)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:174)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:09:23,431 ERROR [org.infinispan.transaction.TransactionCoordinator] (http-/127.0.0.1:8080-1) ISPN000097: Error while processing a prepare in a single-phase transaction: org.infinispan.statetransfer.StateTransferInProgressException: Timed out waiting for the state transfer lock, state transfer in progress for view 4
at org.infinispan.interceptors.StateTransferLockInterceptor.signalStateTransferInProgress(StateTransferLockInterceptor.java:201)
at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:81)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:132)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:91)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:86)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:174)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:09:23,453 ERROR [org.infinispan.transaction.tm.DummyTransaction] (http-/127.0.0.1:8080-1) ISPN000111: afterCompletion() failed for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=DummyTransaction{xid=DummyXid

{id=19}

, status=3}, lockedKeys=null, backupKeyLocks=null, viewId=4} org.infinispan.transaction.synchronization.SyncLocalTransaction@10} org.infinispan.transaction.synchronization.SynchronizationAdapter@2f: org.infinispan.CacheException: Could not commit.
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:83)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]
Caused by: javax.transaction.xa.XAException
at org.infinispan.transaction.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:223)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:176)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
... 23 more

09:09:23,477 INFO [stdout] (http-/127.0.0.1:8080-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getSecondBeanEmployee
09:09:23,481 INFO [stdout] (http-/127.0.0.1:8080-1) getSecondBeanEmployee(version=created, HashMap version=created) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=EntityKey[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1],collectionKeys=[]];ActionQueue[insertions=EntityInsertAction[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:09:23,482 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000161: Logging statistics....
09:09:23,484 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000251: Start time: 1342616826811
09:09:23,485 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000242: Sessions opened: 1
09:09:23,486 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000241: Sessions closed: 0
09:09:23,487 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000266: Transactions: 0
09:09:23,488 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000258: Successful transactions: 0
09:09:23,489 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000187: Optimistic lock failures: 0
09:09:23,490 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000105: Flushes: 0
09:09:23,491 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000048: Connections obtained: 0
09:09:23,492 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000253: Statements prepared: 0
09:09:23,493 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000252: Statements closed: 0
09:09:23,494 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000239: Second level cache puts: 0
09:09:23,495 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000237: Second level cache hits: 0
09:09:23,496 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000238: Second level cache misses: 0
09:09:23,497 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000079: Entities loaded: 0
09:09:23,498 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000080: Entities updated: 0
09:09:23,499 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000078: Entities inserted: 0
09:09:23,500 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000076: Entities deleted: 0
09:09:23,501 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000077: Entities fetched (minimize this): 0
09:09:23,502 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000033: Collections loaded: 0
09:09:23,503 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000036: Collections updated: 0
09:09:23,504 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000035: Collections removed: 0
09:09:23,505 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000034: Collections recreated: 0
09:09:23,506 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000032: Collections fetched (minimize this): 0
09:09:23,506 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000438: NaturalId cache puts: 0
09:09:23,508 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000439: NaturalId cache hits: 0
09:09:23,509 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000440: NaturalId cache misses: 0
09:09:23,510 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000441: Max NaturalId query time: 0ms
09:09:23,511 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000442: NaturalId queries executed to database: 0
09:09:23,512 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000210: Queries executed to database: 0
09:09:23,513 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000215: Query cache puts: 0
09:09:23,513 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000433: update timestamps cache puts: 0
09:09:23,514 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000434: update timestamps cache hits: 0
09:09:23,514 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000435: update timestamps cache misses: 0
09:09:23,515 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000213: Query cache hits: 0
09:09:23,516 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000214: Query cache misses: 0
09:09:23,516 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8080-1) HHH000173: Max query time: 0ms
09:09:23,518 INFO [stdout] (http-/127.0.0.1:8080-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:09:23,519 INFO [stdout] (http-/127.0.0.1:8080-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:09:23,524 INFO [stdout] (http-/127.0.0.1:8080-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getSecondBeanEmployee finished
09:10:23,528 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (http-/127.0.0.1:8080-1) ISPN000136: Execution error: org.infinispan.statetransfer.StateTransferInProgressException: Timed out waiting for the state transfer lock, state transfer in progress for view 4
at org.infinispan.interceptors.StateTransferLockInterceptor.signalStateTransferInProgress(StateTransferLockInterceptor.java:201)
at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:81)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:132)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:91)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:86)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:174)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:23,548 ERROR [org.infinispan.transaction.TransactionCoordinator] (http-/127.0.0.1:8080-1) ISPN000097: Error while processing a prepare in a single-phase transaction: org.infinispan.statetransfer.StateTransferInProgressException: Timed out waiting for the state transfer lock, state transfer in progress for view 4
at org.infinispan.interceptors.StateTransferLockInterceptor.signalStateTransferInProgress(StateTransferLockInterceptor.java:201)
at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:81)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:132)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:91)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:86)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:174)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:23,567 ERROR [org.infinispan.transaction.tm.DummyTransaction] (http-/127.0.0.1:8080-1) ISPN000111: afterCompletion() failed for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=DummyTransaction{xid=DummyXid

{id=23}

, status=3}, lockedKeys=null, backupKeyLocks=null, viewId=4} org.infinispan.transaction.synchronization.SyncLocalTransaction@14} org.infinispan.transaction.synchronization.SynchronizationAdapter@33: org.infinispan.CacheException: Could not commit.
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:83)
at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1515) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:857) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]
Caused by: javax.transaction.xa.XAException
at org.infinispan.transaction.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:223)
at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:176)
at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
... 23 more

Wed Jul 18 09:10:23 EDT 2012starting deployment=deployment-1, container=container-1
09:10:23,583 INFO [org.jboss.arquillian.container.test.impl.client.container.ClientContainerController] (main) Manual starting of a server instance
09:10:23,589 INFO [org.jboss.as.arquillian.container.managed.ManagedDeployableContainer] (main) Starting container with: [/opt/jdk1.6.0_29/bin/java, -Xmx512m, -XX:MaxPermSize=256m, -Djboss.dist=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/../../../build/target/jboss-as-7.2.0.Alpha1-SNAPSHOT, -Djava.net.preferIPv4Stack=true, -Djava.net.preferIPv6Addresses=false, -Dts.timeout.factor=100, -Dnode0=127.0.0.1, -Dnode1=127.0.0.1, -Dmcast=230.0.0.4, -Djbossas.ts.submodule.dir=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust, -Djbossas.ts.integ.dir=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/.., -Djbossas.ts.dir=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/../.., -Djbossas.project.dir=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/../../.., -Djboss.dist=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/../../../build/target/jboss-as-7.2.0.Alpha1-SNAPSHOT, -Djboss.inst=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/target/jbossas-clustering-udp-1, -Djboss.node.name=node-1, -Djboss.port.offset=100, -ea, -Djboss.home.dir=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/target/jbossas-clustering-udp-1, -Dorg.jboss.boot.log.file=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/target/jbossas-clustering-udp-1/standalone/log/boot.log, -Dlogging.configuration=file:/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/target/jbossas-clustering-udp-1/standalone/configuration/logging.properties, -Djboss.bundles.dir=/home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/../../../build/target/jboss-as-7.2.0.Alpha1-SNAPSHOT/bundles, -jar, /home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/target/jbossas-clustering-udp-1/jboss-modules.jar, -mp, /home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/../../../build/target/jboss-as-7.2.0.Alpha1-SNAPSHOT/modules, -jaxpmodule, javax.xml.jaxp-provider, org.jboss.as.standalone, -server-config, standalone-ha.xml]
09:10:24,477 INFO [org.jboss.modules] JBoss Modules version 1.1.2.GA
09:10:24,739 INFO [org.jboss.msc] JBoss MSC version 1.0.2.GA
09:10:24,817 INFO [org.jboss.as] JBAS015899: JBoss AS 7.2.0.Alpha1-SNAPSHOT "Steropes" starting
09:10:26,497 INFO [org.xnio] XNIO Version 3.0.5.GA
09:10:26,498 INFO [org.jboss.as.server] JBAS015888: Creating http management service using socket-binding (management-http)
09:10:26,508 INFO [org.xnio.nio] XNIO NIO Implementation Version 3.0.5.GA
09:10:26,519 INFO [org.jboss.remoting] JBoss Remoting version 3.2.8.GA
09:10:26,553 INFO [org.jboss.as.logging] JBAS011502: Removing bootstrap log handlers
09:10:26,562 INFO [org.jboss.as.configadmin] (ServerService Thread Pool – 29) JBAS016200: Activating ConfigAdmin Subsystem
09:10:26,587 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 34) JBAS010280: Activating Infinispan subsystem.
09:10:26,621 INFO [org.jboss.as.clustering.jgroups] (ServerService Thread Pool – 38) JBAS010260: Activating JGroups subsystem.
09:10:26,635 INFO [org.jboss.as.naming] (ServerService Thread Pool – 44) JBAS011800: Activating Naming Subsystem
09:10:26,655 INFO [org.jboss.as.osgi] (ServerService Thread Pool – 45) JBAS011906: Activating OSGi Subsystem
09:10:26,707 INFO [org.jboss.as.security] (ServerService Thread Pool – 50) JBAS013171: Activating Security Subsystem
09:10:26,762 INFO [org.jboss.as.connector.logging] (MSC service thread 1-6) JBAS010408: Starting JCA Subsystem (JBoss IronJacamar 1.0.11.Final)
09:10:26,770 INFO [org.jboss.as.security] (MSC service thread 1-3) JBAS013170: Current PicketBox version=4.0.9.Final
09:10:26,840 INFO [org.jboss.as.webservices] (ServerService Thread Pool – 54) JBAS015537: Activating WebServices Extension
09:10:26,892 INFO [org.jboss.as.naming] (MSC service thread 1-5) JBAS011802: Starting Naming Service
09:10:26,945 INFO [org.jboss.as.mail.extension] (MSC service thread 1-6) JBAS015400: Bound mail session [java:jboss/mail/Default]
09:10:27,251 INFO [org.jboss.as.connector.subsystems.datasources] (ServerService Thread Pool – 30) JBAS010403: Deploying JDBC-compliant driver class org.h2.Driver (version 1.3)
09:10:27,404 INFO [org.jboss.ws.common.management.AbstractServerConfig] (MSC service thread 1-1) JBoss Web Services - Stack CXF Server 4.1.0.Beta1
09:10:27,563 INFO [org.apache.coyote.http11.Http11Protocol] (MSC service thread 1-6) Starting Coyote HTTP/1.1 on http-/127.0.0.1:8180
09:10:27,572 INFO [org.apache.coyote.ajp.AjpProtocol] (MSC service thread 1-4) Starting Coyote AJP/1.3 on ajp-/127.0.0.1:8109
09:10:27,724 INFO [org.jboss.modcluster.ModClusterService] (ServerService Thread Pool – 56) Initializing mod_cluster 1.2.1.Final
09:10:27,814 INFO [org.jboss.modcluster.advertise.impl.AdvertiseListenerImpl] (ServerService Thread Pool – 56) Listening to proxy advertisements on 224.0.1.105:23,364
09:10:27,990 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (ServerService Thread Pool – 34) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:28,001 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (ServerService Thread Pool – 34) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:28,116 INFO [org.jboss.as.remoting] (MSC service thread 1-1) JBAS017100: Listening on 127.0.0.1:10099
09:10:28,121 INFO [org.jboss.as.remoting] (MSC service thread 1-5) JBAS017100: Listening on 127.0.0.1:4547
09:10:28,123 INFO [org.jboss.as.server.deployment.scanner] (MSC service thread 1-6) JBAS015012: Started FileSystemDeploymentService for directory /home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/target/jbossas-clustering-udp-1/standalone/deployments
09:10:28,135 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-6) JBAS010400: Bound data source [java:jboss/datasources/ExampleDS]
09:10:28,251 INFO [org.jboss.as] (Controller Boot Thread) JBAS015961: Http management interface listening on http://127.0.0.1:10090/management
09:10:28,252 INFO [org.jboss.as] (Controller Boot Thread) JBAS015951: Admin console listening on http://127.0.0.1:10090
09:10:28,253 INFO [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss AS 7.2.0.Alpha1-SNAPSHOT "Steropes" started in 4323ms - Started 138 of 285 services (146 services are passive or on-demand)
09:10:30,467 INFO [org.jboss.as.repository] (management-handler-thread - 2) JBAS014900: Content added at location /home/jenkins/jenkins-work/workspace/as7-master-testsuite/testsuite/integration/clust/target/jbossas-clustering-udp-1/standalone/data/content/24/dc3242e01ad0f0e794838ac801d7826a102a72/content
09:10:30,526 INFO [org.jboss.as.server.deployment] (MSC service thread 1-2) JBAS015876: Starting deployment of "stateful.war"
09:10:30,915 INFO [org.jboss.as.jpa] (MSC service thread 1-5) JBAS011401: Read persistence.xml for mypc
09:10:30,928 INFO [org.jboss.osgi.framework] (MSC service thread 1-1) JBOSGI011006: OSGi Framework - 2.0.0.CR12
09:10:31,372 INFO [org.jboss.as.ejb3.deployment.processors.EjbJndiBindingsDeploymentUnitProcessor] (MSC service thread 1-5) JNDI bindings for session bean named StatefulBean in deployment unit deployment "stateful.war" are as follows:

java:global/stateful/StatefulBean!org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Stateful
java:app/stateful/StatefulBean!org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Stateful
java:module/StatefulBean!org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Stateful
java:global/stateful/StatefulBean
java:app/stateful/StatefulBean
java:module/StatefulBean

09:10:31,375 INFO [org.jboss.as.ejb3.deployment.processors.EjbJndiBindingsDeploymentUnitProcessor] (MSC service thread 1-5) JNDI bindings for session bean named SecondBean in deployment unit deployment "stateful.war" are as follows:

java:global/stateful/SecondBean!org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.SecondBean
java:app/stateful/SecondBean!org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.SecondBean
java:module/SecondBean!org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.SecondBean
java:global/stateful/SecondBean
java:app/stateful/SecondBean
java:module/SecondBean

09:10:32,389 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-3) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:32,407 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-6) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:32,450 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-6) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:32,886 WARN [org.jgroups.protocols.UDP] (ServerService Thread Pool – 7) send buffer of socket java.net.DatagramSocket@1280d11b was set to 640KB, but the OS only allocated 131.07KB. This might lead to performance problems. Please set your max send buffer in the OS correctly (e.g. net.core.wmem_max on Linux)
09:10:32,887 WARN [org.jgroups.protocols.UDP] (ServerService Thread Pool – 7) receive buffer of socket java.net.DatagramSocket@1280d11b was set to 20MB, but the OS only allocated 131.07KB. This might lead to performance problems. Please set your max receive buffer in the OS correctly (e.g. net.core.rmem_max on Linux)
09:10:32,888 WARN [org.jgroups.protocols.UDP] (ServerService Thread Pool – 7) send buffer of socket java.net.MulticastSocket@19a60a71 was set to 640KB, but the OS only allocated 131.07KB. This might lead to performance problems. Please set your max send buffer in the OS correctly (e.g. net.core.wmem_max on Linux)
09:10:32,888 WARN [org.jgroups.protocols.UDP] (ServerService Thread Pool – 7) receive buffer of socket java.net.MulticastSocket@19a60a71 was set to 25MB, but the OS only allocated 131.07KB. This might lead to performance problems. Please set your max receive buffer in the OS correctly (e.g. net.core.rmem_max on Linux)
09:10:32,913 INFO [stdout] (ServerService Thread Pool – 7)
09:10:32,913 INFO [stdout] (ServerService Thread Pool – 7) -------------------------------------------------------------------
09:10:32,914 INFO [stdout] (ServerService Thread Pool – 7) GMS: address=node-1/hibernate, cluster=hibernate, physical address=127.0.0.1:55300
09:10:32,914 INFO [stdout] (ServerService Thread Pool – 7) -------------------------------------------------------------------
09:10:32,964 INFO [stdout] (ServerService Thread Pool – 27)
09:10:32,964 INFO [stdout] (ServerService Thread Pool – 27) -------------------------------------------------------------------
09:10:32,965 INFO [stdout] (ServerService Thread Pool – 27) GMS: address=node-1/web, cluster=web, physical address=127.0.0.1:55300
09:10:32,965 INFO [stdout] (ServerService Thread Pool – 27) -------------------------------------------------------------------
09:10:32,997 INFO [stdout] (ServerService Thread Pool – 26)
09:10:32,997 INFO [stdout] (ServerService Thread Pool – 26) -------------------------------------------------------------------
09:10:32,998 INFO [stdout] (ServerService Thread Pool – 26) GMS: address=node-1/ejb, cluster=ejb, physical address=127.0.0.1:55300
09:10:32,998 INFO [stdout] (ServerService Thread Pool – 26) -------------------------------------------------------------------
09:10:33,033 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ViewHandler,hibernate,node-0/hibernate) ISPN000094: Received new cluster view: [node-0/hibernate|3] [node-0/hibernate, node-1/hibernate]
09:10:33,045 INFO [org.jboss.as.clustering] (ViewHandler,web,node-0/web) JBAS010225: New cluster view for partition web (id: 5, delta: 1, merge: false) : [node-0/web, node-1/web]
09:10:33,046 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ViewHandler,web,node-0/web) ISPN000094: Received new cluster view: [node-0/web|5] [node-0/web, node-1/web]
09:10:33,072 INFO [org.jboss.as.clustering] (ViewHandler,ejb,node-0/ejb) JBAS010225: New cluster view for partition ejb (id: 3, delta: 1, merge: false) : [node-0/ejb, node-1/ejb]
09:10:33,073 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ViewHandler,ejb,node-0/ejb) ISPN000094: Received new cluster view: [node-0/ejb|3] [node-0/ejb, node-1/ejb]
09:10:33,090 INFO [org.jboss.as.jpa] (ServerService Thread Pool – 27) JBAS011402: Starting Persistence Unit Service 'stateful.war#mypc'
09:10:33,206 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 26) ISPN000078: Starting JGroups Channel
09:10:33,206 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 28) ISPN000078: Starting JGroups Channel
09:10:33,231 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 26) ISPN000094: Received new cluster view: [node-0/ejb|3] [node-0/ejb, node-1/ejb]
09:10:33,232 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 26) ISPN000079: Cache local address is node-1/ejb, physical addresses are [127.0.0.1:55300]
09:10:33,234 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 28) ISPN000094: Received new cluster view: [node-0/web|5] [node-0/web, node-1/web]
09:10:33,235 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 28) ISPN000079: Cache local address is node-1/web, physical addresses are [127.0.0.1:55300]
09:10:33,258 INFO [org.infinispan.factories.GlobalComponentRegistry] (ServerService Thread Pool – 26) ISPN000128: Infinispan version: Infinispan 'Brahma' 5.1.5.FINAL
09:10:33,258 INFO [org.infinispan.factories.GlobalComponentRegistry] (ServerService Thread Pool – 28) ISPN000128: Infinispan version: Infinispan 'Brahma' 5.1.5.FINAL
09:10:33,269 INFO [org.infinispan.config.ConfigurationValidatingVisitor] (ServerService Thread Pool – 28) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:33,479 INFO [org.hibernate.annotations.common.Version] (ServerService Thread Pool – 27) HCANN000001: Hibernate Commons Annotations

{4.0.1.Final}

09:10:33,502 INFO [org.hibernate.Version] (ServerService Thread Pool – 27) HHH000412: Hibernate Core

{4.1.4.Final}

09:10:33,508 INFO [org.hibernate.cfg.Environment] (ServerService Thread Pool – 27) HHH000206: hibernate.properties not found
09:10:33,515 INFO [org.hibernate.cfg.Environment] (ServerService Thread Pool – 27) HHH000021: Bytecode provider name : javassist
09:10:33,599 INFO [org.hibernate.ejb.Ejb3Configuration] (ServerService Thread Pool – 27) HHH000204: Processing PersistenceUnitInfo [
name: mypc
...]
09:10:33,617 INFO [org.infinispan.config.ConfigurationValidatingVisitor] (ServerService Thread Pool – 7) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:33,722 INFO [org.infinispan.jmx.CacheJmxRegistration] (ServerService Thread Pool – 22) ISPN000031: MBeans were successfully registered to the platform mbean server.
09:10:33,734 INFO [org.infinispan.jmx.CacheJmxRegistration] (ServerService Thread Pool – 7) ISPN000031: MBeans were successfully registered to the platform mbean server.
09:10:33,750 INFO [org.infinispan.jmx.CacheJmxRegistration] (ServerService Thread Pool – 28) ISPN000031: MBeans were successfully registered to the platform mbean server.
09:10:33,763 INFO [org.infinispan.jmx.CacheJmxRegistration] (ServerService Thread Pool – 26) ISPN000031: MBeans were successfully registered to the platform mbean server.
09:10:33,958 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 28) JBAS010281: Started default-host/stateful cache from web container
09:10:33,958 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 26) JBAS010281: Started repl cache from ejb container
09:10:33,967 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 7) JBAS010281: Started repl cache from web container
09:10:34,002 INFO [org.jboss.as.clustering] (MSC service thread 1-4) JBAS010238: Number of cluster members: 2
09:10:34,005 INFO [org.jboss.as.clustering] (MSC service thread 1-3) JBAS010238: Number of cluster members: 2
09:10:34,106 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 22) JBAS010281: Started remote-connector-client-mappings cache from ejb container
09:10:34,205 INFO [org.infinispan.jmx.CacheJmxRegistration] (MSC service thread 1-2) ISPN000031: MBeans were successfully registered to the platform mbean server.
09:10:34,243 INFO [org.infinispan.jmx.CacheJmxRegistration] (MSC service thread 1-4) ISPN000031: MBeans were successfully registered to the platform mbean server.
09:10:34,264 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-4) JBAS010281: Started org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.SecondBean cache from ejb container
09:10:34,283 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-2) JBAS010281: Started org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulBean cache from ejb container
09:10:34,328 INFO [org.hibernate.service.jdbc.connections.internal.ConnectionProviderInitiator] (ServerService Thread Pool – 27) HHH000130: Instantiating explicit connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider
09:10:34,593 INFO [org.hibernate.dialect.Dialect] (ServerService Thread Pool – 27) HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
09:10:34,599 WARN [org.hibernate.dialect.H2Dialect] (ServerService Thread Pool – 27) HHH000431: Unable to determine H2 database version, certain features may not work
09:10:34,604 INFO [org.hibernate.engine.jdbc.internal.LobCreatorBuilder] (ServerService Thread Pool – 27) HHH000423: Disabling contextual LOB creation as JDBC driver reported JDBC version [3] less than 4
09:10:34,614 INFO [org.hibernate.engine.transaction.internal.TransactionFactoryInitiator] (ServerService Thread Pool – 27) HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jta.CMTTransactionFactory
09:10:34,619 INFO [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (ServerService Thread Pool – 27) HHH000397: Using ASTQueryTranslatorFactory
09:10:34,679 INFO [org.hibernate.validator.util.Version] (ServerService Thread Pool – 27) Hibernate Validator 4.2.0.Final
09:10:34,969 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 27) ISPN000078: Starting JGroups Channel
09:10:34,972 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 27) ISPN000094: Received new cluster view: [node-0/hibernate|3] [node-0/hibernate, node-1/hibernate]
09:10:34,973 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (ServerService Thread Pool – 27) ISPN000079: Cache local address is node-1/hibernate, physical addresses are [127.0.0.1:55300]
09:10:35,009 INFO [org.infinispan.jmx.CacheJmxRegistration] (ServerService Thread Pool – 27) ISPN000031: MBeans were successfully registered to the platform mbean server.
09:10:35,046 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool – 27) JBAS010281: Started stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee cache from hibernate container
09:10:35,247 INFO [org.hibernate.tool.hbm2ddl.SchemaExport] (ServerService Thread Pool – 27) HHH000227: Running hbm2ddl schema export
09:10:35,256 INFO [stdout] (ServerService Thread Pool – 27) Hibernate: drop table Employee if exists
09:10:35,257 INFO [stdout] (ServerService Thread Pool – 27) Hibernate: create table Employee (id integer not null, address varchar(255), name varchar(255), primary key (id))
09:10:35,258 INFO [org.hibernate.tool.hbm2ddl.SchemaExport] (ServerService Thread Pool – 27) HHH000230: Schema export complete
09:10:35,328 INFO [org.jboss.web] (MSC service thread 1-6) JBAS018210: Register web context: /stateful
09:10:35,390 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-6) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:35,418 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-6) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:35,420 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-6) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:35,422 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-6) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
09:10:35,824 INFO [org.jboss.as.server] (management-handler-thread - 2) JBAS018559: Deployed "stateful.war"
Wed Jul 18 09:10:36 EDT 2012started deployment=deployment-1, container=container-1
Wed Jul 18 09:10:36 EDT 20122. started node2 + deployed, about to read entity on node1
09:10:36,626 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:36,632 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:36,633 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:36,633 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:36,633 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 1
09:10:36,634 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:36,634 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:36,634 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:36,635 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:36,635 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:36,635 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 0
09:10:36,636 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 0
09:10:36,636 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:36,636 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:36,637 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:36,637 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 0
09:10:36,637 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:36,638 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:36,638 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:36,638 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:36,638 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:36,639 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:36,639 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:36,639 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:36,640 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:36,640 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:36,640 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:36,641 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:36,641 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:36,641 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:36,642 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:36,642 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:36,642 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:36,643 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:36,643 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:36,643 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:36,644 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:36,644 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:36,644 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:36,645 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:36,646 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:36,682 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:36,760 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:36,907 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:36,908 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:36,909 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:36,909 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:36,909 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 2
09:10:36,910 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:36,910 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:36,910 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:36,911 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:36,911 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:36,911 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 1
09:10:36,911 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 1
09:10:36,912 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:36,912 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:36,912 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:36,913 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 1
09:10:36,913 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:36,913 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:36,914 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:36,914 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:36,914 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:36,915 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:36,915 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:36,915 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:36,916 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:36,916 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:36,916 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:36,917 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:36,917 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:36,917 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:36,918 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:36,918 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:36,918 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:36,918 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:36,919 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:36,919 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:36,919 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:36,920 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:36,920 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:36,920 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:36,921 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=1,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:36,924 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:36,932 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:37,050 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:37,051 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:37,052 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:37,052 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:37,053 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 3
09:10:37,053 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:37,053 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:37,054 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:37,054 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:37,054 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:37,055 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 2
09:10:37,055 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 2
09:10:37,056 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:37,057 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:37,057 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:37,057 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 2
09:10:37,058 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:37,058 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:37,058 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:37,059 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:37,059 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:37,059 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:37,060 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:37,060 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:37,060 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:37,061 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:37,061 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:37,061 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:37,062 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:37,062 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:37,062 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:37,063 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:37,063 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:37,063 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:37,063 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:37,064 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:37,064 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:37,064 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:37,065 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:37,065 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:37,066 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=2,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:37,067 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:37,073 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:37,196 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:37,200 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:37,201 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:37,202 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:37,202 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 4
09:10:37,203 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:37,203 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:37,204 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:37,204 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:37,205 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:37,205 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 3
09:10:37,206 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 3
09:10:37,207 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:37,207 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:37,211 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:37,212 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 3
09:10:37,213 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:37,214 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:37,215 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:37,217 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:37,218 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:37,219 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:37,220 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:37,221 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:37,221 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:37,222 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:37,223 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:37,224 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:37,225 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:37,226 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:37,226 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:37,227 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:37,228 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:37,229 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:37,230 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:37,231 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:37,232 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:37,233 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:37,233 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:37,234 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:37,236 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=3,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:37,239 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:37,254 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:37,398 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:37,402 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:37,404 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:37,405 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:37,406 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 5
09:10:37,407 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:37,408 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:37,409 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:37,410 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:37,411 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:37,412 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 4
09:10:37,413 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 4
09:10:37,414 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:37,415 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:37,416 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:37,417 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 4
09:10:37,418 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:37,419 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:37,420 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:37,421 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:37,422 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:37,423 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:37,424 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:37,425 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:37,426 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:37,427 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:37,428 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:37,429 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:37,430 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:37,431 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:37,432 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:37,433 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:37,434 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:37,435 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:37,436 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:37,437 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:37,438 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:37,440 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:37,441 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:37,442 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:37,444 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=4,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:37,446 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:37,463 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:37,613 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:37,617 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:37,619 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:37,620 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:37,621 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 6
09:10:37,621 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:37,622 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:37,623 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:37,624 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:37,625 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:37,626 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 5
09:10:37,627 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 5
09:10:37,627 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:37,628 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:37,629 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:37,630 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 5
09:10:37,631 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:37,632 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:37,633 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:37,633 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:37,634 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:37,635 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:37,636 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:37,637 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:37,637 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:37,638 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:37,639 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:37,640 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:37,641 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:37,642 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:37,642 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:37,643 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:37,644 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:37,645 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:37,646 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:37,647 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:37,648 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:37,648 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:37,649 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:37,650 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:37,652 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=5,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:37,655 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:37,668 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:37,808 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:37,812 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:37,813 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:37,814 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:37,815 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 7
09:10:37,816 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:37,817 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:37,817 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:37,818 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:37,819 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:37,821 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 6
09:10:37,822 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 6
09:10:37,823 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:37,823 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:37,824 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:37,825 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 6
09:10:37,826 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:37,827 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:37,828 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:37,828 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:37,829 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:37,830 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:37,831 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:37,832 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:37,832 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:37,833 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:37,834 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:37,835 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:37,836 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:37,837 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:37,837 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:37,838 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:37,839 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:37,840 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:37,841 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:37,842 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:37,843 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:37,844 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:37,845 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:37,846 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:37,847 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=6,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:37,850 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:37,866 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:38,009 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:38,014 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:38,015 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:38,016 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:38,017 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 8
09:10:38,018 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:38,019 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:38,020 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:38,021 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:38,022 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:38,022 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 7
09:10:38,023 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 7
09:10:38,024 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:38,024 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:38,025 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:38,026 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 7
09:10:38,027 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:38,028 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:38,029 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:38,030 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:38,031 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:38,032 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:38,033 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:38,034 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:38,035 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:38,036 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:38,037 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:38,038 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:38,039 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:38,040 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:38,041 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:38,042 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:38,043 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:38,044 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:38,045 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:38,046 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:38,047 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:38,048 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:38,049 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:38,050 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:38,052 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=7,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:38,055 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:38,082 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:38,225 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:38,229 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:38,230 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:38,231 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:38,232 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 9
09:10:38,233 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:38,234 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:38,234 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:38,235 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:38,236 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:38,237 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 8
09:10:38,238 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 8
09:10:38,239 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:38,239 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:38,240 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:38,241 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 8
09:10:38,243 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:38,244 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:38,244 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:38,245 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:38,246 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:38,247 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:38,248 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:38,249 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:38,250 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:38,250 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:38,251 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:38,252 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:38,253 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:38,254 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:38,255 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:38,255 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:38,256 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:38,257 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:38,258 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:38,259 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:38,260 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:38,261 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:38,261 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:38,262 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:38,264 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=8,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:38,267 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:38,281 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:38,413 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:38,415 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:38,415 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:38,415 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:38,416 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 10
09:10:38,416 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:38,416 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:38,417 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:38,417 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:38,417 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:38,417 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 9
09:10:38,418 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 9
09:10:38,418 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:38,418 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:38,419 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:38,419 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 9
09:10:38,419 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:38,419 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:38,420 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:38,420 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:38,420 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:38,420 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:38,421 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:38,421 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:38,422 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:38,423 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:38,423 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:38,423 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:38,423 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:38,424 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:38,424 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:38,424 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:38,425 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:38,425 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:38,425 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:38,425 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:38,426 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:38,426 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:38,426 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:38,427 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:38,427 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=9,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:38,428 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:38,439 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:38,559 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:38,561 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:38,561 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:38,562 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:38,562 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 11
09:10:38,562 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:38,562 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:38,563 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:38,563 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:38,563 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:38,563 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 10
09:10:38,564 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 10
09:10:38,564 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:38,564 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:38,564 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:38,565 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 10
09:10:38,565 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:38,565 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:38,566 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:38,566 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:38,566 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:38,566 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:38,567 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:38,567 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:38,567 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:38,567 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:38,568 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:38,568 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:38,568 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:38,569 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:38,569 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:38,570 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:38,570 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:38,570 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:38,570 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:38,571 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:38,571 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:38,571 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:38,571 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:38,572 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:38,573 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=10,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:38,574 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:38,580 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:38,712 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:38,716 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:38,717 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:38,718 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:38,719 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 12
09:10:38,720 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:38,720 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:38,721 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:38,722 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:38,723 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:38,723 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 11
09:10:38,724 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 11
09:10:38,725 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:38,725 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:38,726 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:38,727 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 11
09:10:38,728 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:38,728 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:38,729 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:38,730 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:38,730 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:38,731 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:38,732 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:38,733 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:38,733 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:38,734 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:38,735 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:38,735 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:38,736 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:38,737 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:38,738 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:38,738 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:38,739 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:38,740 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:38,740 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:38,741 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:38,742 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:38,743 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:38,744 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:38,745 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:38,746 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=11,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:38,757 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:38,788 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]

09:10:38,931 INFO [stdout] (http-/127.0.0.1:8180-1) org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet: command = getEmployee
09:10:38,936 INFO [stdout] (http-/127.0.0.1:8180-1) getEmployee 1(version=initial, HashMap version=null) logging statistics for session = SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[] unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])
09:10:38,937 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000161: Logging statistics....
09:10:38,938 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000251: Start time: 1342617035266
09:10:38,939 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000242: Sessions opened: 13
09:10:38,940 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000241: Sessions closed: 0
09:10:38,941 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000266: Transactions: 0
09:10:38,942 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000258: Successful transactions: 0
09:10:38,943 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000187: Optimistic lock failures: 0
09:10:38,944 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000105: Flushes: 0
09:10:38,945 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000048: Connections obtained: 12
09:10:38,946 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000253: Statements prepared: 12
09:10:38,947 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000252: Statements closed: 0
09:10:38,948 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000239: Second level cache puts: 0
09:10:38,949 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000237: Second level cache hits: 0
09:10:38,950 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000238: Second level cache misses: 12
09:10:38,951 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000079: Entities loaded: 0
09:10:38,952 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000080: Entities updated: 0
09:10:38,953 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000078: Entities inserted: 0
09:10:38,954 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000076: Entities deleted: 0
09:10:38,955 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000077: Entities fetched (minimize this): 0
09:10:38,956 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000033: Collections loaded: 0
09:10:38,957 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000036: Collections updated: 0
09:10:38,958 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000035: Collections removed: 0
09:10:38,959 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000034: Collections recreated: 0
09:10:38,959 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000032: Collections fetched (minimize this): 0
09:10:38,960 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000438: NaturalId cache puts: 0
09:10:38,961 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000439: NaturalId cache hits: 0
09:10:38,962 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000440: NaturalId cache misses: 0
09:10:38,964 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000441: Max NaturalId query time: 0ms
09:10:38,965 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000442: NaturalId queries executed to database: 0
09:10:39,050 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000210: Queries executed to database: 0
09:10:39,050 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000215: Query cache puts: 0
09:10:39,051 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000433: update timestamps cache puts: 0
09:10:39,051 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000434: update timestamps cache hits: 0
09:10:39,051 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000435: update timestamps cache misses: 0
09:10:39,052 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000213: Query cache hits: 0
09:10:39,053 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000214: Query cache misses: 0
09:10:39,054 INFO [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (http-/127.0.0.1:8180-1) HHH000173: Max query time: 0ms
09:10:39,055 INFO [stdout] (http-/127.0.0.1:8180-1) cache entity region name = stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee
09:10:39,057 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: SecondLevelCacheStatistics[hitCount=0,missCount=12,putCount=0,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
09:10:39,059 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: select employee0_.id as id0_0_, employee0_.address as address0_0_, employee0_.name as name0_0_ from Employee employee0_ where employee0_.id=?
09:10:39,074 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/stateful].[org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet]] (http-/127.0.0.1:8180-1) Servlet.service() for servlet org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet threw exception: javax.servlet.ServletException: couldn't load Employee entity (with id=1) from database
at org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.StatefulServlet.doGet(StatefulServlet.java:73) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final.jar:1.0.2.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.16.Final.jar:]
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.event(JBossWebContext.java:67)
at org.jboss.modcluster.container.jbossweb.JBossWebContext$RequestListenerValve.invoke(JBossWebContext.java:48)
at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:125) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:156) [jboss-as-web-7.2.0.Alpha1-SNAPSHOT.jar:7.2.0.Alpha1-SNAPSHOT]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.16.Final.jar:]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.16.Final.jar:]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:679) [jbossweb-7.0.16.Final.jar:]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.16.Final.jar:]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_29]