Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
3.0.6
-
None
-
None
-
1
Description
Libcouchbase is looping during 2 sec after callback completed with LCB_ERR_TIMEOUT (cf. attached files for multiget).
Attachments
For Gerrit Dashboard: CCBC-1335 | ||||||
---|---|---|---|---|---|---|
# | Subject | Branch | Project | Status | CR | V |
140318,9 | [CCBC-1335] fix next timeout computation on requesting config | master | libcouchbase | Status: MERGED | +2 | +1 |
Activity
Sergey Avseyev i manage to reproduce the issue on multiget after a failover. Could you have a look ?
I ran this command : export LCB_LOGLEVEL=4 && export GTEST_FILTER="GetUnitTest.*" && ctest -V
New unit test is about
- set of 20 keys dispatched on the 4 nodes of the mock
- multiget of the 20 keys in SUCCESS
- failover node 0 (w/o rebalance)
- a new multiget of the 20 keys in SUCCESS for master key not in node 0
- another multiget of the 20 keys but after all callbacks completed, lcb attempts scheduling next timeout (during 2s)
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key12' on get callback 1, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key13' on get callback 2, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key4' on get callback 3, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key10' on get callback 4, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key11' on get callback 5, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key1' on get callback 6, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key3' on get callback 7, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key0' on get callback 8, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key6' on get callback 9, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key2' on get callback 10, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key7' on get callback 11, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key5' on get callback 12, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key9' on get callback 13, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key8' on get callback 14, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key16' on get callback 15, status: LCB_SUCCESS (0) |
9: 1303ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key14' on get callback 16, status: LCB_SUCCESS (0) |
9: 1304ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key18' on get callback 17, status: LCB_SUCCESS (0) |
9: 1304ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key15' on get callback 18, status: LCB_SUCCESS (0) |
9: 1304ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key17' on get callback 19, status: LCB_SUCCESS (0) |
9: 1304ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key19' on get callback 20, status: LCB_SUCCESS (0) |
9: 1306ms [I6d7a08f77e380702] {23494} [INFO] (tests-GET - L:581) Failover node 0 ... |
9: 1307ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key12' on get callback 1, status: LCB_SUCCESS (0) |
9: 1307ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key13' on get callback 2, status: LCB_SUCCESS (0) |
9: 1309ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key1' on get callback 3, status: LCB_SUCCESS (0) |
9: 1309ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key3' on get callback 4, status: LCB_SUCCESS (0) |
9: 1309ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key6' on get callback 5, status: LCB_SUCCESS (0) |
9: 1310ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key7' on get callback 6, status: LCB_SUCCESS (0) |
9: 1310ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key9' on get callback 7, status: LCB_SUCCESS (0) |
9: 1310ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key16' on get callback 8, status: LCB_SUCCESS (0) |
9: 1310ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key18' on get callback 9, status: LCB_SUCCESS (0) |
9: 1314ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key0' on get callback 10, status: LCB_SUCCESS (0) |
9: 1314ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key2' on get callback 11, status: LCB_SUCCESS (0) |
9: 1314ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key5' on get callback 12, status: LCB_SUCCESS (0) |
9: 1314ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key8' on get callback 13, status: LCB_SUCCESS (0) |
9: 1314ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key14' on get callback 14, status: LCB_SUCCESS (0) |
9: 1314ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key15' on get callback 15, status: LCB_SUCCESS (0) |
9: 1314ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key17' on get callback 16, status: LCB_SUCCESS (0) |
9: 1315ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key19' on get callback 17, status: LCB_SUCCESS (0) |
9: 1407ms [I6d7a08f77e380702] {23494} [WARN] (server - L:775) Failing command with error LCB_ERR_TIMEOUT (201): {"b":"default","i":"6d7a08f77e380702/8a419d01f7ead5ff/2c","l":"127.0.0.1:60094","r":"localhost:40373","s":"kv:get","t":100000} |
9: 1407ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key4' on get callback 18, status: LCB_ERR_TIMEOUT (201) |
9: 1407ms [I6d7a08f77e380702] {23494} [WARN] (server - L:775) Failing command with error LCB_ERR_TIMEOUT (201): {"b":"default","i":"6d7a08f77e380702/8a419d01f7ead5ff/32","l":"127.0.0.1:60094","r":"localhost:40373","s":"kv:get","t":100000} |
9: 1407ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key10' on get callback 19, status: LCB_ERR_TIMEOUT (201) |
9: 1407ms [I6d7a08f77e380702] {23494} [WARN] (server - L:775) Failing command with error LCB_ERR_TIMEOUT (201): {"b":"default","i":"6d7a08f77e380702/8a419d01f7ead5ff/33","l":"127.0.0.1:60094","r":"localhost:40373","s":"kv:get","t":100000} |
9: 1407ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key11' on get callback 20, status: LCB_ERR_TIMEOUT (201) |
9: 1407ms [I6d7a08f77e380702] {23494} [TRACE] (confmon - L:297) Refreshing current cluster map (bucket: default) |
9: 1407ms [I6d7a08f77e380702] {23494} [DEBUG] (server - L:872) <localhost:40373> (CTX=0x55eb2e4b6e20,memcached,SRV=0x55eb2e4b18e0,IX=0) Server timed out. Some commands have failed |
9: 1407ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:40373> (CTX=0x55eb2e4b6e20,memcached,SRV=0x55eb2e4b18e0,IX=0) Scheduling next timeout for 100 ms. This is not an error |
9: 1408ms [I6d7a08f77e380702] {23494} [TRACE] (confmon - L:283) Attempting to retrieve cluster map via CCCP |
9: 1408ms [I6d7a08f77e380702] {23494} [TRACE] (cccp - L:150) Re-Issuing CCCP Command on server struct 0x55eb2e4b18e0 (localhost:40373) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key1' on get callback 1, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key3' on get callback 2, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key12' on get callback 3, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key13' on get callback 4, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key0' on get callback 5, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key2' on get callback 6, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key5' on get callback 7, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key6' on get callback 8, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key7' on get callback 9, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key8' on get callback 10, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key9' on get callback 11, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key14' on get callback 12, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key16' on get callback 13, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key15' on get callback 14, status: LCB_SUCCESS (0) |
9: 1408ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key18' on get callback 15, status: LCB_SUCCESS (0) |
9: 1409ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key17' on get callback 16, status: LCB_SUCCESS (0) |
9: 1409ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key19' on get callback 17, status: LCB_SUCCESS (0) |
9: 1509ms [I6d7a08f77e380702] {23494} [WARN] (server - L:775) Failing command with error LCB_ERR_TIMEOUT (201): {"b":"default","i":"6d7a08f77e380702/8a419d01f7ead5ff/40","l":"127.0.0.1:60094","r":"localhost:40373","s":"kv:get","t":100000} |
9: 1509ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key4' on get callback 18, status: LCB_ERR_TIMEOUT (201) |
9: 1509ms [I6d7a08f77e380702] {23494} [WARN] (server - L:775) Failing command with error LCB_ERR_TIMEOUT (201): {"b":"default","i":"6d7a08f77e380702/8a419d01f7ead5ff/46","l":"127.0.0.1:60094","r":"localhost:40373","s":"kv:get","t":100000} |
9: 1509ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key10' on get callback 19, status: LCB_ERR_TIMEOUT (201) |
9: 1509ms [I6d7a08f77e380702] {23494} [WARN] (server - L:775) Failing command with error LCB_ERR_TIMEOUT (201): {"b":"default","i":"6d7a08f77e380702/8a419d01f7ead5ff/47","l":"127.0.0.1:60094","r":"localhost:40373","s":"kv:get","t":100000} |
9: 1509ms [I6d7a08f77e380702] {23494} [DEBUG] (tests-GET - L:513) receive 'key11' on get callback 20, status: LCB_ERR_TIMEOUT (201) |
9: 1509ms [I6d7a08f77e380702] {23494} [DEBUG] (server - L:872) <localhost:40373> (CTX=0x55eb2e4b6e20,memcached,SRV=0x55eb2e4b18e0,IX=0) Server timed out. Some commands have failed |
9: 1509ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:40373> (CTX=0x55eb2e4b6e20,memcached,SRV=0x55eb2e4b18e0,IX=0) Scheduling next timeout for 1898 ms. This is not an error |
9: 1509ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 1509ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 1509ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 1609ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 1609ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 1609ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 1710ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 1710ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 1710ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 1810ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 1810ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 1810ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 1912ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 1912ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 1912ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2012ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2013ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2013ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2113ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2113ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2113ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2214ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2214ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2214ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2314ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2314ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2314ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2415ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2415ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2415ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2515ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2515ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2515ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2616ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2616ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2616ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2716ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2716ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2716ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2817ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2817ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2817ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 2917ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 2917ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 2917ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 3019ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 3019ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 3019ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 3119ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 3119ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 3119ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 3221ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 3221ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 3221ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 3322ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:45767> (CTX=0x55eb2e4b5890,memcached,SRV=0x55eb2e48f0d0,IX=3) Scheduling next timeout for 100 ms. This is not an error |
9: 3322ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:39721> (CTX=0x55eb2e49a200,memcached,SRV=0x55eb2e4b0c50,IX=2) Scheduling next timeout for 100 ms. This is not an error |
9: 3322ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:46537> (CTX=0x55eb2e4b0870,memcached,SRV=0x55eb2e4afee0,IX=1) Scheduling next timeout for 100 ms. This is not an error |
9: 3405ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:40373> (CTX=0x55eb2e4b6e20,memcached,SRV=0x55eb2e4b18e0,IX=0) Scheduling next timeout for 2 ms. This is not an error |
9: 3405ms [I6d7a08f77e380702] {23494} [ERROR] (cccp - L:171) <NOHOST:NOPORT> (CTX=(nil),) Could not get configuration: LCB_ERR_TIMEOUT (201) |
9: 3405ms [I6d7a08f77e380702] {23494} [TRACE] (cccp - L:150) Re-Issuing CCCP Command on server struct 0x55eb2e4afee0 (localhost:46537) |
9: 3409ms [I6d7a08f77e380702] {23494} [WARN] (server - L:775) Failing command with error LCB_ERR_TIMEOUT (201): {"b":"default","i":"6d7a08f77e380702/8a419d01f7ead5ff/50","l":"127.0.0.1:60094","r":"localhost:40373","s":"kv:get_cluster_config","t":2000000} |
9: 3409ms [I6d7a08f77e380702] {23494} [DEBUG] (server - L:872) <localhost:40373> (CTX=0x55eb2e4b6e20,memcached,SRV=0x55eb2e4b18e0,IX=0) Server timed out. Some commands have failed |
9: 3409ms [I6d7a08f77e380702] {23494} [TRACE] (server - L:876) <localhost:40373> (CTX=0x55eb2e4b6e20,memcached,SRV=0x55eb2e4b18e0,IX=0) Scheduling next timeout for 100 ms. This is not an error |
9: 3416ms [I6d7a08f77e380702] {23494} [INFO] (confmon - L:167) Setting new configuration. Received via CCCP |
9: 3416ms [I6d7a08f77e380702] {23494} [INFO] (bootstrap - L:151) Got new config (source=CCCP, bucket=default, rev=101). Will refresh asynchronously |
9: 3417ms [I6d7a08f77e380702] {23494} [INFO] (newconfig - L:163) Config Diff: [ vBuckets Modified=3072 ], [Sequence Changed=1] |
9: 3417ms [I6d7a08f77e380702] {23494} [INFO] (newconfig - L:172) Detected server localhost:40373(Data=40373, Index=0, Query=40131) removed |
9: 3417ms [I6d7a08f77e380702] {23494} [INFO] (newconfig - L:260) Reusing server localhost:46537 (0x55eb2e4afee0). OldIndex=1. NewIndex=0 |
9: 3417ms [I6d7a08f77e380702] {23494} [INFO] (newconfig - L:260) Reusing server localhost:39721 (0x55eb2e4b0c50). OldIndex=2. NewIndex=1 |
9: 3417ms [I6d7a08f77e380702] {23494} [INFO] (newconfig - L:260) Reusing server localhost:45767 (0x55eb2e48f0d0). OldIndex=3. NewIndex=2 |
9: 3417ms [I6d7a08f77e380702] {23494} [WARN] (server - L:779) <localhost:40373> (CTX=0x55eb2e4b6e20,memcached,SRV=0x55eb2e4b18e0,IX=0) Failing command (pkt=0x55eb2e4bf730, opaque=86, opcode=0x0) with error LCB_ERR_MAP_CHANGED (1037) |
|
after further investigation on code, i ve seen that a new computation of next timeout is performed (with new deadline parameter).
- by default, next timeout is set as previous lcb 2.x :
start + default_timeout (100ms in the example above)
- but in lcb 3.x, after config requested (after some failure detected), deadline is changed to:
start + config_node_timeout (2s by default)
is it a normal behaviour ? what is the reason for having change the computation ? do you think we can reduce this new deadline while failure happened ?
change related to http://review.couchbase.org/c/libcouchbase/+/111761/4/src/mcserver/mcserver.cc#b743
Hi Alexis, sorry for delay. Yes, you right it should use operation timeout setting here, because the configuration update uses KV protocol here. It still have another top-level logical timeout for node bootstrap, but it is different matter.
Thanks, I will accept and merge the change
Build couchbase-server-7.0.0-4433 contains libcouchbase commit be0f4eb with commit message:
CCBC-1335 fix next timeout computation on requesting config
Issue found during Lcb 3.0.6 migration in couchbase client at Amadeus IT. will try to attach reproducer in unit test.