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

teamcity: failed test: TestInitialPartitioning #41862

Closed
cockroach-teamcity opened this issue Oct 23, 2019 · 0 comments · Fixed by #41880
Closed

teamcity: failed test: TestInitialPartitioning #41862

cockroach-teamcity opened this issue Oct 23, 2019 · 0 comments · Fixed by #41880
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
19.2

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed on master (testrace): TestInitialPartitioning, TestInitialPartitioning/oid_table, TestInitialPartitioning/time_table

You may want to check for open issues.

#1555171:

TestInitialPartitioning/time_table
...n1,client=127.0.0.1:37330,user=root] planning ends
              [n1,client=127.0.0.1:37330,user=root] checking distributability
              [n1,client=127.0.0.1:37330,user=root] will distribute plan: true
              [n1,client=127.0.0.1:37330,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:37330,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:37330,user=root] querying next range at /Table/90/1/70864787051
              [n1,client=127.0.0.1:37330,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.2 KiB
            cockroach.streamid: 1
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 17.488ms
              [n3] starting scan with limitBatches false
               === SPAN START: [async] drain ===
               === SPAN START: flow ===
              [n1,client=127.0.0.1:37330,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n3] Consumer sent handshake. Consuming flow scheduled: true
              [n3] Scan /Table/90/1/70864787051{-/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n3,txn=651fa751] querying next range at /Table/90/1/70864787051
              [n3,txn=651fa751] r282: sending batch 1 Scan to (n3,s3):1
              [n3,txn=651fa751] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n3] 1 Scan
              [n3,s3] executing 1 requests
              [n3,s3,r282/1:/Table/90/1/7086478705{1-2}] read-only path
              [n3,s3,r282/1:/Table/90/1/7086478705{1-2}] acquire latches
              [n3,s3,r282/1:/Table/90/1/7086478705{1-2}] waited 67.734µs to acquire latches
              [n3,s3,r282/1:/Table/90/1/7086478705{1-2}] waiting for read lock
              [n3,s3,r282/1:/Table/90/1/7086478705{1-2}] read completed
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 387µs
              [n1,client=127.0.0.1:37330,user=root] execution ends
              [n1,client=127.0.0.1:37330,user=root] rows affected: 1
              [n1,client=127.0.0.1:37330,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:37330,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:37330,user=root] [NoTxn pos:16669] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:37330,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1017066 [running]:
            runtime/debug.Stack(0xc003b71e60, 0x6722540, 0xc0049171a0)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816840, 0xc003d6de00, 0xc003b71e60)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc003d6de00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc003d6de00, 0xc004865980)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning
...):2LEARNER] remove []): existing descriptor r13:/Table/1{7-8} [(n1,s1):1, next=2, gen=0]
I191023 15:33:30.771566 3193 storage/replica_raft.go:291  [n1,s1,r13/1:/Table/1{7-8}] proposing ADD_REPLICA[(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I191023 15:33:30.833179 23943 storage/raft_snapshot_queue.go:125  [n1,raftsnapshot,s1,r13/1:/Table/1{7-8}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I191023 15:33:30.838719 3193 storage/store_snapshot.go:978  [n1,replicate,s1,r13/1:/Table/1{7-8}] sending LEARNER snapshot 50c023ed at applied index 17
I191023 15:33:30.841037 3193 storage/store_snapshot.go:1021  [n1,replicate,s1,r13/1:/Table/1{7-8}] streamed snapshot to (n3,s3):2LEARNER: kv pairs: 6, log entries: 0, rate-limit: 8.0 MiB/sec, 0.04s
I191023 15:33:30.843449 23958 storage/replica_raftstorage.go:794  [n3,s3,r13/2:{-}] applying LEARNER snapshot [id=50c023ed index=17]
I191023 15:33:30.851622 23958 storage/replica_raftstorage.go:815  [n3,s3,r13/2:/Table/1{7-8}] applied LEARNER snapshot [total=8ms ingestion=4@6ms id=50c023ed index=17]
I191023 15:33:30.877071 3193 storage/replica_command.go:1586  [n1,replicate,s1,r13/1:/Table/1{7-8}] change replicas (add [(n3,s3):2] remove []): existing descriptor r13:/Table/1{7-8} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I191023 15:33:30.914140 3193 storage/replica_raft.go:291  [n1,s1,r13/1:/Table/1{7-8}] proposing ADD_REPLICA[(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I191023 15:33:30.920251 3193 storage/replica_command.go:1586  [n1,replicate,s1,r13/1:/Table/1{7-8}] change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r13:/Table/1{7-8} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I191023 15:33:30.999792 3193 storage/replica_raft.go:291  [n1,s1,r13/1:/Table/1{7-8}] proposing ADD_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I191023 15:33:31.031430 3193 storage/store_snapshot.go:978  [n1,replicate,s1,r13/1:/Table/1{7-8}] sending LEARNER snapshot a1f11959 at applied index 22
I191023 15:33:31.032395 3193 storage/store_snapshot.go:1021  [n1,replicate,s1,r13/1:/Table/1{7-8}] streamed snapshot to (n2,s2):3LEARNER: kv pairs: 10, log entries: 0, rate-limit: 8.0 MiB/sec, 0.02s
I191023 15:33:31.047785 24326 storage/replica_raftstorage.go:794  [n2,s2,r13/3:{-}] applying LEARNER snapshot [id=a1f11959 index=22]
I191023 15:33:31.056949 24255 storage/raft_snapshot_queue.go:125  [n1,raftsnapshot,s1,r13/1:/Table/1{7-8}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):3LEARNER
I191023 15:33:31.064360 24326 storage/replica_raftstorage.go:815  [n2,s2,r13/3:/Table/1{7-8}] applied LEARNER snapshot [total=15ms ingestion=4@8ms id=a1f11959 index=22]
I191023 15:33:31.069614 3193 storage/replica_command.go:1586  [n1,replicate,s1,r13/1:/Table/1{7-8}] change replicas (add [(n2,s2):3] remove []): existing descriptor r13:/Table/1{7-8} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I191023 15:33:31.133057 3193 storage/replica_raft.go:291  [n1,s1,r13/1:/Table/1{7-8}] proposing ADD_REPLICA[(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I191023 15:33:31.159291 3193 storage/queue.go:1134  [n1,replicate] purgatory is now empty
I191023 15:33:31.205379 2718 testutils/testcluster/testcluster.go:747  WaitForFullReplication took: 11.994357815s
I191023 15:33:31.358080 4433 sql/event_log.go:132  [n1,client=127.0.0.1:37330,user=root] Event: "create_database", target: 52, info: {DatabaseName:data Statement:CREATE DATABASE data User:root}
I191023 15:33:31.509368 4433 sql/event_log.go:132  [n1,client=127.0.0.1:37330,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:server.declined_reservation_timeout Value:00:00:00 User:root}
I191023 15:33:31.615365 4433 sql/event_log.go:132  [n1,client=127.0.0.1:37330,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:server.failed_reservation_timeout Value:00:00:00 User:root}



TestInitialPartitioning/oid_table
...nd RPC: leaseholder s1 (via (n3,s3):1) not in cached replicas [(n3,s3):1]
              [n3,txn=3fe2126c] evicting range descriptor on *roachpb.SendError and backoff for re-lookup: r268:/Table/87/{1/1336527720-2} [(n3,s3):1, next=2, gen=226]
              [n3,txn=3fe2126c] evicting cached range descriptor
              [n3] Consumer sent handshake. Consuming flow scheduled: false
              [n3] Consumer sent handshake. Consuming flow scheduled: true
               === SPAN START: range lookup ===
               === SPAN START: dist sender send ===
              [n3,txn=3fe2126c,range-lookup=/Table/87/1/1336527720] querying next range at /Meta2/Table/87/1/1336527720/NULL
              [n3,txn=3fe2126c,range-lookup=/Table/87/1/1336527720] r1: sending batch 1 Scan to (n2,s2):3
              [n3,txn=3fe2126c,range-lookup=/Table/87/1/1336527720] sending request to 127.0.0.1:35105
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r1/3:/{Min-System/NodeL…}] read-only path
              [n2,s2,r1/3:/{Min-System/NodeL…}] acquire latches
              [n2,s2,r1/3:/{Min-System/NodeL…}] operation accepts inconsistent results
              [n2,s2,r1/3:/{Min-System/NodeL…}] waiting for read lock
              [n2,s2,r1/3:/{Min-System/NodeL…}] read completed
              [n3,txn=3fe2126c] looked up range descriptor: r268:/Table/87/{1/1336527720-2} [(n3,s3):1, (n1,s1):2, next=3, gen=228]
              [n3,txn=3fe2126c] r268: sending batch 1 Scan to (n1,s1):2
              [n3,txn=3fe2126c] sending request to 127.0.0.1:40629
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] 1 Scan
              [n1,s1] executing 1 requests
              [n1,s1,r268/2:/Table/87/{1/13365…-2}] read-only path
              [n1,s1,r268/2:/Table/87/{1/13365…-2}] read has no clock uncertainty
              [n1,s1,r268/2:/Table/87/{1/13365…-2}] acquire latches
              [n1,s1,r268/2:/Table/87/{1/13365…-2}] waited 128.862µs to acquire latches
              [n1,s1,r268/2:/Table/87/{1/13365…-2}] waiting for read lock
              [n1,s1,r268/2:/Table/87/{1/13365…-2}] read completed
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 708µs
              [n1,client=127.0.0.1:37330,user=root] execution ends
              [n1,client=127.0.0.1:37330,user=root] rows affected: 1
              [n1,client=127.0.0.1:37330,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:37330,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:37330,user=root] [NoTxn pos:15256] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:37330,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 857563 [running]:
            runtime/debug.Stack(0xc006001c80, 0x6722540, 0xc003ce2180)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816840, 0xc005a74f00, 0xc006001c80)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc005a74f00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc005a74f00, 0xc005236e40)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Oct 23, 2019
@cockroach-teamcity cockroach-teamcity added this to the 19.2 milestone Oct 23, 2019
andreimatei added a commit to andreimatei/cockroach that referenced this issue Oct 23, 2019
@andreimatei
all: Revert cockroachdb#39722
0cf7360 
This reverts commit 0b0c71f, reversing
changes made to 9b36103.

Reverting "config,sqlbase: move computation of splits for SQL tables to
sqlbase". It seems to have caused TestInitialPartitioning and
TestRepartitioning to timeout often when run under testrace on TC (only
when the build runs on the master branch and these tests are run in
conjunction with all the other packages). I don't know what's wrong yet.

Fixes cockroachdb#41812
Fixes cockroachdb#41821
Fixes cockroachdb#41825
Fixes cockroachdb#41831
Fixes cockroachdb#41835
Fixes cockroachdb#41843
Fixes cockroachdb#41846
Fixes cockroachdb#41850
Fixes cockroachdb#41862
Fixes cockroachdb#41874
Fixes cockroachdb#41879

Fixes cockroachdb#41652
Fixes cockroachdb#41813
Fixes cockroachdb#41822
Fixes cockroachdb#41826
Fixes cockroachdb#41832
Fixes cockroachdb#41836
Fixes cockroachdb#41844
Fixes cockroachdb#41847
Fixes cockroachdb#41851
Fixes cockroachdb#41868
Fixes cockroachdb#41875

Release note: None
@andreimatei andreimatei mentioned this issue Oct 23, 2019
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
19.2
Development

Successfully merging a pull request may close this issue.

all: Revert #39722 andreimatei/cockroach
1 participant
@cockroach-teamcity