TimeoutException on creating multiple secondary indexes using java client

I am trying to create secondary indexes in Couchbase using the official Java client. The code is working for the most part, and I am testing it with Junit, where the tests connect to a Couchbase v6.0 instance in Docker.

With this, I am intermittently getting java.util.concurrent.TimeoutException thrown with no useful stack trace. This happens randomly when trying to create multiple indexes in succession. I am creating them in deferred mode synchronously using AsyncBucketManager::createN1qlIndex, then calling AsyncBucketManager::buildN1qlDeferredIndexes and finally AsyncBucketManager::watchN1qlIndexes.

Stack trace I see in console:

java.util.concurrent.TimeoutException
	at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.onTimeout(OnSubscribeTimeoutTimedWithFallback.java:166)
	at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber$TimeoutTask.call(OnSubscribeTimeoutTimedWithFallback.java:191)
	at rx.internal.schedulers.EventLoopsScheduler$EventLoopWorker$2.call(EventLoopsScheduler.java:189)
	at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	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)

Catching the exception and printing it out tells me this:

java.lang.RuntimeException: java.util.concurrent.TimeoutException: {"b":"my-bucket","r":"127.0.0.1:8093","s":"n1ql","c":"57158C0A687CF54B/0000000044B97E41","t":75000000,"l":"127.0.0.1:57109"}

Any idea what’s causing these and possible solution?

@kirasagi, Could you please confirm at what stage (create/build/watch) that you see this exception thrown?

Hi @kirasagi,

As per the java sdk documentation, watchN1qlIndexes waits until indexes become online. It also takes a timeout as input. If the index doesn’t get built within this timeout, one can possibly see this error.
What is the timeout passed to watchN1qlIndexes? Did you later check up on the indexes to be built (via Web UI maybe)?

cc @daschl to confirm sdk behaviour.

@amit.kulkarni The timeout I put is 10000 hours just to test it out.

Did you later check up on the indexes to be built (via Web UI maybe)?

The index did not get created, at least on the one where the exception threw. Also, they indexes that were created are still deferred, so this means it’s failing on the create phase and not the watch phase.

Also, I found a better stack trace:

Caused by: java.lang.RuntimeException: java.util.concurrent.TimeoutException: {"b":"my-bucket","r":"127.0.0.1:8093","s":"n1ql","c":"11CBACBB51857569/FFFFFFFFE5BAD44F","t":75000000,"l":"127.0.0.1:60567"}
	at rx.exceptions.Exceptions.propagate(Exceptions.java:57)
	at rx.singles.BlockingSingle.value(BlockingSingle.java:86)
	at com.ibm.bti.sdk.couchbase.index.CouchbaseIndexManager.lambda$15(CouchbaseIndexManager.java:158)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.onNext(OnSubscribeMap.java:69)
	at rx.internal.operators.OnSubscribeFromIterable$IterableProducer.fastPath(OnSubscribeFromIterable.java:173)
	at rx.internal.operators.OnSubscribeFromIterable$IterableProducer.request(OnSubscribeFromIterable.java:86)
	at rx.Subscriber.setProducer(Subscriber.java:211)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.setProducer(OnSubscribeMap.java:102)
	at rx.internal.operators.OnSubscribeFromIterable.call(OnSubscribeFromIterable.java:63)
	at rx.internal.operators.OnSubscribeFromIterable.call(OnSubscribeFromIterable.java:34)
	at rx.Observable.unsafeSubscribe(Observable.java:10327)
	at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:48)
	at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:33)
	at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
	at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
	at rx.Observable.unsafeSubscribe(Observable.java:10327)
	at rx.internal.operators.OnSubscribeSingle.call(OnSubscribeSingle.java:81)
	at rx.internal.operators.OnSubscribeSingle.call(OnSubscribeSingle.java:27)
	at rx.Single.subscribe(Single.java:1979)
	at rx.Single$2$1.onSuccess(Single.java:687)
	at rx.Single$2$1.onSuccess(Single.java:683)
	at rx.internal.operators.SingleOnSubscribeMap$MapSubscriber.onSuccess(SingleOnSubscribeMap.java:74)
	at rx.internal.operators.OnSubscribeSingle$1.onCompleted(OnSubscribeSingle.java:55)
	at rx.internal.producers.SingleDelayedProducer.emit(SingleDelayedProducer.java:110)
	at rx.internal.producers.SingleDelayedProducer.setValue(SingleDelayedProducer.java:85)
	at rx.internal.operators.OperatorToObservableList$1.onCompleted(OperatorToObservableList.java:98)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emitLoop(OperatorMerge.java:656)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emit(OperatorMerge.java:568)
	at rx.internal.operators.OperatorMerge$InnerSubscriber.onCompleted(OperatorMerge.java:860)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.onCompleted(OnSubscribeMap.java:97)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emitLoop(OperatorMerge.java:656)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emit(OperatorMerge.java:568)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.onCompleted(OperatorMerge.java:281)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.onCompleted(OnSubscribeMap.java:97)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emitLoop(OperatorMerge.java:656)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emit(OperatorMerge.java:568)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.onCompleted(OperatorMerge.java:281)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.onCompleted(OnSubscribeMap.java:97)
	at rx.observers.Subscribers$5.onCompleted(Subscribers.java:225)
	at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onCompleted(OnSubscribeDoOnEach.java:70)
	at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onCompleted(OperatorOnErrorResumeNextViaFunction.java:101)
	at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.onCompleted(OnSubscribeTimeoutTimedWithFallback.java:147)
	at rx.observers.SafeSubscriber.onCompleted(SafeSubscriber.java:79)
	at rx.internal.producers.SingleProducer.request(SingleProducer.java:75)
	at rx.internal.producers.ProducerArbiter.setProducer(ProducerArbiter.java:126)
	at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.setProducer(OnSubscribeTimeoutTimedWithFallback.java:155)
	at rx.Subscriber.setProducer(Subscriber.java:205)
	at rx.subjects.AsyncSubject.onCompleted(AsyncSubject.java:103)
	at com.couchbase.client.core.endpoint.AbstractGenericHandler.completeResponse(AbstractGenericHandler.java:508)
	at com.couchbase.client.core.endpoint.AbstractGenericHandler.access$000(AbstractGenericHandler.java:86)
	at com.couchbase.client.core.endpoint.AbstractGenericHandler$1.call(AbstractGenericHandler.java:526)
	at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	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)
Caused by: java.util.concurrent.TimeoutException: {"b":my-bucket,"r":"127.0.0.1:8093","s":"n1ql","c":"11CBACBB51857569/FFFFFFFFE5BAD44F","t":75000000,"l":"127.0.0.1:60567"}
	at com.couchbase.client.java.bucket.api.Utils$1.call(Utils.java:131)
	at com.couchbase.client.java.bucket.api.Utils$1.call(Utils.java:127)
	at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onError(OperatorOnErrorResumeNextViaFunction.java:140)
	at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.onTimeout(OnSubscribeTimeoutTimedWithFallback.java:166)
	at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber$TimeoutTask.call(OnSubscribeTimeoutTimedWithFallback.java:191)
	... 8 more
Caused by: rx.exceptions.OnErrorThrowable$OnNextValue: OnError while emitting onNext value: com.ibm.bti.sdk.couchbase.index.schema.GsonIndex.class
	at rx.exceptions.OnErrorThrowable.addValueAsLastCause(OnErrorThrowable.java:118)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.onNext(OnSubscribeMap.java:73)
	at rx.internal.operators.OnSubscribeFromIterable$IterableProducer.fastPath(OnSubscribeFromIterable.java:173)
	at rx.internal.operators.OnSubscribeFromIterable$IterableProducer.request(OnSubscribeFromIterable.java:86)
	at rx.Subscriber.setProducer(Subscriber.java:211)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.setProducer(OnSubscribeMap.java:102)
	at rx.internal.operators.OnSubscribeFromIterable.call(OnSubscribeFromIterable.java:63)
	at rx.internal.operators.OnSubscribeFromIterable.call(OnSubscribeFromIterable.java:34)
	at rx.Observable.unsafeSubscribe(Observable.java:10327)
	at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:48)
	at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:33)
	at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
	at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
	at rx.Observable.unsafeSubscribe(Observable.java:10327)
	at rx.internal.operators.OnSubscribeSingle.call(OnSubscribeSingle.java:81)
	at rx.internal.operators.OnSubscribeSingle.call(OnSubscribeSingle.java:27)
	at rx.Single.subscribe(Single.java:1979)
	at rx.Single$2$1.onSuccess(Single.java:687)
	at rx.Single$2$1.onSuccess(Single.java:683)
	at rx.internal.operators.SingleOnSubscribeMap$MapSubscriber.onSuccess(SingleOnSubscribeMap.java:74)
	at rx.internal.operators.OnSubscribeSingle$1.onCompleted(OnSubscribeSingle.java:55)
	at rx.internal.producers.SingleDelayedProducer.emit(SingleDelayedProducer.java:110)
	at rx.internal.producers.SingleDelayedProducer.setValue(SingleDelayedProducer.java:85)
	at rx.internal.operators.OperatorToObservableList$1.onCompleted(OperatorToObservableList.java:98)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emitLoop(OperatorMerge.java:656)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emit(OperatorMerge.java:568)
	at rx.internal.operators.OperatorMerge$InnerSubscriber.onCompleted(OperatorMerge.java:860)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.onCompleted(OnSubscribeMap.java:97)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emitLoop(OperatorMerge.java:656)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emit(OperatorMerge.java:568)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.onCompleted(OperatorMerge.java:281)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.onCompleted(OnSubscribeMap.java:97)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emitLoop(OperatorMerge.java:656)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.emit(OperatorMerge.java:568)
	at rx.internal.operators.OperatorMerge$MergeSubscriber.onCompleted(OperatorMerge.java:281)
	at rx.internal.operators.OnSubscribeMap$MapSubscriber.onCompleted(OnSubscribeMap.java:97)
	at rx.observers.Subscribers$5.onCompleted(Subscribers.java:225)
	at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onCompleted(OnSubscribeDoOnEach.java:70)
	at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onCompleted(OperatorOnErrorResumeNextViaFunction.java:101)
	at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.onCompleted(OnSubscribeTimeoutTimedWithFallback.java:147)
	at rx.observers.SafeSubscriber.onCompleted(SafeSubscriber.java:79)
	at rx.internal.producers.SingleProducer.request(SingleProducer.java:75)
	at rx.internal.producers.ProducerArbiter.setProducer(ProducerArbiter.java:126)
	at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.setProducer(OnSubscribeTimeoutTimedWithFallback.java:155)
	at rx.Subscriber.setProducer(Subscriber.java:205)
	at rx.subjects.AsyncSubject.onCompleted(AsyncSubject.java:103)
	at com.couchbase.client.core.endpoint.AbstractGenericHandler.completeResponse(AbstractGenericHandler.java:508)
	at com.couchbase.client.core.endpoint.AbstractGenericHandler.access$000(AbstractGenericHandler.java:86)
	at com.couchbase.client.core.endpoint.AbstractGenericHandler$1.call(AbstractGenericHandler.java:526)
	... 8 more

