Unambiguous and Ambiguous Timeout Exceptions with Java SDK

Couchbase Server
1

These timeout exceptions are frequently happening while using Java SDK 3.0 that connects with Couchbase Server 6.0. What could be the cause of it. Below is the env settings I am using,

ClusterEnvironment.builder()
            .timeoutConfig(TimeoutConfig
                .kvTimeout(Duration.ofMillis(300000))
                .kvDurableTimeout(Duration.ofMillis(300000))
                .queryTimeout(Duration.ofMillis(300000))
            )
            .ioConfig(IoConfig
                .captureTraffic(ServiceType.KV)
                .captureTraffic(ServiceType.QUERY)
                .numKvConnections(2)
            )
            .loggerConfig(LoggerConfig
                .enableDiagnosticContext(true)
            )
            .ioEnvironment(IoEnvironment
                .eventLoopThreadCount(4)
            )
            .orphanReporterConfig(OrphanReporterConfig
                .sampleSize(Integer.MAX_VALUE)
            )
            .retryStrategy(BestEffortRetryStrategy.INSTANCE)
            .build();

Exceptions,

com.couchbase.client.core.error.AmbiguousTimeoutException: InsertRequest
	at com.couchbase.client.core.msg.BaseRequest.cancel(BaseRequest.java:163) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.Timer.lambda$register$2(Timer.java:157) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.deps.io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:672) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.deps.io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:747) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.deps.io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:472) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.deps.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[core-io-2.0.5.jar!/:na]
	at java.base/java.lang.Thread.run(Unknown Source) ~[na:na]

com.couchbase.client.core.error.UnambiguousTimeoutException: GetRequest
	at com.couchbase.client.core.msg.BaseRequest.cancel(BaseRequest.java:163) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.Timer.lambda$register$2(Timer.java:157) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.deps.io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:672) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.deps.io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:747) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.deps.io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:472) ~[core-io-2.0.5.jar!/:na]
	at com.couchbase.client.core.deps.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[core-io-2.0.5.jar!/:na]
	at java.base/java.lang.Thread.run(Unknown Source) ~[na:na]
2

Hi @sekar, could you please post the full exception including the getMessage()? It will contain more diagnostic info to help debug this.

3

Hi Graham, Would this help. The getMessage() has just he timeout, hence turned on DEBUG logging. BUCKET_NOT_AVAILABLE is the error received before the timeout exception is thrown.

2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][8000us] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13249,"requestType":"InsertRequest","retried":8,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"IC:79363165186190,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3451","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":58}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][8000us] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13250,"requestType":"InsertRequest","retried":8,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"IC:46668933055536,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3452","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":34}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][8000us] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13251,"requestType":"InsertRequest","retried":8,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"C:78490371374285,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3453","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":59}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][8000us] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13252,"requestType":"InsertRequest","retried":8,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"C:43207323507684,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3454","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":37}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][8000us] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13253,"requestType":"InsertRequest","retried":8,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"IC:78490371374285,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3455","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":38}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][8000us] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13254,"requestType":"InsertRequest","retried":8,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"IC:43207323507684,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3456","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":33}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][128ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13239,"requestType":"InsertRequest","retried":9,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"C:17802681368522,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3447","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":40}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][128ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13240,"requestType":"InsertRequest","retried":9,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"C:13728679309706,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3448","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":21}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][128ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13241,"requestType":"InsertRequest","retried":9,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"IC:17802681368522,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3449","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":20}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][128ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13242,"requestType":"InsertRequest","retried":9,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"IC:13728679309706,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x344a","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":19}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][128ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13243,"requestType":"InsertRequest","retried":9,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"C:87531564897997,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x344b","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":39}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][128ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13244,"requestType":"InsertRequest","retried":9,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"C:56203948024204,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x344c","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":22}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][128ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13245,"requestType":"InsertRequest","retried":9,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"IC:87531564897997,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x344d","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":20}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][128ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13246,"requestType":"InsertRequest","retried":9,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"IC:56203948024204,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x344e","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":20}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][16ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13247,"requestType":"InsertRequest","retried":8,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"C:79363165186190,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x344f","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":90}}
2020-06-11 06:46:04.405     DEBUG shared-approval-service:devperf [-,-,-] 23 --- [cb-events] com.couchbase.request                    : [com.couchbase.request][RequestRetryScheduledEvent][16ms] Request InsertRequest retry scheduled per RetryStrategy (Reason: BUCKET_NOT_AVAILABLE) {"completed":false,"coreId":"0xc4b0a20c00000001","idempotent":false,"requestId":13248,"requestType":"InsertRequest","retried":8,"retryReasons":["BUCKET_NOT_AVAILABLE"],"service":{"bucket":"eventProcessor","collection":"_default","documentId":"C:46668933055536,2231bb94-05c9-4914-a37e-55ce1907fd02","opaque":"0x3450","scope":"_default","syncDurability":{"empty":true,"present":false},"type":"kv"},"timeoutMs":300000,"timings":{"encodingMicros":37}}
4

Hi, I get the same exceptions with less timeout limit set on my cluster settings.
Number of exception are increasing under high load how can I solve it? My cluster has 13 data nodes, even under high load my nodes cpu metrics were not more than 25%. Am I supposed to increase resources?

KV_TIMEOUT: 300ms
CONNECT_TIMEOUT: 20000ms
JAVA SDK: 3.0

error message: com.couchbase.client.core.error.UnambiguousTimeoutException: SubdocGetRequest, Reason: TIMEOUT

1 Like
5

How was this resolved? I am getting similar errors in Go?

6

A couple things I tried that may work. I had a similar issue in Go.
First, did what you did upped the timeout’s to 5min / 300000 milliseconds / 300 seconds. That did not seem to work. Make sure you are also upping the search timeout (not just the query timeout) and the connection timeout. That helped slightly for me.
Seconds, because the timeouts only helped slightly for me, I soon realized that I was hitting the dev db, which was very under resourced. Make sure the resources are in order for the server. Also, the connection to the server was sub-par, which made things worse. Try to minimize bottlenecks as much as possible like that. I tried to run my query right on the server and that brought me to point 3, but I also ran my app right along side the db on the same server to show the lack of resources but also to minimize things.
Third, I came from a relational DB world, and my query was not using the indexes properly. I assumed that “id” field was indexed, which it was not. And to make things worse, the “id” field was the same as the document id which is also different. So try to make sure you are using an index, or using the document fetch directly (sorry, i don’t know the exact verbiage, still new).

Hopefully this helps someone else :slight_smile:

1 Like
7

Hi Everyone, my application is running on the kubernetes and sometimes randomy i see these errors on some pods. please help how can these be resolved as it is happeneing in prod environment