[JAVA-1311] "IllegalStateException: open" during insert Created: 11/Jul/14  Updated: 23/Jun/15  Resolved: 23/Jun/15

Status: Closed
Project: Java Driver
Component/s: Connection Management, Error Handling
Affects Version/s: 2.12.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Stefan Larsson Assignee: Ross Lawley
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Linux, Oracle JDK 7


Issue Links:
Related
related to JAVA-1251 DBCollection.getIndexInfo() throws "j... Closed
related to JAVA-1437 Ensure contract assertions create mea... Closed

 Description   

Saw this exception in a log file:

2014-07-10 13:58:35,231 [http-apr-8080-exec-4] ERROR MyAppExceptionMapper - Failed to process request
java.lang.IllegalStateException: open
        at org.bson.util.Assertions.isTrue(Assertions.java:36) ~[bson-2.12.2.jar:na]
        at com.mongodb.DBPort.runCommand(DBPort.java:196) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort$NativeAuthenticator.authenticate(DBPort.java:647) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort.authenticate(DBPort.java:364) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort.checkAuth(DBPort.java:375) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector.doOperation(DBTCPConnector.java:209) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector.say(DBTCPConnector.java:181) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insertWithWriteProtocol(DBCollectionImpl.java:528) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insert(DBCollectionImpl.java:193) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insert(DBCollectionImpl.java:165) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.insert(DBCollection.java:161) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.insert(DBCollection.java:107) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.save(DBCollection.java:966) ~[mongo-java-driver-2.12.2.jar:na]
        at org.jongo.Insert.save(Insert.java:50) ~[jongo-1.0.jar:na]
        at org.jongo.MongoCollection.save(MongoCollection.java:128) ~[jongo-1.0.jar:na]
        at MyAppRepository.save(MyAppRepository.java:43) ~[MyAppRepository.class:na]
...

This happened while the app was running (had been started almost exactly 20 minutes before), there was no shutdown in progress (regular application logging just continues after this). There was no IOException or similar logged.

I did have maxConnectionIdleTime assigned to 120000 ms (2 minutes).
This failing request failed on the first mongo query of the webapp request, about 4 seconds after the webapp request came in the IllegalArgumentException was thrown.
The webapp request before this one was about 4 minutes earlier, so probably the max connection idle time cleanup logic had run.

The application currently relies on catching MongoSocketException for retries, would be nice to receive that exception in this case too, if it was indeed a network-related problem.



 Comments   
Comment by Stefan Larsson [ 15/Oct/14 ]

No, haven't seen the error since.

If I look at the call hierarchy of requestStart() and requestDone() they don't leave the driver. The application doesn't use those methods.

Comment by Jeffrey Yemin [ 15/Oct/14 ]

Stefan,

Have you seen this error again? I've been trying to reproduce it but so far no success. One theory is that it is related to use of DB.requestStart/requestDone. Can you let me know whether the application uses those methods?

Comment by sridhar bandari [ 14/Oct/14 ]

@Jeff My bad! You are absolutely right. Going back and refreshing basics on Threads

Comment by Jeffrey Yemin [ 14/Oct/14 ]

Hi Mongolia,

There's a simple reason why the Spring Data app is getting this exception. When you close the ApplicationContext in SpringApp.main, it shuts down all the beans, which in turn closes the MongoClient, which results in the IllegalStateException when the background thread tries to use that MongoClient. If you remove that call to close the ApplicationContext, the Spring Data example doesn't throw an exception either.

Comment by sridhar bandari [ 09/Oct/14 ]

I could able to reproduce this error when using Spring Data Mongo libraries and executing findOne() call from a Thread. Weirdly the same issue wouldn't arise if I use Mongo drivers directly. Below is the code:
Environment: Oracle JDK 1.7, spring-data-mongodb 1.5.2.RELEASE, MongoDB 2.2.1-rc2-pre-

Stacktrace

