[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: |
|
||||||||||||
| Description |
|
Saw this exception in a log file:
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). 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: Stacktrace
SpringApp.Java which uses Spring libraries encounters exception randomly
SimpleApp.java - which uses plain mongo drivers has no issues
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| 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, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| 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:
Then the retry (still same request) faces an IllegalStateException:
On Tomcat's console this was logged:
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Stefan Larsson [ 11/Jul/14 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I actually did find more logging related to the issue now, was logged to tomcat's console:
The webapp request started at 2014-07-10 13:58:31,055: |