[JAVA-1984] DBPort's closed flag is not reset on connection retry causing "java.lang.IllegalStateException: open" Created: 30/Sep/15  Updated: 07/Dec/15  Resolved: 03/Nov/15

Status: Closed
Project: Java Driver
Component/s: Connection Management
Affects Version/s: 2.13.3
Fix Version/s: 2.14.0

Type: Bug Priority: Major - P3
Reporter: Dmitry Panov [X] Assignee: Jeffrey Yemin
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

Hello,

I've seen a following stack trace:

java.lang.IllegalStateException: open
        at org.bson.util.Assertions.isTrue(Assertions.java:36)
        at com.mongodb.DBPort.runCommand(DBPort.java:219)
        at com.mongodb.DBPort.ensureOpen(DBPort.java:319)
        at com.mongodb.DBPort.<init>(DBPort.java:113)
        at com.mongodb.DBPort.<init>(DBPort.java:95)
        at com.mongodb.DBPortFactory.create(DBPortFactory.java:28)
        at com.mongodb.PooledConnectionProvider$ConnectionItemFactory.create(PooledConnectionProvider.java:186)
        at com.mongodb.PooledConnectionProvider$ConnectionItemFactory.create(PooledConnectionProvider.java:183)
        at com.mongodb.ConcurrentPool.createNewAndReleasePermitIfFailure(ConcurrentPool.java:150)
        at com.mongodb.ConcurrentPool.get(ConcurrentPool.java:118)
        at com.mongodb.PooledConnectionProvider.get(PooledConnectionProvider.java:79)
        at com.mongodb.DefaultServer.getConnection(DefaultServer.java:61)
        at com.mongodb.BaseCluster$WrappedServer.getConnection(BaseCluster.java:254)
....

I could not reproduce it, however I found a potential problem in DBPort.java:

        do {
            try {
                _socket = _options.socketFactory.createSocket();
                _socket.connect( _addr.getSocketAddress() , _options.connectTimeout );
 
                _socket.setTcpNoDelay( ! USE_NAGLE );
                _socket.setKeepAlive( _options.socketKeepAlive );
                _socket.setSoTimeout( _options.socketTimeout );
                _in = new BufferedInputStream( _socket.getInputStream() );
                _out = _socket.getOutputStream();
                successfullyConnected = true;
            }
            catch ( IOException e ){
                close();
 
                if (!_options.autoConnectRetry || (provider != null && !provider.hasWorked()))
                    throw e;
 
                long waitSoFar = System.currentTimeMillis() - start;
 
                if (waitSoFar >= maxAutoConnectRetryTime)
                    throw e;
 
                if (sleepTime + waitSoFar > maxAutoConnectRetryTime)
                    sleepTime = maxAutoConnectRetryTime - waitSoFar;
 
                _logger.log(Level.WARNING, "Exception connecting to " + serverAddress().getHost() + ": " + e +
                        ".  Total wait time so far is " + waitSoFar + " ms.  Will retry after sleeping for " + sleepTime + " ms.");
                ThreadUtil.sleep(sleepTime);
                sleepTime *= 2;
            }
        } while (!successfullyConnected);

If the first run of the loop results in an IOException, the DBPort is closed which sets the closed flag to true. However, If a subsequent run succeeds the flag is never reset which can cause the above stacktrace.

Is it a bug or am I missing something?



 Comments   
Comment by Githook User [ 03/Nov/15 ]

Author:

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

Message: JAVA-1984: When retrying attempts to connect, close the socket and streams but not the DBPort itself
Branch: 2.x
https://github.com/mongodb/mongo-java-driver/commit/3e95bb3c88e0f85bed34d3cbb74b1bf2fd60c8d7

Comment by Jeffrey Yemin [ 01/Oct/15 ]

OK, thanks for the information. We'll try to get a fix for it in the next patch release.

Comment by Dmitry Panov [X] [ 30/Sep/15 ]

autoConnectRetry is set to true.

As for the logs, no, unfortunately the log level was not sufficient to record warnings.

Comment by Jeffrey Yemin [ 30/Sep/15 ]

One other question: in your MongoClientOptions, have you set the autoConnectRetry property to true?

Comment by Jeffrey Yemin [ 30/Sep/15 ]

Yes, it definitely looks like a bug. Did you happen to catch in your logs the WARNING generated in that catch clause?

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