@kirasagi,

Just by looking at the stack trace, I am not able to tell why this can happen. I am not sure if something went wrong on couchbase server side. To analyse further, if possible, will you please attach the logs here? indexer.log and query.log files from all nodes will be helpful.

Thanks.

@amit.kulkarni I have sent u the requested logs.

I noticed that after restarting my computer, it started working consistently. However, after closing my laptop a bit (putting it to sleep), it started failing again. Not sure what’s going on there since it’s running in Docker, but that might be a clue on what’s wrong.

@kirasagi, thanks for the logs.

From the logs, I can see there are three indexes that are getting created with {“defer_build”:true}. And after 1 min or so, these indexes are getting dropped. I don’t see any “build index” logs.

Build index request hasn’t reached indexer.

Can you try build index explicitly via “query Web-UI” ? by default that will be a synchronous call and will show us the errors - if any.

@amit.kulkarni

The issue is during the create phase. I was trying to create 4 indexes, and the 4th one seems to be timing out. Sorry if that wasn’t clear.

Sorry for the misunderstanding.

I can see only three “create index” calls have reached query service. Note that the query service will request indexer service to create the index. Can you please try creating those indexes via WebUI and look out for errors if any ?

If the observation is same across multiple runs (i.e. 3 out of 4 indexes getting created), can you try creating fourth index (via WebUI) after first three indexes are created (via SDK)?

I am sorry, but the error message returned by SDK doesn’t have any information. By requesting you to use WebUI, I am trying to narrow down if something is wrong with couchbase server.

Thanks for your patience.

I did as you said. I tried to create 4 indexes and got timeout on the 4th index. Ran the 4th query on the web UI and it was successful.

Ran select * from system:indexes just to verify and they are all there, still deferred, which is exactly what I want.

It seems that it is timing out before finishing the 3rd index request, even though . It’s most likely due to a race condition somewhere. Is there anything in the indexer logs?

All 3 indexes are made successfully though.

@kirasagi, I did not find any evidence of index creation failure in indexer logs or query logs. Need to analyse for java sdk/ java client.

@ingenthr, requesting further analysis from sdk side.