cockroachdb / cockroach

CockroachDB — the cloud native, distributed SQL database designed for high availability, effortless scale, and control over data placement.
https://www.cockroachlabs.com
Other
30.15k stars 3.81k forks source link

ccl/partitionccl: TestRepartitioning failed #49112

Closed cockroach-teamcity closed 1 year ago

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@68ca7367a1bf4c986e7f85de71c099b46bc435ab:

              [n2,txn=0d7cbab8] recording span to refresh: /Table/70/1/{5/9-6}
               === SPAN START: count rows ===
            cockroach.flowid: 5879a52f-c9fe-4614-a209-07215f515aad
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 510µs
              [n1,s1,r109/2:/Table/70/1/5/{8-9}] executing read-only batch
              [n1,s1,r109/2:/Table/70/1/5/{8-9}] read completed
              [n1,client=127.0.0.1:37008,hostssl,user=root,txn=0d7cbab8] querying next range at /Table/70/1/6
              [n1,client=127.0.0.1:37008,hostssl,user=root,txn=0d7cbab8] r112: sending batch 1 Scan to (n1,s1):2
              [n1,client=127.0.0.1:37008,hostssl,user=root,txn=0d7cbab8] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] node received request: 1 Scan
              [n1,s1] executing [txn: 0d7cbab8], Scan [/Table/70/1/6,/Table/70/2)
              [n1,s1,r112/2:/Table/70/{1/6-2}] read-only path
              [n1,s1,r112/2:/Table/70/{1/6-2}] read has no clock uncertainty
              [n1,s1,r112/2:/Table/70/{1/6-2}] sequencing request
              [n1,s1,r112/2:/Table/70/{1/6-2}] acquiring latches
              [n1,s1,r112/2:/Table/70/{1/6-2}] scanning lock table for conflicting locks
              [n1,s1,r112/2:/Table/70/{1/6-2}] executing read-only batch
              [n1,s1,r112/2:/Table/70/{1/6-2}] read completed
              [n1,client=127.0.0.1:37008,hostssl,user=root,txn=0d7cbab8] recording span to refresh: /Table/70/1/5/{8-9}
              [n1,client=127.0.0.1:37008,hostssl,user=root,txn=0d7cbab8] recording span to refresh: /Table/70/{1/6-2}
               === SPAN START: count rows ===
            cockroach.flowid: 5879a52f-c9fe-4614-a209-07215f515aad
            cockroach.processorid: 2
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 710µs
              [n1,client=127.0.0.1:37008,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:37008,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:37008,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:37008,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:37008,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:37008,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:37008,hostssl,user=root] [NoTxn pos:4786] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:37008,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1452672 [running]:
            runtime/debug.Stack(0xc00946e030, 0x70b4e00, 0xc00991b440)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x71bf780, 0xc00a24c900, 0xc00946e030)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc00a24c900)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc00a24c900, 0xc0141b1770)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

Jira issue: CRDB-4256

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@5156843cc23adecb6a70fabf19f51f46de1241ec:

               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n1,client=127.0.0.1:38790,hostssl,user=root,txn=3e7c5559] querying next range at /Table/66/1/5
              [n3,txn=3e7c5559] recording span to refresh: /Table/66/{1/6-2}
               === SPAN START: count rows ===
            cockroach.flowid: 296244bd-84fd-4fd3-a5eb-ea6c1f82ea58
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 582µs
              [n1,client=127.0.0.1:38790,hostssl,user=root,txn=3e7c5559] r78: sending batch 1 Scan to (n1,s1):3
              [n1,client=127.0.0.1:38790,hostssl,user=root,txn=3e7c5559] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] node received request: 1 Scan
              [n1,s1] executing [txn: 3e7c5559], Scan [/Table/66/1/5,/Table/66/1/6)
              [n3] Consumer sent handshake. Consuming flow scheduled: true
              [n1,s1,r78/3:/Table/66/1/{5-6}] read-only path
              [n1,s1,r78/3:/Table/66/1/{5-6}] read has no clock uncertainty
              [n1,s1,r78/3:/Table/66/1/{5-6}] sequencing request
              [n1,s1,r78/3:/Table/66/1/{5-6}] acquiring latches
              [n1,s1,r78/3:/Table/66/1/{5-6}] scanning lock table for conflicting locks
              [n1,s1,r78/3:/Table/66/1/{5-6}] executing read-only batch
              [n1,s1,r78/3:/Table/66/1/{5-6}] read completed
              [n1,client=127.0.0.1:38790,hostssl,user=root,txn=3e7c5559] recording span to refresh: /Table/66/1/{5-6}
               === SPAN START: count rows ===
            cockroach.flowid: 296244bd-84fd-4fd3-a5eb-ea6c1f82ea58
            cockroach.processorid: 2
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 643µs
              [n1,client=127.0.0.1:38790,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:38790,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:38790,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:38790,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:38790,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:38790,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:38790,hostssl,user=root] [NoTxn pos:3204] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:38790,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1327349 [running]:
            runtime/debug.Stack(0xc00fbd1980, 0x70bf3e0, 0xc00a415d60)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x71c9ee0, 0xc00bce4b00, 0xc00fbd1980)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc00bce4b00)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc00bce4b00, 0xc00aa39590)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@a0f5c15b3929c224a46e3ca2545171f349c233fa:

              [n3,s3,r147/2:/Table/76/1/{3-4}] executing read-only batch
              [n1,client=127.0.0.1:57840,hostssl,user=root,txn=852e4c46] querying next range at /Table/76/1
              [n1,client=127.0.0.1:57840,hostssl,user=root,txn=852e4c46] r146: sending batch 1 Scan to (n1,s1):2
              [n1,client=127.0.0.1:57840,hostssl,user=root,txn=852e4c46] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] node received request: 1 Scan
              [n1,s1] executing [txn: 852e4c46], Scan [/Table/76/1,/Table/76/1/3)
              [n1,s1,r146/2:/Table/76/1{-/3}] read-only path
              [n1,s1,r146/2:/Table/76/1{-/3}] read has no clock uncertainty
              [n1,s1,r146/2:/Table/76/1{-/3}] sequencing request
              [n1,s1,r146/2:/Table/76/1{-/3}] acquiring latches
              [n1,s1,r146/2:/Table/76/1{-/3}] scanning lock table for conflicting locks
              [n1,s1,r146/2:/Table/76/1{-/3}] executing read-only batch
              [n1,s1,r146/2:/Table/76/1{-/3}] read completed
              [n1,client=127.0.0.1:57840,hostssl,user=root,txn=852e4c46] recording span to refresh: /Table/76/1{-/3}
               === SPAN START: count rows ===
            cockroach.flowid: 281f3025-545e-4104-ae16-90cfbc145997
            cockroach.processorid: 2
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 967µs
              [n3,s3,r147/2:/Table/76/1/{3-4}] read completed
              [n3,txn=852e4c46] recording span to refresh: /Table/76/1/3{-/#}
               === SPAN START: count rows ===
            cockroach.flowid: 281f3025-545e-4104-ae16-90cfbc145997
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 495µs
               === SPAN START: [async] drain ===
              [n1,client=127.0.0.1:57840,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:57840,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:57840,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:57840,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:57840,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:57840,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:57840,hostssl,user=root] [NoTxn pos:6474] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:57840,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1773556 [running]:
            runtime/debug.Stack(0xc019b92630, 0x7182240, 0xc01b1ba9e0)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x728eae0, 0xc01040b400, 0xc019b92630)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc01040b400)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc01040b400, 0xc010b15110)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@8fec3f4c6d136a86f472c975edd36b75e5ab9a8c:

               === SPAN START: flow ===
              [n1,client=127.0.0.1:36098,hostssl,user=root] starting (0 processors, 0 startables)
               === SPAN START: table reader ===
            cockroach.flowid: 00000000-0000-0000-0000-000000000000
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 216µs
              [n1,client=127.0.0.1:36098,hostssl,user=root] starting scan with limitBatches false
              [n1,client=127.0.0.1:36098,hostssl,user=root] Scan /Table/90/1/3{-/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n1,client=127.0.0.1:36098,hostssl,user=root,txn=bbe01bbd] querying next range at /Table/90/1/3
              [n1,client=127.0.0.1:36098,hostssl,user=root,txn=bbe01bbd] r183: sending batch 1 Scan to (n1,s1):2
              [n1,client=127.0.0.1:36098,hostssl,user=root,txn=bbe01bbd] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] node received request: 1 Scan
              [n1,s1] executing [txn: bbe01bbd], Scan [/Table/90/1/3,/Table/90/1/3/#)
              [n1,s1,r183/2:/Table/90/1/{3-4}] read-only path
              [n1,s1,r183/2:/Table/90/1/{3-4}] read has no clock uncertainty
              [n1,s1,r183/2:/Table/90/1/{3-4}] sequencing request
              [n1,s1,r183/2:/Table/90/1/{3-4}] acquiring latches
              [n1,s1,r183/2:/Table/90/1/{3-4}] scanning lock table for conflicting locks
              [n1,s1,r183/2:/Table/90/1/{3-4}] executing read-only batch
              [n1,s1,r183/2:/Table/90/1/{3-4}] read completed
              [n1,client=127.0.0.1:36098,hostssl,user=root,txn=bbe01bbd] recording span to refresh: /Table/90/1/3{-/#}
               === SPAN START: count rows ===
            cockroach.flowid: 00000000-0000-0000-0000-000000000000
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 41µs
              [n1,client=127.0.0.1:36098,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:36098,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:36098,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:36098,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:36098,hostssl,user=root] [NoTxn pos:10140] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:36098,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 575504 [running]:
            runtime/debug.Stack(0xc00c99f530, 0x47c2620, 0xc00c6eb2c0)
                /usr/local/go/src/runtime/debug/stack.go:24 +0x9d
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x48c0740, 0xc006ac9200, 0xc00c99f530)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x6b
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc006ac9200)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1313 +0x2b6
            testing.tRunner(0xc006ac9200, 0xc005ede900)
                /usr/local/go/src/testing/testing.go:909 +0xc9
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x350
More

