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 #41835

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

teamcity: failed test: TestInitialPartitioning #41835

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/date_table, TestInitialPartitioning/list-range_partitioning, TestInitialPartitioning/interval_table, TestInitialPartitioning, TestInitialPartitioning/int_table, TestInitialPartitioning/varbit_table, TestInitialPartitioning/secondary_index_-list_partitioning-_DEFAULT, TestInitialPartitioning/timestamptz_table, TestInitialPartitioning/time_table, TestInitialPartitioning/inet_table, TestInitialPartitioning/timestamp_table, TestInitialPartitioning/collatedstring{en}_table, TestInitialPartitioning/scans, TestInitialPartitioning/oid_table

You may want to check for open issues.

#1554080:

TestInitialPartitioning/oid_table
....oid_table' to table collection
              [n1,client=127.0.0.1:48344,user=root] query cache hit
              [n1,client=127.0.0.1:48344,user=root] planning ends
              [n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/87/1/1018102105
              [n1,client=127.0.0.1:48344,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: [async] drain ===
               === SPAN START: flow ===
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 25.35ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/87/{1/1018102105-2}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=41ef914a] querying next range at /Table/87/1/1018102105
              [n2,txn=41ef914a] r253: sending batch 1 Scan to (n2,s2):1
              [n2,txn=41ef914a] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r253/1:/{Table/87/1/1…-Max}] read-only path
              [n2,s2,r253/1:/{Table/87/1/1…-Max}] acquire latches
              [n2,s2,r253/1:/{Table/87/1/1…-Max}] waited 86.477µs to acquire latches
              [n2,s2,r253/1:/{Table/87/1/1…-Max}] waiting for read lock
              [n2,s2,r253/1:/{Table/87/1/1…-Max}] 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: 579µs
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:16420] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1207128 [running]:
            runtime/debug.Stack(0xc0057a9050, 0x6722520, 0xc0062c6620)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc00100ec00, 0xc0057a9050)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc00100ec00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc00100ec00, 0xc004222150)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/interval_table
...      [n1,client=127.0.0.1:48344,user=root] planning ends
              [n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/83/1/-5 years -8 mons -823 days -46:21:06.876517
              [n1,client=127.0.0.1:48344,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 4.653ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/83/{1/-5 years -8 mons -823 days -46:21:06.876517-2}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=98828f30] querying next range at /Table/83/1/-5 years -8 mons -823 days -46:21:06.876517
              [n2,txn=98828f30] r234: sending batch 1 Scan to (n2,s2):1
               === SPAN START: flow ===
              [n2,txn=98828f30] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
              [n2] 1 Scan
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2,s2] executing 1 requests
              [n2,s2,r234/1:/Table/83/{1/-5 ye…-2}] read-only path
              [n2,s2,r234/1:/Table/83/{1/-5 ye…-2}] acquire latches
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.3 KiB
            cockroach.streamid: 1
              [n2,s2,r234/1:/Table/83/{1/-5 ye…-2}] waited 134.125µs to acquire latches
              [n2,s2,r234/1:/Table/83/{1/-5 ye…-2}] waiting for read lock
              [n2,s2,r234/1:/Table/83/{1/-5 ye…-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: 587µs
               === SPAN START: [async] drain ===
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:14240] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1028984 [running]:
            runtime/debug.Stack(0xc00242e0c0, 0x6722520, 0xc005986200)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc000ecdf00, 0xc00242e0c0)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc000ecdf00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc000ecdf00, 0xc00601cf00)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/varbit_table
