[JAVA-1251] DBCollection.getIndexInfo() throws "java.lang.IllegalStateException: open" without explanation Created: 19/May/14  Updated: 23/Jun/15  Resolved: 23/Jun/15

Status: Closed
Project: Java Driver
Component/s: API, Error Handling
Affects Version/s: 2.12.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Hendy Irawan Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Oracle JDK 8, Linux Mint 16 64-bit, MongoDB 2.6.1


Issue Links:
Related
related to JAVA-1437 Ensure contract assertions create mea... Closed
is related to JAVA-1311 "IllegalStateException: open" during ... Closed

 Description   

Sometimes... DBCollection.getIndexInfo() simply throws java.lang.IllegalStateException: open without explanation.

Please handle this case or provide a more detailed exception message.

BTW, we reuse a MongoClient connection through the lifetime of the application.

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.DBCursor._check(DBCursor.java:454)
     at com.mongodb.DBCursor._hasNext(DBCursor.java:546)
     at com.mongodb.DBCursor.hasNext(DBCursor.java:571)
     at com.mongodb.DBCollection.getIndexInfo(DBCollection.java:1697)



 Comments   
Comment by Jeffrey Yemin [ 23/Jun/15 ]

Closing this as works as designed. The error message is also a bit better in the 3.0 release. Instead of just "open", it says "state should be open"

Comment by Jeffrey Yemin [ 12/Sep/14 ]

Hi Henry,

Thanks for the suggestions. We'll definitely work on the error messages, as I agree that one is quite poor.

As for isOpen, we'll have to think about this one. Looking around the JDK, I don't find any examples of Closeable classes that provide a corresponding isOpen method. I think the reason behind that is that if you are trying to use a closed instance of some class, it's probably due to a bug in your application, and therefore should be indicated by an exception being thrown.

Comment by Hendy Irawan [ 12/Sep/14 ]

Thank you jeff.yemin ross@10gen.com.

After scrutinizing our other classes, we found calls to db.getMongo().close() which caused the issue.

So indeed this is (thankfully) not a MongoDB Java Driver bug but an error in our application.

However, I'd like to add requests:

1. Please make it a better error message. Even better if the error message mentioned when (the timestamp) that the Mongo object has been closed, i.e. "Mongo object has been closed since 2014-08-09 11:53:20.429 +07:00". This would help tremendously in diagnosing "who" closed the Mongo.

2. add MongoClient.isOpen() and Mongo.isOpen() and DB.isOpen() to the API, since Mongo.getConnector().isOpen() is deprecated... please don't simply deprecate APIs without providing adequate replacement.

Thank you for your help and patience.

Comment by Jeffrey Yemin [ 11/Sep/14 ]

Rudy,

That _closed variable that you're seeing is not for a single port/socket, it's for the entire MongoClient. It would only be set to true if there is a call somewhere to com.mongodb.Mongo#close, or even possibly a call to the now deprecated com.mongodb.Mongo#getConnector followed by a call to com.mongodb.DBTCPConnector#close. The driver never does this directly, so I think it has to be application code that is doing it.

Comment by Ross Lawley [ 11/Sep/14 ]

rudi it could be, what are your connection settings? Are you seeing socket issues in your logs?

Comment by Rudi Wijaya [ 11/Sep/14 ]

Seems to be somewhat similar to JAVA-1311

[internal note: happens with Bippo Commerce 5.4.x]

Comment by Rudi Wijaya [ 11/Sep/14 ]

When I see the DBTCPConnector.java code it seems clear:

    DBPort getPrimaryPort() {
        isTrue("open", !_closed);
        return _myPort.get(true, ReadPreference.primary(), null);
    }

There seems to be no logic to retry if the port is closed.

Note that we're reusing a single MongoClient in the app. The MongoClient is never closed throughout the duration of the app.

Comment by Ross Lawley [ 11/Sep/14 ]

Hi rudi the cause is the same as above the operation (this time createIndex) has been called after the connection has been somehow been closed. Can you reproduce the error? It would be great if we could have a reproducible test example.

Comment by Rudi Wijaya [ 11/Sep/14 ]

Happens again on the following code:

	public MongoProductEffectivePriceRepository(String mongoUri) {
		super();
		final DB db;
		try {
			db = MongoUtils.getDb(new MongoClientURI(mongoUri), ReadPreference.secondaryPreferred());
		} catch (UnknownHostException | UnsupportedEncodingException e) {
			throw new MongoRepositoryException("Cannot connect MongoProductEffectivePriceRepository: " + e, e);
		}
		coll = db.getCollection("productEffectivePrice");
		coll.createIndex(new BasicDBObject(ImmutableMap.of("customerRole", 1, "effectivePrice", 1, "productId", 1)),
				new BasicDBObject("unique", true));
	}

Configs:

  • environment = local
  • API = 2.12.1
  • MongoDB server = 2.6.4, configured as standalone (not replica set)
  • readPreference = secondaryPreferred

Error: once this error occurs, it persists until the app is restarted. Note that MongoDB server is still running, so it seems that the MongoDB Java client is not retrying the connection properly.

java.lang.IllegalStateException: open
     at org.bson.util.Assertions.isTrue(Assertions.java:36)
     at com.mongodb.DBTCPConnector.getPrimaryPort(DBTCPConnector.java:416)
     at com.mongodb.DBCollectionImpl.createIndex(DBCollectionImpl.java:337)
     at com.mongodb.DBCollection.createIndex(DBCollection.java:564)
     at id.co.bippo.product.hand.MongoProductEffectivePriceRepository.<init>(MongoProductEffectivePriceRepository.java:127)
     at id.co.bippo.product.hand.MongoProductRepository.<init>(MongoProductRepository.java:188)
     at id.co.bippo.springapp.AppConfig$ProductConfigImpl$2.create(AppConfig.java:1206)
     at id.co.bippo.springapp.AppConfig$ProductConfigImpl$2.create(AppConfig.java:1)
     at org.soluvas.commons.tenant.TenantBeans$CreateAndPut.call(TenantBeans.java:188)
     at org.soluvas.commons.tenant.TenantBeans$CreateAndPut.call(TenantBeans.java:1)
     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
     at com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297)
     at java.util.concurrent.AbstractExecutorService.invokeAll(AbstractExecutorService.java:238)
     at org.soluvas.commons.tenant.TenantBeans.onTenantsStarting(TenantBeans.java:366)
     at org.soluvas.commons.tenant.DirectoryTenantRepository.start(DirectoryTenantRepository.java:359)
     at org.soluvas.commons.tenant.DirectoryTenantRepository.start(DirectoryTenantRepository.java:432)
     at org.soluvas.commons.tenant.DirectoryTenantRepository.modify(DirectoryTenantRepository.java:329)
     at java.lang.reflect.Method.invoke(Method.java:483)
     at org.apache.wicket.proxy.LazyInitProxyFactory$JdkHandler.invoke(LazyInitProxyFactory.java:435)
     at com.sun.proxy.$Proxy179.modify(Unknown Source)
     at id.co.bippo.springapp.web.AppManifestModifyPage$AppManifestModifyForm$8.onSubmit(AppManifestModifyPage.java:355)
     at org.apache.wicket.ajax.markup.html.form.AjaxButton$1.onSubmit(AjaxButton.java:108)
     at org.apache.wicket.ajax.form.AjaxFormSubmitBehavior$1.onSubmit(AjaxFormSubmitBehavior.java:182)
     at org.apache.wicket.markup.html.form.Form.delegateSubmit(Form.java:1266)
     at org.apache.wicket.markup.html.form.Form.process(Form.java:938)
     at org.apache.wicket.markup.html.form.Form.onFormSubmitted(Form.java:770)
     at org.apache.wicket.ajax.form.AjaxFormSubmitBehavior.onEvent(AjaxFormSubmitBehavior.java:159)
     at org.apache.wicket.ajax.AjaxEventBehavior.respond(AjaxEventBehavior.java:124)
     at org.apache.wicket.ajax.AbstractDefaultAjaxBehavior.onRequest(AbstractDefaultAjaxBehavior.java:633)
     at java.lang.reflect.Method.invoke(Method.java:483)
     at org.apache.wicket.RequestListenerInterface.internalInvoke(RequestListenerInterface.java:258)
     at org.apache.wicket.RequestListenerInterface.invoke(RequestListenerInterface.java:241)
     at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.invokeListener(ListenerInterfaceRequestHandler.java:250)
     at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.respond(ListenerInterfaceRequestHandler.java:236)
     at org.apache.wicket.request.cycle.RequestCycle$HandlerExecutor.respond(RequestCycle.java:862)
     at org.apache.wicket.request.RequestHandlerStack.execute(RequestHandlerStack.java:64)
     at org.apache.wicket.request.cycle.RequestCycle.execute(RequestCycle.java:261)
     at org.apache.wicket.request.cycle.RequestCycle.processRequest(RequestCycle.java:218)
     at org.apache.wicket.request.cycle.RequestCycle.processRequestAndDetach(RequestCycle.java:289)
     at org.apache.wicket.protocol.http.WicketFilter.processRequestCycle(WicketFilter.java:259)
     at org.apache.wicket.protocol.http.WicketFilter.processRequest(WicketFilter.java:201)
     at org.apache.wicket.protocol.http.WicketFilter.doFilter(WicketFilter.java:282)
     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
     at org.soluvas.web.site.servlet.ShiroPrincipalsServletFilter.doFilter(ShiroPrincipalsServletFilter.java:59)
     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
     at org.soluvas.web.site.servlet.MoreMdcServletFilter.doFilter(MoreMdcServletFilter.java:62)
     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
     at ch.qos.logback.classic.helpers.MDCInsertingServletFilter.doFilter(MDCInsertingServletFilter.java:51)
     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
     at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)
     at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
     at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
     at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
     at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383)
     at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
     at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
     at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:344)
     at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:261)
     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
     at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:97)
     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
     at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
     at org.apache.catalina.core.StandardContextValve.__invoke(StandardContextValve.java:123)
     at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java)
     at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
     at org.apache.catalina.core.StandardHostValve.__invoke(StandardHostValve.java:171)
     at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java)
     at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
     at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:936)
     at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
     at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
     at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1004)
     at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
     at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310)
     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
     at java.lang.Thread.run(Thread.java:745)