Exception in thread "Thread-2" java.lang.IllegalStateException: open
	at org.bson.util.Assertions.isTrue(Assertions.java:36)
	at com.mongodb.DBTCPConnector.isMongosConnection(DBTCPConnector.java:377)
	at com.mongodb.Mongo.isMongosConnection(Mongo.java:645)
	at com.mongodb.DBCollection.findOne(DBCollection.java:866)
	at com.mongodb.DBCollection.findOne(DBCollection.java:844)
	at com.mongodb.DBCollection.findOne(DBCollection.java:790)
	at org.springframework.data.mongodb.core.MongoTemplate$FindOneCallback.doInCollection(MongoTemplate.java:1985)
	at org.springframework.data.mongodb.core.MongoTemplate$FindOneCallback.doInCollection(MongoTemplate.java:1970)
	at org.springframework.data.mongodb.core.MongoTemplate.executeFindOneInternal(MongoTemplate.java:1744)
	at org.springframework.data.mongodb.core.MongoTemplate.doFindOne(MongoTemplate.java:1562)
	at org.springframework.data.mongodb.core.MongoTemplate.findById(MongoTemplate.java:547)
	at org.springframework.data.mongodb.repository.support.SimpleMongoRepository.findOne(SimpleMongoRepository.java:100)
	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.executeMethodOn(RepositoryFactorySupport.java:405)
	at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:390)
	at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:344)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
	at com.sun.proxy.$Proxy18.findOne(Unknown Source)
	at com.test.SpringApp.executeInternal(SpringApp.java:59)
	at com.test.SpringApp.access$0(SpringApp.java:56)
	at com.test.SpringApp$1.run(SpringApp.java:69)
	at java.lang.Thread.run(Thread.java:745)

SpringApp.Java which uses Spring libraries encounters exception randomly
FYI - Spring docs about thread safety

@Configuration
@EnableMongoRepositories
@ComponentScan
public class AppConfig extends AbstractMongoConfiguration {
 
	@Override
	protected String getDatabaseName() {
		return "test";
	}
 
	@Override
	protected UserCredentials getUserCredentials() {
		return new UserCredentials("test", "test");
	}
 
	@Override
	@Bean
	public Mongo mongo() throws Exception {
		List<ServerAddress> seeds = new ArrayList<ServerAddress>();
		seeds.add(new ServerAddress("host1:27017"));
		seeds.add(new ServerAddress("host2:27017"));
		seeds.add(new ServerAddress("host2:27017"));
 
		MongoClient mongo = new MongoClient(seeds);
		mongo.setReadPreference(ReadPreference.secondaryPreferred());
		mongo.setWriteConcern(WriteConcern.ACKNOWLEDGED);
		return mongo;
	}
 
	@Bean
	public GridFsTemplate gridFsTemplate() throws Exception {
		return new GridFsTemplate(mongoDbFactory(), mappingMongoConverter());
	}
 
	@Override
	@Bean
	public MappingMongoConverter mappingMongoConverter() throws Exception {
		MappingMongoConverter converter = super.mappingMongoConverter();
		converter.setTypeMapper(new DefaultMongoTypeMapper(null));
		return converter;
	}
}

@Document(collection = "test")
public class Test {
 
	@Id
	private int id;
	private String name;
 
	public String getName() {
		return name;
	}
	public void setName(String name) {
		this.name = name;
	}
	public int getId() {
		return id;
	}
	public void setId(int id) {
		this.id = id;
	}
}

public interface TestRepository extends
		PagingAndSortingRepository<Test, Integer> {
}

@Component
public class SpringApp {
 
	private static final int MAX_ITERATIONS = 100;
	@Autowired
	private TestRepository repo;
 
	public static void main(String[] args) throws Exception {
		AnnotationConfigApplicationContext appContext = null;
		try {
			appContext = new AnnotationConfigApplicationContext(AppConfig.class);
			SpringApp app = appContext.getBean(SpringApp.class);
			app.intialize();
			app.simpleExecute();
			app.executeInThread();
		} finally {
			appContext.close();
		}
		System.out.println("done!");
	}
 
	public void intialize() throws UnknownHostException {
		System.out.println("intializing test...");
 
		for (int i = 0; i < MAX_ITERATIONS; i++) {
			Test t = new Test();
			t.setId(i);
			t.setName(getClass().getName() + i);
			repo.save(t);
		}
	}
 
	public void simpleExecute() throws UnknownHostException {
		System.out.println("Executing in main thread....");
		executeInternal();
	}
 
	private void executeInternal() throws UnknownHostException {
 
		for (int i = 0; i < MAX_ITERATIONS; i++) {
			repo.findOne(i);
		}
	}
 
	public void executeInThread() {
		Thread t = new Thread(new Runnable() {
			@Override
			public void run() {
				System.out.println("Executing in thread....");
				try {
					executeInternal();
				} catch (UnknownHostException e) {
					e.printStackTrace();
				}
			}
		});
		t.start();
	}
}

SimpleApp.java - which uses plain mongo drivers has no issues

public class SimpleApp {
 
	private static final int MAX_ITERATIONS = 100;
 
	public static void main(String[] args) throws Exception {
		SimpleApp app = new SimpleApp();
		app.intialize();
		app.simpleExecute();
		app.executeInThread();
		System.out.println("done!");
	}
 
