Maven hangs while running test case Eclipselink & hsqldb

Question

Using jps and jstack I can get to the offending waiting thread but don't know how to troubleshoot it or what is causing it. See below the Maven dependencies and the jstack result and the waiting thread with tid=0x000000000022c000. Analysing further it seems an issue between Eclipselink and hsqldb for the chosen versions. I got this issue as result of upgrading those two libraries since it used to work perfectly for versions 2.0.1 and 1.8.0.10 of Eclipselink and hsqldb respectively.

<dependencies>
 <dependency>
    <groupId>org.eclipse.persistence</groupId>
    <artifactId>eclipselink</artifactId>
    <version>2.4.0</version>
  </dependency> 
 <dependency>
   <groupId>org.hsqldb</groupId>
   <artifactId>hsqldb</artifactId>
   <version>2.2.9</version>
   <scope>test</scope>
 </dependency>                
</dependencies>
<repositories>
<repository>
   <id>EclipseLink</id>
   <url>http://download.eclipse.org/rt/eclipselink/maven.repo</url>
</repository>

and the stacktrace is:

$ jstack 7552
2012-12-21 22:48:53
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.12-b01 mixed mode):

"Low Memory Detector" daemon prio=6 tid=0x0000000006a19000 nid=0x1e00 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x0000000006a0a800 nid=0x2184 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00000000069f5000 nid=0x754 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" daemon prio=10 tid=0x00000000069f3800 nid=0x219c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00000000069a1800 nid=0x2198 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x000000000699f000 nid=0x2384 in Object.wait() [0x00000000075ef000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000007aef280e0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        - locked <0x00000007aef280e0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x0000000006990800 nid=0x21cc in Object.wait() [0x00000000074ef000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000007aef38070> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x00000007aef38070> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x000000000022c000 nid=0xbc0 waiting on condition [0x000000000220c000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000007acd840a0> (a java.util.concurrent.CountDownLatch$Sync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
        at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:207)
        at org.hsqldb.lib.CountUpDownLatch.await(Unknown Source)
        at org.hsqldb.Session.executeCompiledStatement(Unknown Source)
        at org.hsqldb.Session.execute(Unknown Source)
        - locked <0x00000007acd83f70> (a org.hsqldb.Session)
        at org.hsqldb.jdbc.JDBCPreparedStatement.fetchResult(Unknown Source)
        at org.hsqldb.jdbc.JDBCPreparedStatement.executeQuery(Unknown Source)
        - locked <0x00000007acdb2518> (a org.hsqldb.jdbc.JDBCPreparedStatement)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeSelect(DatabaseAccessor.java:938)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:609)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:537)
        at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:1800)
        at org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:566)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:207)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:193)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:264)
        at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:648)
        at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2681)
        at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2634)
        at org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:420)
        at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1149)
        at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:852)
        at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1108)
        at org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:392)
        at org.eclipse.persistence.internal.sessions.AbstractSession.internalExecuteQuery(AbstractSession.java:2946)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1602)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1584)
        at org.eclipse.persistence.sessions.server.ServerSession.executeQuery(ServerSession.java:621)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1448)
        at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1423)
        at org.perfectjpattern.jee.integration.dao.ReadQueryAdapter.getResultList(ReadQueryAdapter.java:79)
        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.perfectjpattern.core.structural.AbstractSurrogate.invoke(AbstractSurrogate.java:115)
        at $Proxy2.getResultList(Unknown Source)
        at org.perfectjpattern.jee.integration.dao.JpaBaseDao.findByNamedQuery(JpaBaseDao.java:158)
        at org.perfectjpattern.support.test.AbstractTestBaseReadOnlyDao.testFindByNamedQueryPositional(AbstractTestBaseReadOnlyDao.java:100)
        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 junit.framework.TestCase.runTest(TestCase.java:168)
        at junit.framework.TestCase.runBare(TestCase.java:134)
        at junit.framework.TestResult$1.protect(TestResult.java:110)
        at junit.framework.TestResult.runProtected(TestResult.java:128)
        at junit.framework.TestResult.run(TestResult.java:113)
        at junit.framework.TestCase.run(TestCase.java:124)
        at junit.framework.TestSuite.runTest(TestSuite.java:232)
        at junit.framework.TestSuite.run(TestSuite.java:227)
        at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83)
        at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:123)
        at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:104)
        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:164)
        at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:110)
        at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:175)
        at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcessWhenForked(SurefireStarter.java:107)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:68)

Answer 1

It does indeed look like a hsqldb issue. Following directions from here the solution was to append the following to the connection-url ;hsqldb.tx=mvcc whatever that means :/

Answer 2

For me this meant that I was using hibernate.hbm2ddl.auto "update" as well as using raw connections to connect to the same HSQL in memory DB. Separating the two into separate in-memory HSQL db's and it started working. Current theory: maybe something is holding onto a session or transaction (esp. one that modifies a whole table) and not closing it? (unfortunately the mvcc fix mentioned didn't help in my case)

hsqldb version 2.3.4, hibernate 4.0.1.Final

my trace:

"main" #1 prio=5 os_prio=31 tid=0x00007fb636001000 nid=0x1303 waiting on condition [0x000000010a68c000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000007957cbd18> (a org.hsqldb.lib.CountUpDownLatch$Sync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
    at org.hsqldb.lib.CountUpDownLatch.await(Unknown Source)
    at org.hsqldb.Session.executeCompiledStatement(Unknown Source)
    at org.hsqldb.Session.execute(Unknown Source)
    - locked <0x00000007957cbbe0> (a org.hsqldb.Session)
    at org.hsqldb.jdbc.JDBCPreparedStatement.fetchResult(Unknown Source)

also ran into it even more with hsqldb version 2.3.4, hibernate 4.1.12.Final

4.0.1.Final worked OK though weird.