Details
-
Bug
-
Status: Closed
-
Critical
-
Resolution: Fixed
-
6.5.0
-
Enterprise Edition 6.5.0 build 4676
-
Triaged
-
Centos 64-bit
-
-
Unknown
-
KV-Engine Mad-Hatter GA
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
Activity
Paolo Cocchi Could you take a look at this once you've finished the current bugs you're working on?
Added due date field (preset to Nov 15). Please update the due date to the current ETA for a fix. Thanks.
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
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
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 StoredValueSome 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:replica2019-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 message2019-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