SYS lock timeout on connection close

[Андрей Турбанов]

Hello.

I'm trying to update H2 used in our tests from 1.3.154 to 1.4.190

After test finish I can see such exceptions:

org.h2.jdbc.JdbcSQLException: Timeout trying to lock table "SYS" [50200-190]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
    at org.h2.message.DbException.get(DbException.java:179)
    at org.h2.message.DbException.get(DbException.java:155)
    at org.h2.mvstore.db.MVTable.doLock1(MVTable.java:223)
    at org.h2.mvstore.db.MVTable.lock(MVTable.java:167)
    at org.h2.engine.Database.lockMeta(Database.java:896)
    at org.h2.engine.Database.removeMeta(Database.java:919)
    at org.h2.table.Table.removeChildrenAndResources(Table.java:525)
    at org.h2.mvstore.db.MVTable.removeChildrenAndResources(MVTable.java:799)
    at org.h2.engine.Session.cleanTempTables(Session.java:830)
    at org.h2.engine.Session.close(Session.java:708)
    at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:383)
    at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
    at com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:621)
    at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1065)
    at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1090)
    at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1051)
    at com.mchange.v2.resourcepool.BasicResourcePool.access$100(BasicResourcePool.java:44)
    at com.mchange.v2.resourcepool.BasicResourcePool$5.run(BasicResourcePool.java:1305)

How to I can find cause of that?

JDBC connection string:
jdbc:h2:mem:test;MODE=PostgreSQL;DB_CLOSE_DELAY=-1;LOCK_TIMEOUT=10000;MVCC=TRUE

[Noel Grandin]

when that happens, perform a thread dump of all the threads, and post that here, we should be able to tell you who is
locking that table.

http://crunchify.com/how-to-generate-java-thread-dump-programmatically/

[Андрей Турбанов]

Full thread dump

2016-01-17 23:52:02
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.60-b23 mixed mode):

"Thread-1" #44 prio=5 os_prio=0 tid=0x000000001c418800 nid=0x922c in Object.wait() [0x0000000018ffe000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.h2.mvstore.db.MVTable.doLock1(MVTable.java:242)
    at org.h2.mvstore.db.MVTable.lock(MVTable.java:167)
    - locked <0x00000000c0313ce0> (a org.h2.engine.Database)

    at org.h2.engine.Database.lockMeta(Database.java:896)
    at org.h2.engine.Database.removeMeta(Database.java:919)

    - locked <0x00000000c0313ce0> (a org.h2.engine.Database)

    at org.h2.table.Table.removeChildrenAndResources(Table.java:525)
    at org.h2.mvstore.db.MVTable.removeChildrenAndResources(MVTable.java:799)
    at org.h2.engine.Session.cleanTempTables(Session.java:830)

    - locked <0x00000000c0313ce0> (a org.h2.engine.Database)
    at org.h2.engine.Session.close(Session.java:708)
    at org.h2.engine.Database.closeAllSessionsException(Database.java:1186)
    - locked <0x00000000c0313ce0> (a org.h2.engine.Database)
    at org.h2.engine.Database.close(Database.java:1224)
    - locked <0x00000000c0313ce0> (a org.h2.engine.Database)
    at org.h2.engine.DatabaseCloser.run(DatabaseCloser.java:63)

   Locked ownable synchronizers:
    - None

"Resource Destroyer in BasicResourcePool.close()" #110 daemon prio=5 os_prio=0 tid=0x000000001c41a000 nid=0x2d44 in Object.wait() [0x000000001b6ae000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.h2.mvstore.db.MVTable.doLock1(MVTable.java:242)
    at org.h2.mvstore.db.MVTable.lock(MVTable.java:167)
    - locked <0x00000000c0313ce0> (a org.h2.engine.Database)

    at org.h2.engine.Database.lockMeta(Database.java:896)
    at org.h2.engine.Database.removeMeta(Database.java:919)

    - locked <0x00000000c0313ce0> (a org.h2.engine.Database)

    at org.h2.table.Table.removeChildrenAndResources(Table.java:525)
    at org.h2.mvstore.db.MVTable.removeChildrenAndResources(MVTable.java:799)
    at org.h2.engine.Session.cleanTempTables(Session.java:830)

    - locked <0x00000000c0313ce0> (a org.h2.engine.Database)

    at org.h2.engine.Session.close(Session.java:708)
    at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:383)

    - locked <0x00000000ede38ce0> (a org.h2.engine.Session)
    - locked <0x00000000ede37708> (a org.h2.jdbc.JdbcConnection)

    at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
    at com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)

    - locked <0x00000000ee186430> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:621)
    - locked <0x00000000ee186490> (a java.lang.Object)

    at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1065)
    at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1090)
    at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1051)
    at com.mchange.v2.resourcepool.BasicResourcePool.access$100(BasicResourcePool.java:44)
    at com.mchange.v2.resourcepool.BasicResourcePool$5.run(BasicResourcePool.java:1305)

   Locked ownable synchronizers:
    - None