Parameters: - TAGS= - GOFLAGS=-parallel=4 ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@d82948a355aef0cc00e280ee8255d385eef5631a:

  github.com/cockroachdb/cockroach/pkg/server.(*TestServer).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/testserver.go:414 +0x30a
  github.com/cockroachdb/cockroach/pkg/testutils/serverutils.StartServerRaw()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/serverutils/test_server_shim.go:255 +0x199
  github.com/cockroachdb/cockroach/pkg/testutils/serverutils.StartServer()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/serverutils/test_server_shim.go:223 +0x73
  github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).doAddServer()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:349 +0x1d1
  github.com/cockroachdb/cockroach/pkg/testutils/testcluster.StartTestCluster()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:223 +0xd33
  github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.setupPartitioningTestCluster()
      /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1158 +0xdb0
  github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning()
      /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1298 +0x1b5
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:909 +0x199

Goroutine 94 (running) created at:
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xc3
  github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/scheduler.go:165 +0x149
  github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaft()
      /go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:573 +0xcb
  github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store.go:1502 +0xc8c
  github.com/cockroachdb/cockroach/pkg/server.(*Node).bootstrapStores()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:564 +0x5f7
  github.com/cockroachdb/cockroach/pkg/server.(*Node).start()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:452 +0x1713
  github.com/cockroachdb/cockroach/pkg/server.(*Server).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/server.go:1355 +0x2ff6
  github.com/cockroachdb/cockroach/pkg/server.(*TestServer).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/testserver.go:414 +0x30a
  github.com/cockroachdb/cockroach/pkg/testutils/serverutils.StartServerRaw()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/serverutils/test_server_shim.go:255 +0x199
  github.com/cockroachdb/cockroach/pkg/testutils/serverutils.StartServer()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/serverutils/test_server_shim.go:223 +0x73
  github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).doAddServer()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:349 +0x1d1
  github.com/cockroachdb/cockroach/pkg/testutils/testcluster.StartTestCluster()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:223 +0xd33
  github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.setupPartitioningTestCluster()
      /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1158 +0xdb0
  github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning()
      /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1298 +0x1b5
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:909 +0x199
==================
FAIL    github.com/cockroachdb/cockroach/pkg/ccl/partitionccl   1119.104s
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@2717561433759ade4b7d4805f196a37f5a462d9b:

               === SPAN START: count rows ===
            cockroach.flowid: 39d6723b-2d35-4e78-b2a6-2df7f2fa7f18
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 743µs
              [n1,s1,r104/2:/Table/70/1/5/{8-9}] scanning lock table for conflicting locks
              [n1,s1,r104/2:/Table/70/1/5/{8-9}] executing read-only batch
              [n1,s1,r104/2:/Table/70/1/5/{8-9}] read completed
              [n1,client=127.0.0.1:56982,hostssl,user=root,txn=a702e6c7] querying next range at /Table/70/1/6
              [n1,client=127.0.0.1:56982,hostssl,user=root,txn=a702e6c7] r107: sending batch 1 Scan to (n1,s1):2
              [n1,client=127.0.0.1:56982,hostssl,user=root,txn=a702e6c7] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] node received request: 1 Scan
              [n1,s1] executing [txn: a702e6c7], Scan [/Table/70/1/6,/Table/70/2)
              [n1,s1,r107/2:/Table/70/{1/6-2}] read-only path
              [n1,s1,r107/2:/Table/70/{1/6-2}] read has no clock uncertainty
              [n1,s1,r107/2:/Table/70/{1/6-2}] sequencing request
              [n1,s1,r107/2:/Table/70/{1/6-2}] acquiring latches
              [n1,s1,r107/2:/Table/70/{1/6-2}] scanning lock table for conflicting locks
              [n1,s1,r107/2:/Table/70/{1/6-2}] executing read-only batch
              [n1,s1,r107/2:/Table/70/{1/6-2}] read completed
              [n1,client=127.0.0.1:56982,hostssl,user=root,txn=a702e6c7] recording span to refresh: /Table/70/1/5/{8-9}
              [n1,client=127.0.0.1:56982,hostssl,user=root,txn=a702e6c7] recording span to refresh: /Table/70/{1/6-2}
               === SPAN START: count rows ===
            cockroach.flowid: 39d6723b-2d35-4e78-b2a6-2df7f2fa7f18
            cockroach.processorid: 2
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 988µs
              [n1,client=127.0.0.1:56982,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:56982,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:56982,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:56982,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:56982,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:56982,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:56982,hostssl,user=root] [NoTxn pos:4150] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:56982,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1495223 [running]:
            runtime/debug.Stack(0xc00e99be30, 0x7633fe0, 0xc003b3b6c0)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x7748fe0, 0xc006561a00, 0xc00e99be30)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc006561a00)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc006561a00, 0xc000fd1920)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@440d6f54012922f14a82317d9130c57cbbb5a1a4:

               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] node received request: 1 Scan
              [n1,s1] executing [txn: fd731aed], Scan [/Table/70/1/6,/Table/70/2)
              [n1,s1,r115/2:/Table/70/{1/6-2}] read-only path
              [n1,s1,r115/2:/Table/70/{1/6-2}] read has no clock uncertainty
              [n1,s1,r115/2:/Table/70/{1/6-2}] sequencing request
              [n1,s1,r115/2:/Table/70/{1/6-2}] acquiring latches
              [n1,s1,r115/2:/Table/70/{1/6-2}] scanning lock table for conflicting locks
              [n1,s1,r115/2:/Table/70/{1/6-2}] executing read-only batch
              [n1,s1,r115/2:/Table/70/{1/6-2}] read completed
              [n1,client=127.0.0.1:47106,hostssl,user=root,txn=fd731aed] recording span to refresh: /Table/70/1/5/{8-9}
              [n1,client=127.0.0.1:47106,hostssl,user=root,txn=fd731aed] recording span to refresh: /Table/70/{1/6-2}
               === SPAN START: count rows ===
            cockroach.flowid: 31cd5ccc-ac82-47b9-94c5-0cd2a25c2484
            cockroach.processorid: 2
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 688µs
               === SPAN START: [async] drain ===
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n2,s2,r114/1:/Table/70/1/{5/9-6}] scanning lock table for conflicting locks
              [n2,s2,r114/1:/Table/70/1/{5/9-6}] executing read-only batch
              [n2,s2,r114/1:/Table/70/1/{5/9-6}] read completed
              [n2,txn=fd731aed] recording span to refresh: /Table/70/1/{5/9-6}
               === SPAN START: count rows ===
            cockroach.flowid: 31cd5ccc-ac82-47b9-94c5-0cd2a25c2484
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 606µs
              [n1,client=127.0.0.1:47106,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:47106,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:47106,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:47106,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:47106,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:47106,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:47106,hostssl,user=root] [NoTxn pos:4666] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:47106,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1391984 [running]:
            runtime/debug.Stack(0xc014ee6030, 0x7636400, 0xc00cb6cf60)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x774b440, 0xc00b506200, 0xc014ee6030)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc00b506200)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc00b506200, 0xc005898300)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@3f7047d48b2bb4ceeaeb11397e7e0d3a527cc24a:

            cockroach.processorid: 2
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 496µs
              [n3,s3,r155/2:/Table/82/1/3{-/4}] read-only path
              [n3,s3,r155/2:/Table/82/1/3{-/4}] sequencing request
              [n3,s3,r155/2:/Table/82/1/3{-/4}] acquiring latches
              [n3,s3,r155/2:/Table/82/1/3{-/4}] scanning lock table for conflicting locks
              [n3,s3,r155/2:/Table/82/1/3{-/4}] executing read-only batch
              [n3,s3,r155/2:/Table/82/1/3{-/4}] read completed
              [n3,txn=28b8a6a0] recording span to refresh: /Table/82/1/3{-/3/#}
               === SPAN START: count rows ===
            cockroach.flowid: ca6da4dd-6569-49e7-8af3-c8e68e12cfe3
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 425µs
               === SPAN START: flow ===
              [n1,client=127.0.0.1:49954,hostssl,user=root] starting (0 processors, 0 startables)
               === SPAN START: ordered aggregator ===
            cockroach.flowid: ca6da4dd-6569-49e7-8af3-c8e68e12cfe3
            cockroach.processorid: 4
            cockroach.stat.aggregator.input.rows: 2
            cockroach.stat.aggregator.mem.max: 10 KiB
            cockroach.stat.aggregator.stalltime: 11.006ms
               === SPAN START: outbox ===
            cockroach.flowid: ca6da4dd-6569-49e7-8af3-c8e68e12cfe3
            cockroach.stat.outbox.bytes_sent: 2.5 KiB
            cockroach.streamid: 2
               === SPAN START: [async] drain ===
              [n1,client=127.0.0.1:49954,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:49954,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:49954,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:49954,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:49954,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:49954,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:49954,hostssl,user=root] [NoTxn pos:9192] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:49954,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 2091589 [running]:
            runtime/debug.Stack(0xc00223de30, 0x75fb7c0, 0xc007c3ce40)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x7710a00, 0xc0066b4300, 0xc00223de30)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc0066b4300)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc0066b4300, 0xc00fdd9f80)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@d04627c975965916f6794503cb2c51530949ef7c:

              [n1] node received request: 1 Scan
               === SPAN START: ordered aggregator ===
            cockroach.flowid: c5df108c-c25d-4f41-8a3c-cb1c1be1a1c8
            cockroach.processorid: 4
            cockroach.stat.aggregator.input.rows: 2
            cockroach.stat.aggregator.mem.max: 10 KiB
            cockroach.stat.aggregator.stalltime: 108.353ms
              [n3,s3,r165/1:/Table/82/1/{3/4-4}] read completed
              [n3,txn=5cf02155] recording span to refresh: /Table/82/1/{3/4-4}
               === SPAN START: count rows ===
            cockroach.flowid: c5df108c-c25d-4f41-8a3c-cb1c1be1a1c8
            cockroach.processorid: 2
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 413µs
              [n1,s1] executing [txn: 5cf02155], Scan [/Table/82/1/4,/Table/82/1/5/5/#)
              [n1,s1,r162/2:/Table/82/1/{4-5/6}] read-only path
              [n1,s1,r162/2:/Table/82/1/{4-5/6}] read has no clock uncertainty
              [n1,s1,r162/2:/Table/82/1/{4-5/6}] sequencing request
              [n1,s1,r162/2:/Table/82/1/{4-5/6}] acquiring latches
              [n1,s1,r162/2:/Table/82/1/{4-5/6}] scanning lock table for conflicting locks
              [n1,s1,r162/2:/Table/82/1/{4-5/6}] executing read-only batch
              [n1,s1,r162/2:/Table/82/1/{4-5/6}] read completed
              [n1,client=127.0.0.1:38698,hostssl,user=root,txn=5cf02155] recording span to refresh: /Table/82/1/{4-5/5/#}
               === SPAN START: count rows ===
            cockroach.flowid: c5df108c-c25d-4f41-8a3c-cb1c1be1a1c8
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 454µs
              [n1,client=127.0.0.1:38698,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:38698,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:38698,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:38698,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:38698,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:38698,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:38698,hostssl,user=root] [NoTxn pos:8526] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:38698,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 2013092 [running]:
            runtime/debug.Stack(0xc002055350, 0x7609760, 0xc014f4bc00)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x771ee40, 0xc006516700, 0xc002055350)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc006516700)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc006516700, 0xc001b2a450)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@3f08089c31824927b7874f2209645cc3977e6893:

               === SPAN START: dist sender send ===
              [n1,client=127.0.0.1:52584,hostssl,user=root,txn=46dd0156] querying next range at /Table/76/1
              [n3] Consumer sent handshake. Consuming flow scheduled: true
              [n1,client=127.0.0.1:52584,hostssl,user=root,txn=46dd0156] r137: sending batch 1 Scan to (n1,s1):2
              [n1,client=127.0.0.1:52584,hostssl,user=root,txn=46dd0156] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] node received request: 1 Scan
              [n1,s1] executing [txn: 46dd0156], Scan [/Table/76/1,/Table/76/1/3)
              [n1,s1,r137/2:/Table/76/1{-/3}] read-only path
              [n1,s1,r137/2:/Table/76/1{-/3}] read has no clock uncertainty
              [n1,s1,r137/2:/Table/76/1{-/3}] sequencing request
              [n1,s1,r137/2:/Table/76/1{-/3}] acquiring latches
              [n1,s1,r137/2:/Table/76/1{-/3}] scanning lock table for conflicting locks
              [n3,s3,r139/3:/Table/76/1/{3-4}] read completed
              [n1,s1,r137/2:/Table/76/1{-/3}] executing read-only batch
              [n3,txn=46dd0156] recording span to refresh: /Table/76/1/3{-/#}
               === SPAN START: count rows ===
            cockroach.flowid: be1cb3cc-bc5b-4414-a12c-267bfeb4cdfe
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 485µs
              [n1,s1,r137/2:/Table/76/1{-/3}] read completed
              [n1,client=127.0.0.1:52584,hostssl,user=root,txn=46dd0156] recording span to refresh: /Table/76/1{-/3}
               === SPAN START: count rows ===
            cockroach.flowid: be1cb3cc-bc5b-4414-a12c-267bfeb4cdfe
            cockroach.processorid: 2
            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:52584,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:52584,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:52584,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:52584,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:52584,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:52584,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:52584,hostssl,user=root] [NoTxn pos:6534] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:52584,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1692869 [running]:
            runtime/debug.Stack(0xc007454c90, 0x76425e0, 0xc00d69bfa0)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x77587a0, 0xc0064f3100, 0xc007454c90)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc0064f3100)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc0064f3100, 0xc009b99cb0)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@47a6a0241d7e5bb5a62e8214fd4fca1ee17d8c69:

  github.com/cockroachdb/cockroach/pkg/server.(*TestServer).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/testserver.go:413 +0x32a
  github.com/cockroachdb/cockroach/pkg/testutils/serverutils.StartServerRaw()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/serverutils/test_server_shim.go:255 +0x15f
  github.com/cockroachdb/cockroach/pkg/testutils/serverutils.StartServer()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/serverutils/test_server_shim.go:223 +0x65
  github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).doAddServer()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:349 +0x196
  github.com/cockroachdb/cockroach/pkg/testutils/testcluster.StartTestCluster()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:223 +0xc90
  github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.setupPartitioningTestCluster()
      /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1158 +0xd48
  github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning()
      /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1298 +0x1b5
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:909 +0x199

