com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool [DATAMONGO-1601]

[spring-projects-issues]

sulabh opened DATAMONGO-1601 and commented

Hi,
We are running multiple threads, which are doing reads and writes operation at same point of time. One of the thread is reading from the database with time filter which is big enough to fetch 111000 records in one shot. The field in indexed in the collection. But, while this query is running it closes the connection pool and resulting the com.mongodb.MongoInterruptedException exception. Can you please tell me in what situation already open cursor will be closed abruptly where application has not initiated any close connection command. Below are the mongo-java-driver logs in trace mode. We are running single node of the mongo-database where mongodb version is 2.6.4 (Also tried with 3.2.8 wiredTiger but no luck) and spring-data 1.8.0.RELEASE, mongo java driver 3.0.2 with java 8 and radhat linux environment. Used MongoDBOption with default configuariont connectionPerHost=100 & maxConnectionTimeout=1000*10

2017/01/28 15:44:41.279 [MongoDbUtils] [SimpleAsyncTaskExecutor-4]: DEBUG: [588CBB1BE4B0F200BF2094F1] Getting Mongo Database name=[COLLECTIONNAME]
2017/01/28 15:44:41.280 [connection] [SimpleAsyncTaskExecutor-4]: TRACE: [588CBB1BE4B0F200BF2094F1] Checked out connection [connectionId
{localValue:8, serverValue:3244}
] to server HOST:27017
2017/01/28 15:44:41.280 [update] [SimpleAsyncTaskExecutor-4]: DEBUG: [588CBB1BE4B0F200BF2094F1] Updating documents in namespace COLLECTIONNAME.scheduled on connection [connectionId
{localValue:8, serverValue:3244}
] to server HOST:27017
2017/01/28 15:44:41.286 [connection] [pool-2-thread-2]: DEBUG: [588CBB3DE4B0F200BF2094FC] Closing connection connectionId
{localValue:10, serverValue:3246}
2017/01/28 15:44:41.289 [connection] [pool-2-thread-2]: TRACE: [588CBB3DE4B0F200BF2094FC] Checked in connection [connectionId
{localValue:10, serverValue:3246}
] to server HOST:27017
2017/01/28 15:44:41.289 [connection] [pool-2-thread-2]: INFO: [588CBB3DE4B0F200BF2094FC] Closed connection [connectionId
{localValue:10, serverValue:3246}
] to HOST:27017 because the pool has been closed.
2017/01/28 15:44:41.289 [connection] [pool-2-thread-2]: DEBUG: [588CBB3DE4B0F200BF2094FC] Closing connection connectionId
{localValue:10, serverValue:3246}
2017/01/28 15:44:41.290 [connection] [pool-2-thread-2]: TRACE: [588CBB3DE4B0F200BF2094FC] Checked out connection [connectionId
{localValue:2, serverValue:3238}
] to server HOST:27017
2017/01/28 15:44:41.290 [killcursor] [pool-2-thread-2]: DEBUG: [588CBB3DE4B0F200BF2094FC] Killing cursors [2428016239190] on connection [connectionId
{localValue:2, serverValue:3238}
] to server HOST:27017
2017/01/28 15:44:41.290 [connection] [pool-2-thread-2]: TRACE: [588CBB3DE4B0F200BF2094FC] Checked in connection [connectionId
{localValue:2, serverValue:3238}
] to server HOST:27017
2017/01/28 15:44:41.307 [update] [SimpleAsyncTaskExecutor-4]: DEBUG: [588CBB1BE4B0F200BF2094F1] Update completed


[ Error while processing [ findContentByDateRange ] with message org.springframework.data.mongodb.UncategorizedMongoDbException: Interrupted acquiring a permit to retrieve an item from the pool ; nested exception is com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool
        at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:101)
        at org.springframework.data.mongodb.core.MongoTemplate.potentiallyConvertRuntimeException(MongoTemplate.java:2013)
        at org.springframework.data.mongodb.core.MongoTemplate.executeFindMultiInternal(MongoTemplate.java:1896)
        at org.springframework.data.mongodb.core.MongoTemplate.doFind(MongoTemplate.java:1707)
        at org.springframework.data.mongodb.core.MongoTemplate.doFind(MongoTemplate.java:1690)
        at org.springframework.data.mongodb.core.MongoTemplate.find(MongoTemplate.java:602)
        at org.springframework.data.mongodb.core.MongoTemplate.find(MongoTemplate.java:593)


