roachtest: replicate/wide failed

[cockroach-teamcity]

roachtest.replicate/wide failed with artifacts on master @ d4a584e49f0b1ca89738376090939d7669c3b3db:

test artifacts and logs in: /artifacts/replicate/wide/run_1
(allocator.go:440).runWideReplication: expected 0 mis-replicated ranges, but found 19

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=1 , ROACHTEST_encrypted=false , ROACHTEST_fs=ext4 , ROACHTEST_localSSD=true , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-25240

[kvoli]

xref #97794

[kvoli]

I've tried reproducing this 5 times and haven't been able to.

There a couple of issues, however the cause of this failure is due to the default span config being used (3x replication). This only occurs for a short period of time right after the circuit breakers reset and connection is established to the rest of the nodes. The default span config causes the replicate queue to remove voters, despite the actual replication factor being 9x. Voter removal stops once the span config is correct for the range and not the default (3x).

Whilst I wasn't able to reproduce the failure, I was able to reproduce the default span config being seen for a short period (much shorter than in the test failure).

Consider this timeline of events:

restart node
circuit breakers trip
circuit breakers reset 
gossip connection established and liveness established
default span config applied
... remove voter actions returned.
... remove voter actions acted upon causing 8x replication instead of 9x
spanconfig-subscriber established
... consider rebalance actions or add voter returned (for replicas removed)

The default replication factor can be seen in the distribution logging, specifically ‹remove voter› - need=3, have=9,.

Distribution Logs

I230310 22:07:04.281788 13756 13@kv/kvserver/replicate_queue.go:626 ⋮ [T1,n3,replicate,s3,r24/10:‹/Table/2{2-3}›] 2880  repair needed (‹range unavailable›), enqueuing

... gossip established, node liveness established, default span config returned for all ranges

I230310 22:07:04.288304 13768 13@kv/kvserver/allocator/allocatorimpl/allocator.go:1034 ⋮ [T1,n3,replicate,s3,r55/2:‹/Table/5{4-5}›] 2881  ‹remove voter› - need=3, have=9, priority=799.00
I230310 22:07:04.288355 13768 13@kv/kvserver/replicate_queue.go:626 ⋮ [T1,n3,replicate,s3,r55/2:‹/Table/5{4-5}›] 2882  repair needed (‹remove voter›), enqueuing

... span config watcher starts up, correct span config returned for all ranges

I230310 22:07:04.374981 13871 13@kv/kvserver/replicate_queue.go:664 ⋮ [T1,n3,replicate,s3,r25/12:‹/Table/2{3-4}›] 2889  no rebalance target found, not enqueuing

Cockroach Logs

Cockroach Logs - these show when gossip, liveness and eventually span configs are established:

I230310 22:07:04.061346 13344 gossip/client.go:124 ⋮ [T1,n3] 127  started gossip client to n0 (‹35.229.107.180:26257›)
I230310 22:07:04.062136 13344 gossip/client.go:129 ⋮ [T1,n3] 128  closing client to n1 (‹35.229.107.180:26257›): stopping outgoing client to n1 (‹35.229.107.180:26257›); already have incoming
I230310 22:07:04.062195 124 1@gossip/gossip.go:1420 ⋮ [T1,n3] 129  node has connected to cluster via gossip
I230310 22:07:04.062779 124 kv/kvserver/stores.go:282 ⋮ [T1,n3] 130  wrote 4 node addresses to persistent storage
I230310 22:07:04.072183 13358 kv/kvserver/liveness/liveness.go:1224 ⋮ [T1,n3,s3,r3/8:‹/System/{NodeLive…-tsd}›] 131  incremented n4 liveness epoch to 3
I230310 22:07:04.324725 13799 kv/kvclient/rangefeed/rangefeedcache/watcher.go:335 ⋮ [T1,n3] 132  spanconfig-subscriber: established range feed cache
I230310 22:07:04.371446 36 1@util/log/event_log.go:32 ⋮ [T1,n3] 133 ={"Timestamp":1678486024371429052,"EventType":"node_restart","NodeID":3,"StartedAt":1678486016052306715,"LastUp":1678486006479237816}
I230310 22:07:04.372991 13824 kv/kvclient/rangefeed/rangefeedcache/watcher.go:335 ⋮ [T1,n3] 134  settings-watcher: established range feed cache

A fix for this is to never use the default span config and instead just error out very loudly.

If a store is connected to gossip and also liveness, however is unable to retrieve a span config for a range - we can't make any decisions.

Using incorrect span configs seems worse than just doing nothing in many cases.

Another issue is that when restarting every node, the rpc circuit breakers kick in causing essentially a stall for 15 seconds.

[irfansharif]

Going to get rid of the release blocker since this bug exists in older releases already.

[kvoli]

Filed #98421

[cockroach-teamcity]

roachtest.replicate/wide failed with artifacts on master @ e4924e2b9be4a36d466beab53a80df9241df4783:

test artifacts and logs in: /artifacts/replicate/wide/run_1
(test_runner.go:990).runTest: test timed out (10m0s)
(cluster.go:1896).Start: ~ COCKROACH_CONNECT_TIMEOUT=0 ./cockroach sql --url 'postgres://root@localhost:26257?sslmode=disable' -e "CREATE SCHEDULE IF NOT EXISTS test_only_backup FOR BACKUP INTO 'gs://cockroachdb-backup-testing/roachprod-scheduled-backups/teamcity-9029456-1678684872-112-n9cpu1/1678723870068004190?AUTH=implicit' RECURRING '*/15 * * * *' FULL BACKUP '@hourly' WITH SCHEDULE OPTIONS first_run = 'now'"
ERROR: server closed the connection.
Is this a CockroachDB node?
unexpected EOF
Failed running "sql": COMMAND_PROBLEM: ssh verbose log retained in ssh_161110.068043100_n1_init-backup-schedule.log: exit status 1

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=1 , ROACHTEST_encrypted=false , ROACHTEST_fs=ext4 , ROACHTEST_localSSD=true , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

[nvanbenschoten]

Adding the GA-blocker back in for tracking purposes, though it looks like this will be closed shortly anyway.