Uploaded image for project: 'Couchbase C client library libcouchbase'
  1. Couchbase C client library libcouchbase
  2. CCBC-1535

Eventing RBAC: Function takes too long to execute resulting in timeout when owner loses query privileges

    XMLWordPrintable

Details

    • Bug
    • Resolution: Resolved
    • Critical
    • None
    • None
    • None
    • Enterprise Edition 7.1.0 build 1650
      Enterprise Edition 7.1.0 build 1691
    • 1

    Description

      STEPS
      Cluster consists of 1 kv, eventing, index and query node each.
      Create user john having following set of roles.

      data_reader[metadata],data_writer[metadata],data_writer[dst_bucket],data_dcp_reader[src_bucket],data_reader[dst_bucket],eventing_manage_functions[src_bucket:_default], query_update[dst_bucket],query_delete[dst_bucket],query_insert[dst_bucket]                                         
      

      Create and deploy following n1ql handler.

      function OnUpdate(doc,meta) {
          var docId = meta.id;
          var query = INSERT INTO dst_bucket ( KEY, VALUE ) VALUES ( $docId ,'Hello World');
      }
       
      function OnDelete(meta) {
          var docId = meta.id;
          try {
              var query = INSERT INTO dst_bucket ( KEY, VALUE ) VALUES ( $docId ,'Hello World');
          } catch (e) {
              log(e);
              if(e["message"].includes("LCB_ERR_AUTHENTICATION_FAILURE")){
                  var query = DELETE FROM dst_bucket where meta().id = $docId;
              }
          }
      }
      

      Script timeout in this case is set as 20 sec.
      Load 20 docs into src bucket.
      Verify 20 docs are inserted into dst bucket.
      Delete 20 docs from src bucket.

      OBSERVATION
      8/20 docs are successfully deleted from dst_bucket and rest of the mutations fail with function execution termination. on_delete_success count is 9 even though 8 docs were deleted successfully.
      Application logs consists of messages of following type -

      {"exception":"","file":"","line":2581480624,"srcLine":"","stack":""}
      

      Eventing stats -

      [
          {
              "dcp_feed_boundary": "everything",
              "event_processing_stats": {
                  "adhoc_timer_response_received": 22,
                  "agg_messages_sent_to_worker": 14045,
                  "agg_queue_memory": 0,
                  "agg_queue_memory_cap": 106954752,
                  "agg_queue_size": 0,
                  "agg_queue_size_cap": 300000,
                  "agg_timer_feedback_queue_cap": 1500,
                  "dcp_deletion": 20,
                  "dcp_deletion_sent_to_worker": 20,
                  "dcp_mutation": 20,
                  "dcp_mutation_sent_to_worker": 20,
                  "dcp_snapshot": 40,
                  "dcp_stream_req_counter": 1024,
                  "dcp_streamreq": 1024,
                  "execution_stats": 2592,
                  "failure_stats": 2592,
                  "latency_stats": 2592,
                  "lcb_exception_stats": 2592,
                  "log_level": 3,
                  "num_processed_events": 40,
                  "processed_events_size": 22820,
                  "thr_count": 3,
                  "thr_map": 3,
                  "v8_init": 3,
                  "v8_load": 3
              },
              "events_remaining": {
                  "dcp_backlog": 0
              },
              "execution_stats": {
                  "agg_queue_memory": 0,
                  "agg_queue_size": 0,
                  "curl": {
                      "delete": 0,
                      "get": 0,
                      "head": 0,
                      "post": 0,
                      "put": 0
                  },
                  "curl_success_count": 0,
                  "dcp_delete_msg_counter": 20,
                  "dcp_delete_parse_failure": 0,
                  "dcp_mutation_msg_counter": 20,
                  "dcp_mutation_parse_failure": 0,
                  "enqueued_dcp_delete_msg_counter": 20,
                  "enqueued_dcp_mutation_msg_counter": 20,
                  "enqueued_timer_msg_counter": 0,
                  "feedback_queue_size": 0,
                  "filtered_dcp_delete_counter": 0,
                  "filtered_dcp_mutation_counter": 0,
                  "lcb_retry_failure": 0,
                  "messages_parsed": 14033,
                  "no_op_counter": 0,
                  "num_processed_events": 40,
                  "on_delete_failure": 11,
                  "on_delete_success": 9,
                  "on_update_failure": 0,
                  "on_update_success": 20,
                  "processed_events_size": 22820,
                  "timer_callback_failure": 0,
                  "timer_callback_success": 0,
                  "timer_cancel_counter": 0,
                  "timer_create_counter": 0,
                  "timer_create_failure": 0,
                  "timer_msg_counter": 0,
                  "timer_responses_sent": 0,
                  "timestamp": {
                      "72987": "2021-11-09T15:15:56Z",
                      "72996": "2021-11-09T15:15:56Z",
                      "73009": "2021-11-09T15:15:57Z"
                  },
                  "uv_msg_parse_failure": 0,
                  "uv_try_write_failure_counter": 0
              },
              "failure_stats": {
                  "app_worker_setting_events_lost": 0,
                  "bkt_ops_cas_mismatch_count": 0,
                  "bucket_cache_overflow_count": 0,
                  "bucket_op_cache_miss_count": 0,
                  "bucket_op_exception_count": 0,
                  "checkpoint_failure_count": 0,
                  "curl_failure_count": 0,
                  "curl_max_resp_size_exceeded": 0,
                  "curl_non_200_response": 0,
                  "curl_timeout_count": 0,
                  "dcp_events_lost": 0,
                  "debugger_events_lost": 0,
                  "delete_events_lost": 0,
                  "mutation_events_lost": 0,
                  "n1ql_op_exception_count": 18,
                  "timeout_count": 16,
                  "timer_callback_missing_counter": 0,
                  "timer_context_size_exceeded_counter": 0,
                  "timer_events_lost": 0,
                  "timestamp": {
                      "72987": "2021-11-09T15:15:56Z",
                      "72996": "2021-11-09T15:15:56Z",
                      "73009": "2021-11-09T15:15:57Z"
                  },
                  "v8worker_events_lost": 0
              },
              "function_id": 1870503761,
              "function_name": "Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro",
              "gocb_creds_request_counter": 2,
              "internal_vb_distribution_stats": {
                  "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_0": "[0-341]",
                  "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_1": "[342-682]",
                  "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_2": "[683-1023]"
              },
              "latency_percentile_stats": {
                  "100": 9999900,
                  "50": 16000,
                  "80": 9999900,
                  "90": 9999900,
                  "95": 9999900,
                  "99": 9999900
              },
              "lcb_creds_request_counter": 6344,
              "lcb_exception_stats": {
                  "13014": 17,
                  "201": 1,
                  "206": 17
              },
              "metastore_stats": {},
              "planner_stats": [
                  {
                      "host_name": "172.23.123.146:8096",
                      "start_vb": 0,
                      "vb_count": 1024
                  }
              ],
              "vb_distribution_stats_from_metadata": {
                  "172.23.123.146:8096": {
                      "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_0": "[0-341]",
                      "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_1": "[342-682]",
                      "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_2": "[683-1023]"
                  }
              },
              "worker_pids": {
                  "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_0": 72987,
                  "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_1": 72996,
                  "worker_Function_45780983_test_authorisation_failures_for_bucket_operations_and_n1ql_queries_if_ro_2": 73009
              }
          }
      ]
      

      NOTE -
      Repeated the same scenario on build Enterprise Edition 7.1.0 build 1691.
      Script timeout for function is set as 120 sec.
      Rest of the parameters remains same as previous case.
      In this case 4/20 docs were deleted successfully but on_delete_success count is 12.

      Eventing stats -

      [
       {
        "dcp_feed_boundary": "everything",
        "event_processing_stats": {
         "adhoc_timer_response_received": 11,
         "agg_messages_sent_to_worker": 16806,
         "agg_queue_memory": 0,
         "agg_queue_memory_cap": 53477376,
         "agg_queue_size": 0,
         "agg_queue_size_cap": 100000,
         "agg_timer_feedback_queue_cap": 500,
         "dcp_deletion": 20,
         "dcp_deletion_sent_to_worker": 20,
         "dcp_mutation": 20,
         "dcp_mutation_sent_to_worker": 20,
         "dcp_snapshot": 40,
         "dcp_stream_req_counter": 1024,
         "dcp_streamreq": 1024,
         "execution_stats": 3144,
         "failure_stats": 3144,
         "latency_stats": 3144,
         "lcb_exception_stats": 3144,
         "log_level": 1,
         "num_processed_events": 40,
         "processed_events_size": 11156,
         "thr_count": 1,
         "thr_map": 1,
         "v8_init": 1,
         "v8_load": 1
        },
        "events_remaining": {
         "dcp_backlog": 0
        },
        "execution_stats": {
         "agg_queue_memory": 0,
         "agg_queue_size": 0,
         "curl": {
          "delete": 0,
          "get": 0,
          "head": 0,
          "post": 0,
          "put": 0
         },
         "curl_success_count": 0,
         "dcp_delete_msg_counter": 20,
         "dcp_delete_parse_failure": 0,
         "dcp_mutation_msg_counter": 20,
         "dcp_mutation_parse_failure": 0,
         "enqueued_dcp_delete_msg_counter": 20,
         "enqueued_dcp_mutation_msg_counter": 20,
         "enqueued_timer_msg_counter": 0,
         "feedback_queue_size": 0,
         "filtered_dcp_delete_counter": 0,
         "filtered_dcp_mutation_counter": 0,
         "lcb_retry_failure": 0,
         "messages_parsed": 16802,
         "no_op_counter": 0,
         "num_processed_events": 40,
         "on_delete_failure": 8,
         "on_delete_success": 12,
         "on_update_failure": 0,
         "on_update_success": 20,
         "processed_events_size": 11156,
         "timer_callback_failure": 0,
         "timer_callback_success": 0,
         "timer_cancel_counter": 0,
         "timer_create_counter": 0,
         "timer_create_failure": 0,
         "timer_msg_counter": 0,
         "timer_responses_sent": 0,
         "timestamp": {
          "63473": "2021-11-12T06:32:57Z"
         },
         "uv_msg_parse_failure": 0,
         "uv_try_write_failure_counter": 0
        },
        "failure_stats": {
         "app_worker_setting_events_lost": 0,
         "bkt_ops_cas_mismatch_count": 0,
         "bucket_cache_overflow_count": 0,
         "bucket_op_cache_miss_count": 0,
         "bucket_op_exception_count": 0,
         "checkpoint_failure_count": 0,
         "curl_failure_count": 0,
         "curl_max_resp_size_exceeded": 0,
         "curl_non_200_response": 0,
         "curl_timeout_count": 0,
         "dcp_events_lost": 0,
         "debugger_events_lost": 0,
         "delete_events_lost": 0,
         "mutation_events_lost": 0,
         "n1ql_op_exception_count": 20,
         "timeout_count": 20,
         "timer_callback_missing_counter": 0,
         "timer_context_size_exceeded_counter": 0,
         "timer_events_lost": 0,
         "timestamp": {
          "63473": "2021-11-12T06:32:57Z"
         },
         "v8worker_events_lost": 0
        },
        "function_name": "n1ql",
        "gocb_creds_request_counter": 3,
        "function_id": 0,
        "internal_vb_distribution_stats": {
         "worker_n1ql_0": "[0-1023]"
        },
        "latency_percentile_stats": {
         "100": 9999900,
         "50": 21600,
         "80": 9999900,
         "90": 9999900,
         "95": 9999900,
         "99": 9999900
        },
        "lcb_creds_request_counter": 46216,
        "lcb_exception_stats": {
         "13014": 19,
         "201": 1,
         "206": 19
        },
        "planner_stats": [
         {
          "host_name": "172.23.106.67:8096",
          "start_vb": 0,
          "vb_count": 1024
         }
        ],
        "metastore_stats": {},
        "vb_distribution_stats_from_metadata": {
         "172.23.106.67:8096": {
          "worker_n1ql_0": "[0-1023]"
         }
        },
        "worker_pids": {
         "worker_n1ql_0": 63473
        }
       }
      ]
      

      Attachments

        Issue Links

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

          Activity

            People

              daschl Michael Nitschinger
              sujay.gad Sujay Gad
              Votes:
              0 Vote for this issue
              Watchers:
              11 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty