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

Query metadata is empty

    XMLWordPrintable

Details

    • Untriaged
    • Unknown

    Description

      Sometimes the metadata for a query is turning out to be empty. I've attached a wireshark dump when the issue got reproduced - tcp-dump.pcap . Also the following client_context_id correspond to those queries for which metadata was empty -

      2019-11-06T18:44:14.568+05:30 [INFO] "ID : doc_id_0 error : Unable to parse error JSON" 
      2019-11-06T18:44:14.575+05:30 [INFO] "ID : doc_id_5 error : Unable to parse error JSON" 
      2019-11-06T18:44:15.495+05:30 [INFO] "ID : doc_id_6 error : Unable to parse error JSON" 
      2019-11-06T18:44:22.592+05:30 [INFO] "ID : doc_id_14 error : Unable to parse error JSON" 
      2019-11-06T18:44:22.593+05:30 [INFO] "ID : doc_id_11 error : Unable to parse error JSON" 
      2019-11-06T18:44:23.508+05:30 [INFO] "ID : doc_id_8 error : Unable to parse error JSON" 
      2019-11-06T18:44:30.595+05:30 [INFO] "ID : doc_id_20 error : Unable to parse error JSON" 
      2019-11-06T18:44:30.599+05:30 [INFO] "ID : doc_id_25 error : Unable to parse error JSON" 
      2019-11-06T18:44:31.514+05:30 [INFO] "ID : doc_id_12 error : Unable to parse error JSON" 
      2019-11-06T18:44:38.615+05:30 [INFO] "ID : doc_id_33 error : Unable to parse error JSON" 
      2019-11-06T18:44:38.615+05:30 [INFO] "ID : doc_id_36 error : Unable to parse error JSON" 
      2019-11-06T18:44:39.530+05:30 [INFO] "ID : doc_id_26 error : Unable to parse error JSON" 
      2019-11-06T18:44:46.617+05:30 [INFO] "ID : doc_id_40 error : Unable to parse error JSON" 
      2019-11-06T18:44:46.617+05:30 [INFO] "ID : doc_id_38 error : Unable to parse error JSON" 
      2019-11-06T18:44:47.532+05:30 [INFO] "ID : doc_id_28 error : Unable to parse error JSON" 
      

      Eventing registers the callback to be invoked by the SDK to receive the data - https://github.com/couchbase/eventing/blob/master/features/query/src/iterator.cc#L85-L86 . Eventing logs the data received from SDK - https://github.com/couchbase/eventing/blob/master/features/query/src/iterator.cc#L106-L111
      We see that the data is empty but the is_last flag is set. (resp->rflags & LCB_RESP_F_FINAL) != 0; evaluates to is_last flag being set -

      2019-11-05T19:10:58.090+05:30 [INFO] Query::Iterator::RowCallback data : <ud></ud> is_last : 1 is_error : 1 is_client_auth_error : 0 resp rflags : 1 resp rc : 23
      

      As per the documentation, if LCB_RESP_F_FINAL is set, it must contain metadata - https://docs.couchbase.com/sdk-api/couchbase-c-client/group__lcb-n1ql-api.html#structlcb___r_e_s_p_n1_q_l . But the data is turning out to be empty.

      Since eventing tries to parse the empty row, it results in an exception as trying to parse an empty string causes an error in JavaScript.

      Attachments

        1. doc id 28.jpg
          doc id 28.jpg
          43 kB
        2. doc id 28 request.jpg
          doc id 28 request.jpg
          50 kB
        3. empty json parse error.jpg
          empty json parse error.jpg
          11 kB
        4. tcp-dump.pcap
          2.24 MB

        Issue Links

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

          Activity

            jeelan.poola Jeelan Poola added a comment -

            Patch is reviewed & finalised. CI is mid way. Very likely to be closed by Friday morning IST.

            jeelan.poola Jeelan Poola added a comment - Patch is reviewed & finalised. CI is mid way. Very likely to be closed by Friday morning IST.

            Build couchbase-server-6.5.0-4876 contains eventing commit cafc1fe with commit message:
            MB-36927 Report SDK and query errors for N1QL

            build-team Couchbase Build Team added a comment - Build couchbase-server-6.5.0-4876 contains eventing commit cafc1fe with commit message: MB-36927 Report SDK and query errors for N1QL

            Build couchbase-server-7.0.0-1062 contains eventing commit cafc1fe with commit message:
            MB-36927 Report SDK and query errors for N1QL

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.0-1062 contains eventing commit cafc1fe with commit message: MB-36927 Report SDK and query errors for N1QL
            siri Sriram Melkote (Inactive) added a comment - - edited

            Vikas Chaudhary you can reproduce this by running a slow N1QL query (that takes >20 seconds. you can do something like:

            SELECT nosuchfield1 from `beer-samples` WHERE meta.id() in (SELECT nosuchfield2 from `travel-samples` WHERE meta.id() in (SELECT nosuchfield3 from `gamesim-samples`)) UNION
            SELECT nosuchfield1 from `beer-samples` WHERE meta.id() in (SELECT nosuchfield2 from `travel-samples` WHERE meta.id() in (SELECT nosuchfield3 from `gamesim-samples`)) UNION
            SELECT nosuchfield1 from `beer-samples` WHERE meta.id() in (SELECT nosuchfield2 from `travel-samples` WHERE meta.id() in (SELECT nosuchfield3 from `gamesim-samples`)) UNION
            SELECT nosuchfield1 from `beer-samples` WHERE meta.id() in (SELECT nosuchfield2 from `travel-samples` WHERE meta.id() in (SELECT nosuchfield3 from `gamesim-samples`)))
            

            Then set the eventing timeout to 15 seconds. The above query will run longer than 15 seconds, and due to bug, you will get a "JSON parse error" in log file instead of expected javascript exception saying query timed out. After fix, this should throw a javascript exception stating query timed out and a few additional details.

            siri Sriram Melkote (Inactive) added a comment - - edited Vikas Chaudhary you can reproduce this by running a slow N1QL query (that takes >20 seconds. you can do something like: SELECT nosuchfield1 from `beer-samples` WHERE meta.id() in (SELECT nosuchfield2 from `travel-samples` WHERE meta.id() in (SELECT nosuchfield3 from `gamesim-samples`)) UNION SELECT nosuchfield1 from `beer-samples` WHERE meta.id() in (SELECT nosuchfield2 from `travel-samples` WHERE meta.id() in (SELECT nosuchfield3 from `gamesim-samples`)) UNION SELECT nosuchfield1 from `beer-samples` WHERE meta.id() in (SELECT nosuchfield2 from `travel-samples` WHERE meta.id() in (SELECT nosuchfield3 from `gamesim-samples`)) UNION SELECT nosuchfield1 from `beer-samples` WHERE meta.id() in (SELECT nosuchfield2 from `travel-samples` WHERE meta.id() in (SELECT nosuchfield3 from `gamesim-samples`))) Then set the eventing timeout to 15 seconds. The above query will run longer than 15 seconds, and due to bug, you will get a "JSON parse error" in log file instead of expected javascript exception saying query timed out. After fix, this should throw a javascript exception stating query timed out and a few additional details.

            Verified on 6.5.0-4890

            Handler 

            function OnUpdate(doc, meta) {
                log('docId', meta.id);
                var query=SELECT nosuchfield1 from `beer-sample` WHERE meta().id in (SELECT nosuchfield2 from `travel-sample` WHERE meta().id in (SELECT nosuchfield3 from `gamesim-sample`)) UNION
                    SELECT nosuchfield1 from `beer-sample` WHERE meta().id in (SELECT nosuchfield2 from `travel-sample` WHERE meta().id in (SELECT nosuchfield3 from `gamesim-sample`));
                for (var item of query){
                }
            }
            function OnDelete(meta) {
            } 

            Seeing lcb error and messages , no JSON parse error

            "lcb_exception_stats": {
                        "23": 585,
                        "44": 547,
                        "46": 8,
                        "59": 8860
                    } 

            logs

            2019-11-25T21:56:39.354-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,cccp L:165 I:395554153] <NOHOST:NOPORT> (CTX=(nil),) Could not get configuration: LCB_PROTOCOL_ERROR (0x16)
            2019-11-25T21:56:39.360-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,confmon L:179 I:395554153] Provider 'CCCP' failed
            2019-11-25T21:56:39.360-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,cccp L:165 I:1368659828] <NOHOST:NOPORT> (CTX=(nil),) Could not get configuration: LCB_PROTOCOL_ERROR (0x16)
            
            

            2019-11-25T21:57:01.193-08:00 [Info] DCPT[eventing:tbahHeMq-10:{eventing:tbahHeMq-8:10.143.192.102:8096_10.143.192.101:11210_worker_test_1}/0] dcp latency stats {"samples": 3324, "min": 0, "max": 6409121, "mean": 14289.62484957882, "variance": 4.32632617364426e+10}
            2019-11-25T21:57:01.193-08:00 [Info] DCPT[eventing:tbahHeMq-10:{eventing:tbahHeMq-8:10.143.192.102:8096_10.143.192.101:11210_worker_test_1}/0] dcp stats bytes: 498627 buffacks: 1 toAckBytes: 484943 streamreqs: 341 snapshots: 1082 mutations: 3324 streamends: 0 closestreams: 0lastAckTime: 1574747797933418045
            2019-11-25T21:57:02.830-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] test.js:4x                ^Error    at OnUpdate (test.js:4:17)
            2019-11-25T21:57:02.830-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] test.js:4                ^Error    at OnUpdate (test.js:4:17)
            2019-11-25T21:57:02.833-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] [lcb,connection L:474 I:1858797301] <10.143.192.103:8093> (SOCK=10d70641f399d393) Starting. Timeout=8000000us
            2019-11-25T21:57:02.833-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] [lcb,connection L:474 I:375867691] <10.143.192.103:8093> (SOCK=dcf63e7a2d9d6545) Starting. Timeout=8000000us
            2019-11-25T21:57:02.833-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] [lcb,connection L:147 I:1858797301] <10.143.192.103:8093> (SOCK=10d70641f399d393) Connected established
            2019-11-25T21:57:02.837-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] [lcb,connection L:147 I:375867691] <10.143.192.103:8093> (SOCK=dcf63e7a2d9d6545) Connected established
            2019-11-25T21:57:03.388-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] test.js:4x                ^Error    at OnUpdate (test.js:4:17)
            2019-11-25T21:57:03.388-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] test.js:4                ^Error    at OnUpdate (test.js:4:17)
            2019-11-25T21:57:03.388-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,connection L:474 I:1368659828] <10.143.192.103:8093> (SOCK=794f76efcf29b538) Starting. Timeout=8000000us
            2019-11-25T21:57:03.390-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,connection L:474 I:395554153] <10.143.192.103:8093> (SOCK=f037d52f68260840) Starting. Timeout=8000000us
            2019-11-25T21:57:03.391-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,connection L:147 I:1368659828] <10.143.192.103:8093> (SOCK=794f76efcf29b538) Connected established
            2019-11-25T21:57:03.391-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,connection L:147 I:395554153] <10.143.192.103:8093> (SOCK=f037d52f68260840) Connected established
            2019-11-25T21:57:03.664-08:00 [Info] eventing-consumer [worker_test_0:/tmp/127.0.0.1:8091_0_843039919.sock:3920] test.js:4x                ^Error    at OnUpdate (test.js:4:17)
            2019-11-25T21:57:03.664-08:00 [Info] eventing-consumer [worker_test_0:/tmp/127.0.0.1:8091_0_843039919.sock:3920] test.js:4                ^Error    at OnUpdate (test.js:4:17) 

            vikas.chaudhary Vikas Chaudhary added a comment - Verified on 6.5.0-4890 Handler  function OnUpdate(doc, meta) {     log('docId', meta.id);     var query=SELECT nosuchfield1 from `beer-sample` WHERE meta().id in (SELECT nosuchfield2 from `travel-sample` WHERE meta().id in (SELECT nosuchfield3 from `gamesim-sample`)) UNION         SELECT nosuchfield1 from `beer-sample` WHERE meta().id in (SELECT nosuchfield2 from `travel-sample` WHERE meta().id in (SELECT nosuchfield3 from `gamesim-sample`));     for (var item of query){     } } function OnDelete(meta) { } Seeing lcb error and messages , no JSON parse error "lcb_exception_stats": {             "23": 585,             "44": 547,             "46": 8,             "59": 8860         } logs 2019-11-25T21:56:39.354-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,cccp L:165 I:395554153] <NOHOST:NOPORT> (CTX=(nil),) Could not get configuration: LCB_PROTOCOL_ERROR (0x16) 2019-11-25T21:56:39.360-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,confmon L:179 I:395554153] Provider 'CCCP' failed 2019-11-25T21:56:39.360-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,cccp L:165 I:1368659828] <NOHOST:NOPORT> (CTX=(nil),) Could not get configuration: LCB_PROTOCOL_ERROR (0x16) 2019-11-25T21:57:01.193-08:00 [Info] DCPT[eventing:tbahHeMq-10:{eventing:tbahHeMq-8:10.143.192.102:8096_10.143.192.101:11210_worker_test_1}/0] dcp latency stats {"samples": 3324, "min": 0, "max": 6409121, "mean": 14289.62484957882, "variance": 4.32632617364426e+10} 2019-11-25T21:57:01.193-08:00 [Info] DCPT[eventing:tbahHeMq-10:{eventing:tbahHeMq-8:10.143.192.102:8096_10.143.192.101:11210_worker_test_1}/0] dcp stats bytes: 498627 buffacks: 1 toAckBytes: 484943 streamreqs: 341 snapshots: 1082 mutations: 3324 streamends: 0 closestreams: 0lastAckTime: 1574747797933418045 2019-11-25T21:57:02.830-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] test.js:4x ^Error at OnUpdate (test.js:4:17) 2019-11-25T21:57:02.830-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] test.js:4 ^Error at OnUpdate (test.js:4:17) 2019-11-25T21:57:02.833-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] [lcb,connection L:474 I:1858797301] <10.143.192.103:8093> (SOCK=10d70641f399d393) Starting. Timeout=8000000us 2019-11-25T21:57:02.833-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] [lcb,connection L:474 I:375867691] <10.143.192.103:8093> (SOCK=dcf63e7a2d9d6545) Starting. Timeout=8000000us 2019-11-25T21:57:02.833-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] [lcb,connection L:147 I:1858797301] <10.143.192.103:8093> (SOCK=10d70641f399d393) Connected established 2019-11-25T21:57:02.837-08:00 [Info] eventing-consumer [worker_test_1:/tmp/127.0.0.1:8091_1_843039919.sock:3930] [lcb,connection L:147 I:375867691] <10.143.192.103:8093> (SOCK=dcf63e7a2d9d6545) Connected established 2019-11-25T21:57:03.388-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] test.js:4x ^Error at OnUpdate (test.js:4:17) 2019-11-25T21:57:03.388-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] test.js:4 ^Error at OnUpdate (test.js:4:17) 2019-11-25T21:57:03.388-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,connection L:474 I:1368659828] <10.143.192.103:8093> (SOCK=794f76efcf29b538) Starting. Timeout=8000000us 2019-11-25T21:57:03.390-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,connection L:474 I:395554153] <10.143.192.103:8093> (SOCK=f037d52f68260840) Starting. Timeout=8000000us 2019-11-25T21:57:03.391-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,connection L:147 I:1368659828] <10.143.192.103:8093> (SOCK=794f76efcf29b538) Connected established 2019-11-25T21:57:03.391-08:00 [Info] eventing-consumer [worker_test_2:/tmp/127.0.0.1:8091_2_843039919.sock:3925] [lcb,connection L:147 I:395554153] <10.143.192.103:8093> (SOCK=f037d52f68260840) Connected established 2019-11-25T21:57:03.664-08:00 [Info] eventing-consumer [worker_test_0:/tmp/127.0.0.1:8091_0_843039919.sock:3920] test.js:4x ^Error at OnUpdate (test.js:4:17) 2019-11-25T21:57:03.664-08:00 [Info] eventing-consumer [worker_test_0:/tmp/127.0.0.1:8091_0_843039919.sock:3920] test.js:4 ^Error at OnUpdate (test.js:4:17)

            People

              vikas.chaudhary Vikas Chaudhary
              Gautham.Banasandra Gautham Banasandra (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              14 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty