Details
-
Bug
-
Resolution: Not a Bug
-
Major
-
None
-
Untriaged
-
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
Issue Links
- relates to
-
MB-34091 In-flight SyncWrites may timeout during rebalance
- Closed