Timeout received after long wait


#1

I am accessing couchbase server locally on OSX from a node application. If I let the application sit idle for an extended period of time and then try to get documents using getMulti, it is failing with "“Client-Side timeout exceeded for operation. Inspect network conditions or increase the timeout”. I am repeating the same query each time and no other traffic is on the machine. Here are the debug logs which were output after the error. Any ideas on how to fix it?

2039098ms [I1] {50f} [DEBUG] (lcbio_mgr - L:416) <127.0.0.1:8092> (HE=0x10282fa00) Creating new connection because none are available in the pool
2039098ms [I1] {50f} [DEBUG] (lcbio_mgr - L:321) <127.0.0.1:8092> (HE=0x10282fa00) Starting connection on I=0x102306c80
2039098ms [I1] {50f} [INFO] (connection - L:450) <127.0.0.1:8092> (SOCK=0x102306600) Starting. Timeout=75000000us
2039100ms [I1] {50f} [TRACE] (connection - L:344) <127.0.0.1:8092> (SOCK=0x102306600) Received completion handler. Status=0. errno=0
2039100ms [I1] {50f} [INFO] (connection - L:116) <127.0.0.1:8092> (SOCK=0x102306600) Connected
2039100ms [I1] {50f} [WARN] (lcbio - L:103) FIXME: Unknown iops/os error code 45. Using NETWORK_ERROR
2039100ms [I1] {50f} [INFO] (lcbio - L:112) Translating errno=45, lcb=0x10 to NETWORK_ERROR
2039100ms [I1] {50f} [INFO] (connection - L:121) <127.0.0.1:8092> (SOCK=0x102306600) Couldn't set TCP_NODELAY
2039100ms [I1] {50f} [DEBUG] (lcbio_mgr - L:271) <127.0.0.1:8092> (HE=0x10282fa00) Received result for I=0x102306c80,C=0x102306600; E=0x0
2039100ms [I1] {50f} [DEBUG] (lcbio_mgr - L:223) <127.0.0.1:8092> (HE=0x10282fa00) Assigning R=0x1023067a0 SOCKET=0x102306600
2039100ms [I1] {50f} [DEBUG] (ioctx - L:101) <127.0.0.1:8092> (CTX=0x104d01d60,unknown) Pairing with SOCK=0x102306600
2039108ms [I1] {50f} [DEBUG] (ioctx - L:151) <127.0.0.1:8092> (CTX=0x104d01d60,mgmt/capi) Destroying. PND=0,ENT=1,SORC=1
2039108ms [I1] {50f} [INFO] (lcbio_mgr - L:491) <127.0.0.1:8092> (HE=0x10282fa00) Placing socket back into the pool. I=0x102306c80,C=0x102306600
2039112ms [I1] {50f} [WARN] (lcbio - L:103) FIXME: Unknown iops/os error code 1. Using NETWORK_ERROR
2039112ms [I1] {50f} [INFO] (lcbio - L:112) Translating errno=1, lcb=0x10 to NETWORK_ERROR
2039112ms [I1] {50f} [WARN] (server - L:640) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Got socket error 0x10
2039112ms [I1] {50f} [DEBUG] (retryq - L:324) Adding PKT=0x102306570 to retry queue. Try count=1
2039112ms [I1] {50f} [TRACE] (retryq - L:187) Next tick in 14 ms
… (previous 2 lines repeat many times
 2039112ms [I1] {50f} [TRACE] (confmon - L:292) Start refresh requested
2039112ms [I1] {50f} [INFO] (server - L:772) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Got handler after close. Checking pending calls
2039112ms [I1] {50f} [INFO] (confmon - L:166) Not applying configuration received via CCCP. No changes detected. A.rev=309, B.rev=309
2039112ms [I1] {50f} [TRACE] (confmon - L:271) Current provider is CCCP
2039112ms [I1] {50f} [INFO] (cccp - L:110) Re-Issuing CCCP Command on server struct 0x10251ea20 (127.0.0.1:11210)
2040678ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 3433 ms
2041116ms [I1] {50f} [ERROR] (cccp - L:133) <NOHOST:NOPORT> Got I/O Error=0x17
2041116ms [I1] {50f} [INFO] (confmon - L:202) Provider 'CCCP' failed
2041116ms [I1] {50f} [TRACE] (confmon - L:226) Maximum provider reached. Resetting index
2044115ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d200, opaque=250, opcode=0xb5) with error 0x17
2044115ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x102306570, opaque=200, opcode=0x0) with error 0x10
… (previous line repeats many times)
 2044122ms [I1] {50f} [INFO] (bootstrap - L:202) Not requesting a config refresh because of throttling parameters. Next refresh possible in 4990ms or 99 errors. See LCB_CNTL_CONFDELAY_THRESH and LCB_CNTL_CONFERRTHRESH to modify the throttling settings

2117452ms [I1] {50f} [DEBUG] (lcbio_mgr - L:416) <127.0.0.1:8092> (HE=0x10282fa00) Creating new connection because none are available in the pool
2117452ms [I1] {50f} [DEBUG] (lcbio_mgr - L:321) <127.0.0.1:8092> (HE=0x10282fa00) Starting connection on I=0x102307a70
2117452ms [I1] {50f} [INFO] (connection - L:450) <127.0.0.1:8092> (SOCK=0x102306460) Starting. Timeout=75000000us
2117454ms [I1] {50f} [TRACE] (connection - L:344) <127.0.0.1:8092> (SOCK=0x102306460) Received completion handler. Status=0. errno=0
2117454ms [I1] {50f} [INFO] (connection - L:116) <127.0.0.1:8092> (SOCK=0x102306460) Connected
2117454ms [I1] {50f} [WARN] (lcbio - L:103) FIXME: Unknown iops/os error code 45. Using NETWORK_ERROR
2117454ms [I1] {50f} [INFO] (lcbio - L:112) Translating errno=45, lcb=0x10 to NETWORK_ERROR
2117454ms [I1] {50f} [INFO] (connection - L:121) <127.0.0.1:8092> (SOCK=0x102306460) Couldn't set TCP_NODELAY
2117454ms [I1] {50f} [DEBUG] (lcbio_mgr - L:271) <127.0.0.1:8092> (HE=0x10282fa00) Received result for I=0x102307a70,C=0x102306460; E=0x0
2117454ms [I1] {50f} [DEBUG] (lcbio_mgr - L:223) <127.0.0.1:8092> (HE=0x10282fa00) Assigning R=0x1023079f0 SOCKET=0x102306460
2117454ms [I1] {50f} [DEBUG] (ioctx - L:101) <127.0.0.1:8092> (CTX=0x104d01e80,unknown) Pairing with SOCK=0x102306460
2117461ms [I1] {50f} [DEBUG] (ioctx - L:151) <127.0.0.1:8092> (CTX=0x104d01e80,mgmt/capi) Destroying. PND=0,ENT=1,SORC=1
2117462ms [I1] {50f} [INFO] (lcbio_mgr - L:491) <127.0.0.1:8092> (HE=0x10282fa00) Placing socket back into the pool. I=0x102307a70,C=0x102306460
2119153ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 3308 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122462ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d250, opaque=251, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d2a0, opaque=252, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d2f0, opaque=253, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d340, opaque=254, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d390, opaque=255, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d3e0, opaque=256, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d430, opaque=257, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d480, opaque=258, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d4d0, opaque=259, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d520, opaque=260, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d570, opaque=261, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d5c0, opaque=262, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d610, opaque=263, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d660, opaque=264, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d6b0, opaque=265, opcode=0x0) with error 0x17
2122463ms [I1] {50f} [TRACE] (confmon - L:292) Start refresh requested
2122463ms [I1] {50f} [ERROR] (server - L:463) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Server timed out. Some commands have failed
2122463ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 0 ms
2122463ms [I1] {50f} [INFO] (confmon - L:166) Not applying configuration received via CCCP. No changes detected. A.rev=309, B.rev=309
2122463ms [I1] {50f} [TRACE] (confmon - L:271) Current provider is CCCP
2122463ms [I1] {50f} [INFO] (cccp - L:110) Re-Issuing CCCP Command on server struct 0x10251ea20 (127.0.0.1:11210)
2122463ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d700, opaque=266, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d750, opaque=267, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d7a0, opaque=268, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d7f0, opaque=269, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d840, opaque=270, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d890, opaque=271, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d8e0, opaque=272, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d930, opaque=273, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d980, opaque=274, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189d9d0, opaque=275, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189da20, opaque=276, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189da70, opaque=277, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189dac0, opaque=278, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189db10, opaque=279, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189db60, opaque=280, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x10189dbb0, opaque=281, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0800, opaque=282, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0850, opaque=283, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a08a0, opaque=284, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a08f0, opaque=285, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0940, opaque=286, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0990, opaque=287, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a09e0, opaque=288, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0a30, opaque=289, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0a80, opaque=290, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0ad0, opaque=291, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0b20, opaque=292, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0b70, opaque=293, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0bc0, opaque=294, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0c10, opaque=295, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0c60, opaque=296, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0cb0, opaque=297, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0d00, opaque=298, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0d50, opaque=299, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0da0, opaque=300, opcode=0x0) with error 0x17
2122464ms [I1] {50f} [ERROR] (server - L:463) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Server timed out. Some commands have failed
2122464ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 4998 ms
2124465ms [I1] {50f} [ERROR] (cccp - L:133) <NOHOST:NOPORT> Got I/O Error=0x17
2124465ms [I1] {50f} [INFO] (confmon - L:202) Provider 'CCCP' failed
2124465ms [I1] {50f} [TRACE] (confmon - L:226) Maximum provider reached. Resetting index
2127464ms [I1] {50f} [DEBUG] (lcbio_mgr - L:464) <127.0.0.1:8092> (HE=0x10282fa00) Idle connection expired
2127464ms [I1] {50f} [WARN] (server - L:380) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Failing command (pkt=0x1018a0df0, opaque=301, opcode=0xb5) with error 0x17
2127464ms [I1] {50f} [INFO] (bootstrap - L:202) Not requesting a config refresh because of throttling parameters. Next refresh possible in 4999ms or 99 errors. See LCB_CNTL_CONFDELAY_THRESH and LCB_CNTL_CONFERRTHRESH to modify the throttling settings
2127464ms [I1] {50f} [ERROR] (server - L:463) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Server timed out. Some commands have failed
2127464ms [I1] {50f} [DEBUG] (server - L:467) <127.0.0.1:11210> (SRV=0x10251ea20,IX=0) Scheduling next timeout for 5000 ms

#2

It would seem you’ve found a bug. I’ve filed it and will look at it later: https://issues.couchbase.com/browse/CCBC-704

For the time being you can simply issue simple commands (perhaps try to “GET” a non-existent key) every few minutes or so to keep the TCP connection alive.