[JBoss JIRA] (AS7-5342) SAR MBean String attributes cannot be longer than about 3650 characters
by John Mazzitelli (JIRA)
John Mazzitelli created AS7-5342:
------------------------------------
Summary: SAR MBean String attributes cannot be longer than about 3650 characters
Key: AS7-5342
URL: https://issues.jboss.org/browse/AS7-5342
Project: Application Server 7
Issue Type: Feature Request
Affects Versions: 7.1.1.Final
Reporter: John Mazzitelli
I have a SAR. One of the MBean attributes is a String (actually, for my real use-case the value is a Properties object, but due to JIRA AS7-5336, there are other problems, but let's just go with String attribute type, because the same problem I will describe happens with that type, too)
If the string value is longer than around 3650 characters the beginning of the string is stripped (I can't nail it down to a specific value, but its around that number, give or take 10 characters or so)
For example, if I have this in jboss-service.xml:
<attribute name="MyStrAttrib">
This is a really long string.
...[lots of characters here]...
It has more than 3650
characters in it.
</attribute>
What my MBean setter (setMyStrAttrib(String s)) will be passed is something like "aracters in it." The characters at index 0 through ~3650 are missing, I only have the parts after it.
In my real example, the reason why the string is so long is that its a Properties string with lots of name/value pairs. I ended up working around AS7-5336 but then I hit this issue.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.jboss.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
11 years, 9 months
[JBoss JIRA] (AS7-5558) More useful error messages when management operations can't be found
by Brian Stansberry (JIRA)
Brian Stansberry created AS7-5558:
-------------------------------------
Summary: More useful error messages when management operations can't be found
Key: AS7-5558
URL: https://issues.jboss.org/browse/AS7-5558
Project: Application Server 7
Issue Type: Enhancement
Components: Domain Management
Reporter: Brian Stansberry
Fix For: 7.2.0.CR1
When the ModelController attempts to find the OperationStepHandler for a given operation + address, it needs to handle failure more intelligently. Instead of providing a one-size fits all exception, it should try to determine why the OSH couldn't be found and tailor the exception accordingly. Specifically, clarify whether the problem is the address is invalid or the operation name is invalid, and if it's the address that's invalid, clarify the point in the resource tree where the address goes wrong.
For example, a user attempting to administer a server that has already been shut down gets this fairly useless exception:
Error loading VM metrics
Unexpected HTTP response: 500
Request
{
"operation" => "composite",
"address" => [],
"steps" => [
{
"address" => [
("host" => "master"),
("server" => "server-one"),
("core-service" => "platform-mbean"),
("type" => "memory")
],
"operation" => "read-resource",
"include-runtime" => true
},
{
"address" => [
("host" => "master"),
("server" => "server-one"),
("core-service" => "platform-mbean"),
("type" => "threading")
],
"operation" => "read-resource",
"include-runtime" => true
},
{
"address" => [
("host" => "master"),
("server" => "server-one"),
("core-service" => "platform-mbean"),
("type" => "runtime")
],
"operation" => "read-resource",
"include-runtime" => true
},
{
"address" => [
("host" => "master"),
("server" => "server-one"),
("core-service" => "platform-mbean"),
("type" => "operating-system")
],
"operation" => "read-resource",
"include-runtime" => true
}
]
}
Response
Internal Server Error
{
"outcome" => "failed",
"failure-description" => "JBAS010850: No handler for operation read-resource at address [
(\"host\" => \"master\"),
(\"server\" => \"server-one\"),
(\"core-service\" => \"platform-mbean\"),
(\"type\" => \"memory\")
]",
"rolled-back" => true
}
The reality is no resource exists at address /host=master/server=server-one. The failure message should emphasize this fact.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
11 years, 9 months
[JBoss JIRA] (AS7-5209) StatefulWithXPCFailoverTestCase intermittently fails
by Jason Greene (JIRA)
Jason Greene created AS7-5209:
---------------------------------
Summary: StatefulWithXPCFailoverTestCase intermittently fails
Key: AS7-5209
URL: https://issues.jboss.org/browse/AS7-5209
Project: Application Server 7
Issue Type: Bug
Components: Clustering
Reporter: Jason Greene
Assignee: Paul Ferraro
Fix For: 7.1.3.Final (EAP), 7.2.0.CR1
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]
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.jboss.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
11 years, 9 months