java.util.concurrent.TimeoutException while executing N1ql queries


#1

Getting Timeout exception while executing N1qL queries. With Niql queries, the application runs fine. I am using Couchbase Server 5.1 and SDK as 2.6.0.

Below is my code to execute n1ql query:

bucket = cluster.openBucket(bucketName);
System.out.println(“Inside get document by Id Method”);
try{
bucket.bucketManager().createN1qlPrimaryIndex(true, false, 120000, TimeUnit.MILLISECONDS);
N1qlQueryResult result = bucket.query(N1qlQuery.simple(“select * from Student”));
for (N1qlQueryRow row : result) {
System.out.println("************Result is : " + row);
}
} catch (Exception e) {
System.out.println(“Exception occured”);
bucket.close();
}

Exception received:

2018-07-27 15:48:38.275 ERROR 5208 — [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: java.util.concurrent.TimeoutException: {“b”:“Student”,“r”:“127.0.0.1:8093”,“s”:“n1ql”,“c”:“45B71F527285AD82/FFFFFFFFC517C66B”,“t”:75000000,“l”:“127.0.0.1:61270”}] with root cause

java.util.concurrent.TimeoutException: {“b”:“Student”,“r”:“127.0.0.1:8093”,“s”:“n1ql”,“c”:“45B71F527285AD82/FFFFFFFFC517C66B”,“t”:75000000,“l”:“127.0.0.1:61270”}
at com.couchbase.client.java.bucket.api.Utils$1.call(Utils.java:131) ~[java-client-2.6.0.jar:na]
at com.couchbase.client.java.bucket.api.Utils$1.call(Utils.java:127) ~[java-client-2.6.0.jar:na]
at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onError(OperatorOnErrorResumeNextViaFunction.java:140) ~[rxjava-1.3.7.jar:1.3.7]
at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.onTimeout(OnSubscribeTimeoutTimedWithFallback.java:166) ~[rxjava-1.3.7.jar:1.3.7]
at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber$TimeoutTask.call(OnSubscribeTimeoutTimedWithFallback.java:191) ~[rxjava-1.3.7.jar:1.3.7]
at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55) ~[rxjava-1.3.7.jar:1.3.7]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[na:1.8.0_121]
at java.util.concurrent.FutureTask.run(Unknown Source) ~[na:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source) ~[na:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) ~[na:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:1.8.0_121]
at java.lang.Thread.run(Unknown Source) [na:1.8.0_121]

2018-07-27 15:48:55.778 WARN 5208 — [tionScheduler-4] c.c.c.c.endpoint.AbstractGenericHandler : [/127.0.0.1:8093][QueryEndpoint]: Got error while consuming KeepAliveResponse.

