[JAVA-2123] Spurious exception logged while ensuring minimum pool size Created: 25/Feb/16  Updated: 19/Oct/16  Resolved: 18/Mar/16

Status: Closed
Project: Java Driver
Component/s: Configuration
Affects Version/s: 3.2.0
Fix Version/s: 3.3.0

Type: Bug Priority: Minor - P4
Reporter: Alex Paransky Assignee: Jeffrey Yemin
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate

 Description   

I got the following error when updated to java mongo driver 3.2.2:

2016-02-24 07:15:20,383 ws-dashboard WARN [pool-1-thread-1] org.mongodb.driver.connection [SLF4JLogger.java:91] Exception thrown while ensuring minimum pool size
com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool 
	at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:186) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:126) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:109) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.internal.connection.PowerOfTwoBufferPool.getBuffer(PowerOfTwoBufferPool.java:76) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.SocketStream.read(SocketStream.java:81) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:503) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.CommandHelper.receiveReply(CommandHelper.java:134) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.CommandHelper.receiveCommandResult(CommandHelper.java:121) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.CommandHelper.executeCommand(CommandHelper.java:32) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnectionInitializer.initializeConnectionDescription(InternalStreamConnectionInitializer.java:83) ~[mongo-java-driver-3.2.2.jar:na]

Here is how I create MongoClientOptions:

public MongoClientOptions mongoClientOptions() {
        return
            MongoClientOptions
                .builder()
                .connectionsPerHost(connectionsPerHost)
                .minConnectionsPerHost(connectionsPerHost)
                .writeConcern(WriteConcern.SAFE)
                .readPreference(
                    readFrom == ReadFrom.PRIMARY
                        ? ReadPreference.primary()
                        : ReadPreference.secondary()
                )
                .connectTimeout(connectTimeout)
                .build();
    }

If I comment out:

.minConnectionsPerHost(connectionsPerHost)

The exception goes away.

Tested to work without issues on:
3.0.2 works
3.0.4 works
3.1.1 works

But switching to 3.2.1 or 3.2.2 causes the exception to be raised.



 Comments   
Comment by Githook User [ 18/Mar/16 ]

Author:

{u'username': u'jyemin', u'name': u'Jeff Yemin', u'email': u'jeff.yemin@10gen.com'}

Message: JAVA-2123: Avoid logging a MongoInterruptedException in the connection pool maintenance task, as this can occur under normal usage when the connection pool is closed while the task is running
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/7a1c98c2c7e1757e54978b73a3d72cbb7fb320d6

Comment by Alex Paransky [ 25/Feb/16 ]

Perhaps, in this instance, even changing the log from WARN to DEBUG, if in fact these types of exceptions are benign... Thanks for the explanation.

Comment by Jeffrey Yemin [ 25/Feb/16 ]

No, it won't break the population of the pool. What's happening here is this:

  1. List<ServerAddress> passed to MongoClient using DNS name (call it "dnsName")
  2. Driver starts background thread and starts populating the connection pool to "dnsName"
  3. Driver calls ismaster command on "dnsName" in background thread
  4. Driver sees in ismaster response that the actual name of "dnsName" is "replicaSetConfigName"
  5. Driver closes connection pool to "dnsName" and interrupts its background thread via a call to ExecutorService#shutdownNow, which sets the interrupted bit on the background thread
  6. Background thread attempts to acquire a semaphore permit, which throws InterruptedException, which is caught, wrapped in MongoInterruptedException, and rethrown.
  7. Background thread catches the MongoInterruptedException in a catch clause for Exception, and logs it.
  8. Driver starts background thread and starts populating the connection pool to "replicaSetConfigName". This is the connection pool that will be used going forward.

What I propose to do is add a more specific catch clause for MongoInterruptedException and not log that particular exception.

I'll also consider delaying the start of the background task until the driver is sure that this is the server that it actually wants to be connected to.

Comment by Alex Paransky [ 25/Feb/16 ]

The real question, is the pool really pre-initialized with the # of connection that I expect when the exception occurs? In other words, if I set connectionsPerHost = minConnectionsPerHost = 100, will the pool contain 100 connections after being initialized despite of this exception? If it does, then I agree, MINOR and disable the log in the future since there is no "harm".

On the other hand, if this exception breaks the population of the pool such that the pool does not contain 100 connections as requested by the MongoClientOptions, perhaps a different solution is needed.

Comment by Jeffrey Yemin [ 25/Feb/16 ]

You can use DNS for the names you see in the seed list, but the driver will re-connect to all the members using the server names reported by the ismaster command. The reason this exception is generated and logged is a bit complicated, but I'm now convinced that it's harmless and that the driver can safely suppress it, since the driver is the one doing the interrupting of this background thread.

