Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

pkg/server/application_api/application_api_test: TestAdminAPITableStats failed #123937

Closed
cockroach-teamcity opened this issue May 10, 2024 · 3 comments · Fixed by #124590
Closed

pkg/server/application_api/application_api_test: TestAdminAPITableStats failed #123937

cockroach-teamcity opened this issue May 10, 2024 · 3 comments · Fixed by #124590
Assignees
@dhartunian
Labels
branch-master Failures on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-observability

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented May 10, 2024 •
edited by cockroach-jira-scripts

pkg/server/application_api/application_api_test.TestAdminAPITableStats failed on master @ 16d41751607b92234351c1ab27053c3875a4f2b7:

Fatal error:

panic: test timed out after 14m57s
running tests:
	TestAdminAPITableStats (14m50s)

Stack:

goroutine 5983272 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2366 +0x385
created by time.goFunc
	GOROOT/src/time/sleep.go:177 +0x2d
Log preceding fatal error 

=== RUN   TestAdminAPITableStats
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestAdminAPITableStats1531336558
    test_log_scope.go:81: use -show-logs to present logs inline
    test_server_shim.go:157: automatically injected a shared process virtual cluster under test; see comment at top of test_server_shim.go for details.

Parameters:

  • attempt=1
  • run=12
  • shard=3
Help

See also: How To Investigate a Go Test Failure (internal)

Same failure on other branches

/cc @cockroachdb/unowned

This test on roachdash | Improve this report!

Jira issue: CRDB-38611
@cockroach-teamcity cockroach-teamcity added branch-master Failures on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. labels May 10, 2024
@cockroach-teamcity
Copy link
Member Author

pkg/server/application_api/application_api_test.TestAdminAPITableStats failed on master @ d8073b58467ddb4c5b2ebe4a485fc42fb98f7200:

=== RUN   TestAdminAPITableStats
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestAdminAPITableStats746859104
    test_log_scope.go:81: use -show-logs to present logs inline
    test_server_shim.go:157: automatically injected an external process virtual cluster under test; see comment at top of test_server_shim.go for details.
    testcluster.go:486: polling for queued jobs to complete: poll-show-jobs: aborted in DistSender: result is ambiguous: node unavailable; try another peer
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestAdminAPITableStats746859104
--- FAIL: TestAdminAPITableStats (587.68s)

Parameters:

  • attempt=1
  • run=22
  • shard=3
Help

See also: How To Investigate a Go Test Failure (internal)

Same failure on other branches

This test on roachdash | Improve this report!

@cockroach-teamcity cockroach-teamcity mentioned this issue May 17, 2024
Closed
@cockroach-teamcity
Copy link
Member Author

pkg/server/application_api/application_api_test.TestAdminAPITableStats failed on master @ 93ad913106b6f0f6ec98bc2cfa788ff6d8085bd4:

