Loading...

XML

Word

Printable

Details

Type: Bug
Resolution: Not a Bug
Priority: Major
Fix Version/s: 6.5.0
Affects Version/s: None
Component/s: ns_server
Labels:
- mad-hatter-committed

Triage:
Untriaged
Epic Link:
Sync replication
Is this a Regression?:
No

Description

I believe that there is a race condition with kv when setting the replication topology during rebalance. I've been implementing the kv logic for second chain in the durability monitor so that we can deal with durable writes during rebalance (~~MB-33959~~). After getting an implementation passing unit tests, I tried a rebalance and found the rebalance completes maybe 5% of the time.

Reproduction steps

Cherry pick http://review.couchbase.org/#/c/108506/, http://review.couchbase.org/#/c/108587/, http://review.couchbase.org/#/c/108507/ on kv.
Cluster run (4 nodes, 1 bucket with 2 replicas, 4 vbuckets)
Do one durable write
Rebalance out one of the replicas

The rebalance fails the majority of the time. The interesting thing is that it sometimes succeeds. Using wireshark and logs, it looks to me like ns_server sets up the replication stream for the node without a replica for the vbucket the sync write is in before (or at the same time as) it sets the topology on the active vbucket.

Bad case. After the exception we fail rebalance and tear down the streams.

2019-05-03T14:01:33.083283+01:00 INFO 40: [ 127.0.0.1:54117 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ] Updated cluster configuration for bucket [default]. New revision: 51

2019-05-03T14:01:33.083375+01:00 INFO Pushing new cluster config for bucket:[default] revision:[51]

2019-05-03T14:01:33.093217+01:00 INFO 45: Client 127.0.0.1:54459 authenticated as <ud>@ns_server</ud>

