We now tried the connection string
cn = Bucket('couchbase://192.168.0.3,192.168.0.4,192.168.0.5/<bucketname>?operation_timeout=120.0')
with couchbase-python-client 2.0.1 and libcouchbase 2.5.0. With the test script I provided we now get the following debug errorr logs:
2015-05-22 10:09:54,912 | INFO | Initializing Couchbase logging. lcb_version=('2.5.0', 132352)
2015-05-22 10:09:54,913 | DEBUG | [0] Preparing providers (this may be called multiple times) (L:89)
2015-05-22 10:09:54,914 | DEBUG | [0] Provider FILE is DISABLED (L:99)
2015-05-22 10:09:54,914 | DEBUG | [0] Provider CCCP is ENABLED (L:96)
2015-05-22 10:09:54,914 | DEBUG | [0] Provider HTTP is ENABLED (L:96)
2015-05-22 10:09:54,914 | DEBUG | [0] Provider MCRAW is DISABLED (L:99)
2015-05-22 10:09:54,915 | DEBUG | [0] Start refresh requested (L:292)
2015-05-22 10:09:54,915 | DEBUG | [0] Current provider is CCCP (L:271)
2015-05-22 10:09:54,915 | INFO | [0] Requesting connection to node 192.168.0.3:11210 for CCCP configuration (L:118)
2015-05-22 10:09:54,916 | DEBUG | [0] <192.168.0.3:11210> (HE=0x102b480) Creating new connection because none are available in the pool (L:416)
2015-05-22 10:09:54,916 | DEBUG | [0] <192.168.0.3:11210> (HE=0x102b480) Starting connection on I=0x10056b0 (L:321)
2015-05-22 10:09:54,916 | INFO | [0] <192.168.0.3:11210> (SOCK=0xf02390) Starting. Timeout=2000000us (L:450)
2015-05-22 10:09:54,916 | DEBUG | [0] <192.168.0.3:11210> (SOCK=0xf02390) Got event handler for new connection (L:267)
2015-05-22 10:09:54,917 | DEBUG | [0] <192.168.0.3:11210> (SOCK=0xf02390) Scheduling asynchronous watch for socket. (L:314)
2015-05-22 10:09:54,917 | DEBUG | [0] <192.168.0.3:11210> (SOCK=0xf02390) Got event handler for new connection (L:267)
2015-05-22 10:09:54,917 | INFO | [0] <192.168.0.3:11210> (SOCK=0xf02390) Connected (L:116)
2015-05-22 10:09:54,917 | DEBUG | [0] <192.168.0.3:11210> (SOCK=0xf02390) Successfuly set TCP_NODELAY (L:123)
2015-05-22 10:09:54,918 | DEBUG | [0] <192.168.0.3:11210> (HE=0x102b480) Received result for I=0x10056b0,C=0xf02390; E=0x0 (L:271)
2015-05-22 10:09:54,918 | DEBUG | [0] <192.168.0.3:11210> (HE=0x102b480) Assigning R=0x100bcf0 SOCKET=0xf02390 (L:223)
2015-05-22 10:09:54,918 | DEBUG | [0] <192.168.0.3:11210> (CTX=0x102c430,unknown) Pairing with SOCK=0xf02390 (L:101)
2015-05-22 10:09:54,919 | DEBUG | [0] <192.168.0.3:11210> (CTX=0x102c430,sasl) Destroying. PND=0,ENT=1,SORC=1 (L:151)
2015-05-22 10:09:54,919 | DEBUG | [0] <192.168.0.3:11210> (CTX=0xeb19b0,unknown) Pairing with SOCK=0xf02390 (L:101)
2015-05-22 10:09:54,919 | DEBUG | [0] <192.168.0.3:11210> (CTX=0xeb19b0,bc_cccp) Destroying. PND=0,ENT=1,SORC=1 (L:151)
2015-05-22 10:09:54,920 | INFO | [0] <192.168.0.3:11210> (HE=0x102b480) Placing socket back into the pool. I=0x10056b0,C=0xf02390 (L:491)
2015-05-22 10:09:54,921 | INFO | [0] Setting new configuration. Received via CCCP (L:174)
2015-05-22 10:09:54,921 | DEBUG | [0] Instance configured! (L:55)
2015-05-22 10:09:54,921 | DEBUG | [0] Preparing providers (this may be called multiple times) (L:89)
2015-05-22 10:09:54,922 | DEBUG | [0] Provider FILE is DISABLED (L:99)
2015-05-22 10:09:54,922 | DEBUG | [0] Provider CCCP is ENABLED (L:96)
2015-05-22 10:09:54,922 | DEBUG | [0] Provider HTTP is DISABLED (L:99)
2015-05-22 10:09:54,922 | DEBUG | [0] Provider MCRAW is DISABLED (L:99)
2015-05-22 10:09:54,923 | INFO | [0] <192.168.0.3:11210> (HE=0x102b480) Found ready connection in pool. Reusing socket and not creating new connection (L:407)
2015-05-22 10:09:54,923 | DEBUG | [0] <192.168.0.3:11210> (HE=0x102b480) Assigning R=0x1008080 SOCKET=0xf02390 (L:223)
2015-05-22 10:09:54,923 | DEBUG | [0] <192.168.0.3:11210> (CTX=0xeb19b0,unknown) Pairing with SOCK=0xf02390 (L:101)
2015-05-22 10:09:54,923 | DEBUG | [0] <192.168.0.3:11210> (SRV=0x103d190,IX=0) Setting initial timeout=119999ms (L:543)
2015-05-22 10:09:54,924 | DEBUG | [0] <192.168.0.4:11210> (HE=0x10385f0) Creating new connection because none are available in the pool (L:416)
2015-05-22 10:09:54,924 | DEBUG | [0] <192.168.0.4:11210> (HE=0x10385f0) Starting connection on I=0xff26f0 (L:321)
2015-05-22 10:09:54,925 | INFO | [0] <192.168.0.4:11210> (SOCK=0x10390e0) Starting. Timeout=120000000us (L:450)
2015-05-22 10:09:54,925 | DEBUG | [0] <192.168.0.4:11210> (SOCK=0x10390e0) Got event handler for new connection (L:267)
2015-05-22 10:09:54,925 | DEBUG | [0] <192.168.0.4:11210> (SOCK=0x10390e0) Scheduling asynchronous watch for socket. (L:314)
2015-05-22 10:09:54,925 | DEBUG | [0] <192.168.0.4:11210> (SOCK=0x10390e0) Got event handler for new connection (L:267)
2015-05-22 10:09:54,926 | INFO | [0] <192.168.0.4:11210> (SOCK=0x10390e0) Connected (L:116)
2015-05-22 10:09:54,926 | DEBUG | [0] <192.168.0.4:11210> (SOCK=0x10390e0) Successfuly set TCP_NODELAY (L:123)
2015-05-22 10:09:54,926 | DEBUG | [0] <192.168.0.4:11210> (HE=0x10385f0) Received result for I=0xff26f0,C=0x10390e0; E=0x0 (L:271)
2015-05-22 10:09:54,926 | DEBUG | [0] <192.168.0.4:11210> (HE=0x10385f0) Assigning R=0xeb6550 SOCKET=0x10390e0 (L:223)
2015-05-22 10:09:54,927 | DEBUG | [0] <192.168.0.4:11210> (SRV=0x103e090) Session not yet negotiated. Negotiating (L:522)
2015-05-22 10:09:54,927 | DEBUG | [0] <192.168.0.4:11210> (CTX=0x10502c0,unknown) Pairing with SOCK=0x10390e0 (L:101)
2015-05-22 10:09:54,927 | DEBUG | [0] <192.168.0.4:11210> (CTX=0x10502c0,sasl) Destroying. PND=0,ENT=1,SORC=1 (L:151)
2015-05-22 10:09:54,928 | DEBUG | [0] <192.168.0.4:11210> (CTX=0x10368e0,unknown) Pairing with SOCK=0x10390e0 (L:101)
2015-05-22 10:09:54,928 | DEBUG | [0] <192.168.0.4:11210> (SRV=0x103e090,IX=1) Setting initial timeout=119996ms (L:543)
set value 0
2015-05-22 10:09:59,848 | WARNING | [0] Polling durability timed out! (L:572)
Traceback (most recent call last):
File "tasks/benchmarking/couchbase_timeout_test.py", line 49, in <module>
repeated_get_set_and_delete(iterations=100)
File "tasks/benchmarking/couchbase_timeout_test.py", line 44, in repeated_get_set_and_delete
cn.delete(key=key, replicate_to=1, persist_to=0)
File "/home/peter/.virtualenvs/peter-beta/lib/python3.4/site-packages/couchbase/bucket.py", line 1317, in _tmpmeth
return _dst(self, *args, **kwargs)
File "/home/peter/.virtualenvs/peter-beta/lib/python3.4/site-packages/couchbase/bucket.py", line 661, in remove
persist_to=persist_to, replicate_to=replicate_to)
couchbase.exceptions._TimeoutError_0x17 (generated, catch TimeoutError): <Key='foo', RC=0x17[Client-Side timeout exceeded for operation. Inspect network conditions or increase the timeout], Operational Error, Results=1, C Source=(src/multiresult.c,309)>
2015-05-22 10:09:59,857 | DEBUG | [0] <192.168.0.3:11210> (SRV=0x103d190,IX=0) Finalizing ctx 0xeb19b0 (L:758)
2015-05-22 10:09:59,857 | DEBUG | [0] <192.168.0.3:11210> (CTX=0xeb19b0,memcached) Destroying. PND=0,ENT=0,SORC=1 (L:151)
2015-05-22 10:09:59,857 | DEBUG | [0] <192.168.0.4:11210> (SRV=0x103e090,IX=1) Finalizing ctx 0x10368e0 (L:758)
2015-05-22 10:09:59,858 | DEBUG | [0] <192.168.0.4:11210> (CTX=0x10368e0,memcached) Destroying. PND=0,ENT=0,SORC=1 (L:151)
The error does not take the operation_timeout config parameter (120s) into account, but it appears after 5s.
Remind that the test script works with the setting replicate_to=0, the error only occurs if we set replicate_to=1.
Thanks again for your great help!