E240518 04:29:36.111633 5258202 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r6/1:/Table/{0-4}] 1847  [n1,s1,r6/1:/Table/{0-4}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r6:/Table/{0-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=5]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":7,"vote":"2","commit":50,"lead":"0","raftState":"StatePreCandidate","applied":50,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/0]
I240518 04:29:36.114803 3067376 sql/catalog/lease/storage.go:273  [n1,replication-reporter,intExec=timestamp-upsert-replication-constraint-stats] 1848  retryable replica error occurred during lease acquisition for 28, retrying: replica unavailable: (n1,s1):1 unable to serve request to r6:/Table/{0-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=5]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":7,"vote":"2","commit":50,"lead":"0","raftState":"StatePreCandidate","applied":50,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/0]
E240518 04:29:36.116339 5258263 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r27/2:/Table/2{4-5}] 1849  [n3,s3,r27/2:/Table/2{4-5}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r27:/Table/2{4-5} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):3); closed timestamp: 1716006329.099432125,0 (2024-05-18 04:25:29); raft status: {"id":"2","term":7,"vote":"2","commit":53,"lead":"0","raftState":"StatePreCandidate","applied":53,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/24]
E240518 04:29:36.117117 5258274 kv/kvserver/queue.go:1202  [T1,Vsystem,n2,lease,s2,r65/2:/Table/6{3-4}] 1850  [n2,s2,r65/2:/Table/6{3-4}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r65:/Table/6{3-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"2","term":11,"vote":"1","commit":46,"lead":"0","raftState":"StatePreCandidate","applied":46,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Table/63]
E240518 04:29:36.121368 5258308 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r28/1:/Table/2{5-6}] 1851  [n1,s1,r28/1:/Table/2{5-6}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r28:/Table/2{5-6} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1716006329.784651167,0 (2024-05-18 04:25:29); raft status: {"id":"1","term":9,"vote":"2","commit":53,"lead":"0","raftState":"StatePreCandidate","applied":53,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/25]
I240518 04:29:36.125149 7063 kv/kvserver/liveness/liveness.go:1077  [T1,Vsystem,n1,liveness-hb] 1852  retrying liveness update after liveness.errRetryLiveness: result is ambiguous: error=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]: closed timestamp: 1716006336.681459510,0 (2024-05-18 04:25:36); raft status: {"id":"1","term":8,"vote":"2","commit":141,"lead":"0","raftState":"StatePreCandidate","applied":141,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/System/NodeLiveness] [exhausted] (last error: failed to connect to n2 at 127.0.0.1:43435: initial connection heartbeat failed: grpc: connection error: desc = "error reading server preface: read tcp 127.0.0.1:53590->127.0.0.1:43435: use of closed network connection" [code 14/Unavailable])
I240518 04:29:36.127047 4468142 sql/catalog/lease/storage.go:273  [n1,intExec=protectedts-GetMetadata] 1853  retryable replica error occurred during lease acquisition for 31, retrying: replica unavailable: (n1,s1):1 unable to serve request to r6:/Table/{0-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=5]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":7,"vote":"2","commit":50,"lead":"0","raftState":"StatePreCandidate","applied":50,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/0]
E240518 04:29:36.129667 5258319 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,replicate,s1,r4/1:/System{/tsd-tse}] 1854  [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, (n2,s2):2, next=3, gen=2]: lost quorum (down: (n2,s2):2); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":8,"vote":"2","commit":109,"lead":"0","raftState":"StatePreCandidate","applied":109,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/System/tsd]
E240518 04:29:36.130544 5258320 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r39/2:/Table/3{6-7}] 1855  [n3,s3,r39/2:/Table/3{6-7}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r39:/Table/3{6-7} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"2","term":10,"vote":"3","commit":46,"lead":"0","raftState":"StatePreCandidate","applied":46,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Table/36]
E240518 04:29:36.131109 5258321 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r28/3:/Table/2{5-6}] 1856  [n3,s3,r28/3:/Table/2{5-6}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r28:/Table/2{5-6} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):2); closed timestamp: 1716006338.693321574,0 (2024-05-18 04:25:38); raft status: {"id":"3","term":8,"vote":"3","commit":53,"lead":"0","raftState":"StatePreCandidate","applied":53,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/25]
E240518 04:29:36.131642 5258322 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r25/2:/Table/2{2-3}] 1857  [n3,s3,r25/2:/Table/2{2-3}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r25:/Table/2{2-3} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):3); closed timestamp: 1716006336.970442789,0 (2024-05-18 04:25:36); raft status: {"id":"2","term":7,"vote":"2","commit":50,"lead":"0","raftState":"StatePreCandidate","applied":50,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/22]
E240518 04:29:36.132149 5258323 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r18/2:/Table/1{5-6}] 1858  [n3,s3,r18/2:/Table/1{5-6}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r18:/Table/1{5-6} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: closed timestamp: 1716006329.099432125,0 (2024-05-18 04:25:29); raft status: {"id":"2","term":8,"vote":"0","commit":112,"lead":"0","raftState":"StateFollower","applied":112,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/15]
E240518 04:29:36.132675 5258324 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r9/3:/Table/{5-6}] 1859  [n3,s3,r9/3:/Table/{5-6}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r9:/Table/{5-6} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"3","term":8,"vote":"3","commit":63,"lead":"0","raftState":"StatePreCandidate","applied":63,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/5]
E240518 04:29:36.133180 5258325 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r10/2:/Table/{6-7}] 1860  [n3,s3,r10/2:/Table/{6-7}]: could not obtain lease: replica unavailable: (n3,s3):2 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: (n1,s1):1,(n2,s2):3); closed timestamp: 1716006342.631679839,0 (2024-05-18 04:25:42); raft status: {"id":"2","term":7,"vote":"2","commit":55,"lead":"0","raftState":"StatePreCandidate","applied":55,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Table/6]
E240518 04:29:36.133682 5258326 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r6/3:/Table/{0-4}] 1861  [n3,s3,r6/3:/Table/{0-4}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r6:/Table/{0-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=5]: closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"3","term":9,"vote":"3","commit":50,"lead":"0","raftState":"StatePreCandidate","applied":50,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Table/0]
E240518 04:29:36.134198 5258327 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r20/2:/Table/1{7-8}] 1862  [n3,s3,r20/2:/Table/1{7-8}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r20:/Table/1{7-8} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"2","term":10,"vote":"2","commit":47,"lead":"0","raftState":"StatePreCandidate","applied":47,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/17]
E240518 04:29:36.134738 5258328 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r1/3:/{Min-System/NodeL…}] 1863  [n3,s3,r1/3:/{Min-System/NodeL…}]: could not obtain lease: replica unavailable: (n3,s3):3 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,(n2,s2):2); closed timestamp: 1716006332.716857194,0 (2024-05-18 04:25:32); raft status: {"id":"3","term":7,"vote":"3","commit":629,"lead":"0","raftState":"StatePreCandidate","applied":629,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Min]
E240518 04:29:36.135248 5258329 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r67/3:/Table/6{5-6}] 1864  [n3,s3,r67/3:/Table/6{5-6}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r67:/Table/6{5-6} [(n1,s1):1, (n3,s3):3, (n2,s2):5, next=6, gen=10]: lost quorum (down: (n1,s1):1,(n2,s2):5); closed timestamp: 1716006336.970442789,0 (2024-05-18 04:25:36); raft status: {"id":"3","term":7,"vote":"3","commit":73,"lead":"0","raftState":"StatePreCandidate","applied":73,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/65]
E240518 04:29:36.135776 5258330 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r24/2:/Table/2{1-2}] 1865  [n3,s3,r24/2:/Table/2{1-2}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r24:/Table/2{1-2} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):3); closed timestamp: 1716006331.200952098,0 (2024-05-18 04:25:31); raft status: {"id":"2","term":8,"vote":"2","commit":58,"lead":"0","raftState":"StatePreCandidate","applied":58,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/21]
E240518 04:29:36.136275 5258331 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r37/2:/Table/3{4-5}] 1866  [n3,s3,r37/2:/Table/3{4-5}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r37:/Table/3{4-5} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: closed timestamp: 1716006329.099432125,0 (2024-05-18 04:25:29); raft status: {"id":"2","term":8,"vote":"0","commit":53,"lead":"0","raftState":"StateFollower","applied":53,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/34]
E240518 04:29:36.136791 5258332 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r42/3:/Table/{39-40}] 1867  [n3,s3,r42/3:/Table/{39-40}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r42:/Table/{39-40} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1716006334.670766171,0 (2024-05-18 04:25:34); raft status: {"id":"3","term":8,"vote":"3","commit":95,"lead":"0","raftState":"StatePreCandidate","applied":95,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/39]
E240518 04:29:36.137331 5258333 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r46/3:/Table/4{3-4}] 1868  [n3,s3,r46/3:/Table/4{3-4}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r46:/Table/4{3-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):2); closed timestamp: 1716006334.672355200,0 (2024-05-18 04:25:34); raft status: {"id":"3","term":12,"vote":"2","commit":52,"lead":"0","raftState":"StatePreCandidate","applied":52,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/43]
E240518 04:29:36.137885 5258334 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r48/2:/Table/4{5-6}] 1869  [n3,s3,r48/2:/Table/4{5-6}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r48:/Table/4{5-6} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):3); closed timestamp: 1716006329.784651167,0 (2024-05-18 04:25:29); raft status: {"id":"2","term":10,"vote":"3","commit":51,"lead":"0","raftState":"StatePreCandidate","applied":51,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/45]
E240518 04:29:36.138465 5258335 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r16/3:/Table/1{3-4}] 1870  [n3,s3,r16/3:/Table/1{3-4}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r16:/Table/1{3-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):2); closed timestamp: 1716006335.369702818,0 (2024-05-18 04:25:35); raft status: {"id":"3","term":7,"vote":"3","commit":343,"lead":"0","raftState":"StatePreCandidate","applied":343,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Table/13]
E240518 04:29:36.138950 5258336 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r11/2:/Table/{7-8}] 1871  [n3,s3,r11/2:/Table/{7-8}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r11:/Table/{7-8} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: closed timestamp: 1716006342.631679839,0 (2024-05-18 04:25:42); raft status: {"id":"2","term":7,"vote":"2","commit":58,"lead":"0","raftState":"StatePreCandidate","applied":58,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/7]
E240518 04:29:36.140562 5258347 kv/kvserver/queue.go:1202  [T1,Vsystem,n2,lease,s2,r5/2:/{Systemtse-Table/0}] 1872  [n2,s2,r5/2:/{Systemtse-Table/0}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r5:/{Systemtse-Table/0} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"2","term":11,"vote":"1","commit":48,"lead":"0","raftState":"StatePreCandidate","applied":48,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/System/"tse"]
E240518 04:29:36.142809 5258368 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r50/1:/Table/4{7-8}] 1873  [n1,s1,r50/1:/Table/4{7-8}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r50:/Table/4{7-8} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1716006331.200952098,0 (2024-05-18 04:25:31); raft status: {"id":"1","term":7,"vote":"2","commit":57,"lead":"0","raftState":"StateFollower","applied":57,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/47]
E240518 04:29:36.144306 5258389 kv/kvserver/queue.go:1202  [T1,Vsystem,n2,replicaGC,s2,r54/2:/Table/5{2-5}] 1874  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: 1716006332.716857194,0 (2024-05-18 04:25:32); raft status: {"id":"2","term":6,"vote":"0","commit":629,"lead":"0","raftState":"StatePreCandidate","applied":629,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Min]
E240518 04:29:36.144893 5258392 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r15/2:/Table/1{2-3}] 1875  [n3,s3,r15/2:/Table/1{2-3}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r15:/Table/1{2-3} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):3); closed timestamp: 1716006336.970442789,0 (2024-05-18 04:25:36); raft status: {"id":"2","term":7,"vote":"2","commit":88,"lead":"0","raftState":"StatePreCandidate","applied":88,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Table/12]
E240518 04:29:36.146240 5258393 kv/kvserver/queue.go:1202  [T1,Vsystem,n2,lease,s2,r27/3:/Table/2{4-5}] 1876  [n2,s2,r27/3:/Table/2{4-5}]: could not obtain lease: replica unavailable: (n2,s2):3 unable to serve request to r27:/Table/2{4-5} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):2); closed timestamp: 1716006329.099432125,0 (2024-05-18 04:25:29); raft status: {"id":"3","term":9,"vote":"1","commit":53,"lead":"0","raftState":"StatePreCandidate","applied":53,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/24]
E240518 04:29:36.151031 5258414 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r31/1:/Table/2{8-9}] 1877  [n1,s1,r31/1:/Table/2{8-9}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r31:/Table/2{8-9} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n3,s3):2,(n2,s2):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":8,"vote":"1","commit":47,"lead":"0","raftState":"StatePreCandidate","applied":47,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/28]
E240518 04:29:36.151658 5258415 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r63/1:/Table/6{1-2}] 1878  [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, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1716006330.200386888,0 (2024-05-18 04:25:30); raft status: {"id":"1","term":11,"vote":"1","commit":52,"lead":"0","raftState":"StatePreCandidate","applied":52,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/61]
E240518 04:29:36.154032 5258449 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r38/3:/Table/3{5-6}] 1879  [n3,s3,r38/3:/Table/3{5-6}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r38:/Table/3{5-6} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):2); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"3","term":10,"vote":"3","commit":47,"lead":"0","raftState":"StatePreCandidate","applied":47,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/35]
E240518 04:29:36.155065 5258470 kv/kvserver/queue.go:1202  [T1,Vsystem,n2,lease,s2,r53/2:/Table/5{1-2}] 1880  [n2,s2,r53/2:/Table/5{1-2}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r53:/Table/5{1-2} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):3); closed timestamp: 1716006332.045021993,0 (2024-05-18 04:25:32); raft status: {"id":"2","term":9,"vote":"2","commit":50,"lead":"0","raftState":"StatePreCandidate","applied":50,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/51]
E240518 04:29:36.157424 5258512 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r11/1:/Table/{7-8}] 1881  [n1,s1,r11/1:/Table/{7-8}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r11:/Table/{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: 1716006336.970442789,0 (2024-05-18 04:25:36); raft status: {"id":"1","term":10,"vote":"1","commit":56,"lead":"0","raftState":"StatePreCandidate","applied":56,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/7]
E240518 04:29:36.161460 5258584 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r47/2:/Table/4{4-5}] 1882  [n3,s3,r47/2:/Table/4{4-5}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r47:/Table/4{4-5} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n1,s1):1); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"2","term":7,"vote":"2","commit":41,"lead":"0","raftState":"StatePreCandidate","applied":41,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/44]
E240518 04:29:36.162001 5258585 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r36/3:/Table/3{3-4}] 1883  [n3,s3,r36/3:/Table/3{3-4}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r36:/Table/3{3-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n2,s2):2); closed timestamp: 1716006338.693321574,0 (2024-05-18 04:25:38); raft status: {"id":"3","term":9,"vote":"3","commit":56,"lead":"0","raftState":"StatePreCandidate","applied":56,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal RequestLease [/Table/33]
E240518 04:29:36.164334 5258471 kv/kvserver/queue.go:1202  [T1,Vsystem,n2,lease,s2,r15/3:/Table/1{2-3}] 1884  [n2,s2,r15/3:/Table/1{2-3}]: could not obtain lease: replica unavailable: (n2,s2):3 unable to serve request to r15:/Table/1{2-3} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):2); closed timestamp: 1716006336.970442789,0 (2024-05-18 04:25:36); raft status: {"id":"3","term":16,"vote":"0","commit":88,"lead":"0","raftState":"StatePreCandidate","applied":88,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/12]
--- FAIL: TestAdminAPITableStats (324.44s)
E240518 04:29:36.181035 5258646 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r20/1:/Table/1{7-8}] 1885  [n1,s1,r20/1:/Table/1{7-8}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r20:/Table/1{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: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":9,"vote":"3","commit":47,"lead":"0","raftState":"StatePreCandidate","applied":47,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/17]
E240518 04:29:36.181758 5258647 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r9/1:/Table/{5-6}] 1886  [n1,s1,r9/1:/Table/{5-6}]: could not obtain lease: 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]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":8,"vote":"2","commit":63,"lead":"0","raftState":"StatePreCandidate","applied":63,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/5]
E240518 04:29:36.182322 5258648 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r62/1:/Table/6{0-1}] 1887  [n1,s1,r62/1:/Table/6{0-1}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r62:/Table/6{0-1} [(n1,s1):1, (n2,s2):3, next=4, gen=6]: lost quorum (down: (n2,s2):3); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":7,"vote":"1","commit":51,"lead":"0","raftState":"StatePreCandidate","applied":51,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/60]
E240518 04:29:36.182860 5258649 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,lease,s1,r52/1:/Table/5{0-1}] 1888  [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):3, (n3,s3):4, next=5, gen=8]: lost quorum (down: (n2,s2):3,(n3,s3):4); closed timestamp: 1716006336.715475019,0 (2024-05-18 04:25:36); raft status: {"id":"1","term":6,"vote":"1","commit":60,"lead":"0","raftState":"StatePreCandidate","applied":60,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/50]
E240518 04:29:36.183665 5258650 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,replicaGC,s3,r26/2:/Table/2{3-4}] 1889  replica unavailable: (n3,s3):3 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,(n2,s2):2); closed timestamp: 1716006332.716857194,0 (2024-05-18 04:25:32); raft status: {"id":"3","term":7,"vote":"3","commit":629,"lead":"0","raftState":"StatePreCandidate","applied":629,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Min]
E240518 04:29:36.185636 5258651 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,replicate,s3,r41/2:/Table/3{8-9}] 1890  [n3,s3,r41/2:/Table/3{8-9}]: could not obtain lease: replica unavailable: (n3,s3):2 unable to serve request to r41:/Table/3{8-9} [(n1,s1):1, (n3,s3):2, next=3, gen=2]: lost quorum (down: (n1,s1):1); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"2","term":7,"vote":"1","commit":41,"lead":"0","raftState":"StatePreCandidate","applied":41,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/38]
E240518 04:29:36.190800 5258653 kv/kvserver/queue.go:1202  [T1,Vsystem,n1,replicate,s1,r19/1:/Table/1{6-7}] 1891  [n1,s1,r19/1:/Table/1{6-7}]: could not obtain lease: replica unavailable: (n1,s1):1 unable to serve request to r19:/Table/1{6-7} [(n1,s1):1, (n2,s2):2, next=3, gen=2]: lost quorum (down: (n2,s2):2); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"1","term":8,"vote":"2","commit":41,"lead":"0","raftState":"StatePreCandidate","applied":41,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/16]
E240518 04:29:36.192042 5258654 kv/kvserver/queue.go:1202  [T1,Vsystem,n3,lease,s3,r43/3:/Table/4{0-1}] 1892  [n3,s3,r43/3:/Table/4{0-1}]: could not obtain lease: replica unavailable: (n3,s3):3 unable to serve request to r43:/Table/4{0-1} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]: closed timestamp: 1716006330.200386888,0 (2024-05-18 04:25:30); raft status: {"id":"3","term":10,"vote":"3","commit":52,"lead":"0","raftState":"StatePreCandidate","applied":52,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/40]
W240518 04:29:36.192863 15494 kv/kvserver/replica_gossip.go:158  [T1,Vsystem,n3,s3,r1/3:/{Min-System/NodeL…}] 1893  could not acquire lease for range gossip: replica unavailable: (n3,s3):3 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,(n2,s2):2); closed timestamp: 1716006332.716857194,0 (2024-05-18 04:25:32); raft status: {"id":"3","term":7,"vote":"3","commit":629,"lead":"0","raftState":"StatePreCandidate","applied":629,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Min]
E240518 04:29:36.197783 5258695 kv/kvserver/queue.go:1202  [T1,Vsystem,n2,lease,s2,r11/3:/Table/{7-8}] 1894  [n2,s2,r11/3:/Table/{7-8}]: could not obtain lease: replica unavailable: (n2,s2):3 unable to serve request to r11:/Table/{7-8} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=4]: lost quorum (down: (n1,s1):1,(n3,s3):2); closed timestamp: 1716006342.631679839,0 (2024-05-18 04:25:42); raft status: {"id":"3","term":10,"vote":"1","commit":58,"lead":"0","raftState":"StatePreCandidate","applied":58,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Table/7]
E240518 04:29:36.198276 5258696 kv/kvserver/queue.go:1202  [T1,Vsystem,n2,lease,s2,r69/2:/Table/{19-20}] 1895  [n2,s2,r69/2:/Table/{19-20}]: could not obtain lease: replica unavailable: (n2,s2):2 unable to serve request to r69:/Table/{19-20} [(n1,s1):1, (n2,s2):2, next=3, gen=4]: lost quorum (down: (n1,s1):1); closed timestamp: 1716006328.672629530,0 (2024-05-18 04:25:28); raft status: {"id":"2","term":7,"vote":"2","commit":39,"lead":"0","raftState":"StatePreCandidate","applied":39,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/Table/19]