"ForkJoinPool.commonPool-worker-2" #92 daemon prio=5 os_prio=0 tid=0x000000001c41a800 nid=0x8de8 waiting on condition [0x00000000256df000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000fe1dc608> (a java.util.concurrent.ForkJoinPool)
    at java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1824)
    at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1693)
    at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

   Locked ownable synchronizers:
    - None

"ForkJoinPool.commonPool-worker-1" #91 daemon prio=5 os_prio=0 tid=0x000000001c417800 nid=0x77c waiting on condition [0x000000002549f000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000fe1dc608> (a java.util.concurrent.ForkJoinPool)
    at java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1824)
    at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1693)
    at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

   Locked ownable synchronizers:
    - None

"MVStore background writer nio:D:/svn/dxcore_trunk/test1.mv.db" #43 daemon prio=5 os_prio=0 tid=0x00000000183d5800 nid=0x90c8 in Object.wait() [0x000000001a1df000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.h2.mvstore.MVStore$BackgroundWriterThread.run(MVStore.java:2684)
    - locked <0x00000000c00071a0> (a java.lang.Object)

   Locked ownable synchronizers:
    - None

"pool-1-thread-1" #40 prio=5 os_prio=0 tid=0x0000000017dd2000 nid=0x493c waiting on condition [0x00000000193fe000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000c000eee0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"MonitoringScheduler" #38 daemon prio=5 os_prio=0 tid=0x00000000182b2000 nid=0x4acc waiting on condition [0x0000000019ade000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000c0007328> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.DelayQueue.take(DelayQueue.java:223)
    at org.some.mars.common.MARSScheduler.runInternal(MARSScheduler.java:208)
    at org.some.mars.common.MARSScheduler.access$000(MARSScheduler.java:27)
    at org.some.mars.common.MARSScheduler$5.run(MARSScheduler.java:173)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"CpuMonitor" #37 daemon prio=10 os_prio=2 tid=0x00000000177c5000 nid=0x4c4 waiting on condition [0x00000000196fe000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.some.mars.jvm.CpuCounter$Accessor.run(CpuCounter.java:94)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"TimeSyncTrackerReceiver" #36 daemon prio=5 os_prio=0 tid=0x0000000016ce3800 nid=0x5ad8 runnable [0x00000000195fe000]
   java.lang.Thread.State: RUNNABLE
    at java.net.TwoStacksPlainDatagramSocketImpl.receive0(Native Method)
    - locked <0x00000000c00131f0> (a java.net.TwoStacksPlainDatagramSocketImpl)
    at java.net.TwoStacksPlainDatagramSocketImpl.receive(TwoStacksPlainDatagramSocketImpl.java:114)
    - locked <0x00000000c00131f0> (a java.net.TwoStacksPlainDatagramSocketImpl)
    at java.net.DatagramSocket.receive(DatagramSocket.java:812)
    - locked <0x00000000c0013230> (a java.net.DatagramPacket)
    - locked <0x00000000c0013258> (a java.net.MulticastSocket)
    at org.some.de.tools.TimeSyncTracker.receive(TimeSyncTracker.java:236)
    at org.some.de.tools.TimeSyncTracker.access$400(TimeSyncTracker.java:26)
    at org.some.de.tools.TimeSyncTracker$Receiver.doWork(TimeSyncTracker.java:509)
    at org.some.de.qtp.QTPWorkerThread.run(QTPWorkerThread.java:68)

   Locked ownable synchronizers:
    - None

"TimeSyncTrackerSender" #35 daemon prio=5 os_prio=0 tid=0x0000000016ce3000 nid=0x4220 waiting on condition [0x00000000194ff000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.some.de.tools.TimeSyncTracker$Sender.doWork(TimeSyncTracker.java:479)
    at org.some.de.qtp.QTPWorkerThread.run(QTPWorkerThread.java:68)

   Locked ownable synchronizers:
    - None

"SeedGenerator Thread" #13 daemon prio=1 os_prio=-2 tid=0x0000000017a31000 nid=0x42b8 in Object.wait() [0x00000000192fe000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000c000f138> (a sun.security.provider.SeedGenerator$ThreadedSeedGenerator)
    at java.lang.Object.wait(Object.java:502)
    at sun.security.provider.SeedGenerator$ThreadedSeedGenerator.run(SeedGenerator.java:334)
    - locked <0x00000000c000f138> (a sun.security.provider.SeedGenerator$ThreadedSeedGenerator)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"Monitor Ctrl-Break" #10 daemon prio=5 os_prio=0 tid=0x0000000016d3f000 nid=0x2f6c runnable [0x000000001754e000]
   java.lang.Thread.State: RUNNABLE
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
    at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
    - locked <0x00000000c000f5d8> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:545)
    at java.net.ServerSocket.accept(ServerSocket.java:513)
    at com.intellij.rt.execution.application.AppMain$1.run(AppMain.java:90)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"Service Thread" #9 daemon prio=9 os_prio=0 tid=0x0000000016cd1800 nid=0x6e6c runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C1 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x0000000016c96800 nid=0x9300 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x0000000016be3000 nid=0x4c14 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x0000000016c3d800 nid=0x2944 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x0000000015519000 nid=0x83f0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x0000000015518000 nid=0x1990 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x0000000002e39000 nid=0x6730 in Object.wait() [0x000000001686f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000000c005d470> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

   Locked ownable synchronizers:
    - None

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000002e30800 nid=0x1a34 in Object.wait() [0x000000001676f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
    - locked <0x00000000c001a288> (a java.lang.ref.Reference$Lock)

   Locked ownable synchronizers:
    - None

"main" #1 prio=5 os_prio=0 tid=0x0000000002d43800 nid=0x1534 in Object.wait() [0x0000000002bae000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Thread.join(Thread.java:1245)
    - locked <0x00000000c056bb60> (a org.h2.engine.DatabaseCloser)
    at java.lang.Thread.join(Thread.java:1319)
    at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:106)
    at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
    at java.lang.Shutdown.runHooks(Shutdown.java:123)
    at java.lang.Shutdown.sequence(Shutdown.java:167)
    at java.lang.Shutdown.exit(Shutdown.java:212)
    - locked <0x00000000c02c67e8> (a java.lang.Class for java.lang.Shutdown)
    at java.lang.Runtime.exit(Runtime.java:109)
    at java.lang.System.exit(System.java:971)
    at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:75)
    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 com.intellij.rt.execution.application.AppMain.main(AppMain.java:144)

   Locked ownable synchronizers:
    - None

