[JBoss JIRA] (ISPN-6439) Improve stability of ExampleConfigsIT.testLevelDBCacheStoreConfig
by Sebastian Łaskawiec (JIRA)
[ https://issues.jboss.org/browse/ISPN-6439?page=com.atlassian.jira.plugin.... ]
Sebastian Łaskawiec updated ISPN-6439:
--------------------------------------
Status: Pull Request Sent (was: Open)
Git Pull Request: https://github.com/infinispan/infinispan/pull/4183
> Improve stability of ExampleConfigsIT.testLevelDBCacheStoreConfig
> -----------------------------------------------------------------
>
> Key: ISPN-6439
> URL: https://issues.jboss.org/browse/ISPN-6439
> Project: Infinispan
> Issue Type: Bug
> Reporter: Sebastian Łaskawiec
> Assignee: Sebastian Łaskawiec
>
> http://ci.infinispan.org/viewLog.html?buildId=37942&tab=buildResultsDiv&b...
> {code}
> java.lang.AssertionError: expected:<v0> but was:<null>
> at org.junit.Assert.fail(Assert.java:88)
> at org.junit.Assert.failNotEquals(Assert.java:743)
> at org.junit.Assert.assertEquals(Assert.java:118)
> at org.junit.Assert.assertEquals(Assert.java:144)
> at org.infinispan.server.test.configs.ExampleConfigsIT.doPutGet(ExampleConfigsIT.java:660)
> at org.infinispan.server.test.configs.ExampleConfigsIT.doPutGetCheckPath(ExampleConfigsIT.java:667)
> at org.infinispan.server.test.configs.ExampleConfigsIT.testLevelDBCacheStoreConfig(ExampleConfigsIT.java:297)
> ------- Stdout: -------
> &#27;[0m18:34:35,724 INFO [org.jboss.modules] (main) JBoss Modules version 1.5.1.Final
> &#27;[0m&#27;[0m18:34:35,974 INFO [org.jboss.msc] (main) JBoss MSC version 1.2.6.Final
> &#27;[0m&#27;[0m18:34:36,084 INFO [org.jboss.as] (MSC service thread 1-7) WFLYSRV0049: Infinispan Server 9.0.0-SNAPSHOT (WildFly Core 2.0.10.Final) starting
> &#27;[0m&#27;[0m18:34:37,773 INFO [org.jboss.as.server] (Controller Boot Thread) WFLYSRV0039: Creating http management service using socket-binding (management-http)
> &#27;[0m&#27;[0m18:34:37,806 INFO [org.xnio] (MSC service thread 1-5) XNIO version 3.3.4.Final
> &#27;[0m&#27;[0m18:34:37,820 INFO [org.xnio.nio] (MSC service thread 1-5) XNIO NIO Implementation Version 3.3.4.Final
> &#27;[0m&#27;[0m18:34:37,888 INFO [org.jboss.remoting] (MSC service thread 1-5) JBoss Remoting version 4.0.18.Final
> &#27;[0m&#27;[0m18:34:37,897 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 19) Activating Infinispan subsystem.
> &#27;[0m&#27;[0m18:34:37,920 INFO [org.wildfly.extension.io] (ServerService Thread Pool -- 21) WFLYIO001: Worker 'default' has auto-configured to 8 core threads with 64 task threads based on your 4 available processors
> &#27;[0m&#27;[0m18:34:37,979 INFO [org.jboss.as.naming] (ServerService Thread Pool -- 25) WFLYNAM0001: Activating Naming Subsystem
> &#27;[0m&#27;[33m18:34:37,994 WARN [org.jboss.as.txn] (ServerService Thread Pool -- 29) WFLYTX0013: Node identifier property is set to the default value. Please make sure it is unique.
> &#27;[0m&#27;[0m18:34:38,008 INFO [org.jboss.as.connector] (MSC service thread 1-3) WFLYJCA0009: Starting JCA Subsystem (WildFly/IronJacamar 1.3.2.Final)
> &#27;[0m&#27;[0m18:34:38,013 INFO [org.jboss.as.security] (ServerService Thread Pool -- 27) WFLYSEC0002: Activating Security Subsystem
> &#27;[0m&#27;[0m18:34:38,051 INFO [org.jboss.as.security] (MSC service thread 1-6) WFLYSEC0001: Current PicketBox version=4.9.4.Final
> &#27;[0m&#27;[0m18:34:38,086 INFO [org.jboss.as.naming] (MSC service thread 1-4) WFLYNAM0003: Starting Naming Service
> &#27;[0m&#27;[0m18:34:38,146 INFO [org.jboss.as.connector.subsystems.datasources] (ServerService Thread Pool -- 18) WFLYJCA0004: Deploying JDBC-compliant driver class org.h2.Driver (version 1.3)
> &#27;[0m&#27;[0m18:34:38,163 INFO [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-8) WFLYJCA0018: Started Driver service with driver-name = h2
> &#27;[0m&#27;[0m18:34:38,549 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-8) WFLYJCA0001: Bound data source [java:jboss/datasources/ExampleDS]
> &#27;[0m&#27;[0m18:34:38,570 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (ServerService Thread Pool -- 19) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
> &#27;[0m&#27;[0m18:34:38,685 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0027: Starting deployment of "custom-store.jar" (runtime-name: "custom-store.jar")
> &#27;[0m&#27;[0m18:34:38,693 INFO [org.jboss.as.server.deployment.scanner] (MSC service thread 1-4) WFLYDS0013: Started FileSystemDeploymentService for directory /opt/buildAgent/work/64255532d1f9a010/server/integration/testsuite/target/server/node1/standalone/deployments
> &#27;[0m&#27;[0m18:34:39,187 INFO [org.infinispan.factories.GlobalComponentRegistry] (MSC service thread 1-2) ISPN000128: Infinispan version: Infinispan 'Chakra' 9.0.0-SNAPSHOT
> &#27;[0m&#27;[0m18:34:39,250 INFO [org.infinispan.server.endpoint] (MSC service thread 1-3) DGENDPT10000: REST starting
> &#27;[0m&#27;[0m18:34:39,254 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-4) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
> &#27;[0m&#27;[0m18:34:39,264 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-4) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
> &#27;[0m&#27;[0m18:34:39,267 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-4) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
> &#27;[0m&#27;[0m18:34:39,785 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-3) DGISPN0001: Started default cache from local container
> &#27;[0m&#27;[0m18:34:39,792 INFO [org.infinispan.server.endpoint] (MSC service thread 1-7) DGENDPT10000: HotRodServer starting
> &#27;[0m&#27;[0m18:34:39,793 INFO [org.infinispan.server.endpoint] (MSC service thread 1-7) DGENDPT10001: HotRodServer listening on 127.0.0.1:11222
> &#27;[0m&#27;[0m18:34:39,794 INFO [org.infinispan.server.endpoint] (MSC service thread 1-5) DGENDPT10000: WebSocketServer starting
> &#27;[0m&#27;[0m18:34:39,795 INFO [org.infinispan.server.endpoint] (MSC service thread 1-5) DGENDPT10001: WebSocketServer listening on 127.0.0.1:8181
> &#27;[0m&#27;[0m18:34:39,807 INFO [org.infinispan.persistence.leveldb.LevelDBStore] (MSC service thread 1-4) ISPN023006: Using pure Java LevelDB implementation: org.iq80.leveldb.impl.Iq80DBFactory
> &#27;[0m&#27;[0m18:34:39,862 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) DGISPN0007: Registering Deployed Cache Store service for store 'org.infinispan.persistence.cluster.MyCustomCacheStore'
> &#27;[0m&#27;[0m18:34:39,868 INFO [org.infinispan.persistence.leveldb.LevelDBStore] (MSC service thread 1-2) ISPN023005: Using JNI LevelDB implementation: org.fusesource.leveldbjni.JniDBFactory
> &#27;[0m&#27;[0m18:34:39,902 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-2) DGISPN0001: Started memcachedCache cache from local container
> &#27;[0m&#27;[0m18:34:39,903 INFO [org.infinispan.server.endpoint] (MSC service thread 1-2) DGENDPT10000: MemcachedServer starting
> &#27;[0m&#27;[0m18:34:39,903 INFO [org.infinispan.server.endpoint] (MSC service thread 1-2) DGENDPT10001: MemcachedServer listening on 127.0.0.1:11211
> &#27;[0m&#27;[0m18:34:39,908 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-3) DGISPN0001: Started ___protobuf_metadata cache from local container
> &#27;[0m&#27;[0m18:34:39,923 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-3) DGISPN0001: Started ___script_cache cache from local container
> &#27;[0m&#27;[0m18:34:40,166 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-4) DGISPN0001: Started namedCache cache from local container
> &#27;[0m&#27;[0m18:34:40,416 INFO [org.infinispan.rest.NettyRestServer] (MSC service thread 1-3) ISPN012003: REST server starting, listening on 127.0.0.1:8080
> &#27;[0m&#27;[0m18:34:40,416 INFO [org.infinispan.server.endpoint] (MSC service thread 1-3) DGENDPT10002: REST mapped to /rest
> &#27;[0m&#27;[0m18:34:40,439 INFO [org.jboss.as.server] (ServerService Thread Pool -- 17) WFLYSRV0010: Deployed "custom-store.jar" (runtime-name : "custom-store.jar")
> &#27;[0m&#27;[0m18:34:40,522 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0060: Http management interface listening on http://127.0.0.1:9990/management
> &#27;[0m&#27;[0m18:34:40,522 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0051: Admin console listening on http://127.0.0.1:9990
> &#27;[0m&#27;[0m18:34:40,522 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: Infinispan Server 9.0.0-SNAPSHOT (WildFly Core 2.0.10.Final) started in 5456ms - Started 176 of 182 services (46 services are lazy, passive or on-demand)
> &#27;[0m&#27;[0m18:34:41,888 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0211: Suspending server with 0ms timeout.
> &#27;[0m&#27;[0m18:34:41,893 INFO [org.jboss.as.server] (Thread-2) WFLYSRV0220: Server shutdown has been requested.
> &#27;[0m&#27;[0m18:34:42,011 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-7) WFLYJCA0010: Unbound data source [java:jboss/datasources/ExampleDS]
> &#27;[0m&#27;[0m18:34:42,126 INFO [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-2) WFLYJCA0019: Stopped Driver service with driver-name = h2
> &#27;[0m&#27;[0m18:34:42,142 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (MSC service thread 1-1) ISPN000029: Passivating all entries to disk
> &#27;[0m&#27;[0m18:34:42,188 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (MSC service thread 1-1) ISPN000030: Passivated 0 entries in 45 milliseconds
> &#27;[0m&#27;[0m18:34:42,224 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-5) DGISPN0002: Stopped memcachedCache cache from local container
> &#27;[0m&#27;[0m18:34:42,226 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-2) DGISPN0002: Stopped default cache from local container
> &#27;[0m&#27;[0m18:34:42,231 INFO [org.jboss.as.server.deployment] (MSC service thread 1-7) WFLYSRV0028: Stopped deployment custom-store.jar (runtime-name: custom-store.jar) in 295ms
> &#27;[0m&#27;[0m18:34:42,258 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) DGISPN0002: Stopped namedCache cache from local container
> &#27;[0m&#27;[0m18:34:42,282 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) DGISPN0002: Stopped ___protobuf_metadata cache from local container
> &#27;[0m&#27;[0m18:34:42,308 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) DGISPN0002: Stopped ___script_cache cache from local container
> &#27;[0m&#27;[0m18:34:42,328 INFO [org.jboss.as] (MSC service thread 1-8) WFLYSRV0050: Infinispan Server 9.0.0-SNAPSHOT (WildFly Core 2.0.10.Final) stopped in 392ms
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-6439) Improve stability of ExampleConfigsIT.testLevelDBCacheStoreConfig
by Sebastian Łaskawiec (JIRA)
Sebastian Łaskawiec created ISPN-6439:
-----------------------------------------
Summary: Improve stability of ExampleConfigsIT.testLevelDBCacheStoreConfig
Key: ISPN-6439
URL: https://issues.jboss.org/browse/ISPN-6439
Project: Infinispan
Issue Type: Bug
Reporter: Sebastian Łaskawiec
Assignee: Sebastian Łaskawiec
http://ci.infinispan.org/viewLog.html?buildId=37942&tab=buildResultsDiv&b...
{code}
java.lang.AssertionError: expected:<v0> but was:<null>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:743)
at org.junit.Assert.assertEquals(Assert.java:118)
at org.junit.Assert.assertEquals(Assert.java:144)
at org.infinispan.server.test.configs.ExampleConfigsIT.doPutGet(ExampleConfigsIT.java:660)
at org.infinispan.server.test.configs.ExampleConfigsIT.doPutGetCheckPath(ExampleConfigsIT.java:667)
at org.infinispan.server.test.configs.ExampleConfigsIT.testLevelDBCacheStoreConfig(ExampleConfigsIT.java:297)
------- Stdout: -------
&#27;[0m18:34:35,724 INFO [org.jboss.modules] (main) JBoss Modules version 1.5.1.Final
&#27;[0m&#27;[0m18:34:35,974 INFO [org.jboss.msc] (main) JBoss MSC version 1.2.6.Final
&#27;[0m&#27;[0m18:34:36,084 INFO [org.jboss.as] (MSC service thread 1-7) WFLYSRV0049: Infinispan Server 9.0.0-SNAPSHOT (WildFly Core 2.0.10.Final) starting
&#27;[0m&#27;[0m18:34:37,773 INFO [org.jboss.as.server] (Controller Boot Thread) WFLYSRV0039: Creating http management service using socket-binding (management-http)
&#27;[0m&#27;[0m18:34:37,806 INFO [org.xnio] (MSC service thread 1-5) XNIO version 3.3.4.Final
&#27;[0m&#27;[0m18:34:37,820 INFO [org.xnio.nio] (MSC service thread 1-5) XNIO NIO Implementation Version 3.3.4.Final
&#27;[0m&#27;[0m18:34:37,888 INFO [org.jboss.remoting] (MSC service thread 1-5) JBoss Remoting version 4.0.18.Final
&#27;[0m&#27;[0m18:34:37,897 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 19) Activating Infinispan subsystem.
&#27;[0m&#27;[0m18:34:37,920 INFO [org.wildfly.extension.io] (ServerService Thread Pool -- 21) WFLYIO001: Worker 'default' has auto-configured to 8 core threads with 64 task threads based on your 4 available processors
&#27;[0m&#27;[0m18:34:37,979 INFO [org.jboss.as.naming] (ServerService Thread Pool -- 25) WFLYNAM0001: Activating Naming Subsystem
&#27;[0m&#27;[33m18:34:37,994 WARN [org.jboss.as.txn] (ServerService Thread Pool -- 29) WFLYTX0013: Node identifier property is set to the default value. Please make sure it is unique.
&#27;[0m&#27;[0m18:34:38,008 INFO [org.jboss.as.connector] (MSC service thread 1-3) WFLYJCA0009: Starting JCA Subsystem (WildFly/IronJacamar 1.3.2.Final)
&#27;[0m&#27;[0m18:34:38,013 INFO [org.jboss.as.security] (ServerService Thread Pool -- 27) WFLYSEC0002: Activating Security Subsystem
&#27;[0m&#27;[0m18:34:38,051 INFO [org.jboss.as.security] (MSC service thread 1-6) WFLYSEC0001: Current PicketBox version=4.9.4.Final
&#27;[0m&#27;[0m18:34:38,086 INFO [org.jboss.as.naming] (MSC service thread 1-4) WFLYNAM0003: Starting Naming Service
&#27;[0m&#27;[0m18:34:38,146 INFO [org.jboss.as.connector.subsystems.datasources] (ServerService Thread Pool -- 18) WFLYJCA0004: Deploying JDBC-compliant driver class org.h2.Driver (version 1.3)
&#27;[0m&#27;[0m18:34:38,163 INFO [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-8) WFLYJCA0018: Started Driver service with driver-name = h2
&#27;[0m&#27;[0m18:34:38,549 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-8) WFLYJCA0001: Bound data source [java:jboss/datasources/ExampleDS]
&#27;[0m&#27;[0m18:34:38,570 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (ServerService Thread Pool -- 19) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
&#27;[0m&#27;[0m18:34:38,685 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0027: Starting deployment of "custom-store.jar" (runtime-name: "custom-store.jar")
&#27;[0m&#27;[0m18:34:38,693 INFO [org.jboss.as.server.deployment.scanner] (MSC service thread 1-4) WFLYDS0013: Started FileSystemDeploymentService for directory /opt/buildAgent/work/64255532d1f9a010/server/integration/testsuite/target/server/node1/standalone/deployments
&#27;[0m&#27;[0m18:34:39,187 INFO [org.infinispan.factories.GlobalComponentRegistry] (MSC service thread 1-2) ISPN000128: Infinispan version: Infinispan 'Chakra' 9.0.0-SNAPSHOT
&#27;[0m&#27;[0m18:34:39,250 INFO [org.infinispan.server.endpoint] (MSC service thread 1-3) DGENDPT10000: REST starting
&#27;[0m&#27;[0m18:34:39,254 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-4) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
&#27;[0m&#27;[0m18:34:39,264 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-4) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
&#27;[0m&#27;[0m18:34:39,267 INFO [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (MSC service thread 1-4) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
&#27;[0m&#27;[0m18:34:39,785 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-3) DGISPN0001: Started default cache from local container
&#27;[0m&#27;[0m18:34:39,792 INFO [org.infinispan.server.endpoint] (MSC service thread 1-7) DGENDPT10000: HotRodServer starting
&#27;[0m&#27;[0m18:34:39,793 INFO [org.infinispan.server.endpoint] (MSC service thread 1-7) DGENDPT10001: HotRodServer listening on 127.0.0.1:11222
&#27;[0m&#27;[0m18:34:39,794 INFO [org.infinispan.server.endpoint] (MSC service thread 1-5) DGENDPT10000: WebSocketServer starting
&#27;[0m&#27;[0m18:34:39,795 INFO [org.infinispan.server.endpoint] (MSC service thread 1-5) DGENDPT10001: WebSocketServer listening on 127.0.0.1:8181
&#27;[0m&#27;[0m18:34:39,807 INFO [org.infinispan.persistence.leveldb.LevelDBStore] (MSC service thread 1-4) ISPN023006: Using pure Java LevelDB implementation: org.iq80.leveldb.impl.Iq80DBFactory
&#27;[0m&#27;[0m18:34:39,862 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) DGISPN0007: Registering Deployed Cache Store service for store 'org.infinispan.persistence.cluster.MyCustomCacheStore'
&#27;[0m&#27;[0m18:34:39,868 INFO [org.infinispan.persistence.leveldb.LevelDBStore] (MSC service thread 1-2) ISPN023005: Using JNI LevelDB implementation: org.fusesource.leveldbjni.JniDBFactory
&#27;[0m&#27;[0m18:34:39,902 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-2) DGISPN0001: Started memcachedCache cache from local container
&#27;[0m&#27;[0m18:34:39,903 INFO [org.infinispan.server.endpoint] (MSC service thread 1-2) DGENDPT10000: MemcachedServer starting
&#27;[0m&#27;[0m18:34:39,903 INFO [org.infinispan.server.endpoint] (MSC service thread 1-2) DGENDPT10001: MemcachedServer listening on 127.0.0.1:11211
&#27;[0m&#27;[0m18:34:39,908 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-3) DGISPN0001: Started ___protobuf_metadata cache from local container
&#27;[0m&#27;[0m18:34:39,923 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-3) DGISPN0001: Started ___script_cache cache from local container
&#27;[0m&#27;[0m18:34:40,166 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-4) DGISPN0001: Started namedCache cache from local container
&#27;[0m&#27;[0m18:34:40,416 INFO [org.infinispan.rest.NettyRestServer] (MSC service thread 1-3) ISPN012003: REST server starting, listening on 127.0.0.1:8080
&#27;[0m&#27;[0m18:34:40,416 INFO [org.infinispan.server.endpoint] (MSC service thread 1-3) DGENDPT10002: REST mapped to /rest
&#27;[0m&#27;[0m18:34:40,439 INFO [org.jboss.as.server] (ServerService Thread Pool -- 17) WFLYSRV0010: Deployed "custom-store.jar" (runtime-name : "custom-store.jar")
&#27;[0m&#27;[0m18:34:40,522 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0060: Http management interface listening on http://127.0.0.1:9990/management
&#27;[0m&#27;[0m18:34:40,522 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0051: Admin console listening on http://127.0.0.1:9990
&#27;[0m&#27;[0m18:34:40,522 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: Infinispan Server 9.0.0-SNAPSHOT (WildFly Core 2.0.10.Final) started in 5456ms - Started 176 of 182 services (46 services are lazy, passive or on-demand)
&#27;[0m&#27;[0m18:34:41,888 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0211: Suspending server with 0ms timeout.
&#27;[0m&#27;[0m18:34:41,893 INFO [org.jboss.as.server] (Thread-2) WFLYSRV0220: Server shutdown has been requested.
&#27;[0m&#27;[0m18:34:42,011 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-7) WFLYJCA0010: Unbound data source [java:jboss/datasources/ExampleDS]
&#27;[0m&#27;[0m18:34:42,126 INFO [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-2) WFLYJCA0019: Stopped Driver service with driver-name = h2
&#27;[0m&#27;[0m18:34:42,142 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (MSC service thread 1-1) ISPN000029: Passivating all entries to disk
&#27;[0m&#27;[0m18:34:42,188 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (MSC service thread 1-1) ISPN000030: Passivated 0 entries in 45 milliseconds
&#27;[0m&#27;[0m18:34:42,224 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-5) DGISPN0002: Stopped memcachedCache cache from local container
&#27;[0m&#27;[0m18:34:42,226 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-2) DGISPN0002: Stopped default cache from local container
&#27;[0m&#27;[0m18:34:42,231 INFO [org.jboss.as.server.deployment] (MSC service thread 1-7) WFLYSRV0028: Stopped deployment custom-store.jar (runtime-name: custom-store.jar) in 295ms
&#27;[0m&#27;[0m18:34:42,258 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) DGISPN0002: Stopped namedCache cache from local container
&#27;[0m&#27;[0m18:34:42,282 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) DGISPN0002: Stopped ___protobuf_metadata cache from local container
&#27;[0m&#27;[0m18:34:42,308 INFO [org.jboss.as.clustering.infinispan] (MSC service thread 1-1) DGISPN0002: Stopped ___script_cache cache from local container
&#27;[0m&#27;[0m18:34:42,328 INFO [org.jboss.as] (MSC service thread 1-8) WFLYSRV0050: Infinispan Server 9.0.0-SNAPSHOT (WildFly Core 2.0.10.Final) stopped in 392ms
{code}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-6098) LockManagerTest.testMultipleCounterStripped random failures
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-6098?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-6098:
-------------------------------
Attachment: (was: LocalTopKeyTest.log.gz)
> LockManagerTest.testMultipleCounterStripped random failures
> -----------------------------------------------------------
>
> Key: ISPN-6098
> URL: https://issues.jboss.org/browse/ISPN-6098
> Project: Infinispan
> Issue Type: Bug
> Components: Test Suite - Core
> Affects Versions: 8.1.0.Final
> Reporter: Dan Berindei
> Assignee: Pedro Ruivo
> Fix For: 9.0.0.Alpha1
>
> Attachments: LockManagerTest_ISPN-3305_remove_lock_reordering_tests_20160324.log.gz
>
>
> Doesn't appear to fail in CI, but I did get a couple failures running the test on my machine:
> {noformat}
> 17:42:29,998 ERROR (testng-LockManagerTest:) [UnitTestTestNGListener] Test testMultipleCounterStripped(org.infinispan.lock.LockManagerTest) failed.
> java.util.concurrent.ExecutionException: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key key-6 and requestor Thread[pool-1127-thread-4,5,main]. Lock is held by null
> at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_60]
> at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_60]
> at org.infinispan.lock.LockManagerTest.doMultipleCounterTest(LockManagerTest.java:193) ~[test-classes/:?]
> at org.infinispan.lock.LockManagerTest.testMultipleCounterStripped(LockManagerTest.java:67) ~[test-classes/:?]
> Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key key-6 and requestor Thread[pool-1127-thread-4,5,main]. Lock is held by null
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236) ~[classes/:?]
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305) ~[classes/:?]
> at org.infinispan.lock.LockManagerTest.lambda$doMultipleCounterTest$483(LockManagerTest.java:163) ~[test-classes/:?]
> ... 4 more
> {noformat}
> In another run, I got a deadlock that I think is related in {{InfinispanLockTest}}:
> {noformat}
> "testng-InfinispanLockTest" #19 prio=5 os_prio=0 tid=0x00007ff7f0eeb800 nid=0x4f5d waiting on condition [0x00007ff770da5000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x0000000084202448> (a java.util.concurrent.FutureTask)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
> at java.util.concurrent.FutureTask.get(FutureTask.java:191)
> at org.infinispan.lock.InfinispanLockTest.testSingleCounter(InfinispanLockTest.java:262)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:497)
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84)
> at org.testng.internal.Invoker.invokeMethod(Invoker.java:714)
> at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901)
> at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231)
> at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
> at org.testng.TestRunner.privateRun(TestRunner.java:767)
> at org.testng.TestRunner.run(TestRunner.java:617)
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:348)
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:38)
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382)
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x0000000082875cc0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> "pool-1011-thread-7" #9840 prio=5 os_prio=0 tid=0x00007ff7380da000 nid=0x75f7 waiting on condition [0x00007ff698409000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000000842020d8> (a java.util.concurrent.CompletableFuture$Signaller)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695)
> at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
> at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775)
> at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
> at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:74)
> at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lock(InfinispanLock.java:319)
> at org.infinispan.lock.InfinispanLockTest.lambda$testSingleCounter$509(InfinispanLockTest.java:243)
> at org.infinispan.lock.InfinispanLockTest$$Lambda$516/1905052434.call(Unknown Source)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x00000000842021f8> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> "pool-1011-thread-6" #9839 prio=5 os_prio=0 tid=0x00007ff738130800 nid=0x75f6 waiting on condition [0x00007ff699c21000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000000842023a0> (a java.util.concurrent.CompletableFuture$Signaller)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695)
> at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
> at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775)
> at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
> at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:74)
> at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lock(InfinispanLock.java:319)
> at org.infinispan.lock.InfinispanLockTest.lambda$testSingleCounter$509(InfinispanLockTest.java:243)
> at org.infinispan.lock.InfinispanLockTest$$Lambda$516/1905052434.call(Unknown Source)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x0000000084202468> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> {noformat}
> I also suggest using {{AbstractInfinispanTest.fork()}} instead of an explicit {{ExecutorService}} in both tests, because without the test name in the thread name it's impossible to filter the test logs.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-6098) LockManagerTest.testMultipleCounterStripped random failures
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-6098?page=com.atlassian.jira.plugin.... ]
Dan Berindei edited comment on ISPN-6098 at 3/24/16 1:54 PM:
-------------------------------------------------------------
-May be related to the random failures in LocalTopKeyTest, I've attached a log.-
LocalTopKeyTest log moved to ISPN-6437
was (Author: dan.berindei):
May be related to the random failures in LocalTopKeyTest, I've attached a log.
> LockManagerTest.testMultipleCounterStripped random failures
> -----------------------------------------------------------
>
> Key: ISPN-6098
> URL: https://issues.jboss.org/browse/ISPN-6098
> Project: Infinispan
> Issue Type: Bug
> Components: Test Suite - Core
> Affects Versions: 8.1.0.Final
> Reporter: Dan Berindei
> Assignee: Pedro Ruivo
> Fix For: 9.0.0.Alpha1
>
> Attachments: LockManagerTest_ISPN-3305_remove_lock_reordering_tests_20160324.log.gz
>
>
> Doesn't appear to fail in CI, but I did get a couple failures running the test on my machine:
> {noformat}
> 17:42:29,998 ERROR (testng-LockManagerTest:) [UnitTestTestNGListener] Test testMultipleCounterStripped(org.infinispan.lock.LockManagerTest) failed.
> java.util.concurrent.ExecutionException: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key key-6 and requestor Thread[pool-1127-thread-4,5,main]. Lock is held by null
> at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_60]
> at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_60]
> at org.infinispan.lock.LockManagerTest.doMultipleCounterTest(LockManagerTest.java:193) ~[test-classes/:?]
> at org.infinispan.lock.LockManagerTest.testMultipleCounterStripped(LockManagerTest.java:67) ~[test-classes/:?]
> Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key key-6 and requestor Thread[pool-1127-thread-4,5,main]. Lock is held by null
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236) ~[classes/:?]
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305) ~[classes/:?]
> at org.infinispan.lock.LockManagerTest.lambda$doMultipleCounterTest$483(LockManagerTest.java:163) ~[test-classes/:?]
> ... 4 more
> {noformat}
> In another run, I got a deadlock that I think is related in {{InfinispanLockTest}}:
> {noformat}
> "testng-InfinispanLockTest" #19 prio=5 os_prio=0 tid=0x00007ff7f0eeb800 nid=0x4f5d waiting on condition [0x00007ff770da5000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x0000000084202448> (a java.util.concurrent.FutureTask)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
> at java.util.concurrent.FutureTask.get(FutureTask.java:191)
> at org.infinispan.lock.InfinispanLockTest.testSingleCounter(InfinispanLockTest.java:262)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:497)
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84)
> at org.testng.internal.Invoker.invokeMethod(Invoker.java:714)
> at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901)
> at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231)
> at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
> at org.testng.TestRunner.privateRun(TestRunner.java:767)
> at org.testng.TestRunner.run(TestRunner.java:617)
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:348)
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:38)
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382)
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x0000000082875cc0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> "pool-1011-thread-7" #9840 prio=5 os_prio=0 tid=0x00007ff7380da000 nid=0x75f7 waiting on condition [0x00007ff698409000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000000842020d8> (a java.util.concurrent.CompletableFuture$Signaller)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695)
> at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
> at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775)
> at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
> at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:74)
> at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lock(InfinispanLock.java:319)
> at org.infinispan.lock.InfinispanLockTest.lambda$testSingleCounter$509(InfinispanLockTest.java:243)
> at org.infinispan.lock.InfinispanLockTest$$Lambda$516/1905052434.call(Unknown Source)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x00000000842021f8> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> "pool-1011-thread-6" #9839 prio=5 os_prio=0 tid=0x00007ff738130800 nid=0x75f6 waiting on condition [0x00007ff699c21000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000000842023a0> (a java.util.concurrent.CompletableFuture$Signaller)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695)
> at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
> at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775)
> at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
> at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:74)
> at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lock(InfinispanLock.java:319)
> at org.infinispan.lock.InfinispanLockTest.lambda$testSingleCounter$509(InfinispanLockTest.java:243)
> at org.infinispan.lock.InfinispanLockTest$$Lambda$516/1905052434.call(Unknown Source)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x0000000084202468> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> {noformat}
> I also suggest using {{AbstractInfinispanTest.fork()}} instead of an explicit {{ExecutorService}} in both tests, because without the test name in the thread name it's impossible to filter the test logs.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-6437) InfinispanLock.LockPlaceHolder sometimes doesn't invoke its listeners
by Dan Berindei (JIRA)
Dan Berindei created ISPN-6437:
----------------------------------
Summary: InfinispanLock.LockPlaceHolder sometimes doesn't invoke its listeners
Key: ISPN-6437
URL: https://issues.jboss.org/browse/ISPN-6437
Project: Infinispan
Issue Type: Bug
Components: Core, Test Suite - Core
Affects Versions: 8.2.0.Final
Reporter: Dan Berindei
Assignee: Pedro Ruivo
Fix For: 9.0.0.Alpha1
When {{InfinispanLock.LockPlaceHolder.lock()}} times out in the {{await()}} call, it doesn't CAS the state and it doesn't run the listeners.
Listeners are used by the extended statistics module, and missed invocations cause random failures in {{LocalTopKeyTest}}:
{noformat}
17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [DefaultLockManager] Lock key=key for owner=GlobalTransaction:<null>:34:local. timeout=100 (MILLISECONDS)
17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Acquire lock for GlobalTransaction:<null>:34:local. Timeout=100 (MILLISECONDS)
17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Created a new one: LockPlaceHolder{lockState=WAITING, owner=GlobalTransaction:<null>:34:local}
17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=GlobalTransaction:<null>:34:local}. Current=LockPlaceHolder{lockState=ACQUIRED, owner=GlobalTransaction:<null>:33:local}
17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Unable to acquire. Lock is held.
17:44:50,515 ERROR (testng-LocalTopKeyTest:[___defaultcache]) [InvocationContextInterceptor] ISPN000136: Error executing command VersionedPrepareCommand, writing keys [key]
org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 100 milliseconds for key key and requestor GlobalTransaction:<null>:34:local. Lock is held by GlobalTransaction:<null>:33:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:200) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:200) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:166) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:70) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:153) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:140) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.stats.topK.LocalTopKeyTest$PrepareCommandBlocker.visitPrepareCommand(LocalTopKeyTest.java:229) ~[test-classes/:?]
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.stats.topK.CacheUsageInterceptor.visitPrepareCommand(CacheUsageInterceptor.java:78) ~[classes/:?]
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:79) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:335) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.transaction.impl.TransactionCoordinator.prepare(TransactionCoordinator.java:121) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.transaction.impl.TransactionCoordinator.prepare(TransactionCoordinator.java:104) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:111) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:698) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2364) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1518) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1200) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
at org.infinispan.cache.impl.CacheImpl.tryCommit(CacheImpl.java:1679) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.cache.impl.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1636) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.cache.impl.CacheImpl.putInternal(CacheImpl.java:1163) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1153) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1699) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:241) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
at org.infinispan.stats.topK.LocalTopKeyTest.testLockFailed(LocalTopKeyTest.java:84) [test-classes/:?]
17:44:50,581 ERROR (testng-LocalTopKeyTest:[]) [UnitTestTestNGListener] Test testLockFailed(org.infinispan.stats.topK.LocalTopKeyTest) failed.
java.lang.AssertionError: Wrong number of locked keys expected [2] but found [1]
at org.testng.Assert.fail(Assert.java:94) ~[testng-6.8.8.jar:?]
at org.testng.Assert.failNotEquals(Assert.java:494) ~[testng-6.8.8.jar:?]
at org.testng.Assert.assertEquals(Assert.java:123) ~[testng-6.8.8.jar:?]
at org.testng.Assert.assertEquals(Assert.java:265) ~[testng-6.8.8.jar:?]
at org.infinispan.stats.topK.LocalTopKeyTest.assertTopKeyLocked(LocalTopKeyTest.java:188) ~[test-classes/:?]
at org.infinispan.stats.topK.LocalTopKeyTest.assertLockInformation(LocalTopKeyTest.java:204) ~[test-classes/:?]
at org.infinispan.stats.topK.LocalTopKeyTest.testLockFailed(LocalTopKeyTest.java:96) ~[test-classes/:?]
{noformat}
{{Log.unableToAcquireLock}} doesn't log the cause exception, but it seems unlikely that the timeout came from somewhere else.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-6437) InfinispanLock.LockPlaceHolder sometimes doesn't invoke its listeners
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-6437?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-6437:
-------------------------------
Status: Open (was: New)
> InfinispanLock.LockPlaceHolder sometimes doesn't invoke its listeners
> ---------------------------------------------------------------------
>
> Key: ISPN-6437
> URL: https://issues.jboss.org/browse/ISPN-6437
> Project: Infinispan
> Issue Type: Bug
> Components: Core, Test Suite - Core
> Affects Versions: 8.2.0.Final
> Reporter: Dan Berindei
> Assignee: Pedro Ruivo
> Labels: testsuite_stability
> Fix For: 9.0.0.Alpha1
>
> Attachments: LocalTopKeyTest.log.gz
>
>
> When {{InfinispanLock.LockPlaceHolder.lock()}} times out in the {{await()}} call, it doesn't CAS the state and it doesn't run the listeners.
> Listeners are used by the extended statistics module, and missed invocations cause random failures in {{LocalTopKeyTest}}:
> {noformat}
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [DefaultLockManager] Lock key=key for owner=GlobalTransaction:<null>:34:local. timeout=100 (MILLISECONDS)
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Acquire lock for GlobalTransaction:<null>:34:local. Timeout=100 (MILLISECONDS)
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Created a new one: LockPlaceHolder{lockState=WAITING, owner=GlobalTransaction:<null>:34:local}
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=GlobalTransaction:<null>:34:local}. Current=LockPlaceHolder{lockState=ACQUIRED, owner=GlobalTransaction:<null>:33:local}
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Unable to acquire. Lock is held.
> 17:44:50,515 ERROR (testng-LocalTopKeyTest:[___defaultcache]) [InvocationContextInterceptor] ISPN000136: Error executing command VersionedPrepareCommand, writing keys [key]
> org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 100 milliseconds for key key and requestor GlobalTransaction:<null>:34:local. Lock is held by GlobalTransaction:<null>:33:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:200) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:200) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:166) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:70) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:153) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:140) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.stats.topK.LocalTopKeyTest$PrepareCommandBlocker.visitPrepareCommand(LocalTopKeyTest.java:229) ~[test-classes/:?]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.stats.topK.CacheUsageInterceptor.visitPrepareCommand(CacheUsageInterceptor.java:78) ~[classes/:?]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:79) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:335) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.transaction.impl.TransactionCoordinator.prepare(TransactionCoordinator.java:121) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.transaction.impl.TransactionCoordinator.prepare(TransactionCoordinator.java:104) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:111) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:698) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2364) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1518) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1200) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at org.infinispan.cache.impl.CacheImpl.tryCommit(CacheImpl.java:1679) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1636) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.putInternal(CacheImpl.java:1163) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1153) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1699) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:241) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.stats.topK.LocalTopKeyTest.testLockFailed(LocalTopKeyTest.java:84) [test-classes/:?]
> 17:44:50,581 ERROR (testng-LocalTopKeyTest:[]) [UnitTestTestNGListener] Test testLockFailed(org.infinispan.stats.topK.LocalTopKeyTest) failed.
> java.lang.AssertionError: Wrong number of locked keys expected [2] but found [1]
> at org.testng.Assert.fail(Assert.java:94) ~[testng-6.8.8.jar:?]
> at org.testng.Assert.failNotEquals(Assert.java:494) ~[testng-6.8.8.jar:?]
> at org.testng.Assert.assertEquals(Assert.java:123) ~[testng-6.8.8.jar:?]
> at org.testng.Assert.assertEquals(Assert.java:265) ~[testng-6.8.8.jar:?]
> at org.infinispan.stats.topK.LocalTopKeyTest.assertTopKeyLocked(LocalTopKeyTest.java:188) ~[test-classes/:?]
> at org.infinispan.stats.topK.LocalTopKeyTest.assertLockInformation(LocalTopKeyTest.java:204) ~[test-classes/:?]
> at org.infinispan.stats.topK.LocalTopKeyTest.testLockFailed(LocalTopKeyTest.java:96) ~[test-classes/:?]
> {noformat}
> {{Log.unableToAcquireLock}} doesn't log the cause exception, but it seems unlikely that the timeout came from somewhere else.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-6437) InfinispanLock.LockPlaceHolder sometimes doesn't invoke its listeners
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-6437?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-6437:
-------------------------------
Attachment: LocalTopKeyTest.log.gz
> InfinispanLock.LockPlaceHolder sometimes doesn't invoke its listeners
> ---------------------------------------------------------------------
>
> Key: ISPN-6437
> URL: https://issues.jboss.org/browse/ISPN-6437
> Project: Infinispan
> Issue Type: Bug
> Components: Core, Test Suite - Core
> Affects Versions: 8.2.0.Final
> Reporter: Dan Berindei
> Assignee: Pedro Ruivo
> Labels: testsuite_stability
> Fix For: 9.0.0.Alpha1
>
> Attachments: LocalTopKeyTest.log.gz
>
>
> When {{InfinispanLock.LockPlaceHolder.lock()}} times out in the {{await()}} call, it doesn't CAS the state and it doesn't run the listeners.
> Listeners are used by the extended statistics module, and missed invocations cause random failures in {{LocalTopKeyTest}}:
> {noformat}
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [DefaultLockManager] Lock key=key for owner=GlobalTransaction:<null>:34:local. timeout=100 (MILLISECONDS)
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Acquire lock for GlobalTransaction:<null>:34:local. Timeout=100 (MILLISECONDS)
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Created a new one: LockPlaceHolder{lockState=WAITING, owner=GlobalTransaction:<null>:34:local}
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=GlobalTransaction:<null>:34:local}. Current=LockPlaceHolder{lockState=ACQUIRED, owner=GlobalTransaction:<null>:33:local}
> 17:44:50,412 TRACE (testng-LocalTopKeyTest:[___defaultcache]) [InfinispanLock] Unable to acquire. Lock is held.
> 17:44:50,515 ERROR (testng-LocalTopKeyTest:[___defaultcache]) [InvocationContextInterceptor] ISPN000136: Error executing command VersionedPrepareCommand, writing keys [key]
> org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 100 milliseconds for key key and requestor GlobalTransaction:<null>:34:local. Lock is held by GlobalTransaction:<null>:33:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:200) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:200) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:166) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:70) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:153) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:140) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.stats.topK.LocalTopKeyTest$PrepareCommandBlocker.visitPrepareCommand(LocalTopKeyTest.java:229) ~[test-classes/:?]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.stats.topK.CacheUsageInterceptor.visitPrepareCommand(CacheUsageInterceptor.java:78) ~[classes/:?]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99) ~[infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:79) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:176) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:335) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.transaction.impl.TransactionCoordinator.prepare(TransactionCoordinator.java:121) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.transaction.impl.TransactionCoordinator.prepare(TransactionCoordinator.java:104) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:111) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:698) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2364) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1518) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1200) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jta-5.0.4.Final.jar:5.0.4.Final (revision: b4060)]
> at org.infinispan.cache.impl.CacheImpl.tryCommit(CacheImpl.java:1679) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1636) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.putInternal(CacheImpl.java:1163) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1153) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1699) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:241) [infinispan-core-9.0.0-SNAPSHOT.jar:9.0.0-SNAPSHOT]
> at org.infinispan.stats.topK.LocalTopKeyTest.testLockFailed(LocalTopKeyTest.java:84) [test-classes/:?]
> 17:44:50,581 ERROR (testng-LocalTopKeyTest:[]) [UnitTestTestNGListener] Test testLockFailed(org.infinispan.stats.topK.LocalTopKeyTest) failed.
> java.lang.AssertionError: Wrong number of locked keys expected [2] but found [1]
> at org.testng.Assert.fail(Assert.java:94) ~[testng-6.8.8.jar:?]
> at org.testng.Assert.failNotEquals(Assert.java:494) ~[testng-6.8.8.jar:?]
> at org.testng.Assert.assertEquals(Assert.java:123) ~[testng-6.8.8.jar:?]
> at org.testng.Assert.assertEquals(Assert.java:265) ~[testng-6.8.8.jar:?]
> at org.infinispan.stats.topK.LocalTopKeyTest.assertTopKeyLocked(LocalTopKeyTest.java:188) ~[test-classes/:?]
> at org.infinispan.stats.topK.LocalTopKeyTest.assertLockInformation(LocalTopKeyTest.java:204) ~[test-classes/:?]
> at org.infinispan.stats.topK.LocalTopKeyTest.testLockFailed(LocalTopKeyTest.java:96) ~[test-classes/:?]
> {noformat}
> {{Log.unableToAcquireLock}} doesn't log the cause exception, but it seems unlikely that the timeout came from somewhere else.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-6098) LockManagerTest.testMultipleCounterStripped random failures
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-6098?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-6098:
-------------------------------
Attachment: LocalTopKeyTest.log.gz
May be related to the random failures in LocalTopKeyTest, I've attached a log.
> LockManagerTest.testMultipleCounterStripped random failures
> -----------------------------------------------------------
>
> Key: ISPN-6098
> URL: https://issues.jboss.org/browse/ISPN-6098
> Project: Infinispan
> Issue Type: Bug
> Components: Test Suite - Core
> Affects Versions: 8.1.0.Final
> Reporter: Dan Berindei
> Assignee: Pedro Ruivo
> Fix For: 9.0.0.Alpha1
>
> Attachments: LocalTopKeyTest.log.gz, LockManagerTest_ISPN-3305_remove_lock_reordering_tests_20160324.log.gz
>
>
> Doesn't appear to fail in CI, but I did get a couple failures running the test on my machine:
> {noformat}
> 17:42:29,998 ERROR (testng-LockManagerTest:) [UnitTestTestNGListener] Test testMultipleCounterStripped(org.infinispan.lock.LockManagerTest) failed.
> java.util.concurrent.ExecutionException: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key key-6 and requestor Thread[pool-1127-thread-4,5,main]. Lock is held by null
> at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_60]
> at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_60]
> at org.infinispan.lock.LockManagerTest.doMultipleCounterTest(LockManagerTest.java:193) ~[test-classes/:?]
> at org.infinispan.lock.LockManagerTest.testMultipleCounterStripped(LockManagerTest.java:67) ~[test-classes/:?]
> Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key key-6 and requestor Thread[pool-1127-thread-4,5,main]. Lock is held by null
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236) ~[classes/:?]
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305) ~[classes/:?]
> at org.infinispan.lock.LockManagerTest.lambda$doMultipleCounterTest$483(LockManagerTest.java:163) ~[test-classes/:?]
> ... 4 more
> {noformat}
> In another run, I got a deadlock that I think is related in {{InfinispanLockTest}}:
> {noformat}
> "testng-InfinispanLockTest" #19 prio=5 os_prio=0 tid=0x00007ff7f0eeb800 nid=0x4f5d waiting on condition [0x00007ff770da5000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x0000000084202448> (a java.util.concurrent.FutureTask)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
> at java.util.concurrent.FutureTask.get(FutureTask.java:191)
> at org.infinispan.lock.InfinispanLockTest.testSingleCounter(InfinispanLockTest.java:262)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:497)
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84)
> at org.testng.internal.Invoker.invokeMethod(Invoker.java:714)
> at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901)
> at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231)
> at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
> at org.testng.TestRunner.privateRun(TestRunner.java:767)
> at org.testng.TestRunner.run(TestRunner.java:617)
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:348)
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:38)
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382)
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x0000000082875cc0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> "pool-1011-thread-7" #9840 prio=5 os_prio=0 tid=0x00007ff7380da000 nid=0x75f7 waiting on condition [0x00007ff698409000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000000842020d8> (a java.util.concurrent.CompletableFuture$Signaller)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695)
> at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
> at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775)
> at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
> at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:74)
> at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lock(InfinispanLock.java:319)
> at org.infinispan.lock.InfinispanLockTest.lambda$testSingleCounter$509(InfinispanLockTest.java:243)
> at org.infinispan.lock.InfinispanLockTest$$Lambda$516/1905052434.call(Unknown Source)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x00000000842021f8> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> "pool-1011-thread-6" #9839 prio=5 os_prio=0 tid=0x00007ff738130800 nid=0x75f6 waiting on condition [0x00007ff699c21000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000000842023a0> (a java.util.concurrent.CompletableFuture$Signaller)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695)
> at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
> at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775)
> at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
> at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:74)
> at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lock(InfinispanLock.java:319)
> at org.infinispan.lock.InfinispanLockTest.lambda$testSingleCounter$509(InfinispanLockTest.java:243)
> at org.infinispan.lock.InfinispanLockTest$$Lambda$516/1905052434.call(Unknown Source)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Locked ownable synchronizers: - <0x0000000084202468> (a java.util.concurrent.ThreadPoolExecutor$Worker)
> {noformat}
> I also suggest using {{AbstractInfinispanTest.fork()}} instead of an explicit {{ExecutorService}} in both tests, because without the test name in the thread name it's impossible to filter the test logs.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months