Details
-
Bug
-
Resolution: Duplicate
-
Critical
-
Cheshire-Cat
-
Untriaged
-
1
-
Unknown
Description
Build : 7.0.0-3273
Test : ./testrunner -i node_conf.ini -p get-cbcollect-info=True,get-couch-dbinfo=True,skip_cleanup=False -t tuqquery.tuq_index.QueriesViewsTests.test_primary_create_delete_index,doc-per-day=2,primary_indx_type=GSI,reload_data=False,force_clean=True,nodes_init=1
Job : 1-node sanity (test_15)
This looks like an intermittent issue when a bucket is deleted (in the previous test) and then created with the same name (in the next test), and then an index is created on this bucket.
On a single node cluster, a default bucket is created at 2020-10-01 16:25:56
[2020-10-01 16:25:56,402] - [rest_client:2691] INFO - http://172.23.107.190:8091/pools/default/buckets with param: name=default&authType=sasl&saslPassword=None&ramQuotaMB=3287&replicaNumber=1&bucketType=membase&replicaIndex=1&threadsNumber=3&flushEnabled=1&evictionPolicy=valueOnly&compressionMode=passive&storageBackend=couchstore
|
[2020-10-01 16:25:56,410] - [rest_client:2716] INFO - 0.01 seconds to create bucket default
|
Then few seconds later, at, a primary index is attempted to be created, which fails.
[2020-10-01 16:26:01,191] - [tuq:1408] INFO - RUN QUERY CREATE PRIMARY INDEX ON `default` USING gsi
|
[2020-10-01 16:26:01,191] - [rest_client:3738] INFO - query params : statement=CREATE+PRIMARY+INDEX+ON+%60default%60+USING+gsi&scan_consistency=REQUEST_PLUS
|
[2020-10-01 16:26:11,281] - [rest_client:986] ERROR - POST http://172.23.107.190:8093/query?statement=CREATE+PRIMARY+INDEX+ON+%60default%60+USING+gsi&scan_consistency=REQUEST_PLUS body: headers: {'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA=='} error: 500 reason: unknown b'{\n"requestID": "035c11ab-9fc9-4f1a-94a1-cc454f7cfac0",\n"signature": null,\n"results": [\n],\n"errors": [{"code":5000,"msg":"GSI CreatePrimaryIndex() - cause: Unknown Bucket\\n"}],\n"status": "errors",\n"metrics": {"elapsedTime": "10.087421367s","executionTime": "10.087279449s","resultCount": 0,"resultSize": 0,"serviceLoad": 1,"errorCount": 1}\n}\n' auth: Administrator:password
|
[2020-10-01 16:26:11,283] - [basetestcase:567] INFO - sleep for 1 secs. exception returned: CBQError: host 172.23.107.190: ERROR:{'requestID': '035c11ab-9fc9-4f1a-94a1-cc454f7cfac0', 'signature': None, 'results': [], 'errors': [{'code': 5000, 'msg': 'GSI CreatePrimaryIndex() - cause: Unknown Bucket\n'}], 'status': 'errors', 'metrics': {'elapsedTime': '10.087421367s', 'executionTime': '10.087279449s', 'resultCount': 0, 'resultSize': 0, 'serviceLoad': 1, 'errorCount': 1}}
|
Indexer logs shows the following from before the bucket got recreated :
2020-10-01T16:25:54.528-07:00 [Error] Unable to connect with bucket "default"
|
2020-10-01T16:25:54.529-07:00 [Warn] Indexer::getCurrentKVTs error=No bucket named default Retrying (9)
|
2020-10-01T16:25:54.534-07:00 [Error] Unable to connect with bucket "default"
|
2020-10-01T16:25:54.535-07:00 [Warn] Indexer::getCurrentKVTs error=No bucket named default Retrying (10)
|
2020-10-01T16:25:54.540-07:00 [Error] Unable to connect with bucket "default"
|
2020-10-01T16:25:54.541-07:00 [Error] Indexer::getCurrentKVTs Error Connecting to KV Cluster No bucket named default
|
2020-10-01T16:25:55.541-07:00 [Error] Timekeeper::handleStats Error occured while obtaining KV seqnos - No bucket named default
|
2020-10-01T16:26:01.195-07:00 [Info] LifecycleMgr.handlePrepareCreateIndex() : Accept 14124029142478771429
|
2020-10-01T16:26:01.195-07:00 [Info] lifecycleMgr.dispatchRequest: op OPCODE_PREPARE_CREATE_INDEX elapsed 152.073µs len(expediates) 0 len(incomings) 0 len(outgoings) 0
|
2020-10-01T16:26:01.218-07:00 [Info] DDLServiceMgr::handleListCreateTokens Processing Request &{GET /listCreateTokens HTTP/1.1 1 1 map[Accept-Encoding:[gzip] Authorization:[Basic QGNicS1lbmdpbmUtY2JhdXRoOjhlNjhhMGJkNGY2MDBjNjE1MjYzZGVkNTNmMWE4YjE1] User-Agent:[Go-http-client/1.1]] {} <nil> 0 [] false 127.0.0.1:9102 map[] map[] <nil> map[] 127.0.0.1:42792 /listCreateTokens <nil> <nil> <nil> 0xc00bf75600}
|
2020-10-01T16:26:01.221-07:00 [Info] DDLServiceMgr::handleListDeleteTokens Processing Request &{GET /listDeleteTokens HTTP/1.1 1 1 map[Accept-Encoding:[gzip] Authorization:[Basic QGNicS1lbmdpbmUtY2JhdXRoOjhlNjhhMGJkNGY2MDBjNjE1MjYzZGVkNTNmMWE4YjE1] User-Agent:[Go-http-client/1.1]] {} <nil> 0 [] false 127.0.0.1:9102 map[] map[] <nil> map[] 127.0.0.1:42792 /listDeleteTokens <nil> <nil> <nil> 0xc009afc580}
|
2020-10-01T16:26:01.225-07:00 [Info] DDLServiceMgr::handleListDropInstanceTokens Processing Request &{GET /listDropInstanceTokens HTTP/1.1 1 1 map[Accept-Encoding:[gzip] Authorization:[Basic QGNicS1lbmdpbmUtY2JhdXRoOjhlNjhhMGJkNGY2MDBjNjE1MjYzZGVkNTNmMWE4YjE1] User-Agent:[Go-http-client/1.1]] {} <nil> 0 [] false 127.0.0.1:9102 map[] map[] <nil> map[] 127.0.0.1:42792 /listDropInstanceTokens <nil> <nil> <nil> 0xc009afc640}
|
2020-10-01T16:26:01.228-07:00 [Info] Indexer::ReadMemstats Time Taken 167.036µs
|
2020-10-01T16:26:01.243-07:00 [Info] clustMgrAgent::OnIndexCreate Notification Received for Create Index DefnId: 14124029142478771429 Name: #primary Using: plasma Bucket: default Scope/Id: _default/0 Collection/Id: _default/0 IsPrimary: true NumReplica: 0 InstVersion: 0
|
SecExprs: <ud>([])</ud>
|
Desc: []
|
PartitionScheme: SINGLE
|
HashScheme: CRC32 PartitionKeys: [] WhereExpr: <ud>()</ud> RetainDeletedXATTR: false &{0} partitions [0]
|
2020-10-01T16:26:01.243-07:00 [Info] Indexer::handleCreateIndex
|
InstId: 1192387109344779453
|
Defn: DefnId: 14124029142478771429 Name: #primary Using: plasma Bucket: default Scope/Id: _default/0 Collection/Id: _default/0 IsPrimary: true NumReplica: 0 InstVersion: 0
|
SecExprs: <ud>([])</ud>
|
Desc: []
|
PartitionScheme: SINGLE
|
HashScheme: CRC32 PartitionKeys: [] WhereExpr: <ud>()</ud> RetainDeletedXATTR: false
|
State: INDEX_STATE_CREATED
|
RState: RebalActive
|
Stream: NIL_STREAM
|
Version: 0
|
ReplicaId: 0
|
PartitionContainer: &{map[0:{0 0 [:9105]}] 1024 1 1024 SINGLE 0}
|
2020-10-01T16:26:01.243-07:00 [Fatal] Error Fetching Bucket Info: No bucket named default Nids: []
|
2020-10-01T16:26:01.269-07:00 [Error] Indexer::handleCreateIndex Bucket %!v(MISSING) Not Found
|
2020-10-01T16:26:01.269-07:00 [Error] clustMgrAgent::OnIndexCreate Error for Create Index DefnId: 14124029142478771429 Name: #primary Using: plasma Bucket: default Scope/Id: _default/0 Collection/Id: _default/0 IsPrimary: true NumReplica: 0 InstVersion: 0
|
SecExprs: <ud>([])</ud>
|
Desc: []
|
PartitionScheme: SINGLE
|
HashScheme: CRC32 PartitionKeys: [] WhereExpr: <ud>()</ud> RetainDeletedXATTR: false . Error Unknown Bucket.
|
2020-10-01T16:26:01.269-07:00 [Error] LifecycleMgr.CreateIndex() : createIndex fails. Reason = Unknown Bucket
|
2020-10-01T16:26:01.276-07:00 [Error] LifecycleMgr.processCommitToken() : build index fails. Reason = Unknown Bucket
|
2020-10-01T16:26:01.276-07:00 [Info] LifecycleMgr.handleCommitCreateIndex() : Create token posted for 14124029142478771429
|
2020-10-01T16:26:01.276-07:00 [Info] lifecycleMgr.dispatchRequest: op OPCODE_COMMIT_CREATE_INDEX elapsed 38.168926ms len(expediates) 0 len(incomings) 0 len(outgoings) 0
|
Not sure if this is a regression, because this issue can be intermittently seen in the sanity jobs on a couple of platforms atleast since 7.0.0-3237.