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

Ephemeral rebalance failed: abortStoredValue: Cannot call on a non-Pending StoredValue

    XMLWordPrintable

Details

    Description

      Steps to Reproduce:

      Create a 7 node cluster.

      +----------------+----------+--------------+
      | Nodes          | Services | Status       |
      +----------------+----------+--------------+
      | 172.23.106.134 | [u'kv']  | Cluster node |
      | 172.23.106.136 | None     | <--- IN ---  |
      | 172.23.106.137 | None     | <--- IN ---  |
      | 172.23.106.138 | None     | <--- IN ---  |
      | 172.23.105.168 | None     | <--- IN ---  |
      | 172.23.106.82  | None     | <--- IN ---  |
      | 172.23.106.83  | None     | <--- IN ---  |
      +----------------+----------+--------------+ 

             1. Create an ephemeral bucket with replicas=1, eviction policy=noEviction, compression=off.

             2. Load 10M docs with durability = MAJORITY. This step was successfully completed. Bucket Stats after this step:

      +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
      | Bucket         | Type      | Replicas | TTL | Items    | RAM Quota    | RAM Used    | Disk Used |
      +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
      | GleamBookUsers | ephemeral | 1        | 0   | 10000000 | 139732189184 | 29729510584 | 238       |
      +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
       

           3. Rebalance In 1 node(172.23.106.85) with another 2M creates, 4M updates with durability=MAJORITY in parallel. This step was successfully completed. Bucket Stats after this  Step:

      +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
      | Bucket         | Type      | Replicas | TTL | Items    | RAM Quota    | RAM Used    | Disk Used |
      +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
      | GleamBookUsers | ephemeral | 1        | 0   | 12000000 | 159693930496 | 37605497792 | 272       |
      +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
       

           4. Rebalance Out 1 node(172.23.106.83) with another 2M creates, 4M updates, 2M deletes with durability=MAJORITY in parallel. This step was successfully completed. Bucket Stats after this Step:

       +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
      | Bucket         | Type      | Replicas | TTL | Items    | RAM Quota    | RAM Used    | Disk Used |
      +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
      | GleamBookUsers | ephemeral | 1        | 0   | 12000000 | 139732189184 | 40522783760 | 238       |
      +----------------+-----------+----------+-----+----------+--------------+-------------+-----------+
      

          5. Rebalance In 2 nodes(172.23.106.83, 172.23.106.86) and Rebalance Out 1 node(172.23.106.137) with another 2M creates, 4M updates, 2M deletes with durability=MAJORITY in parallel. Rebalance Operation failed in this step.

      Error Messages:

      Rebalance exited with reason {mover_crashed,
      {unexpected_exit,
      {'EXIT',<0.15239.12>,
      {{{{{child_interrupted,
      {'EXIT',<23442.27660.5>,socket_closed}},
      [{dcp_replicator,spawn_and_wait,1,
      [{file,"src/dcp_replicator.erl"},
      {line,266}]},
      {dcp_replicator,handle_call,3,
      [{file,"src/dcp_replicator.erl"},
      {line,121}]},
      {gen_server,try_handle_call,4,
      [{file,"gen_server.erl"},{line,636}]},
      {gen_server,handle_msg,6,
      [{file,"gen_server.erl"},{line,665}]},
      {proc_lib,init_p_do_apply,3,
      [{file,"proc_lib.erl"},{line,247}]}]},
      {gen_server,call,
      [<23442.27659.5>,
      {setup_replication,[416,430,431,432,433]},
      infinity]}},
      {gen_server,call,
      ['replication_manager-GleamBookUsers',
      {change_vbucket_replication,430,
      'ns_1@172.23.106.136'},
      infinity]}},
      {gen_server,call,
      [{'janitor_agent-GleamBookUsers',
      'ns_1@172.23.106.83'},
      {if_rebalance,<0.6571.12>,
      {update_vbucket_state,966,active,
      undefined,undefined,
      [['ns_1@172.23.106.83',
      'ns_1@172.23.106.86']]}},
      infinity]}}}}}.
      Rebalance Operation Id = 6e1498b429d0c4f57e09d5db488c9f4e 

       Worker <0.6765.12> (for action {move,{966,
      ['ns_1@172.23.106.137',
      'ns_1@172.23.106.136'],
      ['ns_1@172.23.106.83',
      'ns_1@172.23.106.86'],
      []}}) exited with reason {unexpected_exit,
      {'EXIT',
      <0.15239.12>,
      {{{{{child_interrupted,
      {'EXIT',
      <23442.27660.5>,
      socket_closed}},
      [{dcp_replicator,
      spawn_and_wait,
      1,
      [{file,
      "src/dcp_replicator.erl"},
      {line,
      266}]},
      {dcp_replicator,
      handle_call,
      3,
      [{file,
      "src/dcp_replicator.erl"},
      {line,
      121}]},
      {gen_server,
      try_handle_call,
      4,
      [{file,
      "gen_server.erl"},
      {line,
      636}]},
      {gen_server,
      handle_msg,
      6,
      [{file,
      "gen_server.erl"},
      {line,
      665}]},
      {proc_lib,
      init_p_do_apply,
      3,
      [{file,
      "proc_lib.erl"},
      {line,
      247}]}]},
      {gen_server,
      call,
      [<23442.27659.5>,
      {setup_replication,
      [416,
      430,
      431,
      432,
      433]},
      infinity]}},
      {gen_server,
      call,
      ['replication_manager-GleamBookUsers',
      {change_vbucket_replication,
      430,
      'ns_1@172.23.106.136'},
      infinity]}},
      {gen_server,
      call,
      [{'janitor_agent-GleamBookUsers',
      'ns_1@172.23.106.83'},
      {if_rebalance,
      <0.6571.12>,
      {update_vbucket_state,
      966,
      active,
      undefined,
      undefined,
      [['ns_1@172.23.106.83',
      'ns_1@172.23.106.86']]}},
      infinity]}}}}

      Note: This warning message was not found in memcached logs.

      Disconnecting the connection as there is no memory to complete replication

       

      Attachments

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

        Activity

          drigby Dave Rigby added a comment -

          Timestamp of rebalance failure is:

          [ns_server:info,2019-10-25T01:34:57.603-07:00,ns_1@172.23.106.136:rebalance_agent<0.3477.0>:rebalance_agent:handle_down:296]Rebalancer process <23133.6008.12> died (reason {mover_crashed,
          

          This corresponds to the following error on node .106.83, which causes the DCP connection to be closed (and hence rebalance fails):

          2019-10-25T01:34:57.241398-07:00 ERROR 93: exception occurred in runloop during packet execution. Cookie info: [{"aiostat":"success","connection":"[ 127.0.0.1:43619 - 127.0.0.1:11209 (<ud>@ns_server</ud>) ]","engine_storage":"0x00007fd93ad9ae10","ewouldblock":false,"packet":{"bodylen":30,"cas":0,"datatype":"raw","extlen":16,"key":"<ud>Users-01024899</ud>","keylen":14,"magic":"ClientRequest","opaque":30,"opcode":"DCP_ABORT","vbucket":416},"refcount":1}] - closing connection ([ 127.0.0.1:43619 - 127.0.0.1:11209 (<ud>@ns_server</ud>) ]): EphemeralVBucket::abortStoredValue: Cannot call on a non-Pending StoredValue
          

          Some context leading up to this error for the affected vb:416:

          2019-10-25T01:33:47.672699-07:00 INFO (GleamBookUsers) VBucket::setState: transitioning vb:416 with high seqno:0 from:replica to:replica
          2019-10-25T01:33:47.675395-07:00 INFO 79: (GleamBookUsers) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.106.134->ns_1@172.23.106.83:GleamBookUsers - (vb:416) Attempting to add stream: opaque_:16, start_seqno_:0, end_seqno_:18446744073709551615, vb_uuid:132115003169186, snap_start_seqno_:0
          , snap_end_seqno_:0, last_seqno:0, stream_req_value:{"uid":"0"}
          ... 36s later ...
          2019-10-25T01:34:23.326619-07:00 INFO 79: (GleamBookUsers) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.106.134->ns_1@172.23.106.83:GleamBookUsers - (vb:416) Setting stream to dead state, last_seqno is 47118, unAckedBytes is 0, status is The stream closed due to a close stream message
          2019-10-25T01:34:23.326652-07:00 INFO 79: (GleamBookUsers) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.106.134->ns_1@172.23.106.83:GleamBookUsers - (vb:416) End stream received with reason 1
          ... 34s later ...
          2019-10-25T01:34:57.237037-07:00 INFO 93: (GleamBookUsers) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.106.136->ns_1@172.23.106.83:GleamBookUsers - (vb:416) Attempting to add stream: opaque_:30, start_seqno_:47118, end_seqno_:18446744073709551615, vb_uuid:173839965648806, snap_start_seqno_:47118, snap_end_seqno_:47118, last_seqno:47118, stream_req_value:{"uid":"0"}
          2019-10-25T01:34:57.241398-07:00 ERROR 93: exception occurred in runloop during packet execution. Cookie info: [{"aiostat":"success","connection":"[ 127.0.0.1:43619 - 127.0.0.1:11209 (<ud>@ns_server</ud>) ]","engine_storage":"0x00007fd93ad9ae10","ewouldblock":false,"packet":{"bodylen":30,"cas":0,"datatype":"raw","extlen":16,"key":"<ud>Users-01024899</ud>","keylen":14,"magic":"ClientRequest","opaque":30,"opcode":"DCP_ABORT","vbucket":416},"refcount":1}] - closing connection ([ 127.0.0.1:43619 - 127.0.0.1:11209 (<ud>@ns_server</ud>) ]): EphemeralVBucket::abortStoredValue: Cannot call on a non-Pending StoredValue
          

          drigby Dave Rigby added a comment - Timestamp of rebalance failure is: [ns_server:info,2019-10-25T01:34:57.603-07:00,ns_1@172.23.106.136:rebalance_agent<0.3477.0>:rebalance_agent:handle_down:296]Rebalancer process <23133.6008.12> died (reason {mover_crashed, This corresponds to the following error on node .106.83, which causes the DCP connection to be closed (and hence rebalance fails): 2019-10-25T01:34:57.241398-07:00 ERROR 93: exception occurred in runloop during packet execution. Cookie info: [{"aiostat":"success","connection":"[ 127.0.0.1:43619 - 127.0.0.1:11209 (<ud>@ns_server</ud>) ]","engine_storage":"0x00007fd93ad9ae10","ewouldblock":false,"packet":{"bodylen":30,"cas":0,"datatype":"raw","extlen":16,"key":"<ud>Users-01024899</ud>","keylen":14,"magic":"ClientRequest","opaque":30,"opcode":"DCP_ABORT","vbucket":416},"refcount":1}] - closing connection ([ 127.0.0.1:43619 - 127.0.0.1:11209 (<ud>@ns_server</ud>) ]): EphemeralVBucket::abortStoredValue: Cannot call on a non-Pending StoredValue Some context leading up to this error for the affected vb:416: 2019-10-25T01:33:47.672699-07:00 INFO (GleamBookUsers) VBucket::setState: transitioning vb:416 with high seqno:0 from:replica to:replica 2019-10-25T01:33:47.675395-07:00 INFO 79: (GleamBookUsers) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.106.134->ns_1@172.23.106.83:GleamBookUsers - (vb:416) Attempting to add stream: opaque_:16, start_seqno_:0, end_seqno_:18446744073709551615, vb_uuid:132115003169186, snap_start_seqno_:0 , snap_end_seqno_:0, last_seqno:0, stream_req_value:{"uid":"0"} ... 36s later ... 2019-10-25T01:34:23.326619-07:00 INFO 79: (GleamBookUsers) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.106.134->ns_1@172.23.106.83:GleamBookUsers - (vb:416) Setting stream to dead state, last_seqno is 47118, unAckedBytes is 0, status is The stream closed due to a close stream message 2019-10-25T01:34:23.326652-07:00 INFO 79: (GleamBookUsers) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.106.134->ns_1@172.23.106.83:GleamBookUsers - (vb:416) End stream received with reason 1 ... 34s later ... 2019-10-25T01:34:57.237037-07:00 INFO 93: (GleamBookUsers) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.106.136->ns_1@172.23.106.83:GleamBookUsers - (vb:416) Attempting to add stream: opaque_:30, start_seqno_:47118, end_seqno_:18446744073709551615, vb_uuid:173839965648806, snap_start_seqno_:47118, snap_end_seqno_:47118, last_seqno:47118, stream_req_value:{"uid":"0"} 2019-10-25T01:34:57.241398-07:00 ERROR 93: exception occurred in runloop during packet execution. Cookie info: [{"aiostat":"success","connection":"[ 127.0.0.1:43619 - 127.0.0.1:11209 (<ud>@ns_server</ud>) ]","engine_storage":"0x00007fd93ad9ae10","ewouldblock":false,"packet":{"bodylen":30,"cas":0,"datatype":"raw","extlen":16,"key":"<ud>Users-01024899</ud>","keylen":14,"magic":"ClientRequest","opaque":30,"opcode":"DCP_ABORT","vbucket":416},"refcount":1}] - closing connection ([ 127.0.0.1:43619 - 127.0.0.1:11209 (<ud>@ns_server</ud>) ]): EphemeralVBucket::abortStoredValue: Cannot call on a non-Pending StoredValue
          drigby Dave Rigby added a comment -

          Paolo Cocchi Could you take a look at this once you've finished the current bugs you're working on?

          drigby Dave Rigby added a comment - Paolo Cocchi Could you take a look at this once you've finished the current bugs you're working on?
          lynn.straus Lynn Straus added a comment -

          Added due date field (preset to Nov 15). Please update the due date to the current ETA for a fix. Thanks.

          lynn.straus Lynn Straus added a comment - Added due date field (preset to Nov 15). Please update the due date to the current ETA for a fix. Thanks.
          paolo.cocchi Paolo Cocchi added a comment - - edited

          The issue in this MB is that for Ephemeral we are not resilient to "unprepared abort" (ie, DCP_ABORT message received but DCP_PREPARE never received) at Replica. That can happen for Backfill Snapshots.

          For EP Bucket, an Abort item can deduplicate the related Prepare on disk (as Prepare and Abort share the same "prepare namespace" on disk). That is why at disk-backfill a Replica may never receive the Prepare but still receive the Abort. We have already addressed this problem for EP Bucket: at first we used to ignore the Abort if the Prepare was never received (done as part of MB-34473 and MB-34474); then we have corrected some issues arisen with the first approach by accepting the "unprepared abort" (MB-35633).

          For Ephemeral Bucket we have a similar scenario. At Active, an Abort just updates the Prepare in the HashTable (CommittedState from Prepare to PrepareAbort). Then, at backfill the active will just send the PrepareAbort as a DCP_ABORT message.

          The issue for Ephemeral is that some (wrong) logic at Replica may lead to processing an "unprepared abort" as if an in-flight Prepare was found in the HashTable. Specifically, let's imagine that at Replica we already have a PrepareAbort (or even PrepareCommit) for some "key". Then:

          http://src.couchbase.org/source/xref/mad-hatter/kv_engine/engines/ep/src/vbucket.cc#875-997

          875  ENGINE_ERROR_CODE VBucket::abort(
          876          const DocKey& key,
          877          uint64_t prepareSeqno,
          878          boost::optional<int64_t> abortSeqno,
          879          const Collections::VB::Manifest::CachingReadHandle& cHandle,
          880          const void* cookie) {
          881      auto htRes = ht.findForUpdate(key);
          882  
          883      if (!htRes.pending) {
          884          <process as if in-flight Prepare NOT found>
          ..
          953          return ENGINE_SUCCESS;
          954      }
          955  
          956      <process as if in-flight Prepare found>
          ..
          996      return ENGINE_SUCCESS;
          997  }
          

          The call to findForUpdate() above calls down to:

          http://src.couchbase.org/source/xref/mad-hatter/kv_engine/engines/ep/src/hash_table.cc#310-334

          310  HashTable::FindInnerResult HashTable::findInner(const DocKey& key) {
          311      if (!isActive()) {
          312          throw std::logic_error(
          313                  "HashTable::find: Cannot call on a "
          314                  "non-active object");
          315      }
          316      HashBucketLock hbl = getLockedBucket(key);
          317      // Scan through all elements in the hash bucket chain looking for Committed
          318      // and Pending items with the same key.
          319      StoredValue* foundCmt = nullptr;
          320      StoredValue* foundPend = nullptr;
          321      for (StoredValue* v = values[hbl.getBucketNum()].get().get(); v;
          322           v = v->getNext().get().get()) {
          323          if (v->hasKey(key)) {
          324              if (v->isPending() || v->isCompleted()) {
          325                  Expects(!foundPend);
          326                  foundPend = v;
          327              } else {
          328                  Expects(!foundCmt);
          329                  foundCmt = v;
          330              }
          331          }
          332      }
          333  
          334      return {std::move(hbl), foundCmt, foundPend};
          

          Block 324-327 above is where we found an in-flight Prepare, but:

          http://src.couchbase.org/source/xref/mad-hatter/kv_engine/engines/ep/src/stored-value.h#819-822

          819      bool isCompleted() const {
          820          return (getCommitted() == CommittedState::PrepareAborted) ||
          821                 (getCommitted() == CommittedState::PrepareCommitted);
          822      }
          

          So essentially we are telling VBucket::abort that we have found an in-flight Prepare even if we have actually found a PrepareAborted/PrepareCommitted. At this point the execution of VBucket::abort proceeds and fails at:

          http://src.couchbase.org/source/xref/mad-hatter/kv_engine/engines/ep/src/ephemeral_vb.cc#674

          674  VBNotifyCtx EphemeralVBucket::abortStoredValue(
          675          const HashTable::HashBucketLock& hbl,
          676          StoredValue& prepared,
          677          int64_t prepareSeqno,
          678          boost::optional<int64_t> abortSeqno) {
          679      if (!prepared.isPending()) {
          680          throw std::invalid_argument(
          681                  "EphemeralVBucket::abortStoredValue: Cannot call on a "
          682                  "non-Pending StoredValue");
          683      }
          ..
          

          paolo.cocchi Paolo Cocchi added a comment - - edited The issue in this MB is that for Ephemeral we are not resilient to "unprepared abort" (ie, DCP_ABORT message received but DCP_PREPARE never received) at Replica. That can happen for Backfill Snapshots. For EP Bucket, an Abort item can deduplicate the related Prepare on disk (as Prepare and Abort share the same "prepare namespace" on disk). That is why at disk-backfill a Replica may never receive the Prepare but still receive the Abort. We have already addressed this problem for EP Bucket: at first we used to ignore the Abort if the Prepare was never received (done as part of MB-34473 and MB-34474 ); then we have corrected some issues arisen with the first approach by accepting the "unprepared abort" ( MB-35633 ). For Ephemeral Bucket we have a similar scenario. At Active, an Abort just updates the Prepare in the HashTable (CommittedState from Prepare to PrepareAbort). Then, at backfill the active will just send the PrepareAbort as a DCP_ABORT message. The issue for Ephemeral is that some (wrong) logic at Replica may lead to processing an "unprepared abort" as if an in-flight Prepare was found in the HashTable. Specifically, let's imagine that at Replica we already have a PrepareAbort (or even PrepareCommit) for some "key". Then: http://src.couchbase.org/source/xref/mad-hatter/kv_engine/engines/ep/src/vbucket.cc#875-997 875 ENGINE_ERROR_CODE VBucket::abort( 876 const DocKey& key, 877 uint64_t prepareSeqno, 878 boost::optional<int64_t> abortSeqno, 879 const Collections::VB::Manifest::CachingReadHandle& cHandle, 880 const void* cookie) { 881 auto htRes = ht.findForUpdate(key); 882 883 if (!htRes.pending) { 884 <process as if in-flight Prepare NOT found> .. 953 return ENGINE_SUCCESS; 954 } 955 956 <process as if in-flight Prepare found> .. 996 return ENGINE_SUCCESS; 997 } The call to findForUpdate() above calls down to: http://src.couchbase.org/source/xref/mad-hatter/kv_engine/engines/ep/src/hash_table.cc#310-334 310 HashTable::FindInnerResult HashTable::findInner(const DocKey& key) { 311 if (!isActive()) { 312 throw std::logic_error( 313 "HashTable::find: Cannot call on a " 314 "non-active object"); 315 } 316 HashBucketLock hbl = getLockedBucket(key); 317 // Scan through all elements in the hash bucket chain looking for Committed 318 // and Pending items with the same key. 319 StoredValue* foundCmt = nullptr; 320 StoredValue* foundPend = nullptr; 321 for (StoredValue* v = values[hbl.getBucketNum()].get().get(); v; 322 v = v->getNext().get().get()) { 323 if (v->hasKey(key)) { 324 if (v->isPending() || v->isCompleted()) { 325 Expects(!foundPend); 326 foundPend = v; 327 } else { 328 Expects(!foundCmt); 329 foundCmt = v; 330 } 331 } 332 } 333 334 return {std::move(hbl), foundCmt, foundPend}; Block 324-327 above is where we found an in-flight Prepare, but: http://src.couchbase.org/source/xref/mad-hatter/kv_engine/engines/ep/src/stored-value.h#819-822 819 bool isCompleted() const { 820 return (getCommitted() == CommittedState::PrepareAborted) || 821 (getCommitted() == CommittedState::PrepareCommitted); 822 } So essentially we are telling VBucket::abort that we have found an in-flight Prepare even if we have actually found a PrepareAborted/PrepareCommitted. At this point the execution of VBucket::abort proceeds and fails at: http://src.couchbase.org/source/xref/mad-hatter/kv_engine/engines/ep/src/ephemeral_vb.cc#674 674 VBNotifyCtx EphemeralVBucket::abortStoredValue( 675 const HashTable::HashBucketLock& hbl, 676 StoredValue& prepared, 677 int64_t prepareSeqno, 678 boost::optional<int64_t> abortSeqno) { 679 if (!prepared.isPending()) { 680 throw std::invalid_argument( 681 "EphemeralVBucket::abortStoredValue: Cannot call on a " 682 "non-Pending StoredValue"); 683 } ..

          Build couchbase-server-6.5.0-4763 contains kv_engine commit e92b7e4 with commit message:
          MB-36650: Ephemeral Replica resilient to unprepared Abort

          build-team Couchbase Build Team added a comment - Build couchbase-server-6.5.0-4763 contains kv_engine commit e92b7e4 with commit message: MB-36650 : Ephemeral Replica resilient to unprepared Abort
          paolo.cocchi Paolo Cocchi added a comment -

          Hi Prateek Kumar, could you re-run the test against the new build please? Thank you

          paolo.cocchi Paolo Cocchi added a comment - Hi Prateek Kumar , could you re-run the test against the new build please? Thank you

          Build couchbase-server-7.0.0-1040 contains kv_engine commit e92b7e4 with commit message:
          MB-36650: Ephemeral Replica resilient to unprepared Abort

          build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.0-1040 contains kv_engine commit e92b7e4 with commit message: MB-36650 : Ephemeral Replica resilient to unprepared Abort

          People

            prateek.kumar Prateek Kumar (Inactive)
            prateek.kumar Prateek 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