"VM Thread" os_prio=2 tid=0x00000000154d7000 nid=0x129c runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000002d58800 nid=0x1ab8 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000002d5a000 nid=0x49cc runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000002d5b800 nid=0x91fc runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000002d5e000 nid=0x12b4 runnable

"VM Periodic Task Thread" os_prio=2 tid=0x0000000016d39800 nid=0xe38 waiting on condition

JNI global references: 1410

[Андрей Турбанов]

I checked intermediate versions. This problem is reproduced with H2 1.3.160+
1.3.159 works fine, any version started with 1.3.160 have such issue.

[Noel Grandin]

Can you try turning on the debug tracing, and then sending me the trace log?

http://h2database.com/html/features.html#trace_options

thanks

[Андрей Турбанов]

Looks like the problem is that org.h2.mvstore.db.MVTable#lockExclusiveSession points to the session which is already closed:
result = {org.h2.engine.Session@6778} "#6 (user: SA)"
serialId = 6
database = {org.h2.engine.Database@4931} "TESTREMOTEMEMORYDXCOREFACTORY1:org.h2.engine.Database@35325dde"
connectionInfo = null
user = {org.h2.engine.User@4932} "SA:2:org.h2.engine.User@3bf5a508"
id = 7
locks = {java.util.ArrayList@10059} size = 1
undoLog = {org.h2.engine.UndoLog@10060}
autoCommit = true
random = null
lockTimeout = 10000
lastIdentity = {org.h2.value.ValueLong@10061} "150"
lastScopeIdentity = {org.h2.value.ValueNull@4936} "NULL"
firstUncommittedLog = -1
firstUncommittedPos = -1
savepoints = null
localTempTables = {java.util.HashMap@10062} size = 0
localTempTableIndexes = {java.util.HashMap@10063} size = 0
localTempTableConstraints = {java.util.HashMap@10064} size = 0
throttle = 0
lastThrottle = 0
currentCommand = null
allowLiterals = false
currentSchemaName = "PUBLIC"
schemaSearchPath = null
trace = {org.h2.message.Trace@10054}
removeLobMap = null
systemIdentifier = 0
procedures = null
undoLogEnabled = true
redoLogBinary = true
autoCommitAtTransactionEnd = false
currentTransactionName = null
cancelAt = 1455276080469
closed = true
sessionStart = 1455276027199
transactionStart = 0
currentCommandStart = 0
variables = null
temporaryResults = null
queryTimeout = 0
commitOrRollbackDisabled = false
waitForLock = null
waitForLockThread = null
modificationId = 22
objectId = 61
queryCacheSize = 8
queryCache = {org.h2.util.SmallLRUCache@10065} size = 8
modificationMetaID = 244
temporaryResultLobs = null
temporaryLobs = null
transaction = {org.h2.mvstore.db.TransactionStore$Transaction@11003} "1"
startStatement = -1
sessionState = null
sessionStateChanged = true
sessionStateUpdating = false

