Aliaksey Artamonau (Inactive) added a comment - 10/Dec/19 2:14 PM ns_server is waiting for sequence number persistence in multiple vbuckets on node .210: $ grep etmpfail ns_server.debug.log [rebalance:debug,2019-12-10T10:17:03.839-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:17:13.873-08:00,ns_1@172.23.106.210:<0.6002.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:1023. Will retry. [rebalance:debug,2019-12-10T10:17:24.214-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:17:34.842-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:17:44.876-08:00,ns_1@172.23.106.210:<0.6002.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:1023. Will retry. [rebalance:debug,2019-12-10T10:17:55.217-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:18:05.845-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:18:26.220-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:18:36.847-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:18:57.222-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:19:07.849-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:19:28.225-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:19:38.853-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:19:59.228-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:20:09.856-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:20:30.230-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:20:40.859-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:21:01.233-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:21:11.861-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:21:32.236-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:21:42.864-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:22:03.238-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:22:13.866-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:22:34.241-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:22:44.869-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:23:05.243-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:23:15.871-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:23:36.246-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:23:46.874-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:24:07.248-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:24:17.876-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry. [rebalance:debug,2019-12-10T10:24:38.251-08:00,ns_1@172.23.106.210:<0.6071.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 2 to persist for vBucket:848. Will retry. [rebalance:debug,2019-12-10T10:24:48.878-08:00,ns_1@172.23.106.210:<0.5989.0>:janitor_agent:do_wait_seqno_persisted:1034]Got etmpfail while waiting for sequence number 1 to persist for vBucket:852. Will retry.

Jim Walker added a comment - 11/Dec/19 12:36 AM 172.23.106.210 connects to 172.23.121.239 and for example wants to stream vb:852 (active on .239) this triggers a backfill on .239 which results in no items. .239 logging 2019-12-10T10:16:52.820398-08:00 INFO 50: (default) DCP (Producer) eq_dcpq:replication:ns_1@172.23.121.239->ns_1@172.23.106.210:default - (vb:852) Creating stream with start seqno 0 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-manifest uid:none, sid:none 2019-12-10T10:16:52.820439-08:00 INFO 50: (default) DCP (Producer) eq_dcpq:replication:ns_1@172.23.121.239->ns_1@172.23.106.210:default - (vb:852) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:replication:ns_1@172.23.121.239->ns_1@172.23.106.210:default" backfill:true, seqno:2 2019-12-10T10:16:52.820456-08:00 INFO 50: (default) DCP (Producer) eq_dcpq:replication:ns_1@172.23.121.239->ns_1@172.23.106.210:default - (vb:852) Scheduling backfill from 1 to 1, reschedule flag : False 2019-12-10T10:16:52.821368-08:00 INFO 50: (default) DCP (Producer) eq_dcpq:replication:ns_1@172.23.121.239->ns_1@172.23.106.210:default - (vb:852) Backfill complete, 0 items read from disk, 0 from memory, last seqno read: 0, pendingBackfill : False 0 items from disk

Jim Walker added a comment - 11/Dec/19 1:33 AM Duplicate of MB-37209 In the example of vb:852, because of the offline upgrade (and MB-37209 ) the high-seq is 1, and max-visible-seq is 0, when they should both be 1. The .239 node runs a backfill, and the stream doesn't have sync-replication enabled (cluster is still mix of 5.0 and 6.5) so it has to use the max-visible seq for the disksnapshot, we try and schedule a backfill from 1 to 0, which just moves straight to complete without sending anything. However this should of been a log message, but there is a minor issue with MB-36948 (which triggered MB-37209 ) in that the log message has incorrect formatting in the string, so the log message which would of made this issue clear doesn't get logged, instead babysitter says [ns_server:info,2019-12-10T10:16:52.987-08:00,babysitter_of_ns_1@cb.local:<0.116.0>:ns_port_server:log:224]memcached<0.116.0>: [*** LOG ERROR ***] [2019-12-10 10:16:52] [default.140710625973264] unmatched '}' in format string Thuan Nguyen please retry with a build where MB-37209 is fixed, fix went into couchbase-server-6.5.0-4939 I'll address the broken logging separately.

Thuan Nguyen added a comment - 11/Dec/19 2:11 AM I will try again on build 6.5.0-4942

Thuan Nguyen added a comment - 11/Dec/19 10:26 AM Verified upgrade to build 6.5.0-4945. This issue is fixed.