	public void intialize() throws UnknownHostException {
		System.out.println("intializing test...");
		MongoClient mongoClient = mongoClient();
 
		DB db = mongoClient.getDB("test");
		DBCollection coll = db.getCollection("test");
 
		for (int i = 0; i < MAX_ITERATIONS; i++) {
			BasicDBObject object = new BasicDBObject("_id", i).append("name",
					getClass().getName() + i);
			coll.save(object);
		}
	}
 
	public void simpleExecute() throws UnknownHostException {
		System.out.println("Executing in main thread....");
		executeInternal();
	}
 
	private void executeInternal() throws UnknownHostException {
		MongoClient mongoClient = mongoClient();
 
		DB db = mongoClient.getDB("test");
		DBCollection coll = db.getCollection("test");
 
		for (int i = 0; i < MAX_ITERATIONS; i++) {
			coll.findOne();
			coll.findOne(new BasicDBObject("_id", i));
		}
	}
 
	public void executeInThread() {
		Thread t = new Thread(new Runnable() {
			@Override
			public void run() {
				System.out.println("Executing in thread....");
				try {
					executeInternal();
				} catch (UnknownHostException e) {
					e.printStackTrace();
				}
			}
		});
		t.start();
	}
 
	protected MongoClient mongoClient() throws UnknownHostException {
		MongoCredential credential = MongoCredential.createMongoCRCredential(
				"test", "test", "summerheat".toCharArray());
		MongoClient mongoClient = new MongoClient(Arrays.asList(
				new ServerAddress("host1", 27017),
				new ServerAddress("host2", 27011), new ServerAddress(
						"host3", 27017)),
				Arrays.asList(credential));
		return mongoClient;
	}
}

Comment by Stefan Larsson [ 12/Aug/14 ]

Couldn't find any more SocketTimeoutException/ensureOpen messages in any logs, besides the old ones above from July 10th, so appears rare and difficult to reproduce by chance.

Comment by Stefan Larsson [ 02/Aug/14 ]

Hi, no problem, am still off from work, will be back in a week.

If I recall correctly though it looked like it could be a race condition between deciding to send an operation and then checking the connection-open flag, presumably with another thread closing the connection. Follow the call stack to methods reading and writing the flag checked by Assertions.isTrue(), there's a limited amount of paths setting the flag to not open.

It happened on a development/test environment, which consists of virtual machines with possibly too much/complex network infrastructure in between the virtual hosts and also unpredictable CPU and I/O latencies. Am uncertain of how frequently it occurs yet.

Comment by Jeffrey Yemin [ 31/Jul/14 ]

Hi Stefan,

Sorry it took so long to respond to this. Are you still experiencing the problem, and can you reproduce it reliably? If so, can you reproduce it without maxConnectionIdleTime set?

We're going to look into reproducing this on our end.

Regards,
Jeff

Comment by Stefan Larsson [ 11/Jul/14 ]

Here's another instance of the IllegalStateException, after a "normal" com.mongodb.MongoException$Network exception due to a java.net.SocketTimeoutException:

First a MongoException$Network exception, which causes the app to retry the request, which fails with an IllegalStateException:

2014-07-10 13:27:31,602 [http-apr-8080-exec-34] WARN  MyAppRepository - Failed to save document, try=1/3
com.mongodb.MongoException$Network: Operation on server 192.168.xxx.yyy:27017 failed
        at com.mongodb.DBTCPConnector.doOperation(DBTCPConnector.java:217) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector.say(DBTCPConnector.java:181) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insertWithWriteProtocol(DBCollectionImpl.java:528) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insert(DBCollectionImpl.java:193) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insert(DBCollectionImpl.java:165) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.insert(DBCollection.java:161) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.insert(DBCollection.java:107) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.save(DBCollection.java:966) ~[mongo-java-driver-2.12.2.jar:na]
        at org.jongo.Insert.save(Insert.java:50) ~[jongo-1.0.jar:na]
        at org.jongo.MongoCollection.save(MongoCollection.java:128) ~[jongo-1.0.jar:na]
        at MyAppRepository.save(MyAppRepository.java:43) ~[MyAppRepository.class:na]