Goroutine 188 (running) created at:
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xc3
  github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/scheduler.go:165 +0x149
  github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaft()
      /go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:573 +0xcb
  github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store.go:1506 +0xc8c
  github.com/cockroachdb/cockroach/pkg/server.(*Node).bootstrapStores()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:564 +0x5f7
  github.com/cockroachdb/cockroach/pkg/server.(*Node).start()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:452 +0x1713
  github.com/cockroachdb/cockroach/pkg/server.(*Server).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/server.go:1366 +0x2fda
  github.com/cockroachdb/cockroach/pkg/server.(*TestServer).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/server/testserver.go:413 +0x32a
  github.com/cockroachdb/cockroach/pkg/testutils/serverutils.StartServerRaw()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/serverutils/test_server_shim.go:255 +0x15f
  github.com/cockroachdb/cockroach/pkg/testutils/serverutils.StartServer()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/serverutils/test_server_shim.go:223 +0x65
  github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).doAddServer()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:349 +0x196
  github.com/cockroachdb/cockroach/pkg/testutils/testcluster.StartTestCluster()
      /go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:223 +0xc90
  github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.setupPartitioningTestCluster()
      /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1158 +0xd48
  github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning()
      /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1298 +0x1b5
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:909 +0x199
==================
FAIL    github.com/cockroachdb/cockroach/pkg/ccl/partitionccl   1288.929s
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@77fa68ebc8bbeabdbf9bbfc9dbe796c3a34f4766:

              [n1,client=127.0.0.1:44844,hostssl,user=root,txn=dd51ece2] querying next range at /Table/70/1/6
              [n1,client=127.0.0.1:44844,hostssl,user=root,txn=dd51ece2] r113: sending batch 1 Scan to (n1,s1):2
              [n1,client=127.0.0.1:44844,hostssl,user=root,txn=dd51ece2] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] node received request: 1 Scan
              [n1,s1] executing [txn: dd51ece2], Scan [/Table/70/1/6,/Table/70/2)
              [n2,s2,r102/1:/Table/70/1/{5/9-6}] read completed
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n1,s1,r113/2:/Table/70/{1/6-2}] read-only path
              [n1,s1,r113/2:/Table/70/{1/6-2}] read has no clock uncertainty
              [n1,s1,r113/2:/Table/70/{1/6-2}] sequencing request
              [n1,s1,r113/2:/Table/70/{1/6-2}] acquiring latches
              [n1,s1,r113/2:/Table/70/{1/6-2}] scanning lock table for conflicting locks
              [n1,s1,r113/2:/Table/70/{1/6-2}] executing read-only batch
              [n1,s1,r113/2:/Table/70/{1/6-2}] read completed
              [n1,client=127.0.0.1:44844,hostssl,user=root,txn=dd51ece2] recording span to refresh: /Table/70/1/5/{8-9}
              [n1,client=127.0.0.1:44844,hostssl,user=root,txn=dd51ece2] recording span to refresh: /Table/70/{1/6-2}
               === SPAN START: count rows ===
            cockroach.flowid: b9d9e8d5-136e-49bc-831f-86f0570f6e30
            cockroach.processorid: 2
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 843µs
              [n2,txn=dd51ece2] recording span to refresh: /Table/70/1/{5/9-6}
               === SPAN START: count rows ===
            cockroach.flowid: b9d9e8d5-136e-49bc-831f-86f0570f6e30
            cockroach.processorid: 3
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 542µs
              [n1,client=127.0.0.1:44844,hostssl,user=root] accumulation complete
              [n1,client=127.0.0.1:44844,hostssl,user=root] exiting aggregator
              [n1,client=127.0.0.1:44844,hostssl,user=root] execution ends
              [n1,client=127.0.0.1:44844,hostssl,user=root] rows affected: 1
              [n1,client=127.0.0.1:44844,hostssl,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44844,hostssl,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44844,hostssl,user=root] [NoTxn pos:5224] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44844,hostssl,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1579032 [running]:
            runtime/debug.Stack(0xc000ec3350, 0x77ec460, 0xc0093c8e20)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x7908c40, 0xc001bbec00, 0xc000ec3350)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc001bbec00)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1365 +0xb41
            testing.tRunner(0xc001bbec00, 0xc006448660)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