Here is a state of org.h2.mvstore.db.MVTable#database object (it does not have "#6 (user: SA)" among sessions):
result = {org.h2.engine.Database@4931} "TESTREMOTEMEMORYDXCOREFACTORY1:org.h2.engine.Database@35325dde"
persistent = false
databaseName = "mem:testRemoteMemoryDXCoreFactory1"
databaseShortName = "TESTREMOTEMEMORYDXCOREFACTORY1"
databaseURL = "jdbc:h2:mem:testRemoteMemoryDXCoreFactory1"
cipher = null
filePasswordHash = null
fileEncryptionKey = null
roles = {java.util.HashMap@5431} size = 1
users = {java.util.HashMap@5432} size = 1
settings = {java.util.HashMap@5433} size = 3
schemas = {java.util.HashMap@5434} size = 2
rights = {java.util.HashMap@5435} size = 0
userDataTypes = {java.util.HashMap@5436} size = 0
aggregates = {java.util.HashMap@5437} size = 0
comments = {java.util.HashMap@5438} size = 0
tableEngines = {java.util.HashMap@5439} size = 1
userSessions = {java.util.Collections$SynchronizedSet@5440} size = 4
0 = {org.h2.engine.Session@11023} "#3 (user: SA)"
1 = {org.h2.engine.Session@11024} "#4 (user: SA)"
2 = {org.h2.engine.Session@10302} "#5 (user: SA)"
3 = {org.h2.engine.Session@6335} "#7 (user: SA)"
exclusiveSession = null
objectIds = {org.h2.util.BitField@5441}
lobSyncObject = {java.lang.Object@5442}
mainSchema = {org.h2.schema.Schema@5443} "PUBLIC:0:org.h2.schema.Schema@359d1be9"
infoSchema = {org.h2.schema.Schema@5444} "INFORMATION_SCHEMA:-1:org.h2.schema.Schema@3b00d018"
nextSessionId = 8
nextTempTableId = 0
systemUser = {org.h2.engine.User@5445} "SA:0:org.h2.engine.User@5af6c968"
systemSession = {org.h2.engine.Session@5421} "#0 (user: SA)"
lobSession = {org.h2.engine.Session@5446} "#1 (user: SA)"
meta = {org.h2.mvstore.db.MVTable@5447} "PUBLIC.SYS"
metaIdIndex = {org.h2.mvstore.db.MVDelegateIndex@5448} "SYS_ID:0:org.h2.mvstore.db.MVDelegateIndex@3221808"
lock = null
writer = null
starting = false
traceSystem = {org.h2.message.TraceSystem@5449}
trace = {org.h2.message.Trace@5450}
fileLockMethod = 4
publicRole = {org.h2.engine.Role@5451} "PUBLIC:0:org.h2.engine.Role@5e3d19d6"
modificationDataId = 4439
modificationMetaId = 484
compareMode = {org.h2.value.CompareMode@5452}
cluster = "''"
readOnly = false
writeDelay = 500
eventListener = null
maxMemoryRows = 35566
maxMemoryUndo = 50000
lockMode = 3
maxLengthInplaceLob = 256
allowLiterals = 2
powerOffCount = 0
closeDelay = -1
delayedCloser = null
closing = false
ignoreCase = false
deleteFilesOnDisconnect = false
lobCompressionAlgorithm = null
optimizeReuseResults = true
cacheType = "LRU"
accessModeData = "rw"
referentialIntegrity = true
multiVersion = true
closeOnExit = null
mode = {org.h2.engine.Mode@5456}
multiThreaded = false
maxOperationMemory = 100000
lobFileListCache = null
autoServerMode = false
autoServerPort = 0
server = null
linkConnections = null
tempFileDeleter = {org.h2.util.TempFileDeleter@5457}
pageStore = null
reconnectLastLock = null
reconnectCheckNext = 0
reconnectChangePending = false
checkpointAllowed = 0
checkpointRunning = false
reconnectSync = {java.lang.Object@5458}
cacheSize = 58272
compactMode = 0
compiler = null
metaTablesInitialized = false
flushOnEachCommit = false
lobStorage = {org.h2.store.LobStorageMap@5459}
pageSize = 4096
defaultTableType = 0
dbSettings = {org.h2.engine.DbSettings@5460}
reconnectCheckDelay = 200
logMode = 2
mvStore = {org.h2.mvstore.db.MVTableEngine$Store@5461}
retentionTime = 0
backgroundException = null
javaObjectSerializer = null
javaObjectSerializerName = null
javaObjectSerializerInitialized = false
queryStatistics = false
queryStatisticsMaxEntries = 100
queryStatisticsData = null

среда, 20 января 2016 г., 11:35:25 UTC+3 пользователь Noel Grandin написал:

[Noel Grandin]

Ah nice, spotting, thanks!

I think I managed to fix this in commit

https://github.com/h2database/h2database/commit/55e9b945ed8a59ded5f1f73f9c8aaa02e94732cf

which means it should be fixed in our nightly build

[Андрей Турбанов]

Still got such messages with 1.4.191-2016-02-25-latest build

org.h2.jdbc.JdbcSQLException: Timeout trying to lock table "SYS" [50200-191]

    at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
    at org.h2.message.DbException.get(DbException.java:179)
    at org.h2.message.DbException.get(DbException.java:155)
    at org.h2.mvstore.db.MVTable.doLock1(MVTable.java:223)
    at org.h2.mvstore.db.MVTable.lock(MVTable.java:167)

    at org.h2.engine.Database.lockMeta(Database.java:906)
    at org.h2.engine.Database.removeMeta(Database.java:929)
    at org.h2.table.Table.removeChildrenAndResources(Table.java:546)
    at org.h2.mvstore.db.MVTable.removeChildrenAndResources(MVTable.java:799)
    at org.h2.engine.Session.cleanTempTables(Session.java:938)
    at org.h2.engine.Session.close(Session.java:814)
    at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:382)

пятница, 12 февраля 2016 г., 15:50:38 UTC+3 пользователь Noel Grandin написал:

[Noel Grandin]

Ah, that is a pity.
Any chance you could debug this like you did last time?
Or maybe you have a test case?

[Alexander Dmitriev]

Hello Noel,

Here is some debugging info. Please, note that stacktraces are provided for code base of the nightly build of 1.4.191 downloaded on 2016-02-25.

Here is a stacktrace at the moment when DbException about timeout is thrown:   

"Resource Destroyer in BasicResourcePool.close()@12663" prio=5 tid=0xa8 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
      at org.h2.mvstore.db.MVTable.doLock1(MVTable.java:223)
      at org.h2.mvstore.db.MVTable.lock(MVTable.java:167)
      - locked <0x319d> (a org.h2.engine.Database)

      at org.h2.engine.Database.lockMeta(Database.java:906)
      at org.h2.engine.Database.removeMeta(Database.java:929)
      at org.h2.table.Table.removeChildrenAndResources(Table.java:546)
      at org.h2.mvstore.db.MVTable.removeChildrenAndResources(MVTable.java:799)
      at org.h2.engine.Session.cleanTempTables(Session.java:938)
      at org.h2.engine.Session.close(Session.java:814)
      at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:382)

      - locked <0x3446> (a org.h2.jdbc.JdbcConnection)
      - locked <0x3445> (a org.h2.engine.Session)

      at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
      at com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)

      - locked <0x3447> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
      at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:621)
      - locked <0x34a0> (a java.lang.Object)

      at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1065)
      at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1090)
      at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1051)
      at com.mchange.v2.resourcepool.BasicResourcePool.access$100(BasicResourcePool.java:44)
      at com.mchange.v2.resourcepool.BasicResourcePool$5.run(BasicResourcePool.java:1305)

Lock is requested for Session '#20 (user: SA)' on MVTable PUBLIC.SYS.
State of objects is similar to the previous case - lock is exclusively held on already closed session '#18 (user: SA)':

result = {org.h2.mvstore.db.MVTable@12700} "PUBLIC.SYS"
 primaryIndex = {org.h2.mvstore.db.MVPrimaryIndex@12709} "SYS_DATA:0:org.h2.mvstore.db.MVPrimaryIndex@5b47b6b0"
 indexes = {java.util.ArrayList@12710}  size = 2
 lastModificationId = 2338
 lockExclusiveSession = {org.h2.engine.Session@12711} "#18 (user: SA)"
  serialId = 18
  database = {org.h2.engine.Database@12701} "TEST2:org.h2.engine.Database@5726a512"
  connectionInfo = null
  user = {org.h2.engine.User@12839} "SA:2:org.h2.engine.User@5b910dbc"
  id = 8
  locks = {java.util.ArrayList@13427}  size = 1
   0 = {org.h2.mvstore.db.MVTable@12700} "PUBLIC.SYS"
  undoLog = {org.h2.engine.UndoLog@13428}
  autoCommit = true

  random = null
  lockTimeout = 10000

  lastIdentity = {org.h2.value.ValueLong@12420} "0"
  lastScopeIdentity = {org.h2.value.ValueNull@12421} "NULL"

  firstUncommittedLog = -1
  firstUncommittedPos = -1
  savepoints = null

  localTempTables = {java.util.HashMap@13429}  size = 0
  localTempTableIndexes = {java.util.HashMap@13430}  size = 0
  localTempTableConstraints = {java.util.HashMap@13431}  size = 0

  throttle = 0
  lastThrottle = 0
  currentCommand = null
  allowLiterals = false
  currentSchemaName = "PUBLIC"
  schemaSearchPath = null

  trace = {org.h2.message.Trace@13432}
  removeLobMap = null

  systemIdentifier = 0
  procedures = null
  undoLogEnabled = true
  redoLogBinary = true
  autoCommitAtTransactionEnd = false
  currentTransactionName = null

  cancelAt = 1458986336539
  closed = true
  sessionStart = 1458985619360

  transactionStart = 0
  currentCommandStart = 0
  variables = null
  temporaryResults = null
  queryTimeout = 0
  commitOrRollbackDisabled = false
  waitForLock = null
  waitForLockThread = null
  modificationId = 22

  objectId = 76
  queryCacheSize = 8
  queryCache = {org.h2.util.SmallLRUCache@13433}  size = 2
  modificationMetaID = 323
  subQueryInfo = null
  parsingView = 0
  preparingQueryExpression = 0
  viewIndexCache = null
  subQueryIndexCache = null
  joinBatchEnabled = false
  forceJoinOrder = false

  temporaryResultLobs = null
  temporaryLobs = null

  transaction = {org.h2.mvstore.db.TransactionStore$Transaction@13434} "1"

  startStatement = -1
  sessionState = null
  sessionStateChanged = true
  sessionStateUpdating = false

 lockSharedSessions = {java.util.concurrent.ConcurrentHashMap@12712}  size = 0
 waitingSessions = {java.util.ArrayDeque@12713}  size = 1
  0 = {org.h2.engine.Session@13381} "#20 (user: SA)"
 traceLock = {org.h2.message.Trace@12714}
 changesSinceAnalyze = 508
 nextAnalyze = 2000
 containsLargeObject = false
 rowIdColumn = null
 store = {org.h2.mvstore.db.MVTableEngine$Store@12715}
 transactionStore = {org.h2.mvstore.db.TransactionStore@12716}
 tableEngine = "org.h2.mvstore.db.MVTableEngine"
 tableEngineParams = {java.util.ArrayList@12717}  size = 0
 globalTemporary = false
 columns = {org.h2.table.Column[4]@12718}
 compareMode = {org.h2.value.CompareMode@11722}
 isHidden = true
 columnMap = {java.util.HashMap@12719}  size = 4
 persistIndexes = false
 persistData = false
 triggers = null
 constraints = null
 sequences = null
 views = null
 checkForeignKeyConstraints = true
 onCommitDrop = false
 onCommitTruncate = false
 nullRow = null
 schema = {org.h2.schema.Schema@12720} "PUBLIC:0:org.h2.schema.Schema@565e9f79"
 database = {org.h2.engine.Database@12701} "TEST2:org.h2.engine.Database@5726a512"
  persistent = false
  databaseName = "mem:test2"
  databaseShortName = "TEST2"
  databaseURL = "jdbc:h2:mem:test2"

  cipher = null
  filePasswordHash = null
  fileEncryptionKey = null

  roles = {java.util.HashMap@13074}  size = 1
  users = {java.util.HashMap@13075}  size = 1
  settings = {java.util.HashMap@13076}  size = 3
   0 = {java.util.HashMap$Node@14868} "DB_CLOSE_DELAY" -> "DB_CLOSE_DELAY:3:org.h2.engine.Setting@37f84c3a"
   1 = {java.util.HashMap$Node@14869} "CREATE_BUILD" -> "CREATE_BUILD:1:org.h2.engine.Setting@33b1d92f"
   2 = {java.util.HashMap$Node@14870} "LOCK_MODE" -> "LOCK_MODE:431:org.h2.engine.Setting@7addacc8"
  schemas = {java.util.HashMap@13077}  size = 2
  rights = {java.util.HashMap@13078}  size = 0
  userDataTypes = {java.util.HashMap@13079}  size = 0
  aggregates = {java.util.HashMap@13080}  size = 0
  comments = {java.util.HashMap@13081}  size = 0
  tableEngines = {java.util.HashMap@13082}  size = 1
   0 = {java.util.HashMap$Node@14882} "org.h2.mvstore.db.MVTableEngine" ->
  userSessions = {java.util.Collections$SynchronizedSet@13083}  size = 10
   0 = {org.h2.engine.Session@13511} "#16 (user: SA)"
   1 = {org.h2.engine.Session@13512} "#17 (user: SA)"
   2 = {org.h2.engine.Session@13513} "#19 (user: SA)"
   3 = {org.h2.engine.Session@13381} "#20 (user: SA)"
   4 = {org.h2.engine.Session@13514} "#21 (user: SA)"
   5 = {org.h2.engine.Session@13515} "#22 (user: SA)"
   6 = {org.h2.engine.Session@13516} "#23 (user: SA)"
   7 = {org.h2.engine.Session@13517} "#24 (user: SA)"
   8 = {org.h2.engine.Session@13518} "#14 (user: SA)"
   9 = {org.h2.engine.Session@12837} "#15 (user: SA)"
  exclusiveSession = null
  objectIds = {org.h2.util.BitField@13084}
  lobSyncObject = {java.lang.Object@13085}
  mainSchema = {org.h2.schema.Schema@12720} "PUBLIC:0:org.h2.schema.Schema@565e9f79"
  infoSchema = {org.h2.schema.Schema@13086} "INFORMATION_SCHEMA:-1:org.h2.schema.Schema@6a12d581"
  nextSessionId = 14
  nextTempTableId = 0
  systemUser = {org.h2.engine.User@13087} "SA:0:org.h2.engine.User@14e526a7"
  systemSession = {org.h2.engine.Session@13088} "#11 (user: SA)"
  lobSession = {org.h2.engine.Session@13089} "#12 (user: SA)"
  meta = {org.h2.mvstore.db.MVTable@12700} "PUBLIC.SYS"
  metaIdIndex = {org.h2.mvstore.db.MVDelegateIndex@13090} "SYS_ID:0:org.h2.mvstore.db.MVDelegateIndex@67bc7e34"

  lock = null
  writer = null
  starting = false

  traceSystem = {org.h2.message.TraceSystem@12953}
  trace = {org.h2.message.Trace@13091}
  fileLockMethod = 4
  publicRole = {org.h2.engine.Role@13092} "PUBLIC:0:org.h2.engine.Role@76d7ee47"
  modificationDataId = 2374
  modificationMetaId = 353
  compareMode = {org.h2.value.CompareMode@11722}
  cluster = "''"

  readOnly = false
  writeDelay = 500
  eventListener = null
  maxMemoryRows = 35566
  maxMemoryUndo = 50000
  lockMode = 3
  maxLengthInplaceLob = 256
  allowLiterals = 2
  powerOffCount = 0
  closeDelay = -1
  delayedCloser = null
  closing = false
  ignoreCase = false
  deleteFilesOnDisconnect = false
  lobCompressionAlgorithm = null
  optimizeReuseResults = true
  cacheType = "LRU"
  accessModeData = "rw"
  referentialIntegrity = true
  multiVersion = true
  closeOnExit = null

  mode = {org.h2.engine.Mode@11767}
  multiThreaded = false

  maxOperationMemory = 100000
  lobFileListCache = null
  autoServerMode = false
  autoServerPort = 0
  server = null
  linkConnections = null

  tempFileDeleter = {org.h2.util.TempFileDeleter@13093}
  pageStore = null

  reconnectLastLock = null
  reconnectCheckNext = 0
  reconnectChangePending = false
  checkpointAllowed = 0
  checkpointRunning = false

  reconnectSync = {java.lang.Object@13094}
  cacheSize = 58272

  compactMode = 0
  compiler = null
  metaTablesInitialized = false
  flushOnEachCommit = false

  lobStorage = {org.h2.store.LobStorageMap@13095}
  pageSize = 4096
  defaultTableType = 0
  dbSettings = {org.h2.engine.DbSettings@13096}
   aliasColumnName = false
   analyzeAuto = 2000
   analyzeSample = 10000
   databaseToUpper = true
   dbCloseOnExit = false
   defaultConnection = false
   defaultEscape = "\"
   defragAlways = false
   dropRestrict = true
   earlyFilter = false
   estimatedFunctionTableRows = 1000
   functionsInSchema = true
   largeTransactions = true
   lobTimeout = 300000
   maxCompactCount = 2147483647
   maxCompactTime = 200
   maxQueryTimeout = 0
   nestedJoins = true
   optimizeDistinct = true
   optimizeEvaluatableSubqueries = true
   optimizeInsertFromSelect = true
   optimizeInList = true
   optimizeInSelect = true
   optimizeIsNull = true
   optimizeOr = true
   optimizeTwoEquals = true
   optimizeUpdate = true
   pageStoreMaxGrowth = 131072
   pageStoreInternalCount = false
   pageStoreTrim = true
   queryCacheSize = 8
   recompileAlways = false
   reconnectCheckDelay = 200
   reuseSpace = true
   rowId = true
   selectForUpdateMvcc = true
   shareLinkedConnections = true
   defaultTableEngine = null
   mvStore = true
   compressData = false
   settings = {java.util.HashMap@14885}  size = 40

  reconnectCheckDelay = 200
  logMode = 2

  mvStore = {org.h2.mvstore.db.MVTableEngine$Store@12715}

  retentionTime = 0
  backgroundException = null
  javaObjectSerializer = null
  javaObjectSerializerName = null
  javaObjectSerializerInitialized = false
  queryStatistics = false
  queryStatisticsMaxEntries = 100
  queryStatisticsData = null

  rowFactory = {org.h2.result.RowFactory$DefaultRowFactory@11772}
 trace = {org.h2.message.Trace@12721}
 comment = null
 id = 0
 objectName = "SYS"
 modificationId = 0
 temporary = false
   

   
