cli: TestDebugCheckStore failed

cockroachdb / cockroach

CockroachDB — the cloud native, distributed SQL database designed for high availability, effortless scale, and control over data placement.

Other

30.01k stars 3.79k forks source link

cli.TestDebugCheckStore failed on master @ e747f6e6857a19d6048cb184b0f55c52cb8a6390:

I231209 10:51:56.263465 323 2@server/status/runtime_log.go:47  [T1,Vsystem,n1] 1377  runtime stats: 3.0 GiB RSS, 1174 goroutines (stacks: 20 MiB), 231 MiB/331 MiB Go alloc/total(stale) (heap fragmentation: 36 MiB, heap reserved: 20 MiB, heap released: 76 MiB), 261 MiB/270 MiB CGO alloc/total (2134.0 CGO/sec), 93.1/4.7 %(u/s)time, 0.0 %gc (926x), 222 KiB/222 KiB (r/w)net
I231209 10:51:56.265823 303 kv/kvserver/replica_rangefeed.go:808  [T1,Vsystem,n1,s1,r6/1:/Table/{0-4}] 1378  RangeFeed closed timestamp 1702118898.265999330,0 is behind by 3m37.999812826s
E231209 10:51:56.270515 6988059 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicaGC,s1,r51/1:/Table/{48-50}] 1379  replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1702118870.108880817,0 (2023-12-09 10:47:50); raft status: {"id":"1","term":43,"vote":"3","commit":1110,"lead":"0","raftState":"StatePreCandidate","applied":1110,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Min,/Min)
E231209 10:51:56.272861 6988121 kv/kvserver/queue.go:1160  [T1,Vsystem,n2,replicate,s2,r23/2:/Table/2{0-1}] 1380  [n2,s2,r23/2:/Table/2{0-1}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r23:/Table/2{0-1} [(n1,s1):1, (n2,s2):2, next=3, gen=2]: lost quorum (down: (n1,s1):1); closed timestamp: 1702118564.502315883,0 (2023-12-09 10:42:44); raft status: {"id":"2","term":160,"vote":"1","commit":456,"lead":"0","raftState":"StatePreCandidate","applied":456,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/20,/Min)
I231209 10:51:56.283349 6988088 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r6/1:/Table/{0-4}] 1381  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r6:/Table/{0-4} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=5]: lost quorum (down: (n3,s3):2,(n2,s2):3); closed timestamp: 1702118898.265999330,0 (2023-12-09 10:48:18); raft status: {"id":"1","term":13,"vote":"2","commit":658,"lead":"0","raftState":"StatePreCandidate","applied":658,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/0,/Min)
I231209 10:51:56.287947 6988098 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r9/1:/Table/{5-6}] 1382  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r9:/Table/{5-6} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702118588.591400730,0 (2023-12-09 10:43:08); raft status: {"id":"1","term":47,"vote":"1","commit":551,"lead":"0","raftState":"StateCandidate","applied":551,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/5,/Min)
E231209 10:51:56.294352 6988120 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r32/1:/{Table/29-NamespaceTab…}] 1383  [n1,s1,r32/1:/{Table/29-NamespaceTab…}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r32:/{Table/29-NamespaceTable/30} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n3,s3):2); closed timestamp: 1702118637.018593603,0 (2023-12-09 10:43:57); raft status: {"id":"1","term":125,"vote":"2","commit":509,"lead":"0","raftState":"StatePreCandidate","applied":509,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/29,/Min)
E231209 10:51:56.296468 6988122 kv/kvserver/queue.go:1160  [T1,Vsystem,n2,replicate,s2,r52/2:/Table/5{0-1}] 1384  [n2,s2,r52/2:/Table/5{0-1}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r52:/Table/5{0-1} [(n1,s1):1, (n2,s2):2, next=4, gen=4]: closed timestamp: 1702118564.268854773,0 (2023-12-09 10:42:44); raft status: {"id":"2","term":110,"vote":"1","commit":488,"lead":"0","raftState":"StatePreCandidate","applied":488,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/50,/Min)
E231209 10:51:56.297885 6988161 kv/kvserver/queue.go:1160  [T1,Vsystem,n2,replicate,s2,r57/2:/Table/5{5-7}] 1385  [n2,s2,r57/2:/Table/5{5-7}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r57:/Table/5{5-7} [(n1,s1):1, (n2,s2):2, next=3, gen=3]: lost quorum (down: (n1,s1):1); closed timestamp: 1702118564.502315883,0 (2023-12-09 10:42:44); raft status: {"id":"2","term":65,"vote":"1","commit":543,"lead":"0","raftState":"StatePreCandidate","applied":543,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/55,/Min)
I231209 10:51:56.306169 6988141 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r10/1:/Table/{6-7}] 1386  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r10:/Table/{6-7} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n3,s3):2,(n2,s2):3); closed timestamp: 1702118898.265999330,0 (2023-12-09 10:48:18); raft status: {"id":"1","term":31,"vote":"2","commit":625,"lead":"0","raftState":"StatePreCandidate","applied":625,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/6,/Min)
I231209 10:51:56.310190 6988151 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r12/1:/Table/{8-9}] 1387  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r12:/Table/{8-9} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n3,s3):2); closed timestamp: 1702118637.018593603,0 (2023-12-09 10:43:57); raft status: {"id":"1","term":53,"vote":"2","commit":559,"lead":"0","raftState":"StatePreCandidate","applied":559,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/8,/Min)
I231209 10:51:56.314196 6988191 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r49/1:/Table/4{6-7}] 1388  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r49:/Table/4{6-7} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n3,s3):2,(n2,s2):3); closed timestamp: 1702118875.096690071,0 (2023-12-09 10:47:55); raft status: {"id":"1","term":46,"vote":"0","commit":623,"lead":"0","raftState":"StatePreCandidate","applied":623,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/46,/Min)
E231209 10:51:56.317396 6988203 kv/kvserver/queue.go:1160  [T1,Vsystem,n2,replicate,s2,r27/2:/Table/2{4-5}] 1389  [n2,s2,r27/2:/Table/2{4-5}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r27:/Table/2{4-5} [(n1,s1):1, (n2,s2):2, next=3, gen=2]: lost quorum (down: (n1,s1):1); closed timestamp: 1702118564.502315883,0 (2023-12-09 10:42:44); raft status: {"id":"2","term":102,"vote":"1","commit":516,"lead":"0","raftState":"StatePreCandidate","applied":516,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/24,/Min)
E231209 10:51:56.348846 6988232 kv/kvserver/queue.go:1160  [T1,Vsystem,n2,replicaGC,s2,r43/2:/Table/4{0-1}] 1390  replica unavailable: (n2,s2):2 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702118861.026609893,0 (2023-12-09 10:47:41); raft status: {"id":"2","term":49,"vote":"3","commit":1106,"lead":"0","raftState":"StateFollower","applied":1106,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Min,/Min)
I231209 10:51:56.353341 6988180 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r23/1:/Table/2{0-1}] 1391  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r23:/Table/2{0-1} [(n1,s1):1, (n2,s2):2, next=3, gen=2]: closed timestamp: 1702118564.502315883,0 (2023-12-09 10:42:44); raft status: {"id":"1","term":116,"vote":"1","commit":456,"lead":"0","raftState":"StateCandidate","applied":456,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/20,/Min)
E231209 10:51:56.354813 6988181 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r27/1:/Table/2{4-5}] 1392  [n1,s1,r27/1:/Table/2{4-5}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r27:/Table/2{4-5} [(n1,s1):1, (n2,s2):2, next=3, gen=2]: closed timestamp: 1702118564.502315883,0 (2023-12-09 10:42:44); raft status: {"id":"1","term":56,"vote":"1","commit":516,"lead":"0","raftState":"StateFollower","applied":516,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/24,/Min)
I231209 10:51:56.360204 6988192 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r50/1:/Table/4{7-8}] 1393  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r50:/Table/4{7-8} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n3,s3):2,(n2,s2):3); closed timestamp: 1702118898.265999330,0 (2023-12-09 10:48:18); raft status: {"id":"1","term":113,"vote":"2","commit":574,"lead":"0","raftState":"StatePreCandidate","applied":574,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/47,/Min)
I231209 10:51:56.362593 6988193 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r52/1:/Table/5{0-1}] 1394  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r52:/Table/5{0-1} [(n1,s1):1, (n2,s2):2, next=4, gen=4]: closed timestamp: 1702118564.268854773,0 (2023-12-09 10:42:44); raft status: {"id":"1","term":61,"vote":"1","commit":488,"lead":"0","raftState":"StateCandidate","applied":488,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/50,/Min)
I231209 10:51:56.376604 6988242 kv/kvserver/replica_rangefeed.go:835  [n1,s1,r59/1:/Table/5{7-8}] 1395  RangeFeed failed to nudge: replica unavailable: (n1,s1):1 unable to serve request to r59:/Table/5{7-8} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n3,s3):2); closed timestamp: 1702118637.018593603,0 (2023-12-09 10:43:57); raft status: {"id":"1","term":167,"vote":"2","commit":484,"lead":"0","raftState":"StatePreCandidate","applied":484,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/57,/Min)
E231209 10:51:56.385746 6988271 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r59/1:/Table/5{7-8}] 1396  [n1,s1,r59/1:/Table/5{7-8}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r59:/Table/5{7-8} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n3,s3):2); closed timestamp: 1702118637.018593603,0 (2023-12-09 10:43:57); raft status: {"id":"1","term":167,"vote":"2","commit":484,"lead":"0","raftState":"StatePreCandidate","applied":484,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/57,/Min)
E231209 10:51:56.388299 6988272 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicaGC,s1,r64/1:/Table/6{2-3}] 1397  replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1702118870.108880817,0 (2023-12-09 10:47:50); raft status: {"id":"1","term":43,"vote":"3","commit":1110,"lead":"0","raftState":"StatePreCandidate","applied":1110,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Min,/Min)
E231209 10:51:56.402514 6988327 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r33/1:/NamespaceTable/{30-Max}] 1398  [n1,s1,r33/1:/NamespaceTable/{30-Max}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r33:/NamespaceTable/{30-Max} [(n1,s1):1, (n2,s2):2, next=3, gen=2]: closed timestamp: 1702118586.987646877,0 (2023-12-09 10:43:06); raft status: {"id":"1","term":64,"vote":"1","commit":518,"lead":"0","raftState":"StatePreCandidate","applied":518,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/NamespaceTable/30,/Min)
E231209 10:51:56.404045 6988392 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r12/1:/Table/{8-9}] 1399  [n1,s1,r12/1:/Table/{8-9}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r12:/Table/{8-9} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n3,s3):2); closed timestamp: 1702118637.018593603,0 (2023-12-09 10:43:57); raft status: {"id":"1","term":53,"vote":"2","commit":559,"lead":"0","raftState":"StatePreCandidate","applied":559,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/8,/Min)
E231209 10:51:56.435919 6988393 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r63/1:/Table/6{1-2}] 1400  [n1,s1,r63/1:/Table/6{1-2}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r63:/Table/6{1-2} [(n1,s1):1, (n3,s3):2, next=4, gen=4]: closed timestamp: 1702118564.502315883,0 (2023-12-09 10:42:44); raft status: {"id":"1","term":84,"vote":"1","commit":489,"lead":"0","raftState":"StatePreCandidate","applied":489,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/61,/Min)
E231209 10:51:56.446223 6988421 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r26/1:/Table/2{3-4}] 1401  [n1,s1,r26/1:/Table/2{3-4}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r26:/Table/2{3-4} [(n1,s1):1, (n2,s2):2, next=3, gen=2]: closed timestamp: 1702118564.268854773,0 (2023-12-09 10:42:44); raft status: {"id":"1","term":24,"vote":"2","commit":527,"lead":"0","raftState":"StateFollower","applied":527,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/23,/Min)
E231209 10:51:56.449026 6988454 kv/kvserver/queue.go:1160  [T1,Vsystem,n2,replicaGC,s2,r34/2:/{NamespaceTab…-Table/32}] 1402  replica unavailable: (n2,s2):2 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702118861.026609893,0 (2023-12-09 10:47:41); raft status: {"id":"2","term":49,"vote":"3","commit":1106,"lead":"0","raftState":"StateFollower","applied":1106,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Min,/Min)
E231209 10:51:56.458224 6988484 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r57/1:/Table/5{5-7}] 1403  [n1,s1,r57/1:/Table/5{5-7}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r57:/Table/5{5-7} [(n1,s1):1, (n2,s2):2, next=3, gen=3]: closed timestamp: 1702118564.502315883,0 (2023-12-09 10:42:44); raft status: {"id":"1","term":18,"vote":"1","commit":543,"lead":"0","raftState":"StateCandidate","applied":543,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/55,/Min)
E231209 10:51:56.483947 6988503 kv/kvserver/queue.go:1160  [T1,Vsystem,n2,merge,s2,r52/2:/Table/5{0-1}] 1404  [n2,s2,r52/2:/Table/5{0-1}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r52:/Table/5{0-1} [(n1,s1):1, (n2,s2):2, next=4, gen=4]: closed timestamp: 1702118564.268854773,0 (2023-12-09 10:42:44); raft status: {"id":"2","term":110,"vote":"1","commit":488,"lead":"0","raftState":"StatePreCandidate","applied":488,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/50,/Min)
E231209 10:51:56.493222 6988556 kv/kvserver/queue.go:1160  [T1,Vsystem,n3,merge,s3,r56/2:/Table/5{4-5}] 1405  [n3,s3,r56/2:/Table/5{4-5}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r56:/Table/5{4-5} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: closed timestamp: 1702118875.096690071,0 (2023-12-09 10:47:55); raft status: {"id":"2","term":25,"vote":"2","commit":629,"lead":"0","raftState":"StateCandidate","applied":629,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/54,/Min)
E231209 10:51:56.519302 6988532 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r32/1:/{Table/29-NamespaceTab…}] 1406  [n1,s1,r32/1:/{Table/29-NamespaceTab…}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r32:/{Table/29-NamespaceTable/30} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n3,s3):2); closed timestamp: 1702118637.018593603,0 (2023-12-09 10:43:57); raft status: {"id":"1","term":125,"vote":"2","commit":509,"lead":"0","raftState":"StatePreCandidate","applied":509,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/29,/Min)
E231209 10:51:56.527397 6988555 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicaGC,s1,r63/1:/Table/6{1-2}] 1407  replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1702118870.108880817,0 (2023-12-09 10:47:50); raft status: {"id":"1","term":43,"vote":"3","commit":1110,"lead":"0","raftState":"StatePreCandidate","applied":1110,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Min,/Min)
E231209 10:51:56.574804 6988557 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r5/1:/{Systemtse-Table/0}] 1408  [n1,s1,r5/1:/{Systemtse-Table/0}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r5:/{Systemtse-Table/0} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: closed timestamp: 1702118661.341883510,0 (2023-12-09 10:44:21); raft status: {"id":"1","term":35,"vote":"1","commit":556,"lead":"0","raftState":"StateCandidate","applied":556,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/System/"tse",/Min)
E231209 10:51:56.593284 6988633 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicaGC,s1,r10/1:/Table/{6-7}] 1409  replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1702118870.108880817,0 (2023-12-09 10:47:50); raft status: {"id":"1","term":43,"vote":"3","commit":1110,"lead":"0","raftState":"StatePreCandidate","applied":1110,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Min,/Min)
E231209 10:51:56.631726 6988672 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r23/1:/Table/2{0-1}] 1410  [n1,s1,r23/1:/Table/2{0-1}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r23:/Table/2{0-1} [(n1,s1):1, (n2,s2):2, next=3, gen=2]: closed timestamp: 1702118564.502315883,0 (2023-12-09 10:42:44); raft status: {"id":"1","term":116,"vote":"1","commit":456,"lead":"0","raftState":"StateCandidate","applied":456,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/20,/Min)
E231209 10:51:56.652310 27803 server/status/recorder.go:595  [T1,Vsystem,n3,summaries] 1411  could not record status summaries: Store 3 could not return descriptor, error: lstat /var/lib/engflow/worker/work/3/exec/_tmp/7ff1d96ba50939140966eb9078b1284a/TestDebugCheckStore3243201223: no such file or directory
W231209 10:51:56.653605 27803 server/node.go:1261  [T1,Vsystem,n3,summaries] 1412  health alerts detected: {Alerts:[{StoreID:0 Category:METRICS Description:liveness.heartbeatfailures Value:3} {StoreID:0 Category:METRICS Description:round-trip-latency-p90 Value:4.067139408291773e+09} {StoreID:0 Category:METRICS Description:timeseries.write.errors Value:1}]}
W231209 10:51:56.676153 25552 kv/kvserver/liveness/liveness.go:752  [T1,Vsystem,n3,liveness-hb] 1414  slow heartbeat took 3.079653906s; err=result is ambiguous: context done during DistSender.Send: ba: ConditionalPut [/System/NodeLiveness/3,/Min), EndTxn(commit modified-span (node-liveness)) [/System/NodeLiveness/3], [txn: 85a212da], [can-forward-ts] RPC error: grpc: context deadline exceeded [code 4/DeadlineExceeded]
W231209 10:51:56.678056 25552 kv/kvserver/liveness/liveness.go:668  [T1,Vsystem,n3,liveness-hb] 1415  failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 3.082s (given timeout 3s): result is ambiguous: context done during DistSender.Send: ba: ConditionalPut [/System/NodeLiveness/3,/Min), EndTxn(commit modified-span (node-liveness)) [/System/NodeLiveness/3], [txn: 85a212da], [can-forward-ts] RPC error: grpc: context deadline exceeded [code 4/DeadlineExceeded]
W231209 10:51:56.678056 25552 kv/kvserver/liveness/liveness.go:668  [T1,Vsystem,n3,liveness-hb] 1415 +
W231209 10:51:56.678056 25552 kv/kvserver/liveness/liveness.go:668  [T1,Vsystem,n3,liveness-hb] 1415 +An inability to maintain liveness will prevent a node from participating in a
W231209 10:51:56.678056 25552 kv/kvserver/liveness/liveness.go:668  [T1,Vsystem,n3,liveness-hb] 1415 +cluster. If this problem persists, it may be a sign of resource starvation or
W231209 10:51:56.678056 25552 kv/kvserver/liveness/liveness.go:668  [T1,Vsystem,n3,liveness-hb] 1415 +of network connectivity problems. For help troubleshooting, visit:
W231209 10:51:56.678056 25552 kv/kvserver/liveness/liveness.go:668  [T1,Vsystem,n3,liveness-hb] 1415 +
W231209 10:51:56.678056 25552 kv/kvserver/liveness/liveness.go:668  [T1,Vsystem,n3,liveness-hb] 1415 +    https://www.cockroachlabs.com/docs/stable/cluster-setup-troubleshooting.html#node-liveness-issues
W231209 10:51:56.692295 286 kv/kvserver/replica_gossip.go:158  [T1,Vsystem,n1,s1,r2/1:/System/NodeLiveness{-Max}] 1416  could not acquire lease for range gossip: replica unavailable: (n1,s1):1 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n3,s3):2,(n2,s2):3); closed timestamp: 1702118899.292235040,0 (2023-12-09 10:48:19); raft status: {"id":"1","term":16,"vote":"2","commit":2755,"lead":"0","raftState":"StatePreCandidate","applied":2755,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/System/NodeLiveness,/Min)
E231209 10:51:56.710653 6988757 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r4/1:/System{/tsd-tse}] 1417  [n1,s1,r4/1:/System{/tsd-tse}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r4:/System{/tsd-tse} [(n1,s1):1, (n3,s3):2, (n2,s2):6LEARNER, next=7, gen=9]: closed timestamp: 1702118792.162256720,0 (2023-12-09 10:46:32); raft status: {"id":"1","term":86,"vote":"1","commit":1067,"lead":"0","raftState":"StatePreCandidate","applied":1067,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/System/tsd,/Min)
E231209 10:51:56.712428 6988815 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r59/1:/Table/5{7-8}] 1418  [n1,s1,r59/1:/Table/5{7-8}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r59:/Table/5{7-8} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n3,s3):2); closed timestamp: 1702118637.018593603,0 (2023-12-09 10:43:57); raft status: {"id":"1","term":167,"vote":"2","commit":484,"lead":"0","raftState":"StatePreCandidate","applied":484,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/57,/Min)
E231209 10:51:56.756314 6988836 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicaGC,s1,r14/1:/Table/1{1-2}] 1419  replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1702118870.108880817,0 (2023-12-09 10:47:50); raft status: {"id":"1","term":43,"vote":"3","commit":1110,"lead":"0","raftState":"StatePreCandidate","applied":1110,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Min,/Min)
E231209 10:51:56.760253 6988846 kv/kvserver/queue.go:1160  [T1,Vsystem,n1,replicate,s1,r52/1:/Table/5{0-1}] 1420  [n1,s1,r52/1:/Table/5{0-1}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r52:/Table/5{0-1} [(n1,s1):1, (n2,s2):2, next=4, gen=4]: closed timestamp: 1702118564.268854773,0 (2023-12-09 10:42:44); raft status: {"id":"1","term":61,"vote":"1","commit":488,"lead":"0","raftState":"StateCandidate","applied":488,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/50,/Min)
--- FAIL: TestDebugCheckStore (2184.88s)

Parameters:

attempt=1
race=true
run=3
shard=8
Help

/cc @cockroachdb/kv @cockroachdb/server _{This test on roachdash | Improve this report!

Jira issue: CRDB-34314}

github.com/cockroachdb/cockroach/pkg/server/node.go:1274 server.(*Node).writeNodeStatus ??? github.com/cockroachdb/cockroach/pkg/server/node.go:1225 server.(*Node).startWriteNodeStatus.func2 ??? github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:484 stop.(*Stopper).RunAsyncTaskEx.func2 ??? goroutine 344767 lock 0xc00afb22e0 github.com/cockroachdb/cockroach/pkg/server/node.go:1765 server.(*lockedMuxStream).Send ??? <<<<< github.com/cockroachdb/cockroach/pkg/server/node.go:1764 server.(*lockedMuxStream).Send ??? github.com/cockroachdb/cockroach/pkg/server/node.go:1751 server.(*setRangeIDEventSink).Send ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:137 kvserver.(*lockedRangefeedStream).Send ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/registry.go:340 rangefeed.(*registration).outputLoop ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/registry.go:361 rangefeed.(*registration).runOutputLoop ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/scheduled_processor.go:360 rangefeed.(*ScheduledProcessor).unregisterClient ??? github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:484 stop.(*Stopper).RunAsyncTaskEx.func2 ??? goroutine 344775 lock 0xc00afb2688 github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:136 kvserver.(*lockedRangefeedStream).Send ??? <<<<< github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:135 kvserver.(*lockedRangefeedStream).Send ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/registry.go:340 rangefeed.(*registration).outputLoop ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/registry.go:361 rangefeed.(*registration).runOutputLoop ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/scheduled_processor.go:360 rangefeed.(*ScheduledProcessor).unregisterClient ??? github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:484 stop.(*Stopper).RunAsyncTaskEx.func2 ??? goroutine 1661185 lock 0xc002bc5a28 github.com/cockroachdb/cockroach/pkg/server/status/recorder.go:631 status.(*MetricsRecorder).WriteNodeStatus ??? <<<<< github.com/cockroachdb/cockroach/pkg/server/status/recorder.go:630 status.(*MetricsRecorder).WriteNodeStatus ??? github.com/cockroachdb/cockroach/pkg/server/node.go:1273 server.(*Node).writeNodeStatus.func1 ??? github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:319 stop.(*Stopper).RunTask ??? github.com/cockroachdb/cockroach/pkg/server/node.go:1274 server.(*Node).writeNodeStatus ??? github.com/cockroachdb/cockroach/pkg/server/node.go:1225 server.(*Node).startWriteNodeStatus.func2 ??? github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:484 stop.(*Stopper).RunAsyncTaskEx.func2 ??? goroutine 344696 lock 0xc00afb2178 github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:136 kvserver.(*lockedRangefeedStream).Send ??? <<<<< github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:135 kvserver.(*lockedRangefeedStream).Send ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/registry.go:340 rangefeed.(*registration).outputLoop ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/registry.go:361 rangefeed.(*registration).runOutputLoop ??? github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed/scheduled_processor.go:360 rangefeed.(*ScheduledProcessor).unregisterClient ??? github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:484 stop.(*Stopper).RunAsyncTaskEx.func2 ??? goroutine 1940196 lock 0xc0060ef0c8 github.com/cockroachdb/cockroach/pkg/server/status/recorder.go:631 status.(*MetricsRecorder).WriteNodeStatus ??? <<<<< github.com/cockroachdb/cockroach/pkg/server/status/recorder.go:630 status.(*MetricsRecorder).WriteNodeStatus ??? github.com/cockroachdb/cockroach/pkg/server/node.go:1273 server.(*Node).writeNodeStatus.func1 ??? github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:319 stop.(*Stopper).RunTask ??? github.com/cockroachdb/cockroach/pkg/server/node.go:1274 server.(*Node).writeNodeStatus ??? github.com/cockroachdb/cockroach/pkg/server/node.go:1225 server.(*Node).startWriteNodeStatus.func2 ??? github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:484 stop.(*Stopper).RunAsyncTaskEx.func2 ???

I231210 09:00:50.939171 1539366 kv/kvserver/store_raft.go:699 [T1,Vsystem,n3,s3,r31/2:/Table/2{8-9},raft] 246 raft ready handling: 1.06s [append=0.00s, apply=0.00s, sync=1.06s, other=0.00s], wrote [append-batch=50 B, ] pebble stats: [commit-wait 1.061204526s sem 180ns]; node might be overloaded E231210 09:00:50.951412 207228239 kv/kvserver/replica_range_lease.go:534 [T1,Vsystem,n2,s2,r49/3:/Table/4{6-7}] 247 failed to increment leaseholder's epoch: replica unavailable: (n2,s2):2 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198735.774625581,0 (2023-12-10 08:58:55); raft status: {"id":"2","term":33,"vote":"3","commit":1382,"lead":"0","raftState":"StatePreCandidate","applied":1382,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/System/NodeLiveness,/Min) W231210 09:00:50.998832 121659322 kv/kvclient/kvcoord/dist_sender.go:1932 [T1,Vsystem,n2,intExec=get-job-row] 248 slow range RPC: have been waiting 580.48s (1 attempts) for RPC Scan [/Table/15/1/104,/Table/15/1/105), [txn: 7570fff1], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 22651] to r18:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, next=3, gen=2]; resp: (err: <nil>), *kvpb.ScanResponse W231210 09:00:51.000461 121659471 kv/kvclient/kvcoord/dist_sender.go:1932 [T1,Vsystem,n2,intExec=get-job-row] 249 slow range RPC: have been waiting 580.32s (1 attempts) for RPC Scan [/Table/15/1/101,/Table/15/1/102), [txn: ac4662bf], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 22651] to r18:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, next=3, gen=2]; resp: (err: <nil>), *kvpb.ScanResponse W231210 09:00:51.001856 121659489 kv/kvclient/kvcoord/dist_sender.go:1932 [T1,Vsystem,n2,intExec=get-job-row] 250 slow range RPC: have been waiting 580.49s (1 attempts) for RPC Scan [/Table/15/1/102,/Table/15/1/103), [txn: 33ce431a], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 22651] to r18:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, next=3, gen=2]; resp: (err: <nil>), *kvpb.ScanResponse E231210 09:00:51.018605 226138392 kv/kvserver/queue.go:1160 [T1,Vsystem,n1,replicaGC,s1,r29/1:/Table/2{6-7}] 251 replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"1","term":25,"vote":"1","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Min,/Min) W231210 09:00:51.175975 121659434 kv/kvclient/kvcoord/dist_sender.go:1932 [T1,Vsystem,n2,intExec=get-job-row] 252 slow range RPC: have been waiting 580.52s (1 attempts) for RPC Scan [/Table/15/1/924474528556089345,/Table/15/1/924474528556089346), [txn: 64037f0e], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 22651] to r18:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, next=3, gen=2]; resp: (err: <nil>), *kvpb.ScanResponse I231210 09:00:51.303069 36653 kv/kvserver/replica_rangefeed.go:808 [T1,Vsystem,n1,s1,r6/1:/Table/{0-4}] 253 RangeFeed closed timestamp 1702198739.469921238,0 is behind by 1m51.833138006s W231210 09:00:51.306683 1346419 kv/kvserver/replica_gossip.go:158 [T1,Vsystem,n2,s2,r1/2:/{Min-System/NodeL…}] 254 could not acquire lease for range gossip: replica unavailable: (n2,s2):2 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"2","term":21,"vote":"0","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Min,/Min) I231210 09:00:51.428651 1539401 kv/kvserver/store_raft.go:699 [T1,Vsystem,n3,s3,r23/3:/Table/2{0-1},raft] 255 raft ready handling: 1.55s [append=0.00s, apply=0.00s, sync=1.55s, other=0.00s], wrote [append-batch=49 B, ] pebble stats: [commit-wait 1.550369852s sem 190ns]; node might be overloaded I231210 09:00:51.429084 1539422 kv/kvserver/replica_raft.go:1571 [T1,Vsystem,n3,s3,r34/2:/{NamespaceTab…-Table/32},raft] 256 slow non-blocking raft commit: commit-wait 1.291048477s sem 100ns I231210 09:00:51.429524 1539376 kv/kvserver/store_raft.go:699 [T1,Vsystem,n3,s3,r27/2:/Table/2{4-5},raft] 257 raft ready handling: 1.55s [append=0.00s, apply=0.00s, sync=1.55s, other=0.00s], wrote [append-batch=49 B, ] pebble stats: [commit-wait 1.550892661s sem 100ns]; node might be overloaded I231210 09:00:51.429913 1539396 kv/kvserver/store_raft.go:699 [T1,Vsystem,n3,s3,r10/3:/Table/{6-7},raft] 258 raft ready handling: 1.55s [append=0.00s, apply=0.00s, sync=1.55s, other=0.00s], wrote [append-batch=49 B, ] pebble stats: [commit-wait 1.55107923s sem 111ns]; node might be overloaded I231210 09:00:51.430407 1539391 kv/kvserver/store_raft.go:699 [T1,Vsystem,n3,s3,r18/3:/Table/1{5-6},raft] 259 raft ready handling: 1.34s [append=0.00s, apply=0.00s, sync=1.34s, other=0.00s], wrote [append-batch=50 B, ] pebble stats: [commit-wait 1.338170693s sem 110ns]; node might be overloaded I231210 09:00:51.430753 225205946 kv/kvserver/replica_rangefeed.go:835 [n1,s1,r6/1:/Table/{0-4}] 260 RangeFeed failed to nudge: retry rangefeed (REASON_NO_LEASEHOLDER) I231210 09:00:51.431081 1539371 kv/kvserver/store_raft.go:699 [T1,Vsystem,n3,s3,r9/3:/Table/{5-6},raft] 261 raft ready handling: 1.34s [append=0.00s, apply=0.00s, sync=1.34s, other=0.00s], wrote [append-batch=49 B, ] pebble stats: [commit-wait 1.335903038s sem 130ns]; node might be overloaded I231210 09:00:51.432360 1539386 kv/kvserver/store_raft.go:699 [T1,Vsystem,n3,s3,r4/3:/System{/tsd-tse},raft] 262 raft ready handling: 1.29s [append=0.00s, apply=0.00s, sync=1.29s, other=0.00s], wrote [append-batch=50 B, ] pebble stats: [commit-wait 1.28945462s sem 270ns]; node might be overloaded I231210 09:00:51.432781 1539381 kv/kvserver/store_raft.go:699 [T1,Vsystem,n3,s3,r16/2:/Table/1{3-4},raft] 263 raft ready handling: 1.29s [append=0.00s, apply=0.00s, sync=1.29s, other=0.00s], wrote [append-batch=50 B, ] pebble stats: [commit-wait 1.28949275s sem 110ns]; node might be overloaded I231210 09:00:51.434428 225207096 kv/kvserver/replica_rangefeed.go:835 [n1,s1,r49/1:/Table/4{6-7}] 264 RangeFeed failed to nudge: retry rangefeed (REASON_NO_LEASEHOLDER) W231210 09:00:51.449129 36557 kv/kvserver/replica_gossip.go:158 [T1,Vsystem,n1,s1,r1/1:/{Min-System/NodeL…}] 265 could not acquire lease for range gossip: replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"1","term":25,"vote":"1","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Min,/Min) W231210 09:00:51.455486 1539730 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n3,liveness-hb] 266 failed node liveness heartbeat: replica unavailable: (n3,s3):3 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198738.625683534,0 (2023-12-10 08:58:58); raft status: {"id":"3","term":37,"vote":"3","commit":1386,"lead":"3","raftState":"StateLeader","applied":1386,"progress":{"1":{"match":0,"next":1396,"state":"StateProbe"},"2":{"match":0,"next":1396,"state":"StateProbe"},"3":{"match":1397,"next":1398,"state":"StateReplicate"}},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/System/NodeLiveness,/Min) W231210 09:00:51.455486 1539730 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n3,liveness-hb] 266 + W231210 09:00:51.455486 1539730 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n3,liveness-hb] 266 +An inability to maintain liveness will prevent a node from participating in a W231210 09:00:51.455486 1539730 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n3,liveness-hb] 266 +cluster. If this problem persists, it may be a sign of resource starvation or W231210 09:00:51.455486 1539730 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n3,liveness-hb] 266 +of network connectivity problems. For help troubleshooting, visit: W231210 09:00:51.455486 1539730 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n3,liveness-hb] 266 + W231210 09:00:51.455486 1539730 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n3,liveness-hb] 266 + https://www.cockroachlabs.com/docs/stable/cluster-setup-troubleshooting.html#node-liveness-issues W231210 09:00:51.525666 1539337 kv/kvserver/replica_gossip.go:158 [T1,Vsystem,n3,s3,r2/3:/System/NodeLiveness{-Max}] 267 could not acquire lease for range gossip: replica unavailable: (n3,s3):3 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198738.625683534,0 (2023-12-10 08:58:58); raft status: {"id":"3","term":37,"vote":"3","commit":1386,"lead":"3","raftState":"StateLeader","applied":1386,"progress":{"1":{"match":0,"next":1396,"state":"StateProbe"},"2":{"match":0,"next":1396,"state":"StateProbe"},"3":{"match":1397,"next":1398,"state":"StateReplicate"}},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/System/NodeLiveness,/Min) E231210 09:00:51.636345 226268556 kv/kvserver/queue.go:1160 [T1,Vsystem,n2,replicaGC,s2,r22/2:/Table/{19-20}] 268 replica unavailable: (n2,s2):2 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"2","term":21,"vote":"0","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Min,/Min) W231210 09:00:51.640076 1346424 kv/kvserver/replica_gossip.go:158 [T1,Vsystem,n2,s2,r2/2:/System/NodeLiveness{-Max}] 269 could not acquire lease for range gossip: replica unavailable: (n2,s2):2 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198735.774625581,0 (2023-12-10 08:58:55); raft status: {"id":"2","term":33,"vote":"3","commit":1382,"lead":"0","raftState":"StatePreCandidate","applied":1382,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/System/NodeLiveness,/Min) E231210 09:00:51.760865 226154106 kv/kvserver/queue.go:1160 [T1,Vsystem,n1,replicaGC,s1,r17/1:/Table/1{4-5}] 270 replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"1","term":25,"vote":"1","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Min,/Min) E231210 09:00:51.762015 226297858 kv/kvserver/queue.go:1160 [T1,Vsystem,n1,replicaGC,s1,r40/1:/Table/3{7-8}] 271 replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"1","term":25,"vote":"1","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Min,/Min) E231210 09:00:51.806404 226303859 kv/kvserver/queue.go:1160 [T1,Vsystem,n2,replicate,s2,r1/2:/{Min-System/NodeL…}] 272 [n2,s2,r1/2:/{Min-System/NodeL…}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"2","term":21,"vote":"0","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Min,/Min) E231210 09:00:51.813986 226305545 kv/kvserver/queue.go:1160 [T1,Vsystem,n2,replicate,s2,r2/2:/System/NodeLiveness{-Max}] 273 [n2,s2,r2/2:/System/NodeLiveness{-Max}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198735.774625581,0 (2023-12-10 08:58:55); raft status: {"id":"2","term":33,"vote":"3","commit":1382,"lead":"0","raftState":"StatePreCandidate","applied":1382,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/System/NodeLiveness,/Min) I231210 09:00:51.830372 226032931 gossip/client.go:133 [T1,Vsystem,n3] 274 closing client to n1 (127.0.0.1:36487): stopping outgoing client to n1 (127.0.0.1:36487); already have incoming E231210 09:00:51.863327 226309060 kv/kvserver/queue.go:1160 [T1,Vsystem,n1,replicaGC,s1,r36/1:/Table/3{3-4}] 275 replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"1","term":25,"vote":"1","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Min,/Min) W231210 09:00:52.003144 1346963 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n2,liveness-hb] 276 failed node liveness heartbeat: replica unavailable: (n2,s2):2 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198735.774625581,0 (2023-12-10 08:58:55); raft status: {"id":"2","term":33,"vote":"3","commit":1382,"lead":"0","raftState":"StatePreCandidate","applied":1382,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/System/NodeLiveness,/Min) W231210 09:00:52.003144 1346963 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n2,liveness-hb] 276 + W231210 09:00:52.003144 1346963 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n2,liveness-hb] 276 +An inability to maintain liveness will prevent a node from participating in a W231210 09:00:52.003144 1346963 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n2,liveness-hb] 276 +cluster. If this problem persists, it may be a sign of resource starvation or W231210 09:00:52.003144 1346963 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n2,liveness-hb] 276 +of network connectivity problems. For help troubleshooting, visit: W231210 09:00:52.003144 1346963 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n2,liveness-hb] 276 + W231210 09:00:52.003144 1346963 kv/kvserver/liveness/liveness.go:668 [T1,Vsystem,n2,liveness-hb] 276 + https://www.cockroachlabs.com/docs/stable/cluster-setup-troubleshooting.html#node-liveness-issues E231210 09:00:52.042035 226292695 kv/kvserver/queue.go:1160 [T1,Vsystem,n2,replicaGC,s2,r37/2:/Table/3{4-5}] 277 replica unavailable: (n2,s2):2 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"2","term":21,"vote":"0","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Min,/Min) W231210 09:00:52.078046 226116189 kv/kvserver/liveness/liveness.go:752 [T1,Vsystem,n3,s3,r3/3:/System/{NodeLive…-tsd}] 278 slow heartbeat took 1.277375453s; err=replica unavailable: (n3,s3):3 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198738.625683534,0 (2023-12-10 08:58:58); raft status: {"id":"3","term":37,"vote":"3","commit":1386,"lead":"3","raftState":"StateLeader","applied":1386,"progress":{"1":{"match":0,"next":1396,"state":"StateProbe"},"2":{"match":0,"next":1396,"state":"StateProbe"},"3":{"match":1397,"next":1398,"state":"StateReplicate"}},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/System/NodeLiveness,/Min) W231210 09:00:52.081761 226138790 kv/kvserver/liveness/liveness.go:752 [T1,Vsystem,n3,s3,r6/2:/Table/{0-4}] 279 slow heartbeat took 1.149422181s; err=replica unavailable: (n3,s3):3 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1702198738.625683534,0 (2023-12-10 08:58:58); raft status: {"id":"3","term":37,"vote":"3","commit":1386,"lead":"3","raftState":"StateLeader","applied":1386,"progress":{"1":{"match":0,"next":1396,"state":"StateProbe"},"2":{"match":0,"next":1396,"state":"StateProbe"},"3":{"match":1397,"next":1398,"state":"StateReplicate"}},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/System/NodeLiveness,/Min) E231210 09:00:52.096857 226327308 kv/kvserver/queue.go:1160 [T1,Vsystem,n2,replicate,s2,r1/2:/{Min-System/NodeL…}] 280 [n2,s2,r1/2:/{Min-System/NodeL…}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198740.627642722,0 (2023-12-10 08:59:00); raft status: {"id":"2","term":21,"vote":"0","commit":902,"lead":"0","raftState":"StatePreCandidate","applied":902,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Min,/Min) E231210 09:00:52.099788 226327790 kv/kvserver/queue.go:1160 [T1,Vsystem,n2,replicate,s2,r2/2:/System/NodeLiveness{-Max}] 281 [n2,s2,r2/2:/System/NodeLiveness{-Max}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1702198735.774625581,0 (2023-12-10 08:58:55); raft status: {"id":"2","term":33,"vote":"3","commit":1382,"lead":"0","raftState":"StatePreCandidate","applied":1382,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/System/NodeLiveness,/Min) I231210 09:00:52.117533 226327841 gossip/client.go:124 [T1,Vsystem,n3] 282 started gossip client to n0 (127.0.0.1:36487) --- FAIL: TestDebugCheckStore (1216.44s)

cockroachdb / cockroach

cli: TestDebugCheckStore failed #115938