...
Caused by: java.net.SocketTimeoutException: Read timed out
        at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.7.0_15]
        at java.net.SocketInputStream.read(Unknown Source) ~[na:1.7.0_15]
        at java.net.SocketInputStream.read(Unknown Source) ~[na:1.7.0_15]
        at java.io.BufferedInputStream.fill(Unknown Source) ~[na:1.7.0_15]
        at java.io.BufferedInputStream.read1(Unknown Source) ~[na:1.7.0_15]
        at java.io.BufferedInputStream.read(Unknown Source) ~[na:1.7.0_15]
        at org.bson.io.Bits.readFully(Bits.java:48) ~[bson-2.12.2.jar:na]
        at org.bson.io.Bits.readFully(Bits.java:35) ~[bson-2.12.2.jar:na]
        at org.bson.io.Bits.readFully(Bits.java:30) ~[bson-2.12.2.jar:na]
        at com.mongodb.Response.<init>(Response.java:42) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort$1.execute(DBPort.java:141) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort$1.execute(DBPort.java:135) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort.doOperation(DBPort.java:164) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort.call(DBPort.java:135) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort.findOne(DBPort.java:189) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort.runCommand(DBPort.java:197) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector._checkWriteError(DBTCPConnector.java:133) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector.access$000(DBTCPConnector.java:39) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector$1.execute(DBTCPConnector.java:186) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector$1.execute(DBTCPConnector.java:181) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector.doOperation(DBTCPConnector.java:210) ~[mongo-java-driver-2.12.2.jar:na]
        ... 112 common frames omitted

Then the retry (still same request) faces an IllegalStateException:

2014-07-10 13:27:44,575 [http-apr-8080-exec-34] ERROR MyAppExceptionMapper - Failed to process request
java.lang.IllegalStateException: open
        at org.bson.util.Assertions.isTrue(Assertions.java:36) ~[bson-2.12.2.jar:na]
        at com.mongodb.DBPort.runCommand(DBPort.java:196) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort$NativeAuthenticator.authenticate(DBPort.java:647) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort.authenticate(DBPort.java:364) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBPort.checkAuth(DBPort.java:375) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector.doOperation(DBTCPConnector.java:209) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBTCPConnector.say(DBTCPConnector.java:181) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insertWithWriteProtocol(DBCollectionImpl.java:528) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insert(DBCollectionImpl.java:193) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollectionImpl.insert(DBCollectionImpl.java:165) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.insert(DBCollection.java:161) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.insert(DBCollection.java:107) ~[mongo-java-driver-2.12.2.jar:na]
        at com.mongodb.DBCollection.save(DBCollection.java:966) ~[mongo-java-driver-2.12.2.jar:na]
        at org.jongo.Insert.save(Insert.java:50) ~[jongo-1.0.jar:na]
        at org.jongo.MongoCollection.save(MongoCollection.java:128) ~[jongo-1.0.jar:na]
        at MyAppRepository.save(MyAppRepository.java:43) ~[MyAppRepository.class:na]
...

On Tomcat's console this was logged:

Jul 10, 2014 1:27:32 PM com.mongodb.DBPort ensureOpen
WARNING: Exception connecting to 192.168.252.111: java.net.SocketTimeoutException: connect timed out.  Total wait time so far is 1002 ms.  Will retry after sleeping
 for 100 ms.
Jul 10, 2014 1:27:33 PM com.mongodb.DBPort ensureOpen
WARNING: Exception connecting to 192.168.252.111: java.net.SocketTimeoutException: connect timed out.  Total wait time so far is 2195 ms.  Will retry after sleeping
 for 200 ms.
Jul 10, 2014 1:27:35 PM com.mongodb.DBPort ensureOpen
WARNING: Exception connecting to 192.168.252.111: java.net.SocketTimeoutException: connect timed out.  Total wait time so far is 3400 ms.  Will retry after sleeping
 for 400 ms.
Jul 10, 2014 1:27:36 PM com.mongodb.DBPort ensureOpen
WARNING: Exception connecting to 192.168.252.111: java.net.SocketTimeoutException: connect timed out.  Total wait time so far is 4803 ms.  Will retry after sleeping
 for 800 ms.
Jul 10, 2014 1:27:38 PM com.mongodb.DBPort ensureOpen
WARNING: Exception connecting to 192.168.252.111: java.net.SocketTimeoutException: connect timed out.  Total wait time so far is 6606 ms.  Will retry after sleeping
 for 1600 ms.
Jul 10, 2014 1:27:40 PM com.mongodb.DBPort ensureOpen
WARNING: Exception connecting to 192.168.252.111: java.net.SocketTimeoutException: connect timed out.  Total wait time so far is 9211 ms.  Will retry after sleeping
 for 3200 ms.

Comment by Stefan Larsson [ 11/Jul/14 ]

I actually did find more logging related to the issue now, was logged to tomcat's console:

Jul 10, 2014 1:58:32 PM com.mongodb.DBPort ensureOpen
WARNING: Exception connecting to 192.168.xxx.yyy: java.net.SocketTimeoutException: connect timed out.  Total wait time so far is 1001 ms.  Will retry after sleeping for 100 ms.

The webapp request started at 2014-07-10 13:58:31,055:
2014-07-10 13:58:31,055 [http-apr-8080-exec-4] INFO MyAppWebService - ...

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