Caused by: com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool
at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:186)
at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:126)
at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:109)
at com.mongodb.internal.connection.PowerOfTwoBufferPool.getBuffer(PowerOfTwoBufferPool.java:77)
at com.mongodb.connection.SocketStream.read(SocketStream.java:81)
at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:503)
at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221)
at com.mongodb.connection.UsageTrackingInternalConnection.receiveMessage(UsageTrackingInternalConnection.java:102)
at com.mongodb.connection.DefaultConnectionPool$PooledConnection.receiveMessage(DefaultConnectionPool.java:416)
at com.mongodb.connection.GetMoreProtocol.receiveMessage(GetMoreProtocol.java:112)
at com.mongodb.connection.GetMoreProtocol.execute(GetMoreProtocol.java:68)
at com.mongodb.connection.GetMoreProtocol.execute(GetMoreProtocol.java:37)
at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:155)
at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:219)
at com.mongodb.connection.DefaultServerConnection.getMore(DefaultServerConnection.java:194)
at com.mongodb.operation.QueryBatchCursor.getMore(QueryBatchCursor.java:197)
at com.mongodb.operation.QueryBatchCursor.hasNext(QueryBatchCursor.java:93)
at com.mongodb.MongoBatchCursorAdapter.hasNext(MongoBatchCursorAdapter.java:46)
at com.mongodb.DBCursor.hasNext(DBCursor.java:152)
at org.springframework.data.mongodb.core.MongoTemplate.executeFindMultiInternal(MongoTemplate.java:1882)
... 156 more
Caused by: java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1302)
at java.util.concurrent.Semaphore.acquire(Semaphore.java:312)
at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:182)
... 175 more

---

Affects: 1.8.6 (Gosling SR6)

[spring-projects-issues]

Oliver Drotbohm commented

Looks like an issue in the driver to me. Have you brought this up with the MongoDB team?

[spring-projects-issues]

sulabh commented

Thanks for the reply Oliver.

Yes, I raised the issue with the MongoDB Java driver team and they says this not an issue from MongoDB java driver. They says, it's application issue where application is issuing Thread.interrupt() but in our application we have not written any Thread.interrupt() anywhere. If this is the case then only spring data is left in between application and MongoDB java driver.

Can you please tell me if Spring Data calls Thread.interrupt() in any of the case while reading a huge amount of data from MongoDB?

Link for MongoDB Jira: https://jira.mongodb.org/browse/JAVA-2438

Thanks,
Sulabh

[spring-projects-issues]

Oliver Drotbohm commented

Spring Data MongoDB is not calling Thread.interrupt() anywhere

[spring-projects-issues]

Eugene Tenkaev commented

Oliver Drotbohm for me it continue to happen in 2.4.0 during shutdown when I use EnableScheduling and do calls inside method with Scheduled.
Even if I set in my config:

spring.task.scheduling.shutdown.await-termination=true
spring.task.scheduling.shutdown.await-termination-period=60s
spring.task.execution.shutdown.await-termination=true
spring.task.execution.shutdown.await-termination-period=60s

I launch spring boot application in IntelliJ IDEA and press stop, and got exception

[spring-projects-issues]

Mark Paluch commented

Spring Task properties aren't related at all to that issue. The interrupt is signalled to the thread that does the work and connection acquisition reacts properly with an InterruptedException. Since Spring Data isn't calling Thread.interrupt() it would rather make sense to report the issue against Spring Boot because Spring Boot is shutting down the application along with a minimal reproducer to investigate the issue on their side

[govinda-raj]

How can we resolve this issue?
Mongo Java Driver Version: 3.12.8

[mrclrchtr]

Maybe it was fixed in: spring-projects/spring-framework#31019