2019-05-03T14:01:33.093708+01:00 INFO 45: HELO [proxy] XATTR, Snappy, JSON [ 127.0.0.1:54459 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:01:33.094073+01:00 INFO 45: DCP connection opened successfully. PRODUCER, INCLUDE_XATTRS, DELETE_TIMES [ 127.0.0.1:54459 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:01:33.095076+01:00 INFO (default) CheckpointManager::registering persistence cursor for vb:1

2019-05-03T14:01:33.095142+01:00 INFO (default) VBucket: created vb:1 with state:pending initialState:dead lastSeqno:0 lastSnapshot:{0,0} persisted_snapshot:{0,0} max_cas:0 uuid:264935640369414 topology:null

2019-05-03T14:01:33.096755+01:00 INFO 47: Client 127.0.0.1:54461 authenticated as <ud>@ns_server</ud>

2019-05-03T14:01:33.097057+01:00 INFO 47: HELO [proxy] XATTR, Snappy, JSON [ 127.0.0.1:54461 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:01:33.097533+01:00 INFO (default) EventuallyPersistentEngine::dcpOpen: opening new DCP Consumer handler - stream name:replication:n_1@127.0.0.1->n_0@127.0.0.1:default, opaque:0, seqno:0, flags:0b00000000000000000000000000100100 value:{"consumer_name":"n_0@127.0.0.1"}

2019-05-03T14:01:33.097559+01:00 INFO 47: DCP connection opened successfully. INCLUDE_XATTRS, DELETE_TIMES [ 127.0.0.1:54461 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:01:33.099790+01:00 INFO 47: (default) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - (vb:1) Attempting to add stream: opaque_:1, start_seqno_:0, end_seqno_:18446744073709551615, vb_uuid:264935640369414, snap_start_seqno_:0, snap_end_seqno_:0, last_seqno:0, stream_req_value:{"uid":"0"}

2019-05-03T14:01:33.100009+01:00 INFO 45: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Creating stream with start seqno 0 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-manifest uid:none, sid:none

2019-05-03T14:01:33.100068+01:00 INFO 45: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default" backfill:true, seqno:3

2019-05-03T14:01:33.100088+01:00 INFO 45: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Scheduling backfill from 1 to 2, reschedule flag : False

2019-05-03T14:01:33.100237+01:00 INFO 45: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Sending disk snapshot with start seqno 0 and end seqno 2

2019-05-03T14:01:33.100267+01:00 INFO 45: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) ActiveStream::registerCursor name "eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default", backfill:true, seqno:3

2019-05-03T14:01:33.100475+01:00 INFO 45: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Backfill complete, 1 items read from disk, 1 from memory, last seqno read: 2, pendingBackfill : False

2019-05-03T14:01:33.100546+01:00 INFO 45: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) ActiveStream::transitionState: Transitioning from backfilling to in-memory

2019-05-03T14:01:33.101829+01:00 WARNING 45: exception occurred in runloop during packet execution. Cookie info: [{"aiostat":"success","connection":"[ 127.0.0.1:54459 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]","engine_storage":"0x0000000112bbf618","ewouldblock":false,"packet":{"bodylen":8,"cas":0,"datatype":"raw","extlen":8,"keylen":0,"magic":"ClientRequest","opaque":1,"opcode":"DCP_SEQNO_ACKNOWLEDGED","vbucket":0},"refcount":1}] - closing connection ([ 127.0.0.1:54459 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]): ActiveDurabilityMonitor::State::getNodeNext: node n_1@127.0.0.1 not found

2019-05-03T14:00:20.249678+01:00 INFO 34: (No Engine) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - Removing connection [ 127.0.0.1:54400 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:00:20.249708+01:00 WARNING 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Stream closing, sent until seqno 2 remaining items 0, reason: The stream closed early because the conn was disconnected

2019-05-03T14:00:20.274493+01:00 INFO 43: (No Engine) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_3@127.0.0.1:default - Removing connection [ 127.0.0.1:54302 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:00:20.274536+01:00 WARNING 43: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_3@127.0.0.1:default - (vb:0) Stream closing, sent until seqno 2 remaining items 0, reason: The stream closed early because the conn was disconnected

2019-05-03T14:00:20.275588+01:00 INFO 42: (No Engine) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - Removing connection [ 127.0.0.1:54301 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:00:20.275620+01:00 WARNING 42: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:0) Stream closing, sent until seqno 2 remaining items 0, reason: The stream closed early because the conn was disconnected

2019-05-03T14:00:20.287671+01:00 INFO 47: (No Engine) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - Removing connection [ 127.0.0.1:54411 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:00:20.287716+01:00 WARNING 47: (default) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - (vb:1) Setting stream to dead state, last_seqno is 0, unAckedBytes is 0, status is The stream closed early because the conn was disconnected

2019-05-03T14:00:20.306916+01:00 INFO 45: (default) DCP (Consumer) eq_dcpq:replication:n_2@127.0.0.1->n_0@127.0.0.1:default - (vb:2) Setting stream to dead state, last_seqno is 0, unAckedBytes is 0, status is The stream closed due to a close stream message

2019-05-03T14:00:20.307152+01:00 INFO 46: (default) DCP (Consumer) eq_dcpq:replication:n_3@127.0.0.1->n_0@127.0.0.1:default - (vb:3) Setting stream to dead state, last_seqno is 0, unAckedBytes is 0, status is The stream closed due to a close stream message

2019-05-03T14:00:20.307940+01:00 INFO 45: (No Engine) DCP (Consumer) eq_dcpq:replication:n_2@127.0.0.1->n_0@127.0.0.1:default - Removing connection [ 127.0.0.1:54313 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:00:20.309288+01:00 INFO 46: (No Engine) DCP (Consumer) eq_dcpq:replication:n_3@127.0.0.1->n_0@127.0.0.1:default - Removing connection [ 127.0.0.1:54315 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:01:19.888972+01:00 INFO (default) VBucket::setState: transitioning vb:1 from:replica to:dead

2019-05-03T14:01:19.889015+01:00 INFO (default) Deletion of vb:1 was completed.

Good case - we got the topology change (I think this was actually after we threw the exception because this rebalance failed, but the one after worked).

2019-05-03T14:02:10.611319+01:00 INFO (default) CheckpointManager::registering persistence cursor for vb:1

2019-05-03T14:02:10.611377+01:00 INFO (default) VBucket: created vb:1 with state:pending initialState:dead lastSeqno:0 lastSnapshot:{0,0} persisted_snapshot:{0,0} max_cas:0 uuid:166796842480876 topology:null

2019-05-03T14:02:10.613115+01:00 INFO 41: Client 127.0.0.1:54735 authenticated as <ud>@ns_server</ud>

2019-05-03T14:02:10.613799+01:00 INFO 41: HELO [proxy] XATTR, Snappy, JSON [ 127.0.0.1:54735 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.614483+01:00 INFO (default) EventuallyPersistentEngine::dcpOpen: opening new DCP Consumer handler - stream name:replication:n_1@127.0.0.1->n_0@127.0.0.1:default, opaque:0, seqno:0, flags:0b00000000000000000000000000100100 value:{"consumer_name":"n_0@127.0.0.1"}

2019-05-03T14:02:10.614524+01:00 INFO 41: DCP connection opened successfully. INCLUDE_XATTRS, DELETE_TIMES [ 127.0.0.1:54735 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.615416+01:00 INFO 34: Client 127.0.0.1:54737 authenticated as <ud>@ns_server</ud>

2019-05-03T14:02:10.615704+01:00 INFO 34: HELO [proxy] XATTR, Snappy, JSON [ 127.0.0.1:54737 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.615993+01:00 INFO 34: DCP connection opened successfully. PRODUCER, INCLUDE_XATTRS, DELETE_TIMES [ 127.0.0.1:54737 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.616639+01:00 INFO 41: (default) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - (vb:1) Attempting to add stream: opaque_:1, start_seqno_:0, end_seqno_:18446744073709551615, vb_uuid:166796842480876, snap_start_seqno_:0, snap_end_seqno_:0, last_seqno:0, stream_req_value:{"uid":"0"}

2019-05-03T14:02:10.621911+01:00 INFO 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Creating stream with start seqno 0 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-manifest uid:none, sid:none

2019-05-03T14:02:10.621983+01:00 INFO 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default" backfill:true, seqno:3

2019-05-03T14:02:10.622004+01:00 INFO 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Scheduling backfill from 1 to 2, reschedule flag : False

2019-05-03T14:02:10.622122+01:00 INFO 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Sending disk snapshot with start seqno 0 and end seqno 2

2019-05-03T14:02:10.622152+01:00 INFO 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) ActiveStream::registerCursor name "eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default", backfill:true, seqno:3

2019-05-03T14:02:10.622313+01:00 INFO 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Backfill complete, 1 items read from disk, 1 from memory, last seqno read: 2, pendingBackfill : False

2019-05-03T14:02:10.622373+01:00 INFO 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) ActiveStream::transitionState: Transitioning from backfilling to in-memory

2019-05-03T14:02:10.625071+01:00 WARNING 34: exception occurred in runloop during packet execution. Cookie info: [{"aiostat":"success","connection":"[ 127.0.0.1:54737 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]","engine_storage":"0x0000000112bbe718","ewouldblock":false,"packet":{"bodylen":8,"cas":0,"datatype":"raw","extlen":8,"keylen":0,"magic":"ClientRequest","

opaque":1,"opcode":"DCP_SEQNO_ACKNOWLEDGED","vbucket":0},"refcount":1}] - closing connection ([ 127.0.0.1:54737 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]): ActiveDurabilityMonitor::State::getNodeNext: node n_1@127.0.0.1 not found

2019-05-03T14:02:10.625124+01:00 INFO 34: (No Engine) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - Removing connection [ 127.0.0.1:54737 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.625168+01:00 WARNING 34: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Stream closing, sent until seqno 2 remaining items 0, reason: The stream closed early because the conn was disconnected

2019-05-03T14:02:10.632108+01:00 INFO 42: Client 127.0.0.1:54743 authenticated as <ud>@ns_server</ud>

2019-05-03T14:02:10.632275+01:00 INFO 42: HELO [regular] [ 127.0.0.1:54743 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.633294+01:00 INFO (default) VBucket::setState: transitioning vb:0 from:active to:active meta:{"topology":[["n_0@127.0.0.1","n_2@127.0.0.1","n_3@127.0.0.1"],["n_0@127.0.0.1","n_2@127.0.0.1","n_1@127.0.0.1"]]}

2019-05-03T14:02:10.639130+01:00 INFO 41: (default) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - (vb:1) Setting stream to dead state, last_seqno is 0, unAckedBytes is 0, status is The stream closed due to a close stream message

2019-05-03T14:02:10.639215+01:00 INFO 48: (No Engine) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_3@127.0.0.1:default - Removing connection [ 127.0.0.1:54724 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.639250+01:00 WARNING 48: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_3@127.0.0.1:default - (vb:0) Stream closing, sent until seqno 2 remaining items 0, reason: The stream closed early because the conn was disconnected

2019-05-03T14:02:10.640120+01:00 WARNING 41: (default) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - (vb:1) End stream received but no such stream for this vBucket

2019-05-03T14:02:10.640282+01:00 INFO 41: (default) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - (vb:1) Attempting to add takeover stream: opaque_:14, start_seqno_:0, end_seqno_:18446744073709551615, vb_uuid:133548509855751, snap_start_seqno_:0, snap_end_seqno_:0, last_seqno:0, stream_req_value:{"uid":"0"}

2019-05-03T14:02:10.640500+01:00 INFO (default) VBucket::setState: transitioning vb:0 from:active to:active meta:{"topology":[["n_0@127.0.0.1","n_2@127.0.0.1","n_1@127.0.0.1"]]}

2019-05-03T14:02:10.642903+01:00 INFO (default) VBucket::setState: transitioning vb:1 from:pending to:active

2019-05-03T14:02:10.643847+01:00 INFO 41: (default) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - (vb:1) End stream received with reason 0

2019-05-03T14:02:10.644241+01:00 INFO 41: (No Engine) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - Removing connection [ 127.0.0.1:54735 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.653434+01:00 INFO 40: [ 127.0.0.1:54117 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ] Updated cluster configuration for bucket [default]. New revision: 122

2019-05-03T14:02:10.653471+01:00 INFO Pushing new cluster config for bucket:[default] revision:[122]

2019-05-03T14:02:10.665694+01:00 INFO 47: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:1) Creating stream with start seqno 0 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-manifest uid:none, sid:none

2019-05-03T14:02:10.665758+01:00 INFO 47: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:1) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default" backfill:true, seqno:1

2019-05-03T14:02:10.665794+01:00 INFO 47: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:1) ActiveStream::transitionState: Transitioning from backfilling to in-memory

2019-05-03T14:02:10.969550+01:00 INFO 47: (No Engine) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - Removing connection [ 127.0.0.1:54722 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.969584+01:00 WARNING 47: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:0) Stream closing, sent until seqno 2 remaining items 0, reason: The stream closed early because the conn was disconnected

2019-05-03T14:02:10.969611+01:00 WARNING 47: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:1) Stream closing, sent until seqno 0 remaining items 0, reason: The stream closed early because the conn was disconnected

2019-05-03T14:02:10.987319+01:00 INFO 49: (default) DCP (Consumer) eq_dcpq:replication:n_3@127.0.0.1->n_0@127.0.0.1:default - (vb:3) Setting stream to dead state, last_seqno is 0, unAckedBytes is 0, status is The stream closed due to a close stream message

2019-05-03T14:02:10.988369+01:00 INFO 49: (No Engine) DCP (Consumer) eq_dcpq:replication:n_3@127.0.0.1->n_0@127.0.0.1:default - Removing connection [ 127.0.0.1:54726 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:10.991165+01:00 INFO 44: (default) DCP (Consumer) eq_dcpq:replication:n_2@127.0.0.1->n_0@127.0.0.1:default - (vb:2) Setting stream to dead state, last_seqno is 0, unAckedBytes is 0, status is The stream closed due to a close stream message

2019-05-03T14:02:10.996557+01:00 INFO 44: (No Engine) DCP (Consumer) eq_dcpq:replication:n_2@127.0.0.1->n_0@127.0.0.1:default - Removing connection [ 127.0.0.1:54719 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.836751+01:00 INFO 40: [ 127.0.0.1:54117 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ] Updated cluster configuration for bucket [default]. New revision: 125

2019-05-03T14:02:14.836840+01:00 INFO Pushing new cluster config for bucket:[default] revision:[125]

2019-05-03T14:02:14.846050+01:00 INFO (default) VBucket::setState: transitioning vb:1 from:active to:active meta:{"topology":[["n_0@127.0.0.1","n_1@127.0.0.1","n_2@127.0.0.1"]]}

2019-05-03T14:02:14.848163+01:00 INFO 41: Client 127.0.0.1:54751 authenticated as <ud>@ns_server</ud>

2019-05-03T14:02:14.848501+01:00 INFO 41: HELO [proxy] XATTR, Snappy, JSON [ 127.0.0.1:54751 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.848996+01:00 INFO (default) EventuallyPersistentEngine::dcpOpen: opening new DCP Consumer handler - stream name:replication:n_1@127.0.0.1->n_0@127.0.0.1:default, opaque:0, seqno:0, flags:0b00000000000000000000000000100100 value:{"consumer_name":"n_0@127.0.0.1"}

2019-05-03T14:02:14.849008+01:00 INFO 41: DCP connection opened successfully. INCLUDE_XATTRS, DELETE_TIMES [ 127.0.0.1:54751 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.849753+01:00 INFO 43: Client 127.0.0.1:54753 authenticated as <ud>@ns_server</ud>

2019-05-03T14:02:14.849906+01:00 INFO 44: Client 127.0.0.1:54755 authenticated as <ud>@ns_server</ud>

2019-05-03T14:02:14.850048+01:00 INFO 43: HELO [proxy] XATTR, Snappy, JSON [ 127.0.0.1:54753 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.850176+01:00 INFO 44: HELO [proxy] XATTR, Snappy, JSON [ 127.0.0.1:54755 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.850317+01:00 INFO 43: DCP connection opened successfully. PRODUCER, INCLUDE_XATTRS, DELETE_TIMES [ 127.0.0.1:54753 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.850501+01:00 INFO 44: DCP connection opened successfully. PRODUCER, INCLUDE_XATTRS, DELETE_TIMES [ 127.0.0.1:54755 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.851380+01:00 INFO 45: Client 127.0.0.1:54757 authenticated as <ud>@ns_server</ud>

2019-05-03T14:02:14.851989+01:00 INFO 45: HELO [proxy] XATTR, Snappy, JSON [ 127.0.0.1:54757 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.852406+01:00 INFO (default) EventuallyPersistentEngine::dcpOpen: opening new DCP Consumer handler - stream name:replication:n_2@127.0.0.1->n_0@127.0.0.1:default, opaque:0, seqno:0, flags:0b00000000000000000000000000100100 value:{"consumer_name":"n_0@127.0.0.1"}

2019-05-03T14:02:14.852416+01:00 INFO 45: DCP connection opened successfully. INCLUDE_XATTRS, DELETE_TIMES [ 127.0.0.1:54757 - 127.0.0.1:11999 (<ud>@ns_server</ud>) ]

2019-05-03T14:02:14.854689+01:00 INFO 41: (default) DCP (Consumer) eq_dcpq:replication:n_1@127.0.0.1->n_0@127.0.0.1:default - (vb:3) Attempting to add stream: opaque_:1, start_seqno_:0, end_seqno_:18446744073709551615, vb_uuid:235497067026847, snap_start_seqno_:0, snap_end_seqno_:0, last_seqno:0, stream_req_value:{"uid":"0"}

2019-05-03T14:02:14.859645+01:00 INFO 44: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) Creating stream with start seqno 2 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-manifest uid:none, sid:none

2019-05-03T14:02:14.859718+01:00 INFO 44: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default" backfill:true, seqno:3

2019-05-03T14:02:14.859739+01:00 INFO 44: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:0) ActiveStream::transitionState: Transitioning from backfilling to in-memory

2019-05-03T14:02:14.859888+01:00 INFO 44: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:1) Creating stream with start seqno 0 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-manifest uid:none, sid:none

2019-05-03T14:02:14.859934+01:00 INFO 44: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:1) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default" backfill:true, seqno:1

2019-05-03T14:02:14.859974+01:00 INFO 44: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_1@127.0.0.1:default - (vb:1) ActiveStream::transitionState: Transitioning from backfilling to in-memory

2019-05-03T14:02:14.860925+01:00 INFO 45: (default) DCP (Consumer) eq_dcpq:replication:n_2@127.0.0.1->n_0@127.0.0.1:default - (vb:2) Attempting to add stream: opaque_:1, start_seqno_:0, end_seqno_:18446744073709551615, vb_uuid:271468263498961, snap_start_seqno_:0, snap_end_seqno_:0, last_seqno:0, stream_req_value:{"uid":"0"}

2019-05-03T14:02:14.867602+01:00 INFO 43: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:0) Creating stream with start seqno 2 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-manifest uid:none, sid:none

2019-05-03T14:02:14.867686+01:00 INFO 43: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:0) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default" backfill:true, seqno:3

2019-05-03T14:02:14.867705+01:00 INFO 43: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:0) ActiveStream::transitionState: Transitioning from backfilling to in-memory

2019-05-03T14:02:14.867853+01:00 INFO 43: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:1) Creating stream with start seqno 0 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-manifest uid:none, sid:none

2019-05-03T14:02:14.867886+01:00 INFO 43: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:1) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default" backfill:true, seqno:1

2019-05-03T14:02:14.867904+01:00 INFO 43: (default) DCP (Producer) eq_dcpq:replication:n_0@127.0.0.1->n_2@127.0.0.1:default - (vb:1) ActiveStream::transitionState: Transitioning from backfilling to in-memory

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

Screen Shot 2019-05-07 at 10.53.14.png
58 kB
07/May/19 2:55 AM

Issue Links

relates to

MB-34091 In-flight SyncWrites may timeout during rebalance

Closed

Gerrit Reviews

- Issue Only
- Show All Reviews
- Show Open Reviews
- Show All Issues
- Show Open Issues

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

Activity

People

Assignee:: Dave Finlay

Reporter:: Ben Huddleston

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 03/May/19 7:17 AM

Updated:: 10/May/19 12:15 AM

Resolved:: 03/May/19 10:21 AM

Gerrit Reviews

There are no open Gerrit changes

Rebalance race condition when setting vbucket replication topology

Details

Description

Attachments

Attachments

Issue Links

Gerrit Reviews

Activity

People

Dates

Gerrit Reviews

PagerDuty