Parameters:

  • attempt=1
  • run=1
  • shard=3
Help

See also: How To Investigate a Go Test Failure (internal)

Same failure on other branches

This test on roachdash | Improve this report!

@github-actions GitHub Actions
Copy link

pkg/server/application_api/application_api_test.TestAdminAPITableStats failed on master @ ceb19c5b75cf4aa02c68a669122349a3e9aca33d:

=== RUN   TestAdminAPITableStats
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestAdminAPITableStats4146859682
    test_log_scope.go:81: use -show-logs to present logs inline
    test_server_shim.go:157: automatically injected an external process virtual cluster under test; see comment at top of test_server_shim.go for details.
    schema_inspection_test.go:504: create-auth-user: job 970417249938276353 could not be loaded: load-job-query: replica unavailable: (n1,s1):1 unable to serve request to r73:/Tenant/10/Table/{12-25} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=9]: lost quorum (down: (n2,s2):2,(n3,s3):3); closed timestamp: 1716218275.726128730,0 (2024-05-20 15:17:55); raft status: {"id":"1","term":13,"vote":"1","commit":115,"lead":"0","raftState":"StatePreCandidate","applied":115,"progress":{},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal RequestLease [/Tenant/10/Table/12]
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestAdminAPITableStats4146859682
--- FAIL: TestAdminAPITableStats (270.45s)

Parameters:

  • attempt=1
  • run=1
  • shard=3
Help

See also: How To Investigate a Go Test Failure (internal)

Same failure on other branches

This test on roachdash | Improve this report!

@xinhaoz xinhaoz removed the release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. label May 22, 2024
@dhartunian dhartunian mentioned this issue May 22, 2024
Merged
@dhartunian dhartunian self-assigned this May 22, 2024
craig bot pushed a commit that referenced this issue May 24, 2024
@dhartunian
Merge #124590
9918a74 
124590: server: remove custom ScanInterval args in test r=kyle-a-wong a=dhartunian

These args might be causing undesired behavior in this test that causes loss of quorum. I believe they're here to make the test fast, but we'd prefer a less flaky one even if it's a bit slow.

Resolves #123937

Release note: None

Co-authored-by: David Hartunian <davidh@cockroachlabs.com>
@craig craig bot closed this as completed in f1b92fa May 24, 2024
blathers-crl bot pushed a commit that referenced this issue May 24, 2024
@dhartunian
server: remove custom ScanInterval args in test
7bd3699 
These args might be causing undesired behavior in this test that
causes loss of quorum. I believe they're here to make the test fast,
but we'd prefer a less flaky one even if it's a bit slow.

Resolves #123937

Release note: None
@blathers-crl blathers-crl bot mentioned this issue May 24, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dhartunian dhartunian

Labels
branch-master Failures on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-observability
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

server: remove custom ScanInterval args in test dhartunian/cockroach
3 participants
@dhartunian @xinhaoz @cockroach-teamcity