Here is state of the Session objects which is get closed:

result = {org.h2.engine.Session@13381} "#20 (user: SA)"
 serialId = 20
 database = {org.h2.engine.Database@12701} "TEST2:org.h2.engine.Database@5726a512"
 connectionInfo = null
 user = {org.h2.engine.User@12839} "SA:2:org.h2.engine.User@5b910dbc"
 id = 10
 locks = {java.util.ArrayList@14891}  size = 0
 undoLog = {org.h2.engine.UndoLog@14892}
  database = {org.h2.engine.Database@12701} "TEST2:org.h2.engine.Database@5726a512"
  storedEntriesPos = {java.util.ArrayList@15006}  size = 0
  records = {java.util.ArrayList@15007}  size = 0
  file = null
  rowBuff = null
  memoryUndo = 0
  storedEntries = 0
  tables = null
  largeTransactions = true

 autoCommit = true
 random = null
 lockTimeout = 10000

 lastIdentity = {org.h2.value.ValueLong@12420} "0"
 lastScopeIdentity = {org.h2.value.ValueNull@12421} "NULL"

 firstUncommittedLog = -1
 firstUncommittedPos = -1
 savepoints = null

 localTempTables = {java.util.HashMap@14893}  size = 10
 localTempTableIndexes = {java.util.HashMap@14894}  size = 5
 localTempTableConstraints = {java.util.HashMap@14895}  size = 5

 throttle = 0
 lastThrottle = 0
 currentCommand = null
 allowLiterals = false
 currentSchemaName = "PUBLIC"
 schemaSearchPath = null

 trace = {org.h2.message.Trace@14896}
 removeLobMap = null

 systemIdentifier = 0
 procedures = null
 undoLogEnabled = true
 redoLogBinary = true
 autoCommitAtTransactionEnd = false
 currentTransactionName = null

 cancelAt = 1458986974209
 closed = false
 sessionStart = 1458985760407
 transactionStart = 0
 currentCommandStart = 1458985760675

 variables = null
 temporaryResults = null
 queryTimeout = 0
 commitOrRollbackDisabled = false

 waitForLock = {org.h2.mvstore.db.MVTable@12700} "PUBLIC.SYS"
 waitForLockThread = {com.mchange.v2.resourcepool.BasicResourcePool$5@12663} "Thread[Resource Destroyer in BasicResourcePool.close(),5,main]"
 modificationId = 12
 objectId = 18
 queryCacheSize = 8
 queryCache = {org.h2.util.SmallLRUCache@14897}  size = 1
 modificationMetaID = 236
 subQueryInfo = null
 parsingView = 0
 preparingQueryExpression = 0
 viewIndexCache = null
 subQueryIndexCache = null
 joinBatchEnabled = false
 forceJoinOrder = false

 temporaryResultLobs = null
 temporaryLobs = null

 transaction = null

 startStatement = -1
 sessionState = null
 sessionStateChanged = true
 sessionStateUpdating = false

   
