teamcity: failed test: TestLogGrowthWhenRefreshingPendingCommands

[cockroach-teamcity]

The following tests appear to have failed on release-2.1 (test): TestLogGrowthWhenRefreshingPendingCommands/proposeOnFollower=true, TestLogGrowthWhenRefreshingPendingCommands

You may want to check for open issues.

#1029822:

TestLogGrowthWhenRefreshingPendingCommands/proposeOnFollower=true
--- FAIL: test/TestLogGrowthWhenRefreshingPendingCommands: TestLogGrowthWhenRefreshingPendingCommands/proposeOnFollower=true (0.120s)
client_raft_test.go:1262: raft log size grew to -15 KiB
------- Stdout: -------
W181128 17:47:48.698284 59047 storage/store.go:1653  [s4,r1/4:/M{in-ax}] could not gossip system config: periodic gossip is disabled
W181128 17:47:48.698342 59048 storage/store.go:1653  [s4,r1/4:/M{in-ax}] could not gossip node liveness: periodic gossip is disabled
W181128 17:47:48.700098 59124 storage/store.go:1653  [s5,r1/5:/M{in-ax}] could not gossip system config: periodic gossip is disabled
W181128 17:47:48.700131 59125 storage/store.go:1653  [s5,r1/5:/M{in-ax}] could not gossip node liveness: periodic gossip is disabled
I181128 17:47:48.701200 59055 storage/node_liveness.go:491  [hb] heartbeat failed on epoch increment; retrying
I181128 17:47:48.712259 58880 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] txnHeartbeat: aborting txn
W181128 17:47:48.813917 58857 storage/raft_transport.go:584  while processing outgoing Raft queue to node 1: rpc error: code = Unavailable desc = transport is closing:



TestLogGrowthWhenRefreshingPendingCommands
...s1,r1/1:/M{in-ax}] streamed snapshot to (n2,s2):?: kv pairs: 51, log entries: 8, rate-limit: 2.0 MiB/sec, 1ms
I181128 17:47:48.039125 58827 storage/replica_raftstorage.go:803  [s2,r1/?:{-}] applying preemptive snapshot at index 18 (id=b8cde652, encoded size=8684, 1 rocksdb batches, 8 log entries)
I181128 17:47:48.041183 58827 storage/replica_raftstorage.go:809  [s2,r1/?:/M{in-ax}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I181128 17:47:48.041608 57675 storage/replica_command.go:814  [s1,r1/1:/M{in-ax}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r1:/M{in-ax} [(n1,s1):1, next=2, gen=0]
I181128 17:47:48.043410 57675 storage/replica.go:3822  [s1,r1/1:/M{in-ax},txn=029c8bb7] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181128 17:47:48.045007 57675 storage/store_snapshot.go:636  [s1,r1/1:/M{in-ax}] sending preemptive snapshot 3f816911 at applied index 20
I181128 17:47:48.045272 57675 storage/store_snapshot.go:679  [s1,r1/1:/M{in-ax}] streamed snapshot to (n3,s3):?: kv pairs: 54, log entries: 10, rate-limit: 2.0 MiB/sec, 1ms
I181128 17:47:48.045691 58785 storage/replica_raftstorage.go:803  [s3,r1/?:{-}] applying preemptive snapshot at index 20 (id=3f816911, encoded size=9626, 1 rocksdb batches, 10 log entries)
I181128 17:47:48.046629 58785 storage/replica_raftstorage.go:809  [s3,r1/?:/M{in-ax}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181128 17:47:48.047137 57675 storage/replica_command.go:814  [s1,r1/1:/M{in-ax}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r1:/M{in-ax} [(n1,s1):1, (n2,s2):2, next=3, gen=0]
I181128 17:47:48.050631 57675 storage/replica.go:3822  [s1,r1/1:/M{in-ax},txn=388f500f] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I181128 17:47:48.053034 57675 storage/store_snapshot.go:636  [s1,r1/1:/M{in-ax}] sending preemptive snapshot 545eebe2 at applied index 22
I181128 17:47:48.053360 57675 storage/store_snapshot.go:679  [s1,r1/1:/M{in-ax}] streamed snapshot to (n4,s4):?: kv pairs: 57, log entries: 12, rate-limit: 2.0 MiB/sec, 2ms
I181128 17:47:48.053930 58865 storage/replica_raftstorage.go:803  [s4,r1/?:{-}] applying preemptive snapshot at index 22 (id=545eebe2, encoded size=10633, 1 rocksdb batches, 12 log entries)
I181128 17:47:48.054939 58865 storage/replica_raftstorage.go:809  [s4,r1/?:/M{in-ax}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181128 17:47:48.055345 57675 storage/replica_command.go:814  [s1,r1/1:/M{in-ax}] change replicas (ADD_REPLICA (n4,s4):4): read existing descriptor r1:/M{in-ax} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=0]
I181128 17:47:48.057926 57675 storage/replica.go:3822  [s1,r1/1:/M{in-ax},txn=4b499fb4] proposing ADD_REPLICA((n4,s4):4): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3 (n4,s4):4] next=5
I181128 17:47:48.060174 57675 storage/store_snapshot.go:636  [s1,r1/1:/M{in-ax}] sending preemptive snapshot b8939480 at applied index 24
I181128 17:47:48.060483 57675 storage/store_snapshot.go:679  [s1,r1/1:/M{in-ax}] streamed snapshot to (n5,s5):?: kv pairs: 60, log entries: 14, rate-limit: 2.0 MiB/sec, 1ms
I181128 17:47:48.060887 58870 storage/replica_raftstorage.go:803  [s5,r1/?:{-}] applying preemptive snapshot at index 24 (id=b8939480, encoded size=11704, 1 rocksdb batches, 14 log entries)
I181128 17:47:48.062057 58870 storage/replica_raftstorage.go:809  [s5,r1/?:/M{in-ax}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181128 17:47:48.062432 57675 storage/replica_command.go:814  [s1,r1/1:/M{in-ax}] change replicas (ADD_REPLICA (n5,s5):5): read existing descriptor r1:/M{in-ax} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n4,s4):4, next=5, gen=0]
I181128 17:47:48.065185 57675 storage/replica.go:3822  [s1,r1/1:/M{in-ax},txn=259f57f2] proposing ADD_REPLICA((n5,s5):5): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3 (n4,s4):4 (n5,s5):5] next=6



TestLogGrowthWhenRefreshingPendingCommands/proposeOnFollower=true
...ore.go:1653  [s5,r1/5:/M{in-ax}] could not gossip system config: periodic gossip is disabled
W181128 18:01:08.558320 59068 storage/store.go:1653  [s5,r1/5:/M{in-ax}] could not gossip node liveness: periodic gossip is disabled
I181128 18:01:08.578896 58992 storage/store_snapshot.go:636  [raftsnapshot,s1,r1/1:/M{in-ax}] sending Raft snapshot ab43381b at applied index 78
I181128 18:01:08.582032 58992 storage/store_snapshot.go:679  [raftsnapshot,s1,r1/1:/M{in-ax}] streamed snapshot to (n4,s4):4: kv pairs: 67, log entries: 32, rate-limit: 8.0 MiB/sec, 9ms
I181128 18:01:08.583455 59300 storage/replica_raftstorage.go:803  [s4,r1/4:/M{in-ax}] applying Raft snapshot at index 78 (id=ab43381b, encoded size=78086, 1 rocksdb batches, 32 log entries)
I181128 18:01:08.655901 59300 storage/replica_raftstorage.go:809  [s4,r1/4:/M{in-ax}] applied Raft snapshot in 72ms [clear=0ms batch=0ms entries=70ms commit=1ms]
I181128 18:01:08.696790 58237 gossip/gossip.go:1513  [n1] node has connected to cluster via gossip
W181128 18:01:09.294579 59307 storage/store.go:1653  [s3,r1/3:/M{in-ax}] could not gossip system config: periodic gossip is disabled
W181128 18:01:09.294624 59308 storage/store.go:1653  [s3,r1/3:/M{in-ax}] could not gossip node liveness: periodic gossip is disabled
W181128 18:01:09.427775 59379 internal/client/txn.go:532  [hb] failure aborting transaction: node unavailable; try another peer; abort caused by: result is ambiguous (server shutdown)
I181128 18:01:09.428048 59379 storage/node_liveness.go:817  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (server shutdown)
W181128 18:01:09.431456 59379 internal/client/txn.go:532  [hb] failure aborting transaction: node unavailable; try another peer; abort caused by: node unavailable; try another peer
W181128 18:01:09.431996 59379 storage/node_liveness.go:494  [hb] failed node liveness heartbeat: node unavailable; try another peer
W181128 18:01:09.452010 58963 storage/raft_transport.go:282  unable to accept Raft message from (n2,s2):2: no handler registered for (n1,s1):1
W181128 18:01:09.453026 58963 storage/raft_transport.go:282  unable to accept Raft message from (n3,s3):3: no handler registered for (n1,s1):1
W181128 18:01:09.453508 58963 storage/raft_transport.go:282  unable to accept Raft message from (n3,s3):?: no handler registered for (n1,s1):?
W181128 18:01:09.453952 58963 storage/raft_transport.go:282  unable to accept Raft message from (n3,s3):3: no handler registered for (n1,s1):1
W181128 18:01:09.455041 58950 storage/store.go:3812  [s2,r1/2:/M{in-ax}] raft error: node 1 claims to not contain store 1 for replica (n1,s1):1: store 1 was not found
W181128 18:01:09.467424 58948 storage/raft_transport.go:584  while processing outgoing Raft queue to node 1: store 1 was not found:
W181128 18:01:09.491426 58909 storage/raft_transport.go:584  while processing outgoing Raft queue to node 2: rpc error: code = Canceled desc = context canceled:client_raft_test.go:1262: raft log size grew to -15 KiB
------- Stdout: -------
W181128 17:47:48.698284 59047 storage/store.go:1653  [s4,r1/4:/M{in-ax}] could not gossip system config: periodic gossip is disabled
W181128 17:47:48.698342 59048 storage/store.go:1653  [s4,r1/4:/M{in-ax}] could not gossip node liveness: periodic gossip is disabled
W181128 17:47:48.700098 59124 storage/store.go:1653  [s5,r1/5:/M{in-ax}] could not gossip system config: periodic gossip is disabled
W181128 17:47:48.700131 59125 storage/store.go:1653  [s5,r1/5:/M{in-ax}] could not gossip node liveness: periodic gossip is disabled
I181128 17:47:48.701200 59055 storage/node_liveness.go:491  [hb] heartbeat failed on epoch increment; retrying
I181128 17:47:48.712259 58880 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] txnHeartbeat: aborting txn
W181128 17:47:48.813917 58857 storage/raft_transport.go:584  while processing outgoing Raft queue to node 1: rpc error: code = Unavailable desc = transport is closing:

Please assign, take a look and update the issue accordingly.

[nvanbenschoten]

@ajwerner do you mind taking a look at this? It's on release-2.1, so it's possible that it will be resolved when #32387 and #32429 are backported.

[ajwerner]

Sure I'll look

[nvanbenschoten]

I think it’s likely that it’s resolved by either #31583 or #31660. Neither of those has been backported.

[ajwerner]

I made #32692 to backport the first two suggested. I'll make another PR to backport the test fixes you posted.