...to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2,s2] executing 1 requests
              [n2,s2,r273/1:/Table/91/1/B0001000101101101…] read-only path
              [n2,s2,r273/1:/Table/91/1/B0001000101101101…] acquire latches
              [n2,s2,r273/1:/Table/91/1/B0001000101101101…] waited 108.41µs to acquire latches
              [n2,s2,r273/1:/Table/91/1/B0001000101101101…] waiting for read lock
              [n2,s2,r273/1:/Table/91/1/B0001000101101101…] replica.Send got error: key range /Table/91/1/B000100010110110110001001010-/Table/91/2 outside of bounds of range /Table/91/1/B00010001011011011000100101-/Table/91/1/B000100010110110110001001010
              [n2] *roachpb.RangeKeyMismatchError
              [n2,txn=4a614812] reply error [txn: 4a614812], Scan [/Table/91/1/B000100010110110110001001010,/Table/91/2): key range /Table/91/1/B000100010110110110001001010-/Table/91/2 outside of bounds of range /Table/91/1/B00010001011011011000100101-/Table/91/1/B000100010110110110001001010
              [n2,txn=4a614812] evicting cached range descriptor with 2 replacements
              [n2,txn=4a614812] likely split; resending batch to span: key range /Table/91/1/B000100010110110110001001010-/Table/91/2 outside of bounds of range /Table/91/1/B00010001011011011000100101-/Table/91/1/B000100010110110110001001010
              [n2,txn=4a614812] querying next range at /Table/91/1/B000100010110110110001001010
              [n2,txn=4a614812] r274: sending batch 1 Scan to (n2,s2):1
              [n2,txn=4a614812] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r274/1:/{Table/91/1/B…-Max}] read-only path
              [n2,s2,r274/1:/{Table/91/1/B…-Max}] acquire latches
              [n2,s2,r274/1:/{Table/91/1/B…-Max}] waited 100.948µs to acquire latches
              [n2,s2,r274/1:/{Table/91/1/B…-Max}] waiting for read lock
              [n2,s2,r274/1:/{Table/91/1/B…-Max}] 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: 778µs
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:18636] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1403315 [running]:
            runtime/debug.Stack(0xc003a526c0, 0x6722520, 0xc003fa5b40)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc003ee6e00, 0xc003a526c0)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc003ee6e00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc003ee6e00, 0xc001c038c0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/list-range_partitioning
...103,0
              [n2] *roachpb.NotLeaseHolderError
              [n2,txn=0f934408] reply error [txn: 0f934408], Scan [/Table/72/1/6,/Table/72/2): failed to send RPC: leaseholder s1 (via (n2,s2):1) not in cached replicas [(n2,s2):1]
              [n2,txn=0f934408] evicting range descriptor on *roachpb.SendError and backoff for re-lookup: r171:/Table/72/{1/6-2} [(n2,s2):1, next=2, gen=129]
              [n2,txn=0f934408] evicting cached range descriptor
              [n2] Consumer sent handshake. Consuming flow scheduled: true
               === SPAN START: range lookup ===
               === SPAN START: dist sender send ===
              [n2,txn=0f934408,range-lookup=/Table/72/1/6] querying next range at /Meta2/Table/72/1/6/NULL
              [n2,txn=0f934408,range-lookup=/Table/72/1/6] r1: sending batch 1 Scan to (n3,s3):2
              [n2,txn=0f934408,range-lookup=/Table/72/1/6] sending request to 127.0.0.1:38513
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n3] 1 Scan
              [n3,s3] executing 1 requests
              [n3,s3,r1/2:/{Min-System/NodeL…}] read-only path
              [n3,s3,r1/2:/{Min-System/NodeL…}] acquire latches
              [n3,s3,r1/2:/{Min-System/NodeL…}] operation accepts inconsistent results
              [n3,s3,r1/2:/{Min-System/NodeL…}] waiting for read lock
              [n3,s3,r1/2:/{Min-System/NodeL…}] read completed
              [n2,txn=0f934408] looked up range descriptor: r171:/Table/72/{1/6-2} [(n2,s2):1, (n1,s1):2, next=3, gen=131]
              [n2,txn=0f934408] r171: sending batch 1 Scan to (n1,s1):2
              [n2,txn=0f934408] sending request to 127.0.0.1:42259
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] 1 Scan
              [n1,s1] executing 1 requests
              [n1,s1,r171/2:/Table/72/{1/6-2}] read-only path
              [n1,s1,r171/2:/Table/72/{1/6-2}] read has no clock uncertainty
              [n1,s1,r171/2:/Table/72/{1/6-2}] acquire latches
              [n1,s1,r171/2:/Table/72/{1/6-2}] waited 78.606µs to acquire latches
              [n1,s1,r171/2:/Table/72/{1/6-2}] waiting for read lock
              [n1,s1,r171/2:/Table/72/{1/6-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: 990µs
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:7778] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 503466 [running]:
            runtime/debug.Stack(0xc0052304b0, 0x6722520, 0xc00627cc80)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc003d70700, 0xc0052304b0)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc003d70700)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc003d70700, 0xc004a591a0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/collatedstring{en}_table