Comment by Hendy Irawan [ 29/Jun/14 ]

I'm not sure, but it doesn't seem that it's closed because the I call getIndexInfo right after ensureIndex. So why would ensureIndex succeed while getIndexInfo failed with this error?

But I can't test it now because I've made workarounds to avoid this issue.

Comment by Jeffrey Yemin [ 29/Jun/14 ]

Can you confirm by inspection the root cause, that the MongoClient instance has been closed? That's what the driver is asserting. If that's not the case, then it's not just the exception message that's the problem.

Comment by Hendy Irawan [ 28/Jun/14 ]

If I remember correctly : it was done on a connection with either primary_preferred or secondary_preferred

Currently we rearrange stuff to make it not happening again, and also use primary for index operations but we're still using replica set configuration with 1 primary, 1 secondary, and 1 arbiter.

Anyway, jeff.yemin we'd definitely appreciate a more detailed exception message in any case it happens to me or anyone else. (this is the purpose of my bug report, i.e. please enhance the exception message, in order to aid diagnose the real problem whether it's user's fault or MongoDB's. without a detailed exception it's like shooting in the dark)

Comment by Jeffrey Yemin [ 19/May/14 ]

From an examination of the code, it looks like the MongoClient that the application called this method on has been closed.

I agree that that the error message is less than helpful. It should say something like "The client is closed".

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