As I noted, its 'locks' list had been empty before the moment when 'this.rollback();' was invoked in 'Session#close'. As a result, 'Session#unlockAll' does not release exclusive lock on the meta table. Probably, this lock should be released in some other way?

[Noel Grandin]

    

As I noted, its 'locks' list had been empty before the moment when 'this.rollback();' was invoked in 'Session#close'. As a result, 'Session#unlockAll' does not release exclusive lock on the meta table. Probably, this lock should be released in some other way?

Hmm, what is weird is that according to your debugging output, session #18 has the problematic lock in it's locks list:

ockExclusiveSession = {org.h2.engine.Session@12711} "#18 (user: SA)"

  serialId = 18
  database = {org.h2.engine.Database@12701} "TEST2:org.h2.engine.Database@5726a512"
  connectionInfo = null
  user = {org.h2.engine.User@12839} "SA:2:org.h2.engine.User@5b910dbc"
  id = 8
  locks = {java.util.ArrayList@13427}  size = 1
   0 = {org.h2.mvstore.db.MVTable@12700} "PUBLIC.SYS"

which means that somehow session #18 was closed in such a way that it did not manage to free this lock.

Are you sure there were no previous exceptions logged which indicate why it closed this way?

[Alexander Dmitriev]

Yes, that's quite strange.
Can it be a thread safety issue? Field org.h2.engine.Session#closed is not volatile and access to it is not synchronized. Can it happen so that one thread closes a session but after that another thread adds a lock?

Are you sure there were no previous exceptions logged which indicate why it closed this way?

I do not see any other exceptions.
There are a bunch of such exceptions in log:

W 160326 193447.825 [Resource Destroyer in BasicResourcePool.close()] BasicResourcePool - Failed to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@2c6f911c
 java.sql.SQLException: Some resources failed to close properly while closing com.mchange.v2.c3p0.impl.NewPooledConnection@2c6f911c
     at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:664)

     at com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
     at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:621)

     at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1065)
     at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1090)
     at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1051)
     at com.mchange.v2.resourcepool.BasicResourcePool.access$100(BasicResourcePool.java:44)
     at com.mchange.v2.resourcepool.BasicResourcePool$5.run(BasicResourcePool.java:1305)

When I debug their cause I can see that it is caused by:

org.h2.jdbc.JdbcSQLException: Timeout trying to lock table "SYS" [50200-191]

As I understand, it is caused by the DbException which I have mentioned in the previous message.

[Noel Grandin]

Aah, I'm being silly - I did not notice that you have MVCC=TRUE.

That is a "deprecated" option i.e. it was an experiment that we are now abandoning.

Please do not use option, it does tend to trigger various problems.

That is probably also why I cannot reproduce these crashes.

​

[Alexander Dmitriev]

Noel, I set MVCC=false but that did not help anyway.
I have debugged more and I can see the following.
Here is the code of Session#close():

    @Override
    public void close() {
        if (!closed) {
            try {
                database.checkPowerOff();
                rollback();
                removeTemporaryLobs(false);
                cleanTempTables(true);
                undoLog.clear();
                database.removeSession(this);
            } finally {
                closed = true;
            }
        }
    }

Calling rollback(); results in unlockAll() and cleans up the #locks field.
However, I can see that #locks contains a new lock on PUBLIC.SYS after cleanTempTables(true); is call is completed. So, lock is aquired at some place in #cleanTempTables and is not released. That results in closed Session with an aquired lock.

After some more debugging I found that lock happens at line "database.lockMeta(session);" of method MVTable#removeChildrenAndResources:

public void removeChildrenAndResources(Session session) {
 if (containsLargeObject) {
 // unfortunately, the data is gone on rollback
 truncate(session);
 database.getLobStorage().removeAllForTable(getId());
 database.lockMeta(session);
 }
 ....

This lock is not released in scope of this method and thus it is left aqcuired ("database.removeMeta(session, getId())" will not release it).
Could you please look into that?

[Noel Grandin]

thank you very much, nice debugging!

I have pushed a fix for this.

​

[Alexander Dmitriev]

Thank you for fixing that! I confirm that it is not reproduced anymore.

[Андрей Турбанов]

Too soon. Still reproduced some times

вторник, 29 марта 2016 г., 18:41:13 UTC+3 пользователь Alexander Dmitriev написал: