Details
-
Bug
-
Resolution: Fixed
-
Major
-
4.0.0
-
Security Level: Public
-
None
-
Centos
Build RC4 4047
-
Untriaged
-
Yes
Description
Repro:
Job run: http://qa.sc.couchbase.com/job/cen006-2i-vset03-03-recoverytests-add-index/111/consoleFull
test_18:
./testrunner -i /tmp/rec-add-index.ini doc-per-day=50,standard_buckets=1,sasl_buckets=1,skip_build_tuq=True,cbq_version=sherlock,scan_consistency=request_plus,get-cbcollect-info=True -t 2i.recovery_2i.SecondaryIndexingRecoveryTests.test_server_crash,initial=,before=create_index,after=query_ops,groups=simple,dataset=default,doc-per-day=10,services_init=n1ql:kv-kv-kv-index-index,nodes_init=5,nodes_out=1,nodes_out_dist=kv:1,targetProcess=memcached,GROUP=KILL-PROCESS;P0
Target process:kill memcached, Target node: KV node - 172.23.121.143
Steps:
1. Create 3 buckets: default, bucket0, standardBucket0; Load 100800 docs in each bucket
2. Create and build 9 indexes in all 3 buckets (index_name_1 to index_name_9)
3. Create 2 more indexes job_title and join_yr on each bucket in deferred mode
4. Build above indexes created in #3
5. While build of these 6 indexes is in progress, kill memcached on 172.23.121.143 KV node
6. After kill, all indexes come online. Start queryig the indexes. The index scan fails with error - N1QLQueryException: unable to get expected results for query CBQError: host 172.23.121.141: ERROR:{u'status': u'errors', u'errors': [
], u'results': [], u'metrics':
{u'elapsedTime': u'4m1.049550256s', u'executionTime': u'4m1.049455225s', u'resultSize': 0, u'resultCount': 0, u'errorCount': 1}, u'requestID': u'cb57c8d2-83e4-40b5-b059-fecaca73915f', u'signature': {u'': u''}}
From Indexer logs of node 145:
2015-08-19T20:10:06.653Z-07:00 [Info] SCAN##1 RESPONSE status:(error = Index scan timed out)
2015-08-19T20:10:06.654Z-07:00 [Info] [Queryport ":9101"] connection "172.23.121.141:57666" skip protobuf.EndStreamRequest
But corresponding SCAN##1 Request as to when it was received is not logged (as this is info logging)
From the query logs: (Node 141)
2015-08-19T20:03:04.576Z-07:00 [Info] serviceChangeNotifier: received PoolChangeNotification
2015-08-19T20:03:04.671Z-07:00 [Info] Refreshing indexer list due to cluster changes or auto-refresh.
2015-08-19T20:03:04.671Z-07:00 [Info] Refreshed Indexer List: [172.23.121.144:9100 172.23.121.145:9100]
2015-08-19T20:04:43.271Z-07:00 [Info] [Queryport-connpool:172.23.121.144:9101] open new connection ...
2015-08-19T20:06:37.477Z-07:00 [Info] DCPT[secidx:getseqnos-42:5f:2f:c:be:dc:15:b1] ##abba feed started ...
2015-08-19T20:06:37.482Z-07:00 [Info] DCPT[secidx:getseqnos-4d:76:10:d1:a2:c4:25:5f] ##abba feed started ...
2015-08-19T20:06:37.487Z-07:00 [Info] DCPT[secidx:getseqnos-20:dd:eb:58:2b:8d:ad:3c] ##abba feed started ...
2015-08-19T20:06:37.488Z-07:00 [Info]
"bucket0" created for dcp_seqno cache...
2015-08-19T20:06:37.503Z-07:00 [Info] [Queryport-connpool:172.23.121.144:9101] open new connection ...
2015-08-19T20:08:06.673Z-07:00 [Info] [Queryport-connpool:172.23.121.145:9101] open new connection ...
2015-08-19T20:10:06.678Z-07:00 [Error] [GsiScanClient:"172.23.121.145:9101"] Range() response failed `Index scan timed out`
2015-08-19T20:10:06.678Z-07:00 [Warn] Trying scan again for index 12556376683248123170 (true true): Index scan timed out ...
2015-08-19T20:12:07.134Z-07:00 [Error] [GsiScanClient:"172.23.121.145:9101"] Range() response failed `Index scan timed out`
2015-08-19T20:14:07.673Z-07:00 [Error] [GsiScanClient:"172.23.121.145:9101"] Range() response failed `Index scan timed out`
2015-08-19T20:14:07.673Z-07:00 [Warn] Trying scan again for index 12556376683248123170 (true true): Index scan timed out ...
2015-08-19T20:16:08.2Z-07:00 [Error] [GsiScanClient:"172.23.121.145:9101"] Range() response failed `Index scan timed out`
2015-08-19T20:20:32.641Z-07:00 [Error] [GsiScanClient:"172.23.121.145:9101"] Range() response failed `Index scan timed out`
2015-08-19T20:20:32.641Z-07:00 [Warn] Trying scan again for index 12556376683248123170 (true true): Index scan timed out ...
2015-08-19T20:22:33.043Z-07:00 [Error] [GsiScanClient:"172.23.121.145:9101"] Range() response failed `Index scan timed out`
2015-08-19T20:24:33.537Z-07:00 [Error] [GsiScanClient:"172.23.121.145:9101"] Range() response failed `Index scan timed out`
2015-08-19T20:24:33.537Z-07:00 [Warn] Trying scan again for index 12556376683248123170 (true true): Index scan timed out ...
2015-08-19T20:26:33.983Z-07:00 [Error] [GsiScanClient:"172.23.121.145:9101"] Range() response failed `Index scan timed out`
Kindly confirm if this index scan timeout is genuine (due to machine slowness perhaps) or otherwise.
Attachments
For Gerrit Dashboard: MB-16135 | ||||||
---|---|---|---|---|---|---|
# | Subject | Branch | Project | Status | CR | V |
55454,2 | MB-16135: log failed scan REQUEST in info-level. | unstable | indexing | Status: MERGED | +2 | +1 |
55559,2 | MB-16135: log failed scan REQUEST in info-level. | testing | indexing | Status: MERGED | +2 | +1 |
55638,1 | Revert commits fcd46e9 c51dac4 d4baa0f 06268d9 79c1447 f012e5b | unstable | indexing | Status: MERGED | +2 | +1 |
55642,1 | MB-16135: log failed scan REQUEST in info-level. | unstable | indexing | Status: MERGED | +2 | +1 |
55647,1 | Revert a7b96d8 996d985 5d2c283 4047d3c e546d25 bd6f752 | unstable | indexing | Status: MERGED | +2 | +1 |