This is essentially a race condition that has always existed but was made much more common to hit in 3.2 when we fixed JAVA-2027.

I'm going to call this a minor bug and use it as the impetus to suppress the log message.

Comment by Alex Paransky [ 25/Feb/16 ]

You are absolutely correct. These ARE in a 3 node replica set. We have all the nodes in the DNS, so when trying to connect, we specify the DNS name. When using the DNS name, I see the exception. When using the "exact" replica name as it appears from rs.status(), I don't see the exception.

As I mentioned, this exception does not really reach the client. However, since it appears in the WARN, our OPS guys get a bit jumpy. This does not appear to be happening in drivers prior to 3.2.

Is using DNS for the servers not a supported configuration? I kinda wanted to avoid having to modify the configurations of all our clients when we add/remove nodes from the replica set.

Comment by Jeffrey Yemin [ 25/Feb/16 ]

Is this connecting to a member of a replica set? If so, does "serverInAWS" match the hostname used in the replica set configuration (rs.status() in the shell)? If it doesn't, try changing it so that it does and let's see if that gets rid of the log message.

If the issue is what I suspect, I agree with your assessment that this log message is harmless to the application.

Comment by Alex Paransky [ 25/Feb/16 ]

Strange, here are various snippets that I have tried:

        MongoClient client = new MongoClient(
            //WORKS: Arrays.asList(new ServerAddress("localhost", 27017)),
            //WORKS: new ServerAddress("serverInAWS", 27000),
            Arrays.asList(new ServerAddress("serverInAWS", 27000)),
            MongoClientOptions
                .builder()
                .connectionsPerHost(100)
                .minConnectionsPerHost(100)
                .build());
 
    client.getDatabase("admin").runCommand(new Document("ping", 1));

As written above, I get the exception, but only when I try to connect to our server in AWS using List<ServerAddress> parameter. So, as written it fails. However, I replace our AWS server with localhost, it works with all options. Also if I don't use the List<ServerAddress> parameter, it also works with our AWS server.

This feels a bit odd.

Here is the full exception stack trace:

07:52:39.825 [pool-1-thread-1] WARN  connection - Exception thrown while ensuring minimum pool size
com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool 
		at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:186) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:126) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:109) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.internal.connection.PowerOfTwoBufferPool.getBuffer(PowerOfTwoBufferPool.java:76) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.SocketStream.read(SocketStream.java:81) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:503) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.CommandHelper.receiveReply(CommandHelper.java:134) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.CommandHelper.receiveCommandResult(CommandHelper.java:121) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.CommandHelper.executeCommand(CommandHelper.java:32) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnectionInitializer.initializeConnectionDescription(InternalStreamConnectionInitializer.java:83) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnectionInitializer.initialize(InternalStreamConnectionInitializer.java:43) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.open(InternalStreamConnection.java:115) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.UsageTrackingInternalConnection.open(UsageTrackingInternalConnection.java:46) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultConnectionPool$UsageTrackingInternalConnectionItemFactory.create(DefaultConnectionPool.java:489) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultConnectionPool$UsageTrackingInternalConnectionItemFactory.create(DefaultConnectionPool.java:477) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.internal.connection.ConcurrentPool.createNewAndReleasePermitIfFailure(ConcurrentPool.java:164) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.internal.connection.ConcurrentPool.ensureMinSize(ConcurrentPool.java:158) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultConnectionPool$3.run(DefaultConnectionPool.java:300) ~[mongo-java-driver-3.2.2.jar:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_65]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [na:1.8.0_65]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_65]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [na:1.8.0_65]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_65]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_65]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
Caused by: java.lang.InterruptedException: null
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1302) ~[na:1.8.0_65]
	at java.util.concurrent.Semaphore.acquire(Semaphore.java:312) ~[na:1.8.0_65]
	at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:182) ~[mongo-java-driver-3.2.2.jar:na]
	... 25 common frames omitted
07:52:40.610 [com.standardset.spring.Launcher.main()] DEBUG Launcher - Hello World!

The exception is only a WARNING and does not appear to float up to the client. So, my client does not actually see any issues, it's only logged to the LOG.

Comment by Jeffrey Yemin [ 25/Feb/16 ]

Do you have a test program that reproduces this? The simple one I tried did not:

        MongoClient client = new MongoClient("localhost",
                MongoClientOptions.builder()
                        .connectionsPerHost(100)
                        .minConnectionsPerHost(100)
                        .build());
 
        client.getDatabase("admin").runCommand(new Document("ping", 1));
 
        Thread.sleep(MAX_VALUE);

Generated at Thu Feb 08 08:56:23 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.