...n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/92/1
              [n1,client=127.0.0.1:48344,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 14.064ms
              [n2] starting scan with limitBatches true
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.4 KiB
            cockroach.streamid: 1
              [n2] Scan /Table/92/1{-/"\x8e\x8c\xae\x8c\xe9\xf7\x90\x98Y\x93_\v\x88ʼn\x93\xa4\x80\x00\x00\x00 \x00 \x00 \x00 \x00 \x00 \x00\x00\x02\x02\x02\x02\x02\x02"}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=211fe98c] querying next range at /Table/92/1
               === SPAN START: [async] drain ===
              [n2,txn=211fe98c] r277: sending batch 1 Scan to (n2,s2):1
              [n2,txn=211fe98c] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: flow ===
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r277/1:/Table/92/1{-/"\x8e\…}] read-only path
              [n2,s2,r277/1:/Table/92/1{-/"\x8e\…}] acquire latches
              [n2,s2,r277/1:/Table/92/1{-/"\x8e\…}] waited 497.343µs to acquire latches
              [n2,s2,r277/1:/Table/92/1{-/"\x8e\…}] waiting for read lock
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n2,s2,r277/1:/Table/92/1{-/"\x8e\…}] 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: 692µs
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:19103] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1455098 [running]:
            runtime/debug.Stack(0xc004fb5890, 0x6722520, 0xc005462940)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc001f26400, 0xc004fb5890)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc001f26400)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc001f26400, 0xc005c33770)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/inet_table
...       [n1,client=127.0.0.1:48344,user=root] planning ends
              [n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/89/1/"\x015gxZ>\b\xa9C\xe8\n\x87`\xee1\x95\xad\x11"
              [n1,client=127.0.0.1:48344,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.3 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: 11.557ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/89/{1/"\x015gxZ>\b\xa9C\xe8\n\x87`\xee1\x95\xad\x11"-2}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=0f99c3cc] querying next range at /Table/89/1/"\x015gxZ>\b\xa9C\xe8\n\x87`\xee1\x95\xad\x11"
              [n2,txn=0f99c3cc] r264: sending batch 1 Scan to (n2,s2):1
              [n2,txn=0f99c3cc] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r264/1:/{Table/89/1/"…-Max}] read-only path
              [n2,s2,r264/1:/{Table/89/1/"…-Max}] acquire latches
               === SPAN START: flow ===
              [n2,s2,r264/1:/{Table/89/1/"…-Max}] waited 84.279µs to acquire latches
              [n2,s2,r264/1:/{Table/89/1/"…-Max}] waiting for read lock
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2,s2,r264/1:/{Table/89/1/"…-Max}] 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: 557µs
               === SPAN START: [async] drain ===
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:17534] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1302453 [running]:
            runtime/debug.Stack(0xc0043e89c0, 0x6722520, 0xc0062241a0)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc002a1ea00, 0xc0043e89c0)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc002a1ea00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc002a1ea00, 0xc003b608d0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning
...5/1:/{Systemtse-Table/System…}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):2LEARNER
I191022 23:35:36.380494 3041 storage/store_snapshot.go:1021  [n1,replicate,s1,r5/1:/{Systemtse-Table/System…}] streamed snapshot to (n2,s2):2LEARNER: kv pairs: 7, log entries: 0, rate-limit: 8.0 MiB/sec, 0.15s
I191022 23:35:36.398718 31976 storage/replica_raftstorage.go:794  [n2,s2,r5/2:{-}] applying LEARNER snapshot [id=ebc45dd0 index=18]
I191022 23:35:36.445332 31976 storage/replica_raftstorage.go:815  [n2,s2,r5/2:/{Systemtse-Table/System…}] applied LEARNER snapshot [total=46ms ingestion=4@27ms id=ebc45dd0 index=18]
I191022 23:35:36.454744 3041 storage/replica_command.go:1586  [n1,replicate,s1,r5/1:/{Systemtse-Table/System…}] change replicas (add [(n2,s2):2] remove []): existing descriptor r5:/{Systemtse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=1]
I191022 23:35:36.596796 3041 storage/replica_raft.go:291  [n1,s1,r5/1:/{Systemtse-Table/System…}] proposing ADD_REPLICA[(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I191022 23:35:36.650440 3041 storage/replica_command.go:1586  [n1,replicate,s1,r5/1:/{Systemtse-Table/System…}] change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r5:/{Systemtse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n2,s2):2, next=3, gen=2]
I191022 23:35:36.810101 3041 storage/replica_raft.go:291  [n1,s1,r5/1:/{Systemtse-Table/System…}] proposing ADD_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
I191022 23:35:36.845457 32686 storage/raft_snapshot_queue.go:125  [n1,raftsnapshot,s1,r5/1:/{Systemtse-Table/System…}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):3LEARNER
I191022 23:35:36.853459 3041 storage/store_snapshot.go:978  [n1,replicate,s1,r5/1:/{Systemtse-Table/System…}] sending LEARNER snapshot 65542334 at applied index 24
I191022 23:35:36.855355 3041 storage/store_snapshot.go:1021  [n1,replicate,s1,r5/1:/{Systemtse-Table/System…}] streamed snapshot to (n3,s3):3LEARNER: kv pairs: 11, log entries: 0, rate-limit: 8.0 MiB/sec, 0.02s
I191022 23:35:36.864088 32667 storage/replica_raftstorage.go:794  [n3,s3,r5/3:{-}] applying LEARNER snapshot [id=65542334 index=24]
I191022 23:35:36.896181 32667 storage/replica_raftstorage.go:815  [n3,s3,r5/3:/{Systemtse-Table/System…}] applied LEARNER snapshot [total=29ms ingestion=4@25ms id=65542334 index=24]
I191022 23:35:36.931950 3041 storage/replica_command.go:1586  [n1,replicate,s1,r5/1:/{Systemtse-Table/System…}] change replicas (add [(n3,s3):3] remove []): existing descriptor r5:/{Systemtse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, next=4, gen=3]
I191022 23:35:36.933298 7514 server/status/runtime.go:498  [n3] runtime stats: 679 MiB RSS, 760 goroutines, 51 MiB/61 MiB/136 MiB GO alloc/idle/total, 84 MiB/124 MiB CGO alloc/total, 2193.0 CGO/sec, 173.3/19.2 %(u/s)time, 0.9 %gc (9x), 3.3 MiB/3.3 MiB (r/w)net
I191022 23:35:37.039477 3041 storage/replica_raft.go:291  [n1,s1,r5/1:/{Systemtse-Table/System…}] proposing ADD_REPLICA[(n3,s3):3]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I191022 23:35:37.181844 3041 storage/queue.go:1134  [n1,replicate] purgatory is now empty
I191022 23:35:37.290759 2631 testutils/testcluster/testcluster.go:747  WaitForFullReplication took: 19.112194213s
I191022 23:35:37.815741 4562 sql/event_log.go:132  [n1,client=127.0.0.1:48344,user=root] Event: "create_database", target: 52, info: {DatabaseName:data Statement:CREATE DATABASE data User:root}
I191022 23:35:38.107975 4562 sql/event_log.go:132  [n1,client=127.0.0.1:48344,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:server.declined_reservation_timeout Value:00:00:00 User:root}
I191022 23:35:38.376070 4562 sql/event_log.go:132  [n1,client=127.0.0.1:48344,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:server.failed_reservation_timeout Value:00:00:00 User:root}



TestInitialPartitioning/date_table
...ient=127.0.0.1:48344,user=root] planning ends
              [n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/81/1
              [n1,client=127.0.0.1:48344,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: 14.857ms
               === SPAN START: [async] drain ===
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/81/1{-/8672/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=3edfa912] querying next range at /Table/81/1
              [n2,txn=3edfa912] r222: sending batch 1 Scan to (n2,s2):1
              [n2,txn=3edfa912] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: flow ===
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r222/1:/Table/81/1{-/8673}] read-only path
              [n2,s2,r222/1:/Table/81/1{-/8673}] acquire latches
              [n2,s2,r222/1:/Table/81/1{-/8673}] waited 103.309µs to acquire latches
              [n2,s2,r222/1:/Table/81/1{-/8673}] waiting for read lock
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2,s2,r222/1:/Table/81/1{-/8673}] 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: 490µs
              [n2] Consumer sent handshake. Consuming flow scheduled: false
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:12916] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 917390 [running]:
            runtime/debug.Stack(0xc002f47d40, 0x6722520, 0xc0058576e0)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc004763700, 0xc002f47d40)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc004763700)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc004763700, 0xc006b56450)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/timestamp_table
...r=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/82/1/0001-01-01T00:00:00.000001Z
              [n1,client=127.0.0.1:48344,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.3 KiB
            cockroach.streamid: 1
               === SPAN START: [async] drain ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 9.278ms
              [n2] starting scan with limitBatches true
              [n2] Consumer sent handshake. Consuming flow scheduled: false
               === SPAN START: flow ===
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2] Scan /Table/82/{1/0001-01-01T00:00:00.000001Z-2}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=46ebae0f] querying next range at /Table/82/1/0001-01-01T00:00:00.000001Z
              [n2,txn=46ebae0f] r229: sending batch 1 Scan to (n2,s2):1
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n2,txn=46ebae0f] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r229/1:/Table/82/{1/0001-…-2}] read-only path
              [n2,s2,r229/1:/Table/82/{1/0001-…-2}] acquire latches
              [n2,s2,r229/1:/Table/82/{1/0001-…-2}] waited 88.745µs to acquire latches
              [n2,s2,r229/1:/Table/82/{1/0001-…-2}] waiting for read lock
              [n2,s2,r229/1:/Table/82/{1/0001-…-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: 396µs
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:13569] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 973415 [running]:
            runtime/debug.Stack(0xc001d60660, 0x6722520, 0xc00587b660)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc004635000, 0xc001d60660)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc004635000)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc004635000, 0xc001803a70)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/time_table
...:48344,user=root] query cache hit
              [n1,client=127.0.0.1:48344,user=root] planning ends
              [n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/90/1
              [n1,client=127.0.0.1:48344,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: [async] drain ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 8.034ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/90/1{-/18098619701/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=ad91ac11] querying next range at /Table/90/1
              [n2,txn=ad91ac11] r267: sending batch 1 Scan to (n2,s2):1
              [n2,txn=ad91ac11] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
               === SPAN START: flow ===
              [n2,s2,r267/1:/Table/90/1{-/180986…}] read-only path
              [n2,s2,r267/1:/Table/90/1{-/180986…}] acquire latches
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
              [n2,s2,r267/1:/Table/90/1{-/180986…}] waited 100.148µs to acquire latches
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2,s2,r267/1:/Table/90/1{-/180986…}] waiting for read lock
              [n2,s2,r267/1:/Table/90/1{-/180986…}] read completed
              [n2] Consumer sent handshake. Consuming flow scheduled: true
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 717µs
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:18121] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1350768 [running]:
            runtime/debug.Stack(0xc0035747e0, 0x6722520, 0xc005b6c1a0)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc004762e00, 0xc0035747e0)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc004762e00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc004762e00, 0xc006b57350)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/int_table
...ry cache hit but needed update
              [n1,client=127.0.0.1:48344,user=root] planning ends
              [n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/78/1/32768
              [n1,client=127.0.0.1:48344,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 5.24ms
              [n2] starting scan with limitBatches true
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.2 KiB
            cockroach.streamid: 1
              [n2] Scan /Table/78/{1/32768-2}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=64e44a97] querying next range at /Table/78/1/32768
               === SPAN START: flow ===
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
               === SPAN START: [async] drain ===
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2,txn=64e44a97] r209: sending batch 1 Scan to (n2,s2):1
              [n2,txn=64e44a97] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r209/1:/Table/78/{1/32767…-2}] read-only path
              [n2,s2,r209/1:/Table/78/{1/32767…-2}] acquire latches
              [n2,s2,r209/1:/Table/78/{1/32767…-2}] waited 180.781µs to acquire latches
              [n2,s2,r209/1:/Table/78/{1/32767…-2}] waiting for read lock
              [n2,s2,r209/1:/Table/78/{1/32767…-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: 609µs
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:11197] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 770239 [running]:
            runtime/debug.Stack(0xc0057a8780, 0x6722520, 0xc005128580)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc001f27500, 0xc0057a8780)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc001f27500)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc001f27500, 0xc00353cdb0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/timestamptz_table
...ble' to table collection
              [n1,client=127.0.0.1:48344,user=root] query cache hit
              [n1,client=127.0.0.1:48344,user=root] planning ends
              [n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/86/1
              [n1,client=127.0.0.1:48344,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: [async] drain ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 15.411ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/86/1{-/1970-01-11T10:44:04.000113Z/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=a78ed641] querying next range at /Table/86/1
              [n2,txn=a78ed641] r247: sending batch 1 Scan to (n2,s2):1
              [n2,txn=a78ed641] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r247/1:/Table/86/1{-/1970-0…}] read-only path
              [n2,s2,r247/1:/Table/86/1{-/1970-0…}] acquire latches
              [n2,s2,r247/1:/Table/86/1{-/1970-0…}] waited 83.949µs to acquire latches
              [n2,s2,r247/1:/Table/86/1{-/1970-0…}] waiting for read lock
              [n2,s2,r247/1:/Table/86/1{-/1970-0…}] 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: 426µs
               === SPAN START: flow ===
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:15965] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1163272 [running]:
            runtime/debug.Stack(0xc005c7f980, 0x6722520, 0xc005d3f040)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc00012cd00, 0xc005c7f980)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc00012cd00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc00012cd00, 0xc003feeed0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/secondary_index_-_list_partitioning_-_DEFAULT
...
              [n2] *roachpb.NotLeaseHolderError
              [n2,txn=795d019c] reply error [txn: 795d019c], Scan [/Table/74/2/6,/Table/74/3): failed to send RPC: leaseholder s1 (via (n2,s2):1) not in cached replicas [(n2,s2):1]
              [n2,txn=795d019c] evicting range descriptor on *roachpb.SendError and backoff for re-lookup: r183:/{Table/74/2/6-Max} [(n2,s2):1, next=2, gen=140]
              [n2,txn=795d019c] evicting cached range descriptor
              [n2] Consumer sent handshake. Consuming flow scheduled: true
               === SPAN START: range lookup ===
               === SPAN START: dist sender send ===
              [n2,txn=795d019c,range-lookup=/Table/74/2/6] querying next range at /Meta2/Table/74/2/6/NULL
              [n2,txn=795d019c,range-lookup=/Table/74/2/6] r1: sending batch 1 Scan to (n3,s3):2
              [n2,txn=795d019c,range-lookup=/Table/74/2/6] sending request to 127.0.0.1:38513
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n3] 1 Scan
              [n3,s3] executing 1 requests
              [n3,s3,r1/2:/{Min-System/NodeL…}] read-only path
              [n3,s3,r1/2:/{Min-System/NodeL…}] acquire latches
              [n3,s3,r1/2:/{Min-System/NodeL…}] operation accepts inconsistent results
              [n3,s3,r1/2:/{Min-System/NodeL…}] waiting for read lock
              [n3,s3,r1/2:/{Min-System/NodeL…}] read completed
              [n2,txn=795d019c] looked up range descriptor: r183:/Table/74/{2/6-3} [(n2,s2):1, (n1,s1):2, next=3, gen=143]
              [n2,txn=795d019c] r183: sending batch 1 Scan to (n1,s1):2
              [n2,txn=795d019c] sending request to 127.0.0.1:42259
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] 1 Scan
              [n1,s1] executing 1 requests
              [n1,s1,r183/2:/Table/74/{2/6-3}] read-only path
              [n1,s1,r183/2:/Table/74/{2/6-3}] read has no clock uncertainty
              [n1,s1,r183/2:/Table/74/{2/6-3}] acquire latches
              [n1,s1,r183/2:/Table/74/{2/6-3}] waited 1.503336ms to acquire latches
              [n1,s1,r183/2:/Table/74/{2/6-3}] waiting for read lock
              [n1,s1,r183/2:/Table/74/{2/6-3}] 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: 3.35ms
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:8726] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 587672 [running]:
            runtime/debug.Stack(0xc004781110, 0x6722520, 0xc0035a6f00)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc004e0ad00, 0xc004781110)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc004e0ad00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc004e0ad00, 0xc0035ff9b0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/scans
...           [n1,client=127.0.0.1:48344,user=root] query cache hit
              [n1,client=127.0.0.1:48344,user=root] planning ends
              [n1,client=127.0.0.1:48344,user=root] checking distributability
              [n1,client=127.0.0.1:48344,user=root] will distribute plan: true
              [n1,client=127.0.0.1:48344,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:48344,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:48344,user=root] querying next range at /Table/76/1/6
              [n1,client=127.0.0.1:48344,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.1 KiB
            cockroach.streamid: 1
               === SPAN START: [async] drain ===
               === SPAN START: flow ===
              [n1,client=127.0.0.1:48344,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 13.39ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/76/{1/6-2}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=cd3a4096] querying next range at /Table/76/1/6
              [n2,txn=cd3a4096] r199: sending batch 1 Scan to (n2,s2):1
              [n2,txn=cd3a4096] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r199/1:/Table/76/{1/6-2}] read-only path
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n2,s2,r199/1:/Table/76/{1/6-2}] acquire latches
              [n2,s2,r199/1:/Table/76/{1/6-2}] waited 113.425µs to acquire latches
              [n2,s2,r199/1:/Table/76/{1/6-2}] waiting for read lock
              [n2,s2,r199/1:/Table/76/{1/6-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: 1.746ms
              [n1,client=127.0.0.1:48344,user=root] execution ends
              [n1,client=127.0.0.1:48344,user=root] rows affected: 1
              [n1,client=127.0.0.1:48344,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:48344,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:48344,user=root] [NoTxn pos:10173] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:48344,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 685243 [running]:
            runtime/debug.Stack(0xc0055487e0, 0x6722520, 0xc005459920)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816820, 0xc004634300, 0xc0055487e0)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc004634300)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc004634300, 0xc005ebba10)
            	/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