knz commented 4 years ago

Here's the specific failure:

"    --- FAIL: TestRepartitioning/multi_col_list_partitioning_-_DEFAULT/multi_col_list_partitioning (101.14s)\n"}
"        partition_test.go:1365: condition failed to evaluate within 45s: expected to scan on n1: SELECT count(*) FROM \"multi col list partitioning\" WHERE (a, b) \u003e (5, 7)\n"}

What's odd is that the trace that follows suggests that the scan is actually properly running on n1:

"              [n1] node received request: 1 Scan\n"}
"              [n1,s1] executing [txn: dd51ece2], Scan [/Table/70/1/6,/Table/70/2)\n"}

So it's possible that the condition used in the test is outdated?

I'm not sure who's best able to triage this. @tbg @dt do you have suggestions?

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@994d3064c68bb9991148960b29cfd66d919dee57:

I200604 19:54:29.093120 1793179 kv/kvserver/replica_raft.go:247  [n2,s2,r149/5:/Table/78/{1/5-2}] proposing SIMPLE(r29) REMOVE_REPLICA[(n1,s1):29LEARNER]: after=[(n2,s2):5] next=30
I200604 19:54:29.137221 1793179 kv/kvserver/replica_command.go:1370  [n2,replicate,s2,r149/5:/Table/78/{1/5-2}] rolled back learner n1,s1 in r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):29LEARNER, next=30, gen=146]
I200604 19:54:29.229218 1807823 kv/kvserver/replica_command.go:1605  [n2,replicate,s2,r149/5:/Table/78/{1/5-2}] change replicas (add [(n1,s1):30LEARNER] remove []): existing descriptor r149:/Table/78/{1/5-2} [(n2,s2):5, next=30, gen=147]
I200604 19:54:29.312595 1805960 kv/kvserver/store_snapshot.go:988  [n2,s2,r149/5:/Table/78/{1/5-2}] streamed LEARNER snapshot fcf5c8bd at applied index 263 to (n1,s1):29LEARNER in 0.04s @ 0 B/s: kv pairs: 67, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.89s
I200604 19:54:29.320755 1806918 kv/kvserver/replica_raftstorage.go:780  [n1,s1,r149/29:{-}] applying LEARNER snapshot [id=fcf5c8bd index=263]
I200604 19:54:29.803789 1708029 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "single col range partitioning" WHERE a < 3
I200604 19:54:29.894510 1807823 kv/kvserver/replica_raft.go:247  [n2,s2,r149/5:/Table/78/{1/5-2}] proposing SIMPLE(l30) ADD_REPLICA[(n1,s1):30LEARNER]: after=[(n2,s2):5 (n1,s1):30LEARNER] next=31
I200604 19:54:29.921123 1708029 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "single col range partitioning" WHERE a >= 3 AND a < 4
I200604 19:54:30.048508 1708029 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "single col range partitioning" WHERE a >= 4
I200604 19:54:30.189648 1708029 ccl/partitionccl/partition_test.go:1366  SucceedsSoon: expected to scan on n1: SELECT count(*) FROM "single col range partitioning" WHERE a >= 4
I200604 19:54:30.273968 1806918 kv/kvserver/replica_raftstorage.go:801  [n1,s1,r149/29:/Table/78/{1/5-2}] applied LEARNER snapshot [total=920ms ingestion=4@120ms id=fcf5c8bd index=263]
I200604 19:54:30.276246 994273 kv/kvserver/store_remove_replica.go:122  [n1,s1,r149/29:/Table/78/{1/5-2}] removing replica r149/29
I200604 19:54:30.299711 1805960 kv/kvserver/replica_command.go:1042  [n2,s2,r149/5:/Table/78/{1/5-2}] could not promote [n1,s1] to voter, rolling back: change replicas of r149 failed: descriptor changed: [expected] r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):29LEARNER, next=30, gen=146] != [actual] r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):30LEARNER, next=31, gen=148]
W200604 19:54:30.354964 990549 kv/kvserver/store_raft.go:509  [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=3, batches=2, state_assertions=1]
I200604 19:54:30.357731 1805960 kv/kvserver/replica_command.go:1605  [n2,s2,r149/5:/Table/78/{1/5-2}] change replicas (add [] remove [(n1,s1):30LEARNER]): existing descriptor r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):30LEARNER, next=31, gen=148]
I200604 19:54:30.393677 994273 kv/kvserver/replica_destroy.go:164  [n1,s1,r149/29:/Table/78/{1/5-2}] removed 5 (0+5) keys in 101ms [clear=101ms commit=1ms]
I200604 19:54:30.749444 1805960 kv/kvserver/replica_raft.go:247  [n2,s2,r149/5:/Table/78/{1/5-2}] proposing SIMPLE(r30) REMOVE_REPLICA[(n1,s1):30LEARNER]: after=[(n2,s2):5] next=31
I200604 19:54:30.910562 1805960 kv/kvserver/replica_command.go:1370  [n2,s2,r149/5:/Table/78/{1/5-2}] rolled back learner n1,s1 in r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):30LEARNER, next=31, gen=148]
E200604 19:54:30.921457 1806210 kv/kvserver/queue.go:1080  [n1,merge,s1,r148/3:/Table/78/1/{4-5}] while carrying out changes [{ADD_REPLICA n1,s1}]: change replicas of r149 failed: descriptor changed: [expected] r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):29LEARNER, next=30, gen=146] != [actual] r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):30LEARNER, next=31, gen=148]
I200604 19:54:31.054494 1809934 kv/kvserver/replica_command.go:1605  [n2,s2,r149/5:/Table/78/{1/5-2}] change replicas (add [(n1,s1):31LEARNER] remove []): existing descriptor r149:/Table/78/{1/5-2} [(n2,s2):5, next=31, gen=149]
I200604 19:54:31.087411 993116 server/status/runtime.go:499  [n2] runtime stats: 3.3 GiB RSS, 853 goroutines, 302 MiB/110 MiB/419 MiB GO alloc/idle/total, 90 MiB/136 MiB CGO alloc/total, 5435.0 CGO/sec, 243.6/23.4 %(u/s)time, 0.4 %gc (2x), 2.2 MiB/2.2 MiB (r/w)net
I200604 19:54:31.208881 1708029 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "single col range partitioning" WHERE a < 3
W200604 19:54:31.236340 990573 kv/kvserver/store_raft.go:509  [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 0.5s [applied=3, batches=2, state_assertions=1]
I200604 19:54:31.481378 1708029 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "single col range partitioning" WHERE a >= 3 AND a < 4
I200604 19:54:31.665196 1708029 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "single col range partitioning" WHERE a >= 4
I200604 19:54:31.738837 1809934 kv/kvserver/replica_raft.go:247  [n2,s2,r149/5:/Table/78/{1/5-2}] proposing SIMPLE(l31) ADD_REPLICA[(n1,s1):31LEARNER]: after=[(n2,s2):5 (n1,s1):31LEARNER] next=32
I200604 19:54:31.830572 1708029 ccl/partitionccl/partition_test.go:1366  SucceedsSoon: expected to scan on n1: SELECT count(*) FROM "single col range partitioning" WHERE a >= 4
I200604 19:54:31.899009 1807823 kv/kvserver/store_snapshot.go:988  [n2,replicate,s2,r149/5:/Table/78/{1/5-2}] streamed LEARNER snapshot 19b34893 at applied index 271 to (n1,s1):30LEARNER in 0.01s @ 0 B/s: kv pairs: 69, log entries: 0, rate-limit: 8.0 MiB/s, queued: 1.89s
I200604 19:54:31.925407 990518 kv/kvserver/replica_destroy.go:170  [n1,s1] removed uninitialized range in 37ms [clear=36ms commit=0ms]
I200604 19:54:31.926008 990518 kv/kvserver/store_remove_replica.go:223  [n1,s1] removing uninitialized replica [n1,s1,r149/30:{-}]
I200604 19:54:31.962937 1807823 kv/kvserver/replica_command.go:1042  [n2,replicate,s2,r149/5:/Table/78/{1/5-2}] could not promote [n1,s1] to voter, rolling back: snapshot failed: (n1,s1):30LEARNER: remote failed to apply snapshot for reason failed to apply snapshot: raft group deleted
I200604 19:54:31.976939 1807823 kv/kvserver/replica_command.go:1605  [n2,replicate,s2,r149/5:/Table/78/{1/5-2}] change replicas (add [] remove [(n1,s1):31LEARNER]): existing descriptor r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):31LEARNER, next=32, gen=150]
I200604 19:54:32.192999 993934 server/status/runtime.go:499  [n3] runtime stats: 3.3 GiB RSS, 846 goroutines, 350 MiB/66 MiB/419 MiB GO alloc/idle/total, 90 MiB/136 MiB CGO alloc/total, 5309.2 CGO/sec, 240.7/22.7 %(u/s)time, 0.4 %gc (2x), 2.2 MiB/2.2 MiB (r/w)net
I200604 19:54:32.525073 1807823 kv/kvserver/replica_raft.go:247  [n2,s2,r149/5:/Table/78/{1/5-2}] proposing SIMPLE(r31) REMOVE_REPLICA[(n1,s1):31LEARNER]: after=[(n2,s2):5] next=32
I200604 19:54:32.705387 1807823 kv/kvserver/replica_command.go:1370  [n2,replicate,s2,r149/5:/Table/78/{1/5-2}] rolled back learner n1,s1 in r149:/Table/78/{1/5-2} [(n2,s2):5, (n1,s1):31LEARNER, next=32, gen=150]
I200604 19:54:32.708641 1807823 kv/kvserver/replicate_queue.go:280  [n2,replicate,s2,r149/5:/Table/78/{1/5-2}] snapshot failed: (n1,s1):30LEARNER: remote failed to apply snapshot for reason failed to apply snapshot: raft group deleted
I200604 19:54:32.827186 1807823 kv/kvserver/replica_command.go:1605  [n2,replicate,s2,r149/5:/Table/78/{1/5-2}] change replicas (add [(n1,s1):32LEARNER] remove []): existing descriptor r149:/Table/78/{1/5-2} [(n2,s2):5, next=32, gen=151]
    --- FAIL: TestRepartitioning/single_col_range_partitioning_-_MAXVALUE/single_col_range_partitioning (87.64s)
        partition_test.go:1366: condition failed to evaluate within 45s: expected to scan on n1: SELECT count(*) FROM "single col range partitioning" WHERE a >= 4
            goroutine 1708029 [running]:
            runtime/debug.Stack(0xc00859bf50, 0x7874060, 0xc00d705fc0)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x7992040, 0xc004aa0300, 0xc00859bf50)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc004aa0300)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1366 +0xb41
            testing.tRunner(0xc004aa0300, 0xc0010e6f90)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@685194e2b53a89ea0c5191f454708a8772c414f8:

I200608 18:06:24.070279 1514045 kv/kvserver/replica_command.go:1042  [n2,replicate,s2,r99/1:/Table/70/1/{5/9-6}] could not promote [n1,s1] to voter, rolling back: change replicas of r99 failed: descriptor changed: [expected] r99:/Table/70/1/{5/9-6} [(n2,s2):1, (n1,s1):19LEARNER, next=20, gen=103] != [actual] r99:/Table/70/1/{5/9-6} [(n2,s2):1, next=20, gen=104]
I200608 18:06:24.085424 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) < (3, 4)
I200608 18:06:24.216691 1516825 kv/kvserver/replica_command.go:1605  [n2,replicate,s2,r99/1:/Table/70/1/{5/9-6}] change replicas (add [(n1,s1):20LEARNER] remove []): existing descriptor r99:/Table/70/1/{5/9-6} [(n2,s2):1, next=20, gen=104]
I200608 18:06:24.251301 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 3 AND b = 4
I200608 18:06:24.419478 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (3, 4) AND (a, b) < (5, 6)
I200608 18:06:24.476475 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 5 AND b = 6
I200608 18:06:24.588714 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 5 AND b = 7
E200608 18:06:24.610675 1517524 kv/kvserver/queue.go:1080  [n2,merge,s2,r99/1:/Table/70/1/{5/9-6}] none of the remaining targets [(n2,s2):?] are legal additions to (n1,s1):2
I200608 18:06:24.629142 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
I200608 18:06:24.732466 1383617 ccl/partitionccl/partition_test.go:1366  SucceedsSoon: expected to scan on n1: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
I200608 18:06:24.846555 1516825 kv/kvserver/replica_raft.go:247  [n2,s2,r99/1:/Table/70/1/{5/9-6}] proposing SIMPLE(l20) ADD_REPLICA[(n1,s1):20LEARNER]: after=[(n2,s2):1 (n1,s1):20LEARNER] next=21
E200608 18:06:25.055720 1516821 kv/kvserver/queue.go:1080  [n1,merge,s1,r97/2:/Table/70/1/5/{8-9}] while carrying out changes [{ADD_REPLICA n1,s1}]: change replicas of r99 failed: descriptor changed: [expected] r99:/Table/70/1/{5/9-6} [(n2,s2):1, next=20, gen=104] != [actual] r99:/Table/70/1/{5/9-6} [(n2,s2):1, (n1,s1):20LEARNER, next=21, gen=105]
I200608 18:06:25.106414 1516825 kv/kvserver/store_snapshot.go:988  [n2,replicate,s2,r99/1:/Table/70/1/{5/9-6}] streamed LEARNER snapshot 282cc467 at applied index 220 to (n1,s1):20LEARNER in 0.00s @ 0 B/s: kv pairs: 44, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.04s
I200608 18:06:25.115327 1518280 kv/kvserver/raft_snapshot_queue.go:126  [n2,raftsnapshot,s2,r99/1:/Table/70/1/{5/9-6}] skipping snapshot; replica is likely a learner in the process of being added: (n1,s1):20LEARNER
I200608 18:06:25.126049 1518166 kv/kvserver/replica_raftstorage.go:780  [n1,s1,r99/20:{-}] applying LEARNER snapshot [id=282cc467 index=220]
I200608 18:06:25.189112 1518364 kv/kvserver/replica_command.go:1605  [n1,merge,s1,r97/2:/Table/70/1/5/{8-9}] change replicas (add [] remove [(n1,s1):20LEARNER]): existing descriptor r99:/Table/70/1/{5/9-6} [(n2,s2):1, (n1,s1):20LEARNER, next=21, gen=105]
I200608 18:06:25.240409 1518166 kv/kvserver/replica_raftstorage.go:801  [n1,s1,r99/20:/Table/70/1/{5/9-6}] applied LEARNER snapshot [total=114ms ingestion=4@65ms id=282cc467 index=220]
I200608 18:06:25.703772 1519004 kv/kvserver/replica_raft.go:247  [n2,s2,r99/1:/Table/70/1/{5/9-6}] proposing SIMPLE(r20) REMOVE_REPLICA[(n1,s1):20LEARNER]: after=[(n2,s2):1] next=21
I200608 18:06:25.737233 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) < (3, 4)
I200608 18:06:25.814154 1519146 kv/kvserver/replica_command.go:1605  [n2,s2,r99/1:/Table/70/1/{5/9-6}] change replicas (add [(n1,s1):21LEARNER] remove []): existing descriptor r99:/Table/70/1/{5/9-6} [(n2,s2):1, next=21, gen=106]
E200608 18:06:25.840114 1518648 kv/kvserver/queue.go:1080  [n2,merge,s2,r99/1:/Table/70/1/{5/9-6}] none of the remaining targets [(n2,s2):?] are legal additions to (n1,s1):2
I200608 18:06:25.842587 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 3 AND b = 4
I200608 18:06:25.985778 1006560 kv/kvserver/store_remove_replica.go:122  [n1,s1,r99/20:/Table/70/1/{5/9-6}] removing replica r99/20
I200608 18:06:26.031493 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (3, 4) AND (a, b) < (5, 6)
I200608 18:06:26.102026 1516825 kv/kvserver/replica_command.go:1042  [n2,replicate,s2,r99/1:/Table/70/1/{5/9-6}] could not promote [n1,s1] to voter, rolling back: change replicas of r99 failed: descriptor changed: [expected] r99:/Table/70/1/{5/9-6} [(n2,s2):1, (n1,s1):20LEARNER, next=21, gen=105] != [actual] r99:/Table/70/1/{5/9-6} [(n2,s2):1, next=21, gen=106]
I200608 18:06:26.205393 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 5 AND b = 6
I200608 18:06:26.392830 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 5 AND b = 7
I200608 18:06:26.487205 1383617 ccl/partitionccl/partition_test.go:220  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
I200608 18:06:26.610365 1383617 ccl/partitionccl/partition_test.go:1366  SucceedsSoon: expected to scan on n1: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
I200608 18:06:26.973497 1519146 kv/kvserver/replica_raft.go:247  [n2,s2,r99/1:/Table/70/1/{5/9-6}] proposing SIMPLE(l21) ADD_REPLICA[(n1,s1):21LEARNER]: after=[(n2,s2):1 (n1,s1):21LEARNER] next=22
I200608 18:06:27.092917 1520822 kv/kvserver/replica_command.go:1605  [n2,merge,s2,r99/1:/Table/70/1/{5/9-6}] change replicas (add [] remove [(n1,s1):21LEARNER]): existing descriptor r99:/Table/70/1/{5/9-6} [(n2,s2):1, (n1,s1):21LEARNER, next=22, gen=107]
I200608 18:06:27.198818 1520944 kv/kvserver/raft_snapshot_queue.go:126  [n2,raftsnapshot,s2,r99/1:/Table/70/1/{5/9-6}] skipping snapshot; replica is likely a learner in the process of being added: (n1,s1):21LEARNER
I200608 18:06:27.211308 1519146 kv/kvserver/store_snapshot.go:988  [n2,s2,r99/1:/Table/70/1/{5/9-6}] streamed LEARNER snapshot 66dbe94f at applied index 229 to (n1,s1):21LEARNER in 0.01s @ 0 B/s: kv pairs: 46, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200608 18:06:27.230001 1520975 kv/kvserver/replica_raftstorage.go:780  [n1,s1,r99/21:{-}] applying LEARNER snapshot [id=66dbe94f index=229]
I200608 18:06:27.341998 1520975 kv/kvserver/replica_raftstorage.go:801  [n1,s1,r99/21:/Table/70/1/{5/9-6}] applied LEARNER snapshot [total=111ms ingestion=4@85ms id=66dbe94f index=229]
I200608 18:06:27.593948 1520822 kv/kvserver/replica_raft.go:247  [n2,s2,r99/1:/Table/70/1/{5/9-6}] proposing SIMPLE(r21) REMOVE_REPLICA[(n1,s1):21LEARNER]: after=[(n2,s2):1] next=22
I200608 18:06:27.619537 1006256 server/status/runtime.go:499  [n1] runtime stats: 3.3 GiB RSS, 838 goroutines, 330 MiB/86 MiB/425 MiB GO alloc/idle/total, 88 MiB/138 MiB CGO alloc/total, 5910.6 CGO/sec, 272.6/19.3 %(u/s)time, 0.2 %gc (2x), 1.7 MiB/1.7 MiB (r/w)net
    --- FAIL: TestRepartitioning/multi_col_list_partitioning_-_DEFAULT/multi_col_list_partitioning (110.33s)
        partition_test.go:1366: condition failed to evaluate within 45s: expected to scan on n1: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
            goroutine 1383617 [running]:
            runtime/debug.Stack(0xc011b648a0, 0x7a23fc0, 0xc00f94a080)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x7b46840, 0xc0087b1800, 0xc011b648a0)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc0087b1800)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1366 +0xb41
            testing.tRunner(0xc0087b1800, 0xc0010a14d0)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@7cf408b1fc5f9381f5f4ac3d04868c01ba0826ac:

I200610 09:10:39.772924 1438139 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (3, 4) AND (a, b) < (5, 6)
I200610 09:10:39.833156 1438139 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 5 AND b = 6
I200610 09:10:39.856331 1554016 kv/kvserver/replica_raft.go:247  [n2,s2,r110/2:/Table/70/1/{5/9-6}] proposing SIMPLE(l27) ADD_REPLICA[(n1,s1):27LEARNER]: after=[(n2,s2):2 (n1,s1):27LEARNER] next=28
E200610 09:10:39.957696 1555049 kv/kvserver/queue.go:1082  [n1,merge,s1,r109/2:/Table/70/1/5/{8-9}] while carrying out changes [{ADD_REPLICA n1,s1}]: change replicas of r110 failed: descriptor changed: [expected] r110:/Table/70/1/{5/9-6} [(n2,s2):2, next=27, gen=120] != [actual] r110:/Table/70/1/{5/9-6} [(n2,s2):2, (n1,s1):27LEARNER, next=28, gen=121]
I200610 09:10:39.964983 1438139 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 5 AND b = 7
I200610 09:10:40.048998 1438139 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
I200610 09:10:40.118143 1555840 kv/kvserver/raft_snapshot_queue.go:128  [n2,raftsnapshot,s2,r110/2:/Table/70/1/{5/9-6}] skipping snapshot; replica is likely a learner in the process of being added: (n1,s1):27LEARNER
I200610 09:10:40.126473 1555496 kv/kvserver/replica_command.go:1605  [n1,merge,s1,r109/2:/Table/70/1/5/{8-9}] change replicas (add [] remove [(n1,s1):27LEARNER]): existing descriptor r110:/Table/70/1/{5/9-6} [(n2,s2):2, (n1,s1):27LEARNER, next=28, gen=121]
I200610 09:10:40.131216 1554016 kv/kvserver/store_snapshot.go:988  [n2,replicate,s2,r110/2:/Table/70/1/{5/9-6}] streamed LEARNER snapshot 167aca34 at applied index 247 to (n1,s1):27LEARNER in 0.01s @ 0 B/s: kv pairs: 63, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.23s
I200610 09:10:40.138815 1555471 kv/kvserver/replica_raftstorage.go:791  [n1,s1,r110/27:{-}] applying LEARNER snapshot [id=167aca34 index=247]
I200610 09:10:40.207114 1438139 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n1: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
I200610 09:10:40.222181 1555471 kv/kvserver/replica_raftstorage.go:812  [n1,s1,r110/27:/Table/70/1/{5/9-6}] applied LEARNER snapshot [total=83ms ingestion=4@59ms id=167aca34 index=247]
I200610 09:10:40.431113 1556377 kv/kvserver/replica_raft.go:247  [n2,s2,r110/2:/Table/70/1/{5/9-6}] proposing SIMPLE(r27) REMOVE_REPLICA[(n1,s1):27LEARNER]: after=[(n2,s2):2] next=28
I200610 09:10:40.493382 1090762 kv/kvserver/store_remove_replica.go:122  [n1,s1,r110/27:/Table/70/1/{5/9-6}] removing replica r110/27
I200610 09:10:40.507056 1554016 kv/kvserver/replica_command.go:1042  [n2,replicate,s2,r110/2:/Table/70/1/{5/9-6}] could not promote [n1,s1] to voter, rolling back: change replicas of r110 failed: descriptor changed: [expected] r110:/Table/70/1/{5/9-6} [(n2,s2):2, (n1,s1):27LEARNER, next=28, gen=121] != [actual] r110:/Table/70/1/{5/9-6} [(n2,s2):2, next=28, gen=122]
I200610 09:10:40.520505 1556491 kv/kvserver/replica_command.go:1605  [n2,s2,r110/2:/Table/70/1/{5/9-6}] change replicas (add [(n1,s1):28LEARNER] remove []): existing descriptor r110:/Table/70/1/{5/9-6} [(n2,s2):2, next=28, gen=122]
I200610 09:10:40.548489 1090513 server/status/runtime.go:504  [n1] runtime stats: 3.3 GiB RSS, 888 goroutines, 281 MiB/131 MiB/419 MiB GO alloc/idle/total, 88 MiB/137 MiB CGO alloc/total, 5898.6 CGO/sec, 295.2/26.0 %(u/s)time, 0.2 %gc (3x), 952 KiB/952 KiB (r/w)net
I200610 09:10:40.557117 1556503 kv/kvserver/replica_command.go:1605  [n2,replicate,s2,r110/2:/Table/70/1/{5/9-6}] change replicas (add [(n1,s1):28LEARNER] remove []): existing descriptor r110:/Table/70/1/{5/9-6} [(n2,s2):2, next=28, gen=122]
E200610 09:10:40.746352 1556707 kv/kvserver/queue.go:1082  [n2,merge,s2,r110/2:/Table/70/1/{5/9-6}] none of the remaining targets [(n2,s2):?] are legal additions to (n1,s1):2
I200610 09:10:41.026443 1556491 kv/kvserver/replica_raft.go:247  [n2,s2,r110/2:/Table/70/1/{5/9-6}] proposing SIMPLE(l28) ADD_REPLICA[(n1,s1):28LEARNER]: after=[(n2,s2):2 (n1,s1):28LEARNER] next=29
I200610 09:10:41.215888 1438139 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (3, 4) AND (a, b) < (5, 6)
I200610 09:10:41.286226 1438139 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 5 AND b = 6
I200610 09:10:41.285950 1557528 kv/kvserver/replica_command.go:1605  [n2,replicate,s2,r110/2:/Table/70/1/{5/9-6}] change replicas (add [] remove [(n1,s1):28LEARNER]): existing descriptor r110:/Table/70/1/{5/9-6} [(n2,s2):2, (n1,s1):28LEARNER, next=29, gen=123]
I200610 09:10:41.391987 1438139 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col list partitioning" WHERE a = 5 AND b = 7
I200610 09:10:41.515564 1438139 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
I200610 09:10:41.614895 1438139 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n1: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
I200610 09:10:41.672063 1558133 kv/kvserver/raft_snapshot_queue.go:128  [n2,raftsnapshot,s2,r110/2:/Table/70/1/{5/9-6}] skipping snapshot; replica is likely a learner in the process of being added: (n1,s1):28LEARNER
I200610 09:10:41.691940 1556491 kv/kvserver/store_snapshot.go:988  [n2,s2,r110/2:/Table/70/1/{5/9-6}] streamed LEARNER snapshot 838207da at applied index 257 to (n1,s1):28LEARNER in 0.02s @ 0 B/s: kv pairs: 63, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.45s
I200610 09:10:41.700882 1557528 kv/kvserver/replica_raft.go:247  [n2,s2,r110/2:/Table/70/1/{5/9-6}] proposing SIMPLE(r28) REMOVE_REPLICA[(n1,s1):28LEARNER]: after=[(n2,s2):2] next=29
I200610 09:10:41.704921 1557407 kv/kvserver/replica_raftstorage.go:791  [n1,s1,r110/28:{-}] applying LEARNER snapshot [id=838207da index=257]
I200610 09:10:41.736578 1557528 kv/kvserver/replica_command.go:1605  [n2,replicate,s2,r110/2:/Table/70/1/{5/9-6}] change replicas (add [(n1,s1):29LEARNER] remove []): existing descriptor r110:/Table/70/1/{5/9-6} [(n2,s2):2, next=29, gen=124]
I200610 09:10:42.147941 1557407 kv/kvserver/replica_raftstorage.go:812  [n1,s1,r110/28:/Table/70/1/{5/9-6}] applied LEARNER snapshot [total=443ms ingestion=4@61ms id=838207da index=257]
I200610 09:10:42.151364 1094563 kv/kvserver/store_remove_replica.go:122  [n1,s1,r110/28:/Table/70/1/{5/9-6}] removing replica r110/28
I200610 09:10:42.232753 1557528 kv/kvserver/replica_raft.go:247  [n2,s2,r110/2:/Table/70/1/{5/9-6}] proposing SIMPLE(l29) ADD_REPLICA[(n1,s1):29LEARNER]: after=[(n2,s2):2 (n1,s1):29LEARNER] next=30
I200610 09:10:42.292166 1556491 kv/kvserver/replica_command.go:1042  [n2,s2,r110/2:/Table/70/1/{5/9-6}] could not promote [n1,s1] to voter, rolling back: change replicas of r110 failed: descriptor changed: [expected] r110:/Table/70/1/{5/9-6} [(n2,s2):2, (n1,s1):28LEARNER, next=29, gen=123] != [actual] r110:/Table/70/1/{5/9-6} [(n2,s2):2, (n1,s1):29LEARNER, next=30, gen=125]
I200610 09:10:42.390610 1556491 kv/kvserver/replica_command.go:1605  [n2,s2,r110/2:/Table/70/1/{5/9-6}] change replicas (add [] remove [(n1,s1):29LEARNER]): existing descriptor r110:/Table/70/1/{5/9-6} [(n2,s2):2, (n1,s1):29LEARNER, next=30, gen=125]
I200610 09:10:42.530814 1094563 kv/kvserver/replica_destroy.go:164  [n1,s1,r110/28:/Table/70/1/{5/9-6}] removed 5 (0+5) keys in 217ms [clear=216ms commit=1ms]
    --- FAIL: TestRepartitioning/multi_col_list_partitioning_-_DEFAULT/multi_col_list_partitioning (95.03s)
        partition_test.go:1367: condition failed to evaluate within 45s: expected to scan on n1: SELECT count(*) FROM "multi col list partitioning" WHERE (a, b) > (5, 7)
            goroutine 1438139 [running]:
            runtime/debug.Stack(0xc0093937a0, 0x7b47c80, 0xc0053d2c20)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x7c6caa0, 0xc0080ee300, 0xc0093937a0)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc0080ee300)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1367 +0xb45
            testing.tRunner(0xc0080ee300, 0xc00881e4e0)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@824df9a984219604a72a51c94e352bb782ce3cf5:

I200612 00:25:29.544718 1860201 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a >= 3 AND a < 4
W200612 00:25:29.662204 1102419 kv/kvserver/store_raft.go:509  [n1,s1,r140/1:/Table/80/1/3{-/4}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=1]
E200612 00:25:29.672213 1967147 kv/kvserver/queue.go:1082  [n1,merge,s1,r140/1:/Table/80/1/3{-/4}] none of the remaining targets [(n1,s1):?] are legal additions to (n3,s3):1
E200612 00:25:29.758635 1970802 kv/kvserver/queue.go:1082  [n1,merge,s1,r140/1:/Table/80/1/3{-/4}] none of the remaining targets [(n1,s1):?] are legal additions to (n3,s3):1
I200612 00:25:29.763781 1860201 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a >= 3 AND a < 4
I200612 00:25:29.959612 1964326 kv/kvserver/replica_command.go:1042  [n1,replicate,s1,r140/1:/Table/80/1/3{-/4}] could not promote [n3,s3] to voter, rolling back: change replicas of r140 failed: descriptor changed: [expected] r140:/Table/80/1/3{-/4} [(n1,s1):1, (n3,s3):5LEARNER, next=6, gen=123] != [actual] r140:/Table/80/1/3{-/4} [(n1,s1):1, next=6, gen=124]
I200612 00:25:30.041116 1970972 kv/kvserver/replica_command.go:1605  [n1,replicate,s1,r140/1:/Table/80/1/3{-/4}] change replicas (add [(n3,s3):6LEARNER] remove []): existing descriptor r140:/Table/80/1/3{-/4} [(n1,s1):1, next=6, gen=124]
E200612 00:25:30.253904 1971212 kv/kvserver/queue.go:1082  [n1,merge,s1,r140/1:/Table/80/1/3{-/4}] none of the remaining targets [(n1,s1):?] are legal additions to (n3,s3):1
I200612 00:25:30.484419 1970972 kv/kvserver/replica_raft.go:247  [n1,s1,r140/1:/Table/80/1/3{-/4}] proposing SIMPLE(l6) ADD_REPLICA[(n3,s3):6LEARNER]: after=[(n1,s1):1 (n3,s3):6LEARNER] next=7
I200612 00:25:30.772065 1860201 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a >= 4 AND (a, b) < (5, 6)
I200612 00:25:30.909065 1860201 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE (a, b) >= (5, 6) AND (a, b) < (5, 7)
I200612 00:25:31.007813 1860201 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE (a, b) >= (5, 7)
I200612 00:25:31.020822 1972333 kv/kvserver/replica_command.go:1605  [n1,merge,s1,r140/1:/Table/80/1/3{-/4}] change replicas (add [] remove [(n3,s3):6LEARNER]): existing descriptor r140:/Table/80/1/3{-/4} [(n1,s1):1, (n3,s3):6LEARNER, next=7, gen=125]
I200612 00:25:31.197354 1860201 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a < 3
I200612 00:25:31.339870 1860201 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a >= 3 AND a < 4
I200612 00:25:31.387520 1972528 kv/kvserver/raft_snapshot_queue.go:128  [n1,raftsnapshot,s1,r140/1:/Table/80/1/3{-/4}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):6LEARNER
I200612 00:25:31.532039 1970972 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r140/1:/Table/80/1/3{-/4}] streamed LEARNER snapshot 8b56c442 at applied index 76 to (n3,s3):6LEARNER in 0.13s @ 0 B/s: kv pairs: 14, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.55s
I200612 00:25:31.536592 1972160 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r140/6:{-}] applying LEARNER snapshot [id=8b56c442 index=76]
I200612 00:25:31.612022 1860201 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a >= 3 AND a < 4
I200612 00:25:31.673830 1972160 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r140/6:/Table/80/1/3{-/4}] applied LEARNER snapshot [total=115ms ingestion=4@82ms id=8b56c442 index=76]
I200612 00:25:31.896366 1972333 kv/kvserver/replica_raft.go:247  [n1,s1,r140/1:/Table/80/1/3{-/4}] proposing SIMPLE(r6) REMOVE_REPLICA[(n3,s3):6LEARNER]: after=[(n1,s1):1] next=7
E200612 00:25:32.033281 1972333 kv/kvserver/queue.go:1082  [n1,merge,s1,r140/1:/Table/80/1/3{-/4}] none of the remaining targets [(n1,s1):?] are legal additions to (n3,s3):1
E200612 00:25:32.050242 1973589 kv/kvserver/queue.go:1082  [n1,merge,s1,r140/1:/Table/80/1/3{-/4}] none of the remaining targets [(n1,s1):?] are legal additions to (n3,s3):1
I200612 00:25:32.081292 1105367 kv/kvserver/store_remove_replica.go:122  [n3,s3,r140/6:/Table/80/1/3{-/4}] removing replica r140/6
I200612 00:25:32.278957 1970972 kv/kvserver/replica_command.go:1042  [n1,replicate,s1,r140/1:/Table/80/1/3{-/4}] could not promote [n3,s3] to voter, rolling back: change replicas of r140 failed: descriptor changed: [expected] r140:/Table/80/1/3{-/4} [(n1,s1):1, (n3,s3):6LEARNER, next=7, gen=125] != [actual] r140:/Table/80/1/3{-/4} [(n1,s1):1, next=7, gen=126]
I200612 00:25:32.339263 1973788 kv/kvserver/replica_command.go:1605  [n1,replicate,s1,r140/1:/Table/80/1/3{-/4}] change replicas (add [(n3,s3):7LEARNER] remove []): existing descriptor r140:/Table/80/1/3{-/4} [(n1,s1):1, next=7, gen=126]
E200612 00:25:32.377367 1973908 kv/kvserver/queue.go:1082  [n1,merge,s1,r140/1:/Table/80/1/3{-/4}] none of the remaining targets [(n1,s1):?] are legal additions to (n3,s3):1
I200612 00:25:32.618430 1860201 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a < 3
I200612 00:25:33.018688 1860201 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a >= 3 AND a < 4
I200612 00:25:33.185998 1973788 kv/kvserver/replica_raft.go:247  [n1,s1,r140/1:/Table/80/1/3{-/4}] proposing SIMPLE(l7) ADD_REPLICA[(n3,s3):7LEARNER]: after=[(n1,s1):1 (n3,s3):7LEARNER] next=8
I200612 00:25:33.223081 1860201 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a >= 3 AND a < 4
I200612 00:25:33.732371 1102273 server/status/runtime.go:504  [n1] runtime stats: 3.5 GiB RSS, 880 goroutines, 226 MiB/169 MiB/463 MiB GO alloc/idle/total, 89 MiB/139 MiB CGO alloc/total, 3508.1 CGO/sec, 212.0/15.3 %(u/s)time, 0.1 %gc (2x), 2.3 MiB/2.3 MiB (r/w)net
I200612 00:25:33.779449 1975302 kv/kvserver/raft_snapshot_queue.go:128  [n1,raftsnapshot,s1,r140/1:/Table/80/1/3{-/4}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):7LEARNER
I200612 00:25:33.791295 1973788 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r140/1:/Table/80/1/3{-/4}] streamed LEARNER snapshot b692b828 at applied index 83 to (n3,s3):7LEARNER in 0.02s @ 0 B/s: kv pairs: 16, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.38s
I200612 00:25:33.794891 1974784 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r140/7:{-}] applying LEARNER snapshot [id=b692b828 index=83]
I200612 00:25:33.917850 1974784 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r140/7:/Table/80/1/3{-/4}] applied LEARNER snapshot [total=122ms ingestion=4@35ms id=b692b828 index=83]
I200612 00:25:34.006131 1973788 kv/kvserver/replica_command.go:1605  [n1,replicate,s1,r140/1:/Table/80/1/3{-/4}] change replicas (add [(n3,s3):7] remove []): existing descriptor r140:/Table/80/1/3{-/4} [(n1,s1):1, (n3,s3):7LEARNER, next=8, gen=127]
    --- FAIL: TestRepartitioning/multi_col_range_partitioning/multi_col_range_partitioning_-_MAXVALUE (101.68s)
        partition_test.go:1367: condition failed to evaluate within 45s: expected to scan on n3: SELECT count(*) FROM "multi col range partitioning - MAXVALUE" WHERE a >= 3 AND a < 4
            goroutine 1860201 [running]:
            runtime/debug.Stack(0xc0043aaba0, 0x7b72aa0, 0xc00602ade0)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x7c9b0c0, 0xc008c5f400, 0xc0043aaba0)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc008c5f400)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1367 +0xb45
            testing.tRunner(0xc008c5f400, 0xc015845a10)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