java.util.concurrent.TimeoutException: null
at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.onTimeout(OnSubscribeTimeoutTimedWithFallback.java:166) [rxjava-1.3.7.jar:1.3.7]
at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber$TimeoutTask.call(OnSubscribeTimeoutTimedWithFallback.java:191) [rxjava-1.3.7.jar:1.3.7]
at rx.internal.schedulers.EventLoopsScheduler$EventLoopWorker$2.call(EventLoopsScheduler.java:189) [rxjava-1.3.7.jar:1.3.7]
at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55) [rxjava-1.3.7.jar:1.3.7]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [na:1.8.0_121]
at java.util.concurrent.FutureTask.run(Unknown Source) [na:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source) [na:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [na:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.8.0_121]
at java.lang.Thread.run(Unknown Source) [na:1.8.0_121]

2018-07-27 15:49:32.710 WARN 5208 — [ cb-tracing-1] c.c.c.core.tracing.ThresholdLogReporter : Operations over threshold: [{“top”:[{“operation_name”:“n1ql”,“last_local_id”:“45B71F527285AD82/FFFFFFFFC517C66B”,“last_local_address”:“127.0.0.1:61270”,“last_remote_address”:“127.0.0.1:8093”,“last_dispatch_us”:121520204,“total_us”:121525575}],“service”:“n1ql”,“count”:1}]
2018-07-27 15:49:32.710 WARN 5208 — [ cb-orphan-1] c.c.c.c.t.DefaultOrphanResponseReporter : Orphan responses observed: [{“top”:[{“b”:“Student”,“r”:“127.0.0.1:8093”,“s”:“n1ql”,“c”:“45B71F527285AD82/FFFFFFFFC517C66B”,“l”:“127.0.0.1:61270”},{“r”:“127.0.0.1:8093”,“s”:“n1ql”,“c”:“45B71F527285AD82/FFFFFFFFC517C66B”,“l”:“127.0.0.1:61270”}],“service”:“n1ql”,“count”:2}]


#2

According to the log there:
“total_us”:121525575

… your timeout is set to 120s and it’s taking slightly longer than that for the query service to send the response. So, the problem isn’t with the SDK, it’s the query and the amount of data.

Question: why are you doing a ‘select *’ here? Often that’s useful at development time, but rarely something you’ll do from a real application. If you really want to get everything, it will take some work/time. Look into the RAW keyword, operating in pages or something else (depending on your app needs) to optimize this further.


#3

Thank you for response. I have increased timeout and also commented the select * query and I am trying to create index on Student bucket for executing N1QL queries. I am getting same exception while creating index through SDK or directly execute query on Couchbase console.

Through SDK, I am executing code as:
bucket = cluster.openBucket(bucketName);
System.out.println(“Inside get document by Id Method”);
try{
bucket.bucketManager().createN1qlPrimaryIndex(true, false, 12000000, TimeUnit.MILLISECONDS);
} catch (Exception e) {
System.out.println(“Exception occured :”);
e.printStackTrace();
bucket.close();
}

and through Couchbase console, I am executing query as:
CREATE PRIMARY INDEX ON Student USING GSI;

The exception I am getting is:
Inside get document by Id Method
Exception occured :com.couchbase.client.core.CouchbaseException: Error creating primary index: [{“msg”:“GSI CreatePrimaryIndex() - cause: Encounter errors during create index. Error=Terminate Request due to server termination\n.”,“code”:5000}]
at com.couchbase.client.java.bucket.DefaultAsyncBucketManager$27$1$1$1.call(DefaultAsyncBucketManager.java:739)
at com.couchbase.client.java.bucket.DefaultAsyncBucketManager$27$1$1$1.call(DefaultAsyncBucketManager.java:729)
at rx.internal.operators.OnSubscribeMap$MapSubscriber.onNext(OnSubscribeMap.java:69)
at rx.internal.producers.SingleDelayedProducer.emit(SingleDelayedProducer.java:102)
at rx.internal.producers.SingleDelayedProducer.setValue(SingleDelayedProducer.java:85)
at rx.internal.operators.OperatorToObservableList$1.onCompleted(OperatorToObservableList.java:98)
at rx.internal.operators.OnSubscribeMap$MapSubscriber.onCompleted(OnSubscribeMap.java:97)
at rx.internal.operators.OperatorOnBackpressureBuffer$BufferSubscriber.complete(OperatorOnBackpressureBuffer.java:163)
at rx.internal.util.BackpressureDrainManager.drain(BackpressureDrainManager.java:187)
at rx.internal.util.BackpressureDrainManager.terminateAndDrain(BackpressureDrainManager.java:115)
at rx.internal.operators.OperatorOnBackpressureBuffer$BufferSubscriber.onCompleted(OperatorOnBackpressureBuffer.java:134)
at rx.observers.SafeSubscriber.onCompleted(SafeSubscriber.java:79)
at rx.internal.operators.NotificationLite.accept(NotificationLite.java:125)
at rx.internal.operators.BufferUntilSubscriber$OnSubscribeAction.call(BufferUntilSubscriber.java:108)
at rx.internal.operators.BufferUntilSubscriber$OnSubscribeAction.call(BufferUntilSubscriber.java:80)

at rx.Observable.subscribe(Observable.java:10423)
at rx.Observable.subscribe(Observable.java:10390)
at com.couchbase.client.core.utils.UnicastAutoReleaseSubject$OnSubscribeAction.call(UnicastAutoReleaseSubject.java:228)
at com.couchbase.client.core.utils.UnicastAutoReleaseSubject$OnSubscribeAction.call(UnicastAutoReleaseSubject.java:207)
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.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.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.OperatorMerge$MergeSubscriber.onNext(OperatorMerge.java:248)
at rx.internal.operators.OperatorMerge$MergeSubscriber.onNext(OperatorMerge.java:148)
at rx.internal.operators.OnSubscribeMap$MapSubscriber.onNext(OnSubscribeMap.java:77)
at rx.internal.operators.OnSubscribeMap$MapSubscriber.onNext(OnSubscribeMap.java:77)
at rx.internal.operators.NotificationLite.accept(NotificationLite.java:135)
at rx.internal.operators.OperatorOnBackpressureBuffer$BufferSubscriber.accept(OperatorOnBackpressureBuffer.java:156)
at rx.internal.util.BackpressureDrainManager.drain(BackpressureDrainManager.java:198)
at rx.internal.operators.OperatorOnBackpressureBuffer$BufferSubscriber.onNext(OperatorOnBackpressureBuffer.java:151)
at rx.internal.producers.SingleProducer.request(SingleProducer.java:65)
at rx.Subscriber.setProducer(Subscriber.java:211)
at rx.subjects.AsyncSubject$1.call(AsyncSubject.java:80)
at rx.subjects.AsyncSubject$1.call(AsyncSubject.java:70)
at rx.subjects.SubjectSubscriptionManager.add(SubjectSubscriptionManager.java:95)
at rx.subjects.SubjectSubscriptionManager.call(SubjectSubscriptionManager.java:60)
at rx.subjects.SubjectSubscriptionManager.call(SubjectSubscriptionManager.java:35)
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.OnSubscribeMap.call(OnSubscribeMap.java:48)
at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:33)
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.OperatorMerge$MergeSubscriber.onNext(OperatorMerge.java:248)
at rx.internal.operators.OperatorMerge$MergeSubscriber.onNext(OperatorMerge.java:148)
at rx.internal.operators.OnSubscribeMap$MapSubscriber.onNext(OnSubscribeMap.java:77)
at rx.internal.operators.OperatorMerge$MergeSubscriber.emitScalar(OperatorMerge.java:511)
at rx.internal.operators.OperatorMerge$MergeSubscriber.tryEmit(OperatorMerge.java:466)
at rx.internal.operators.OperatorMerge$MergeSubscriber.onNext(OperatorMerge.java:244)
at rx.internal.operators.OperatorMerge$MergeSubscriber.onNext(OperatorMerge.java:148)
at rx.internal.operators.OnSubscribeMap$MapSubscriber.onNext(OnSubscribeMap.java:77)
at rx.observers.Subscribers$5.onNext(Subscribers.java:235)
at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onNext(OnSubscribeDoOnEach.java:101)
at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onNext(OperatorOnErrorResumeNextViaFunction.java:154)
at rx.internal.operators.OnSubscribeTimeoutTimedWithFallback$TimeoutMainSubscriber.onNext(OnSubscribeTimeoutTimedWithFallback.java:120)
at rx.observers.SafeSubscriber.onNext(SafeSubscriber.java:134)
at rx.internal.producers.SingleProducer.request(SingleProducer.java:65)
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(Unknown Source)
at java.util.concurrent.FutureTask.run(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

2018-07-30 09:50:57.220 INFO 5156 — [ cb-io-1-1] com.couchbase.client.core.node.Node : Disconnected from Node 127.0.0.1/127.0.0.1
2018-07-30 09:50:57.220 INFO 5156 — [nio-8080-exec-2] c.c.c.core.config.ConfigurationProvider : Closed bucket Student

======================================
The couchbase console error is :
500 | elapsed: 26.20s | execution: 26.20s | count: 0 | size: 0
[
{
“code”: 5000,
“msg”: “GSI CreatePrimaryIndex() - cause: Encounter errors during create index. Error=Terminate Request due to server termination\n.”,
“query_from_user”: “CREATE PRIMARY INDEX ON Student USING GSI;”
}
]

Explain query:
{
“plan”: {
#operator”: “CreatePrimaryIndex”,
“keyspace”: “Student”,
“namespace”: “default”,
“node”: {
“keyspaceRef”: {
“keyspace”: “Student”,
“namespace”: “”
},
“name”: “#primary”,
“type”: “createPrimaryIndex”,
“using”: “gsi”
}
},
“text”: “CREATE PRIMARY INDEX ON Student USING GSI;”
}

What to do. I am trying to create index for last 3 days but unsuccessful. Please assist.


#4

Ah, looks like your primary problem is something with creating the index. What I’d probably recommend is looking at the logs associated with secondary indexing (projector/indexer). You may be able to discern there why it’s crashing.

Perhaps @tai_tran or @jeelan.poola have other thoughts and can point to more info.

Of course, if you’re an Enterprise Edition subscriber, you can also contact Couchbase over those channels and get log analysis/recommended resolution to be owned by someone else.


#5

Check this post for index creation issue. Unable to create index in couchbase


#6

Thanks @vsr1! Just to short circuit others to the answer, there’s suspicion that it could be known issue MB-25086, fixed in 5.5 and with workarounds if corrupt.


#7

Thanks @ingenthr
I am able to create index after reinstallation.