Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-45196

LCB_ERR_INDEX_FAILURE - In n1ql eventing tests causing n1ql_op_exception_count = 1

    XMLWordPrintable

    Details

    • Type: Task
    • Status: Closed
    • Priority: Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: Cheshire-Cat
    • Fix Version/s: 7.0.0
    • Component/s: test-execution
    • Labels:
    • Environment:
      7.0.0-4678
    • Story Points:
      1

      Description

      The test is setup as follows : 

      • Deploy eventing function with n1ql queries inside
      • Load the source bucket
      • Run some access phase mutations

      We have observed the following error log in eventing.log in N1QL Based Eventing Tests. 

      2021-03-19T16:59:15.178-07:00 [Info] eventing-consumer [worker_perf-test1_23:/tmp/127.0.0.1:8091_23_3374800134.sock:123412] {  "message": "SDK error : LCB_ERR_INDEX_FAILURE (402) Query error : {\n\"requestID\": \"20e0a0f0-bff8-4f46-848e-fdbae6761a0f\",\n\"clientContextID\": \"8@perf-test1.js(OnUpdate)\",\n\"errors\": [{\"code\":12003,\"msg\":\"Keyspace not found in CB datastore: default:eventing-bucket-1 - cause: No bucket named eventing-bucket-1\"}],\n\"status\": \"fatal\",\n\"metrics\": {\"elapsedTime\": \"164.504346ms\",\"executionTime\": \"164.433732ms\",\"resultCount\": 0,\"resultSize\": 0,\"serviceLoad\": 47,\"errorCount\": 1}\n}\n",  "stack": "Error\n    at OnUpdate (perf-test1.js:8:21)"} Line: 7 Code: var upsert_query = N1QL('UPSERT INTO `eventing-bucket-1` (KEY, VALUE) VALUES ($docId, \'Hello World\');', {'$docId':docId}, { 'consistency': 'none' }); Stack: Error    at OnUpdate (perf-test1.js:8:21) 

      At this point of time in the test, we have initially begun to load the source bucket- bucket-1 of the eventing function 

      The error log points to another bucket - the destination bucket - eventing-bucket-1 which is created along with the source bucket. The log complains that the bucket is not found but the bucket is not deleted during the test.  The test after this point runs fine and the N1QL queries are executed through eventing. Finally eventing reports this as n1ql_op_exception_count = 1.

      At the same timestamp in query.log we see this 

      2021-03-19T16:59:15.000-07:00 [INFO]  Trying with http://127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 
      _time=2021-03-19T17:23:26.495-07:00 _level=INFO _msg=Created New Bucket eventing 

      Looks like query is still trying to connect to the eventing-bucket-1 bucket and in the meanwhile one operation fails. This is not seen in recent 6.6.2 builds : http://perf.jenkins.couchbase.com/job/themis/9165/ 

      The run on 7.0 : http://perf.jenkins.couchbase.com/job/themis/9436/console 

      Logs : 

      https://s3-us-west-2.amazonaws.com/perf-artifacts/jenkins-themis-9436/172.23.96.16.zip - KV + N1QL

      https://s3-us-west-2.amazonaws.com/perf-artifacts/jenkins-themis-9436/172.23.96.17.zip - KV + N1QL

      https://s3-us-west-2.amazonaws.com/perf-artifacts/jenkins-themis-9436/172.23.96.20.zip - KV + N1QL

      https://s3-us-west-2.amazonaws.com/perf-artifacts/jenkins-themis-9436/172.23.96.23.zip - KV + N1QL

      https://s3-us-west-2.amazonaws.com/perf-artifacts/jenkins-themis-9436/172.23.97.177.zip - Eventing

        Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

          Hide
          kamini.jagtiani Kamini Jagtiani added a comment -

          Hi Prajwal‌ Kiran Kumar‌

          Was the query service up and fully operational?

          Because it says:No bucket named eventing-bucket-1

          Also, after that, the test ran fine with just 1 exception which was "No bucket named eventing-bucket-1"

           

           

          Show
          kamini.jagtiani Kamini Jagtiani added a comment - Hi Prajwal‌ Kiran Kumar‌ Was the query service up and fully operational? Because it says:No bucket named eventing-bucket-1 Also, after that, the test ran fine with just 1 exception which was "No bucket named eventing-bucket-1"    
          Hide
          prajwal.kirankumar Prajwal‌ Kiran Kumar‌ (Inactive) added a comment - - edited

          Kamini Jagtiani - the query.log has this 

          _time=2021-03-19T16:17:25.327-07:00 _level=INFO _msg=cbq-engine started version=7.0.0-N1QL datastore=http://127.0.0.1:8091 max-concurrency=24 loglevel=INFO servicers=96 plus-servicers=384 scan-cap=512 pipeline-cap=512 pipeline-batch=16 request-cap=256 request-size-cap=67108864 max-index-api=4 max-parallelism=1 n1ql-feat-ctrl=76 use-cbo=true timeout=0s txtimeout=0s
          

          before we hit into this issue. So, I'm guessing the query service was up. 

           

          Re : The test ran fine with 1 exception - One on_update_failure is reported by eventing which means one mutation failed to get processed by eventing because of this error.

          Show
          prajwal.kirankumar Prajwal‌ Kiran Kumar‌ (Inactive) added a comment - - edited Kamini Jagtiani  - the query.log has this  _time=2021-03-19T16:17:25.327-07:00 _level=INFO _msg=cbq-engine started version=7.0.0-N1QL datastore=http://127.0.0.1:8091 max-concurrency=24 loglevel=INFO servicers=96 plus-servicers=384 scan-cap=512 pipeline-cap=512 pipeline-batch=16 request-cap=256 request-size-cap=67108864 max-index-api=4 max-parallelism=1 n1ql-feat-ctrl=76 use-cbo=true timeout=0s txtimeout=0s before we hit into this issue. So, I'm guessing the query service was up.    Re : The test ran fine with 1 exception - One on_update_failure is reported by eventing which means one mutation failed to get processed by eventing because of this error.
          Hide
          kamini.jagtiani Kamini Jagtiani added a comment -

          Thanks Prajwal‌ Kiran Kumar‌.

          Were there other mutations that happened on eventing-bucket-1 that were successful?

          Show
          kamini.jagtiani Kamini Jagtiani added a comment - Thanks Prajwal‌ Kiran Kumar‌ . Were there other mutations that happened on eventing-bucket-1 that were successful?
          Hide
          prajwal.kirankumar Prajwal‌ Kiran Kumar‌ (Inactive) added a comment - - edited

          Yes, the other mutations are successful, one mutation in the beginning fails with this error

          .

          Show
          prajwal.kirankumar Prajwal‌ Kiran Kumar‌ (Inactive) added a comment - - edited Yes, the other mutations are successful, one mutation in the beginning fails with this error .
          Hide
          isha Isha Kandaswamy added a comment - - edited

          If you go through the logs then you see that all query nodes show the bucket is not found (eventing-bucket 1). A comparison of when the bucket is successfully created vs when the eventing function was fired off shows that the nodes / ns server hasn't been primed yet and so query returns bucket not found error.

          Eventing function runtime - 2021-03-19T 16:59:15.178 -07:00
          Node 16 - 2021-03-19T 16:59:15.000 -07:00
          Node 17 - 2021-03-19T 16:59:15.002 -07:00
          Node 20 - 2021-03-19T 16:59:15.045 -07:00
          Node 23 - 2021-03-19T 16:59:15.260 -07:00

          Node 23

          _time=2021-03-19T16:59:15.035-07:00 _level=INFO _msg= keyspace eventing-bucket-1 not found No bucket named eventing-bucket-1 
          _time=2021-03-19T16:59:15.041-07:00 _level=INFO _msg= keyspace bucket-1 not found No bucket named bucket-1 
          _time=2021-03-19T16:59:15.176-07:00 _level=INFO _msg= Retrying bucket eventing-bucket-1 
          _time=2021-03-19T16:59:15.176-07:00 _level=INFO _msg= Retrying bucket bucket-1 
          _time=2021-03-19T16:59:15.260-07:00 _level=INFO _msg=Created New Bucket bucket-1 
          _time=2021-03-19T*16:59:15.260-07:00* _level=INFO _msg=Created New Bucket eventing-bucket-1 
          2021-03-19T16:59:15.311-07:00 [INFO]  Trying with http://127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 
          
          

          Node 17

          _time=2021-03-19T16:59:14.929-07:00 _level=INFO _msg= keyspace bucket-1 not found No bucket named bucket-1 
          _time=2021-03-19T16:59:14.971-07:00 _level=INFO _msg= Retrying bucket bucket-1 
          _time=2021-03-19T16:59:14.987-07:00 _level=INFO _msg=Created New Bucket bucket-1 
          2021-03-19T16:59:14.987-07:00 [INFO]  Trying with http://127.0.0.1:8091/pools/default/bucketsStreaming/bucket-1 
          _time=2021-03-19T*16:59:15.002-07:00* _level=INFO _msg=Created New Bucket eventing-bucket-1 
          2021-03-19T16:59:15.002-07:00 [INFO]  Trying with http://127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 
          

          Node 16

          _time=2021-03-19T16:59:14.925-07:00 _level=INFO _msg= keyspace bucket-1 not found No bucket named bucket-1 
          _time=2021-03-19T16:59:14.959-07:00 _level=INFO _msg= Retrying bucket bucket-1 
          _time=2021-03-19T*16:59:14.976-07:00* _level=INFO _msg=Created New Bucket bucket-1 
          2021-03-19T16:59:14.977-07:00 [INFO]  Trying with http://127.0.0.1:8091/pools/default/bucketsStreaming/bucket-1 
          _time=2021-03-19T16:59:15.000-07:00 _level=INFO _msg=Created New Bucket eventing-bucket-1 
          2021-03-19T16:59:15.000-07:00 [INFO]  Trying with http://127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 
          _time=2021-03-19T17:23:26.495-07:00 _level=INFO _msg=Created New Bucket eventing 
          

          Node 20

          _time=2021-03-19T16:59:14.957-07:00 _level=INFO _msg= keyspace bucket-1 not found No bucket named bucket-1 
          _time=2021-03-19T16:59:14.988-07:00 _level=INFO _msg= keyspace eventing-bucket-1 not found No bucket named eventing-bucket-1 
          _time=2021-03-19T16:59:15.003-07:00 _level=INFO _msg= Retrying bucket bucket-1 
          _time=2021-03-19T16:59:15.011-07:00 _level=INFO _msg= Retrying bucket eventing-bucket-1 
          _time=2021-03-19T*16:59:15.045-07:00 *_level=INFO _msg=Created New Bucket eventing-bucket-1 
          _time=2021-03-19T16:59:15.045-07:00 _level=INFO _msg=Created New Bucket bucket-1 
          2021-03-19T16:59:15.045-07:00 [INFO]  Trying with http://127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 
          
          

          The evening query gets fired at 2021-03-19T16:59:15.178-07:00 during which time the nodes / bucket is not fully primed and so the query gets a bucket not found error. This is a test issue.

          Show
          isha Isha Kandaswamy added a comment - - edited If you go through the logs then you see that all query nodes show the bucket is not found (eventing-bucket 1). A comparison of when the bucket is successfully created vs when the eventing function was fired off shows that the nodes / ns server hasn't been primed yet and so query returns bucket not found error. Eventing function runtime - 2021-03-19T 16:59:15.178 -07:00 Node 16 - 2021-03-19T 16:59:15.000 -07:00 Node 17 - 2021-03-19T 16:59:15.002 -07:00 Node 20 - 2021-03-19T 16:59:15.045 -07:00 Node 23 - 2021-03-19T 16:59:15.260 -07:00 Node 23 _time= 2021 - 03 -19T16: 59 : 15.035 - 07 : 00 _level=INFO _msg= keyspace eventing-bucket- 1 not found No bucket named eventing-bucket- 1 _time= 2021 - 03 -19T16: 59 : 15.041 - 07 : 00 _level=INFO _msg= keyspace bucket- 1 not found No bucket named bucket- 1 _time= 2021 - 03 -19T16: 59 : 15.176 - 07 : 00 _level=INFO _msg= Retrying bucket eventing-bucket- 1 _time= 2021 - 03 -19T16: 59 : 15.176 - 07 : 00 _level=INFO _msg= Retrying bucket bucket- 1 _time= 2021 - 03 -19T16: 59 : 15.260 - 07 : 00 _level=INFO _msg=Created New Bucket bucket- 1 _time= 2021 - 03 -19T* 16 : 59 : 15.260 - 07 : 00 * _level=INFO _msg=Created New Bucket eventing-bucket- 1 2021 - 03 -19T16: 59 : 15.311 - 07 : 00 [INFO] Trying with http: //127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 Node 17 _time= 2021 - 03 -19T16: 59 : 14.929 - 07 : 00 _level=INFO _msg= keyspace bucket- 1 not found No bucket named bucket- 1 _time= 2021 - 03 -19T16: 59 : 14.971 - 07 : 00 _level=INFO _msg= Retrying bucket bucket- 1 _time= 2021 - 03 -19T16: 59 : 14.987 - 07 : 00 _level=INFO _msg=Created New Bucket bucket- 1 2021 - 03 -19T16: 59 : 14.987 - 07 : 00 [INFO] Trying with http: //127.0.0.1:8091/pools/default/bucketsStreaming/bucket-1 _time= 2021 - 03 -19T* 16 : 59 : 15.002 - 07 : 00 * _level=INFO _msg=Created New Bucket eventing-bucket- 1 2021 - 03 -19T16: 59 : 15.002 - 07 : 00 [INFO] Trying with http: //127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 Node 16 _time= 2021 - 03 -19T16: 59 : 14.925 - 07 : 00 _level=INFO _msg= keyspace bucket- 1 not found No bucket named bucket- 1 _time= 2021 - 03 -19T16: 59 : 14.959 - 07 : 00 _level=INFO _msg= Retrying bucket bucket- 1 _time= 2021 - 03 -19T* 16 : 59 : 14.976 - 07 : 00 * _level=INFO _msg=Created New Bucket bucket- 1 2021 - 03 -19T16: 59 : 14.977 - 07 : 00 [INFO] Trying with http: //127.0.0.1:8091/pools/default/bucketsStreaming/bucket-1 _time= 2021 - 03 -19T16: 59 : 15.000 - 07 : 00 _level=INFO _msg=Created New Bucket eventing-bucket- 1 2021 - 03 -19T16: 59 : 15.000 - 07 : 00 [INFO] Trying with http: //127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 _time= 2021 - 03 -19T17: 23 : 26.495 - 07 : 00 _level=INFO _msg=Created New Bucket eventing Node 20 _time= 2021 - 03 -19T16: 59 : 14.957 - 07 : 00 _level=INFO _msg= keyspace bucket- 1 not found No bucket named bucket- 1 _time= 2021 - 03 -19T16: 59 : 14.988 - 07 : 00 _level=INFO _msg= keyspace eventing-bucket- 1 not found No bucket named eventing-bucket- 1 _time= 2021 - 03 -19T16: 59 : 15.003 - 07 : 00 _level=INFO _msg= Retrying bucket bucket- 1 _time= 2021 - 03 -19T16: 59 : 15.011 - 07 : 00 _level=INFO _msg= Retrying bucket eventing-bucket- 1 _time= 2021 - 03 -19T* 16 : 59 : 15.045 - 07 : 00 *_level=INFO _msg=Created New Bucket eventing-bucket- 1 _time= 2021 - 03 -19T16: 59 : 15.045 - 07 : 00 _level=INFO _msg=Created New Bucket bucket- 1 2021 - 03 -19T16: 59 : 15.045 - 07 : 00 [INFO] Trying with http: //127.0.0.1:8091/pools/default/bucketsStreaming/eventing-bucket-1 The evening query gets fired at 2021-03-19T16:59:15.178-07:00 during which time the nodes / bucket is not fully primed and so the query gets a bucket not found error. This is a test issue.
          Hide
          prajwal.kirankumar Prajwal‌ Kiran Kumar‌ (Inactive) added a comment -

          Not seeing this issue anymore on recent CC builds 4907 and 4960 : http://perf.jenkins.couchbase.com/job/themis/9911/console http://perf.jenkins.couchbase.com/job/themis/9796/console . Closing this for now.

          Show
          prajwal.kirankumar Prajwal‌ Kiran Kumar‌ (Inactive) added a comment - Not seeing this issue anymore on recent CC builds 4907 and 4960 : http://perf.jenkins.couchbase.com/job/themis/9911/console http://perf.jenkins.couchbase.com/job/themis/9796/console . Closing this for now.

            People

            Assignee:
            prajwal.kirankumar Prajwal‌ Kiran Kumar‌ (Inactive)
            Reporter:
            prajwal.kirankumar Prajwal‌ Kiran Kumar‌ (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Gerrit Reviews

                There are no open Gerrit changes

                  PagerDuty