cockroach-teamcity commented 4 years ago

(ccl/partitionccl).TestRepartitioning failed on master@01a780bdc380d428611348a08aff301ae7c1938b:

I200613 06:09:12.413564 1033842 server/status/runtime.go:504  [n1] runtime stats: 3.7 GiB RSS, 921 goroutines, 249 MiB/215 MiB/486 MiB GO alloc/idle/total, 104 MiB/154 MiB CGO alloc/total, 5337.0 CGO/sec, 281.1/22.0 %(u/s)time, 0.4 %gc (2x), 1.8 MiB/1.8 MiB (r/w)net
I200613 06:09:12.564572 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
I200613 06:09:12.886211 1903787 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
I200613 06:09:12.966149 2052610 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r144/11:/Table/82/1{-/3}] applied LEARNER snapshot [total=886ms ingestion=4@156ms id=019ddec2 index=172]
I200613 06:09:13.663357 2053792 kv/kvserver/replica_raft.go:247  [n1,s1,r144/4:/Table/82/1{-/3}] proposing SIMPLE(r11) REMOVE_REPLICA[(n2,s2):11LEARNER]: after=[(n1,s1):4] next=12
I200613 06:09:13.811795 1036038 kv/kvserver/store_remove_replica.go:122  [n2,s2,r144/11:/Table/82/1{-/3}] removing replica r144/11
E200613 06:09:13.889783 2053792 kv/kvserver/queue.go:1082  [n1,merge,s1,r144/4:/Table/82/1{-/3}] none of the remaining targets [(n1,s1):?] are legal additions to (n2,s2):6
I200613 06:09:13.902616 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
E200613 06:09:13.979151 2055491 kv/kvserver/queue.go:1082  [n1,merge,s1,r144/4:/Table/82/1{-/3}] none of the remaining targets [(n1,s1):?] are legal additions to (n2,s2):6
I200613 06:09:14.135291 2051062 kv/kvserver/replica_command.go:1042  [n1,replicate,s1,r144/4:/Table/82/1{-/3}] could not promote [n2,s2] to voter, rolling back: change replicas of r144 failed: descriptor changed: [expected] r144:/Table/82/1{-/3} [(n1,s1):4, (n2,s2):11LEARNER, next=12, gen=140] != [actual] r144:/Table/82/1{-/3} [(n1,s1):4, next=12, gen=141]
I200613 06:09:14.195207 1903787 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
I200613 06:09:14.323208 2055601 kv/kvserver/replica_command.go:1605  [n1,replicate,s1,r144/4:/Table/82/1{-/3}] change replicas (add [(n2,s2):12LEARNER] remove []): existing descriptor r144:/Table/82/1{-/3} [(n1,s1):4, next=12, gen=141]
I200613 06:09:14.676196 1035915 server/status/runtime.go:504  [n2] runtime stats: 3.7 GiB RSS, 937 goroutines, 341 MiB/134 MiB/486 MiB GO alloc/idle/total, 106 MiB/156 MiB CGO alloc/total, 5087.9 CGO/sec, 279.4/20.8 %(u/s)time, 0.4 %gc (2x), 1.8 MiB/1.8 MiB (r/w)net
I200613 06:09:15.211989 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
I200613 06:09:15.350143 1903787 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
E200613 06:09:15.444233 2057122 kv/kvserver/queue.go:1082  [n1,merge,s1,r144/4:/Table/82/1{-/3}] none of the remaining targets [(n1,s1):?] are legal additions to (n2,s2):6
I200613 06:09:15.582973 2055601 kv/kvserver/replica_raft.go:247  [n1,s1,r144/4:/Table/82/1{-/3}] proposing SIMPLE(l12) ADD_REPLICA[(n2,s2):12LEARNER]: after=[(n1,s1):4 (n2,s2):12LEARNER] next=13
I200613 06:09:15.819527 2057718 kv/kvserver/raft_snapshot_queue.go:128  [n1,raftsnapshot,s1,r144/4:/Table/82/1{-/3}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):12LEARNER
I200613 06:09:15.839842 1036889 server/status/runtime.go:504  [n3] runtime stats: 3.7 GiB RSS, 881 goroutines, 388 MiB/92 MiB/486 MiB GO alloc/idle/total, 102 MiB/156 MiB CGO alloc/total, 5176.1 CGO/sec, 280.4/19.8 %(u/s)time, 0.4 %gc (2x), 1.7 MiB/1.7 MiB (r/w)net
I200613 06:09:15.925096 2055601 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r144/4:/Table/82/1{-/3}] streamed LEARNER snapshot 66a3b4d7 at applied index 185 to (n2,s2):12LEARNER in 0.01s @ 0 B/s: kv pairs: 37, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.02s
I200613 06:09:15.970085 2057858 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r144/12:{-}] applying LEARNER snapshot [id=66a3b4d7 index=185]
I200613 06:09:16.039059 2057986 kv/kvserver/raft_snapshot_queue.go:128  [n1,raftsnapshot,s1,r144/4:/Table/82/1{-/3}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):12LEARNER
I200613 06:09:16.366372 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) >= (5, 7)
I200613 06:09:16.432741 2057858 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r144/12:/Table/82/1{-/3}] applied LEARNER snapshot [total=462ms ingestion=4@323ms id=66a3b4d7 index=185]
I200613 06:09:16.517094 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
I200613 06:09:16.553004 2055601 kv/kvserver/replica_command.go:1605  [n1,replicate,s1,r144/4:/Table/82/1{-/3}] change replicas (add [(n2,s2):12] remove []): existing descriptor r144:/Table/82/1{-/3} [(n1,s1):4, (n2,s2):12LEARNER, next=13, gen=142]
I200613 06:09:16.807998 1903787 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
I200613 06:09:17.384606 2055601 kv/kvserver/replica_raft.go:247  [n1,s1,r144/4:/Table/82/1{-/3}] proposing SIMPLE(v12) ADD_REPLICA[(n2,s2):12]: after=[(n1,s1):4 (n2,s2):12] next=13
E200613 06:09:17.552800 2060024 kv/kvserver/queue.go:1082  [n1,merge,s1,r144/4:/Table/82/1{-/3}] none of the remaining targets [(n1,s1):?] are legal additions to (n2,s2):6
I200613 06:09:17.808427 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) >= (5, 7)
I200613 06:09:17.855184 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
I200613 06:09:17.985814 1903787 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
I200613 06:09:18.986464 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) >= (5, 6) AND (a, b) < (5, 7)
I200613 06:09:19.079083 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) >= (5, 7)
I200613 06:09:19.161470 1903787 ccl/partitionccl/partition_test.go:221  query: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
E200613 06:09:19.329725 2062762 kv/kvserver/queue.go:1082  [n1,merge,s1,r144/4:/Table/82/1{-/3}] none of the remaining targets [(n1,s1):?] are legal additions to (n2,s2):6
I200613 06:09:19.370520 1903787 ccl/partitionccl/partition_test.go:1367  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
    --- FAIL: TestRepartitioning/multi_col_range_partitioning_-_MAXVALUE/multi_col_range_partitioning (146.26s)
        partition_test.go:1367: condition failed to evaluate within 45s: expected to scan on n2: SELECT count(*) FROM "multi col range partitioning" WHERE (a, b) < (3, 4)
            goroutine 1903787 [running]:
            runtime/debug.Stack(0xc0183c1800, 0x7b837e0, 0xc015f306c0)
                /usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x7cac280, 0xc0136b4700, 0xc0183c1800)
                /go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:36 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestRepartitioning.func1(0xc0136b4700)
                /go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1367 +0xb45
            testing.tRunner(0xc0136b4700, 0xc000e478f0)
                /usr/local/go/src/testing/testing.go:909 +0x19a
            created by testing.(*T).Run
                /usr/local/go/src/testing/testing.go:960 +0x652
More

Parameters: - GOFLAGS=-json ``` make stressrace TESTS=TestRepartitioning PKG=./pkg/ccl/partitionccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1 ``` [See this test on roachdash](https://roachdash.crdb.dev/?filter=status%3Aopen+t%3A.%2ATestRepartitioning.%2A&sort=title&restgroup=false&display=lastcommented+project) powered by [pkg/cmd/internal/issues](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/internal/issues)

rytaft commented 4 years ago

This test failed again (https://teamcity.cockroachdb.com//viewLog.html?buildId=2052246&buildTypeId=Cockroach_ExtendedCi):

[17:15:10]i:             [TestRepartitioning/single_col_list_partitioning/single_col_range_partitioning] [Test Output]
    TestRepartitioning/single_col_list_partitioning/single_col_range_partitioning: partition_test.go:1367: condition failed to evaluate within 45s: expected to scan on n2: SELECT count(*) FROM "single col range partitioning" WHERE a < 3
rytaft commented 4 years ago

Another one with the same issue (before the skip took effect): https://teamcity.cockroachdb.com//viewLog.html?buildId=2053133&buildTypeId=Cockroach_ExtendedCi

tbg commented 3 years ago

I ran a one-off of this test just now, and it passed. But it took 3 minutes! How is that even possible.

aadityasondhi commented 1 year ago

Based on an offline discussion: @postamar will continue this investigation

rafiss commented 1 year ago

Link to the offline discussion with ideas on how to improve this: https://cockroachlabs.slack.com/archives/C0168LW5THS/p1688146051790839

postamar commented 1 year ago

See conversation in https://github.com/cockroachdb/cockroach/pull/106340 for how to proceed.

Closely related: https://github.com/cockroachdb/cockroach/issues/49909