[IGNITE-15245] JDBC connection leak with cache.invoke() over cache store with external JDBC storage - ASF JIRA

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: 2.10
Fix Version/s: 2.15
Component/s: cache
Labels:
None

Release Note:
Fixed JDBC connection leak with cache.invoke() over write-behind enabled cache.
Ignite Flags:

Release Notes Required

Description

Given following snippet:

try (Transaction tx = ignite.transactions().txStart(TransactionConcurrency.PESSIMISTIC, TransactionIsolation.REPEATABLE_READ)) {
    cache.invoke(pojo.getId(), entryProcessor, pojo);
    tx.commit();
}

If we run this over the cache that uses external storage (e.g. mysql), we may get exceptions like:

org.apache.ignite.IgniteCheckedException: Failed to load object ...
 at org.apache.ignite.internal.processors.cache.store.GridCacheStoreManagerAdapter.loadFromStore(GridCacheStoreManagerAdapter.java:334)
 at org.apache.ignite.internal.processors.cache.store.GridCacheStoreManagerAdapter.load(GridCacheStoreManagerAdapter.java:292)
 at org.apache.ignite.internal.processors.cache.store.GridCacheStoreManagerAdapter.loadAllFromStore(GridCacheStoreManagerAdapter.java:433)
 at org.apache.ignite.internal.processors.cache.store.GridCacheStoreManagerAdapter.loadAll(GridCacheStoreManagerAdapter.java:399)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.loadMissingFromStore(GridDhtLockFuture.java:1111)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.onComplete(GridDhtLockFuture.java:790)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.onDone(GridDhtLockFuture.java:758)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.onDone(GridDhtLockFuture.java:91)
 at org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:475)
 at org.apache.ignite.internal.util.future.GridCompoundFuture.checkComplete(GridCompoundFuture.java:284)
 at org.apache.ignite.internal.util.future.GridCompoundFuture.markInitialized(GridCompoundFuture.java:273)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.map(GridDhtLockFuture.java:1052)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.onOwnerChanged(GridDhtLockFuture.java:709)
 at org.apache.ignite.internal.processors.cache.GridCacheMvccManager.notifyOwnerChanged(GridCacheMvccManager.java:226)
 at org.apache.ignite.internal.processors.cache.GridCacheMvccManager.access$200(GridCacheMvccManager.java:81)
 at org.apache.ignite.internal.processors.cache.GridCacheMvccManager$3.onOwnerChanged(GridCacheMvccManager.java:163)
 at org.apache.ignite.internal.processors.cache.GridCacheMapEntry.checkOwnerChanged(GridCacheMapEntry.java:5043)
 at org.apache.ignite.internal.processors.cache.GridCacheMapEntry.checkOwnerChanged(GridCacheMapEntry.java:4995)
 at org.apache.ignite.internal.processors.cache.distributed.GridDistributedCacheEntry.readyLock(GridDistributedCacheEntry.java:515)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.readyLocks(GridDhtLockFuture.java:617)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.map(GridDhtLockFuture.java:825)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTransactionalCacheAdapter.lockAllAsyncInternal(GridDhtTransactionalCacheAdapter.java:1027)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxLocalAdapter.obtainLockAsync(GridDhtTxLocalAdapter.java:720)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxLocalAdapter.lockAllAsync(GridDhtTxLocalAdapter.java:665)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTransactionalCacheAdapter.lockAllAsync(GridDhtTransactionalCacheAdapter.java:1238)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTransactionalCacheAdapter.processNearLockRequest0(GridDhtTransactionalCacheAdapter.java:823)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTransactionalCacheAdapter.processNearLockRequest(GridDhtTransactionalCacheAdapter.java:801)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTransactionalCacheAdapter.access$000(GridDhtTransactionalCacheAdapter.java:113)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTransactionalCacheAdapter$3.apply(GridDhtTransactionalCacheAdapter.java:159)
 at org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTransactionalCacheAdapter$3.apply(GridDhtTransactionalCacheAdapter.java:157)
 at org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:1142)
 at org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:591)
 at org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:392)
 at org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:318)
 at org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$100(GridCacheIoManager.java:109)
 at org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:308)
 at org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1719)
 at org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1326)
 at org.apache.ignite.internal.managers.communication.GridIoManager.access$4600(GridIoManager.java:157)
 at org.apache.ignite.internal.managers.communication.GridIoManager$8.execute(GridIoManager.java:1211)
 at org.apache.ignite.internal.managers.communication.TraceRunnable.run(TraceRunnable.java:54)
 at org.apache.ignite.internal.util.StripedExecutor$Stripe.body(StripedExecutor.java:564)
 at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:119)
 at java.lang.Thread.run(Thread.java:748)
Caused by: javax.cache.integration.CacheLoaderException: Failed to load object ...
 at org.apache.ignite.cache.store.jdbc.CacheAbstractJdbcStore.load(CacheAbstractJdbcStore.java:853)
 at org.apache.ignite.internal.processors.cache.store.GridCacheWriteBehindStore.load(GridCacheWriteBehindStore.java:530)
 at org.apache.ignite.internal.processors.cache.CacheStoreBalancingWrapper.load(CacheStoreBalancingWrapper.java:97)
 at org.apache.ignite.internal.processors.cache.store.GridCacheStoreManagerAdapter.loadFromStore(GridCacheStoreManagerAdapter.java:326)
 ... 43 more
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30008ms.
 at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695)
 at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
 at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
 at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
 at org.apache.ignite.cache.store.jdbc.CacheAbstractJdbcStore.openConnection(CacheAbstractJdbcStore.java:324)
 at org.apache.ignite.cache.store.jdbc.CacheAbstractJdbcStore.connection(CacheAbstractJdbcStore.java

This exception was caught when Hikari data source is used for pooling, but this case is also true if we use plain Mysql data source implementation.

This happens because when transaction is commited Ignite opens JDBC connection to underlying storage but doesn't close it when there is a transaction. Check the code of GridCacheWriteBehindStore.closeConnection(connection):

protected void closeConnection(@Nullable Connection conn) {
    CacheStoreSession ses = session();

    // Close connection right away if there is no transaction.
    if (ses.transaction() == null)
        U.closeQuiet(conn);
}

I guess that because connection release should be done somewhere else. GridCacheWriteBehindStore.sessionEnd() is quite obvious place for this purpose, but its 'noop' somewhy. I suspect that it is because sessionEnd() was declared as deprecated, but logic for closing cache session was lost during refactoring. It looks like we can fix this issue If we add a call to underlying cache store:

@Override public void sessionEnd(boolean commit) {
    --- // No-op
    +++ store.sessionEnd(commit);
}

I've created a test to reproduce this issue, and looks like proposed fix do the job, but I guess that this solution may be insufficient because I do not have enough knowledge about involved components so I may miss something and also because sessionEnd() now considered as deprecated.

TEST/REPRODUCER