Details
-
Bug
-
Resolution: Fixed
-
Test Blocker
-
Cheshire-Cat
-
Untriaged
-
-
1
-
Yes
Description
Build : 7.0.0-2802
In the Flex index sanity test, on one of the platforms, all Flex index queries are failing with the following error -
[2020-08-10 08:40:56,973] - [tuq:1408] INFO - RUN QUERY SELECT META().id FROM `default` USE INDEX (USING FTS, USING GSI) WHERE address.ecpdId="1" ORDER BY META().id LIMIT 100
|
[2020-08-10 08:40:56,973] - [rest_client:3704] INFO - query params : statement=SELECT+META%28%29.id+FROM+%60default%60+USE+INDEX+%28USING+FTS%2C+USING+GSI%29+WHERE+address.ecpdId%3D%221%22+ORDER+BY+META%28%29.id+LIMIT+100&scan_consistency=NOT_BOUNDED
|
[2020-08-10 08:40:56,977] - [rest_client:964] ERROR - POST http://172.23.120.57:8093/query?statement=SELECT+META%28%29.id+FROM+%60default%60+USE+INDEX+%28USING+FTS%2C+USING+GSI%29+WHERE+address.ecpdId%3D%221%22+ORDER+BY+META%28%29.id+LIMIT+100&scan_consistency=NOT_BOUNDED body: headers: {'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA=='} error: 500 reason: unknown b'{\n"requestID": "5b6b083b-5aea-4b61-b6e0-1eafccd6aab5",\n"signature": {"id":"json"},\n"results": [\n],\n"errors": [{"code":5000,"msg":"n1fty: search failed - cause: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \\"transport: Error while dialing dial tcp 172.23.120.59:9130: connect: connection refused\\""}],\n"status": "errors",\n"metrics": {"elapsedTime": "2.213098ms","executionTime": "2.160292ms","resultCount": 0,"resultSize": 0,"errorCount": 1}\n}\n' auth: Administrator:password
|
[2020-08-10 08:40:56,977] - [flex_index_phase1:69] INFO - Failed to run flex query: SELECT META().id FROM `default` USE INDEX (USING FTS, USING GSI) WHERE address.ecpdId="1" ORDER BY META().id LIMIT 100
|
[2020-08-10 08:40:56,977] - [flex_index_phase1:70] ERROR - CBQError: host 172.23.120.57: ERROR:{'requestID': '5b6b083b-5aea-4b61-b6e0-1eafccd6aab5', 'signature': {'id': 'json'}, 'results': [], 'errors': [{'code': 5000, 'msg': 'n1fty: search failed - cause: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 172.23.120.59:9130: connect: connection refused"'}], 'status': 'errors', 'metrics': {'elapsedTime': '2.213098ms', 'executionTime': '2.160292ms', 'resultCount': 0, 'resultSize': 0, 'errorCount': 1}}
|
In the FTS logs around the same time, the following errors and warnings are observed -
2020-08-10T08:40:58.104-07:00 [WARN] (GOCBCORE) Config block decode failure (unexpected EOF) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.108-07:00 [WARN] (GOCBCORE) Config block decode failure (unexpected EOF) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.114-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.117-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.117-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.119-07:00 [WARN] (GOCBCORE) Config block decode failure (unexpected EOF) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.119-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.121-07:00 [WARN] (GOCBCORE) Config block decode failure (unexpected EOF) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.124-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.127-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.134-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.135-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.137-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.138-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.144-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.158-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.159-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.175-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.177-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.178-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.179-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.179-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:621
|
2020-08-10T08:40:58.189-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.195-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.197-07:00 [WARN] (GOCBCORE) Config block decode failure (invalid character 'R' looking for beginning of value) -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:623
|
2020-08-10T08:40:58.245-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:621
|
2020-08-10T08:40:58.246-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:621
|
2020-08-10T08:40:58.246-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:621
|
2020-08-10T08:40:58.246-07:00 [INFO] main: meh.OnFeedError, srcType: gocbcore, err: EOF | {"bucket":"default","last_dispatched_to":"172.23.120.60:11210","last_dispatched_from":"172.23.120.59:54346","last_connection_id":"4c0b1dfb310b8b67/db03bf98f39e38c8"}
|
2020-08-10T08:40:58.250-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:621
|
2020-08-10T08:40:58.256-07:00 [INFO] main: meh.OnFeedError, VerifySourceNotExists, srcType: gocbcore, gone: true, indexUUID:
|
2020-08-10T08:40:58.256-07:00 [INFO] main: meh.OnFeedError, DeleteAllIndexFromSource, srcType: gocbcore, bucketName: default, bucketUUID: 962c32f62870823302058027927bca6f
|
2020-08-10T08:40:58.273-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF -- cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:621
|
Similarly in the query logs, following errors are seen -
2020-08-10T08:40:57.041-07:00 [INFO] Using plain authentication for user <ud>@cbq-engine</ud>
|
_time=2020-08-10T08:40:57.450-07:00 _level=INFO _msg=response_handler: buffer outflow observed, cap 512 len 426
|
_time=2020-08-10T08:40:57.453-07:00 _level=INFO _msg=response_handler: n1fty[default_index/default-1597074057372685209] "feb84629-dbc0-4bc3-bc28-cf609dbc8265" started backfill for /opt/couchbase/var/lib/couchbase/tmp/search-results30301393668959
|
_time=2020-08-10T08:40:57.747-07:00 _level=INFO _msg=response_handler: n1fty[default_index/default-1597074057372685209] "feb84629-dbc0-4bc3-bc28-cf609dbc8265" finished backfill for /opt/couchbase/var/lib/couchbase/tmp/search-results30301393668959
|
2020-08-10T08:40:58.104-07:00 [Info] serviceChangeNotifier: received BucketsChangeNotification
|
2020-08-10T08:40:58.104-07:00 [Info] serviceChangeNotifier: Removing the bucket: default from book-keeping
|
2020-08-10T08:40:58.105-07:00 [INFO] Trying with http://172.23.120.57:8091/pools/default/bucketsStreaming/default
|
2020-08-10T08:40:58.109-07:00 [ERROR] Failed to connect to host, unexpected status code: 404. Body Requested resource not found.
|
|
2020-08-10T08:40:58.109-07:00 [INFO] Trying with http://172.23.120.57:8091/pools/default/bucketsStreaming/default
|
2020-08-10T08:40:58.114-07:00 [Warn] servicesChangeNotifier: Connection terminated for collection manifest notifier instance of http://%40cbq-engine-cbauth@127.0.0.1:8091, default, bucket: default, (unexpected EOF)
|
2020-08-10T08:40:58.116-07:00 [ERROR] Failed to connect to host, unexpected status code: 404. Body Requested resource not found.
|
|
2020-08-10T08:40:58.116-07:00 [INFO] Trying with http://172.23.120.57:8091/pools/default/bucketsStreaming/default
|
2020-08-10T08:40:58.120-07:00 [ERROR] Failed to connect to host, unexpected status code: 404. Body Requested resource not found.
|
|
2020-08-10T08:40:58.120-07:00 [INFO] Trying with http://172.23.120.57:8091/pools/default/bucketsStreaming/default
|
2020-08-10T08:40:58.124-07:00 [ERROR] Failed to connect to host, unexpected status code: 404. Body Requested resource not found.
|
|
2020-08-10T08:40:58.124-07:00 [ERROR] Maximum failures reached. Exiting loop...
|
_time=2020-08-10T08:40:58.124-07:00 _level=INFO _msg=Keyspace default being deleted
|
2020-08-10T08:40:58.130-07:00 [Warn] servicesChangeNotifier: Connection terminated for pool notifier instance of http://%40cbq-engine-cbauth@127.0.0.1:8091, default (Notifier invalidated due to internal error)
|
2020-08-10T08:40:58.176-07:00 [ERROR] Bucket Updater exited with err Max failures reached. Last Error Failed to connect to host. Status 404 Body Requested resource not found.
|
|
2020/08/10 08:40:58 cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/indexDefs, key: indexDefs, deletion: false
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #0 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #1 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #2 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #3 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #4 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #0 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #1 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #2 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #3 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.282-07:00 _level=INFO _msg=client: grpc client connection #4 created for host: 172.23.120.59:9130
|
2020/08/10 08:40:58 cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/indexDefs, key: indexDefs, deletion: false
|
2020/08/10 08:40:58 cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/indexDefs, key: indexDefs, deletion: false
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #0 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #1 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #2 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #3 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #4 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #0 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #1 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #2 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #3 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.306-07:00 _level=INFO _msg=client: grpc client connection #4 created for host: 172.23.120.57:9130
|
2020/08/10 08:40:58 cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/indexDefs, key: indexDefs, deletion: false
|
_time=2020-08-10T08:40:58.314-07:00 _level=INFO _msg=client: grpc client connection #0 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #1 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #2 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #3 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #4 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #0 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #1 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #2 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #3 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.315-07:00 _level=INFO _msg=client: grpc client connection #4 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #0 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #1 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #2 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #3 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #4 created for host: 172.23.120.59:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #0 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #1 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #2 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #3 created for host: 172.23.120.57:9130
|
_time=2020-08-10T08:40:58.327-07:00 _level=INFO _msg=client: grpc client connection #4 created for host: 172.23.120.57:9130
|
2020/08/10 08:40:58 cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/curMetaKvPlanKey, key: curMetaKvPlanKey, deletion: false
|
2020/08/10 08:40:58 cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/curMetaKvPlanKey, key: curMetaKvPlanKey, deletion: false
|
2020/08/10 08:40:58 cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/curMetaKvPlanKey, key: curMetaKvPlanKey, deletion: false
|
FTS node = 172.23.120.59
Query node = 172.23.120.57
This issue was not seen with the same build on other platforms. Also have checked the job run previously on Debian9 platform, and the issue wasn't seen in the previous builds. This indicates that this must be an intermittent issue. Hence not marking this as a blocker.
Attachments
For Gerrit Dashboard: MB-40848 | ||||||
---|---|---|---|---|---|---|
# | Subject | Branch | Project | Status | CR | V |
135070,3 | MB-40848: Log a fatal error if primary http/gRPC listeners error | master | cbft | Status: ABANDONED | 0 | 0 |
135078,5 | MB-40848: Only bindGRPCSSL ports to cbauth's refresh config callback | master | cbft | Status: MERGED | +2 | +1 |