search

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.2k stars 3.82k forks source link

ccl/partitionccl: TestRepartitioning failed under stress #28083

Closed cockroach-teamcity closed 6 years ago

cockroach-teamcity commented 6 years ago

SHA: https://github.com/cockroachdb/cockroach/commits/dda801b21f2668537221f58d06a9960d2c05555f

Parameters:

TAGS=
GOFLAGS=-race

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=806542&tab=buildLog

  [n1,client=127.0.0.1:50052,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2402] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50052,user=root] executing: SET TRACING = off in state: NoTxn
I180731 05:30:20.963434 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT DEFAULT" WHERE a = 5 AND b > 8
I180731 05:30:21.207073 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT DEFAULT" WHERE a > 5
I180731 05:30:21.279303 39300 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:21.312650 61644 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:21.375155 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT DEFAULT" WHERE (a, b) < (3, 4)
I180731 05:30:21.463528 39299 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:21.489327 61863 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:21.688944 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT DEFAULT" WHERE a = 3 AND b = 4
I180731 05:30:21.802938 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:21.892934 39301 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:21.907395 61893 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:22.083927 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:22.472607 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT DEFAULT" WHERE a = 5 AND b = 7
I180731 05:30:22.479379 39303 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:22.486092 61848 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:22.566171 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT DEFAULT" WHERE a = 5 AND b = 8
I180731 05:30:22.595979 39302 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n3 established
I180731 05:30:22.609789 61882 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180731 05:30:22.912978 40578 sql/lease.go:313  [n1,client=127.0.0.1:50052,user=root] publish: descID=74 (multi col list partitioning - DEFAULT) version=2 mtime=2018-07-31 05:30:22.703829314 +0000 UTC
I180731 05:30:23.357514 61696 sql/lease.go:812  new lease: 74("multi col list partitioning - DEFAULT") ver=2:1533015262.825236246,0, refcount=0
I180731 05:30:23.840042 40578 sql/lease.go:287  publish (1 leases): desc=[{multi col list partitioning - DEFAULT 74 1}]
I180731 05:30:24.321620 40578 sql/lease.go:313  [n1,client=127.0.0.1:50052,user=root,scExec=] publish: descID=74 (multi col list partitioning - DEFAULT) version=3 mtime=2018-07-31 05:30:24.311421742 +0000 UTC
I180731 05:30:24.473484 40169 server/status/runtime.go:424  [n2] runtime stats: 1.0 GiB RSS, 603 goroutines, 50 MiB/26 MiB/98 MiB GO alloc/idle/total, 95 MiB/145 MiB CGO alloc/total, 1946.57cgo/sec, 0.96/0.04 %(u/s)time, 0.03 %gc (7x)
I180731 05:30:24.726092 62028 sql/lease.go:812  new lease: 74("multi col list partitioning - DEFAULT") ver=3:1533015354.733544160,0, refcount=0
I180731 05:30:24.764045 40578 sql/lease.go:287  publish (1 leases): desc=[{multi col list partitioning - DEFAULT 74 2}]
I180731 05:30:25.072477 40578 sql/lease.go:287  publish (1 leases): desc=[{multi col list partitioning - DEFAULT 74 2}]
I180731 05:30:25.859680 40578 sql/lease.go:313  [n1,client=127.0.0.1:50052,user=root] publish: descID=74 (multi col list partitioning - DEFAULT) version=4 mtime=2018-07-31 05:30:25.515909194 +0000 UTC
I180731 05:30:26.103955 40549 server/status/runtime.go:424  [n3] runtime stats: 1.0 GiB RSS, 603 goroutines, 53 MiB/24 MiB/98 MiB GO alloc/idle/total, 95 MiB/145 MiB CGO alloc/total, 1883.99cgo/sec, 0.91/0.04 %(u/s)time, 0.02 %gc (6x)
I180731 05:30:26.367063 40578 sql/event_log.go:126  [n1,client=127.0.0.1:50052,user=root] Event: "alter_table", target: 74, info: {TableName:data.public."multi col list partitioning - DEFAULT" Statement:ALTER TABLE "multi col list partitioning - DEFAULT" PARTITION BY LIST (a, b) (PARTITION p34 VALUES IN ((3, 4)), PARTITION p57 VALUES IN ((5, 7)), PARTITION p58 VALUES IN ((5, 8)), PARTITION p5d VALUES IN ((5, DEFAULT))) User:root MutationID:0 CascadeDroppedViews:[]}
I180731 05:30:26.750624 62181 sql/lease.go:812  new lease: 74("multi col list partitioning - DEFAULT") ver=4:1533015283.004172332,0, refcount=0
I180731 05:30:26.882848 40578 sql/lease.go:287  publish (1 leases): desc=[{multi col list partitioning - DEFAULT 74 3}]
I180731 05:30:27.187738 39510 server/status/runtime.go:424  [n1] runtime stats: 1.0 GiB RSS, 606 goroutines, 46 MiB/28 MiB/98 MiB GO alloc/idle/total, 95 MiB/145 MiB CGO alloc/total, 1817.91cgo/sec, 0.90/0.04 %(u/s)time, 0.03 %gc (7x)
I180731 05:30:27.623969 39305 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root,intExec=get-all-names] connection to n2 established
I180731 05:30:27.659597 62293 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:27.710032 39306 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root,intExec=crdb-internal-zones-table] connection to n2 established
I180731 05:30:27.772108 62339 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:29.217588 40578 sql/event_log.go:126  [n1,client=127.0.0.1:50052,user=root] Event: "set_zone_config", target: 74, info: {Target:data."multi col list partitioning - DEFAULT"@primary Config:constraints: [+n1] User:root}
I180731 05:30:29.463370 62394 storage/replica_raftstorage.go:520  [replicate,n2,s2,r78/2:/Table/74/1/{3/5-5}] generated preemptive snapshot 67c3a756 at index 31
I180731 05:30:29.501334 39304 rpc/nodedialer/nodedialer.go:92  [intExec=adopt-job] connection to n2 established
I180731 05:30:29.509718 62330 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:29.521460 62394 storage/store_snapshot.go:605  [replicate,n2,s2,r78/2:/Table/74/1/{3/5-5}] streamed snapshot to (n1,s1):?: kv pairs: 12, log entries: 21, rate-limit: 2.0 MiB/sec, 57ms
I180731 05:30:29.525861 62397 storage/replica_raftstorage.go:737  [n1,s1,r78/?:{-}] applying preemptive snapshot at index 31 (id=67c3a756, encoded size=6818, 1 rocksdb batches, 21 log entries)
I180731 05:30:29.535898 62397 storage/replica_raftstorage.go:743  [n1,s1,r78/?:/Table/74/1/{3/5-5}] applied preemptive snapshot in 10ms [clear=0ms batch=0ms entries=9ms commit=0ms]
I180731 05:30:29.549283 62394 storage/replica_command.go:745  [replicate,n2,s2,r78/2:/Table/74/1/{3/5-5}] change replicas (ADD_REPLICA (n1,s1):3): read existing descriptor r78:/Table/74/1/{3/5-5} [(n2,s2):2, next=3]
I180731 05:30:29.816827 62394 storage/replica.go:3645  [n2,s2,r78/2:/Table/74/1/{3/5-5}] proposing ADD_REPLICA((n1,s1):3): updated=[(n2,s2):2 (n1,s1):3] next=4
I180731 05:30:29.945513 62473 storage/replica_range_lease.go:554  [replicate,n2,s2,r78/2:/Table/74/1/{3/5-5}] transferring lease to s1
I180731 05:30:30.042934 62473 storage/replica_range_lease.go:617  [replicate,n2,s2,r78/2:/Table/74/1/{3/5-5}] done transferring lease to s1: <nil>
I180731 05:30:30.046512 39428 storage/replica_proposal.go:222  [n1,s1,r78/3:/Table/74/1/{3/5-5}] new range lease repl=(n1,s1):3 seq=10 start=1533015029.945691905,0 epo=1 pro=1533015029.945735042,0 following repl=(n2,s2):2 seq=9 start=1533015013.867757130,0 epo=1 pro=1533015013.867810310,0
I180731 05:30:30.086713 62465 storage/replica_raftstorage.go:520  [replicate,n2,s2,r82/2:/Table/74/{1/6-2}] generated preemptive snapshot 7eba3b7c at index 26
I180731 05:30:30.089395 40578 sql/event_log.go:126  [n1,client=127.0.0.1:50052,user=root] Event: "set_zone_config", target: 74, info: {Target:data."multi col list partitioning - DEFAULT".p34 Config:constraints: [+n2] User:root}
I180731 05:30:30.112388 62465 storage/store_snapshot.go:605  [replicate,n2,s2,r82/2:/Table/74/{1/6-2}] streamed snapshot to (n1,s1):?: kv pairs: 10, log entries: 16, rate-limit: 2.0 MiB/sec, 16ms
I180731 05:30:30.115585 62480 storage/replica_raftstorage.go:737  [n1,s1,r82/?:{-}] applying preemptive snapshot at index 26 (id=7eba3b7c, encoded size=4662, 1 rocksdb batches, 16 log entries)
I180731 05:30:30.118905 62480 storage/replica_raftstorage.go:743  [n1,s1,r82/?:/Table/74/{1/6-2}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180731 05:30:30.309376 62465 storage/replica_command.go:745  [replicate,n2,s2,r82/2:/Table/74/{1/6-2}] change replicas (ADD_REPLICA (n1,s1):3): read existing descriptor r82:/Table/74/{1/6-2} [(n2,s2):2, next=3]
I180731 05:30:30.679920 62465 storage/replica.go:3645  [n2,s2,r82/2:/Table/74/{1/6-2}] proposing ADD_REPLICA((n1,s1):3): updated=[(n2,s2):2 (n1,s1):3] next=4
I180731 05:30:31.022057 62596 storage/replica_range_lease.go:554  [replicate,n2,s2,r82/2:/Table/74/{1/6-2}] transferring lease to s1
I180731 05:30:31.075478 39476 storage/replica_proposal.go:222  [n1,s1,r82/3:/Table/74/{1/6-2}] new range lease repl=(n1,s1):3 seq=10 start=1533015031.022215722,0 epo=1 pro=1533015031.022242927,0 following repl=(n2,s2):2 seq=9 start=1533015019.448171057,0 epo=1 pro=1533015019.448216115,0
I180731 05:30:31.136525 62596 storage/replica_range_lease.go:617  [replicate,n2,s2,r82/2:/Table/74/{1/6-2}] done transferring lease to s1: <nil>
I180731 05:30:31.139059 62386 storage/replica_raftstorage.go:520  [replicate,n2,s2,r84/2:/Table/74/1{-/3/4}] generated preemptive snapshot 6c0bedae at index 22
I180731 05:30:31.171883 62386 storage/store_snapshot.go:605  [replicate,n2,s2,r84/2:/Table/74/1{-/3/4}] streamed snapshot to (n1,s1):?: kv pairs: 9, log entries: 12, rate-limit: 2.0 MiB/sec, 32ms
I180731 05:30:31.175078 62546 storage/replica_raftstorage.go:737  [n1,s1,r84/?:{-}] applying preemptive snapshot at index 22 (id=6c0bedae, encoded size=2908, 1 rocksdb batches, 12 log entries)
I180731 05:30:31.184743 62546 storage/replica_raftstorage.go:743  [n1,s1,r84/?:/Table/74/1{-/3/4}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=8ms commit=0ms]
I180731 05:30:31.193606 62386 storage/replica_command.go:745  [replicate,n2,s2,r84/2:/Table/74/1{-/3/4}] change replicas (ADD_REPLICA (n1,s1):3): read existing descriptor r84:/Table/74/1{-/3/4} [(n2,s2):2, next=3]
I180731 05:30:31.436711 40578 sql/event_log.go:126  [n1,client=127.0.0.1:50052,user=root] Event: "set_zone_config", target: 74, info: {Target:data."multi col list partitioning - DEFAULT".p57 Config:constraints: [+n3] User:root}
I180731 05:30:31.450438 62386 storage/replica.go:3645  [n2,s2,r84/2:/Table/74/1{-/3/4}] proposing ADD_REPLICA((n1,s1):3): updated=[(n2,s2):2 (n1,s1):3] next=4
I180731 05:30:31.552881 62521 storage/replica_range_lease.go:554  [replicate,n2,s2,r84/2:/Table/74/1{-/3/4}] transferring lease to s1
I180731 05:30:31.722097 62521 storage/replica_range_lease.go:617  [replicate,n2,s2,r84/2:/Table/74/1{-/3/4}] done transferring lease to s1: <nil>
I180731 05:30:31.731512 39464 storage/replica_proposal.go:222  [n1,s1,r84/3:/Table/74/1{-/3/4}] new range lease repl=(n1,s1):3 seq=10 start=1533015031.553075084,0 epo=1 pro=1533015031.553108878,0 following repl=(n2,s2):2 seq=9 start=1533015018.306481454,0 epo=1 pro=1533015018.306510548,0
I180731 05:30:31.788668 62618 storage/replica_command.go:745  [replicate,n1,s1,r78/3:/Table/74/1/{3/5-5}] change replicas (REMOVE_REPLICA (n2,s2):2): read existing descriptor r78:/Table/74/1/{3/5-5} [(n2,s2):2, (n1,s1):3, next=4]
I180731 05:30:32.073647 62666 storage/replica_raftstorage.go:520  [replicate,n2,s2,r79/2:/Table/74/1/5/{7-8}] generated preemptive snapshot 03d3e4ea at index 26
I180731 05:30:32.118096 62618 storage/replica.go:3645  [n1,s1,r78/3:/Table/74/1/{3/5-5}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n1,s1):3] next=4
I180731 05:30:32.121803 62666 storage/store_snapshot.go:605  [replicate,n2,s2,r79/2:/Table/74/1/5/{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 16, rate-limit: 2.0 MiB/sec, 47ms
I180731 05:30:32.155884 62637 storage/replica_raftstorage.go:737  [n3,s3,r79/?:{-}] applying preemptive snapshot at index 26 (id=03d3e4ea, encoded size=4636, 1 rocksdb batches, 16 log entries)
W180731 05:30:32.157016 39460 storage/store.go:3763  [n1,s1] handle raft ready: 0.6s [processed=2]
I180731 05:30:32.215672 62620 storage/replica_raftstorage.go:520  [replicate,n1,s1,r77/2:/Table/74/1/3/{4-5}] generated preemptive snapshot 927b74ce at index 27
I180731 05:30:32.224549 62637 storage/replica_raftstorage.go:743  [n3,s3,r79/?:/Table/74/1/5/{7-8}] applied preemptive snapshot in 68ms [clear=0ms batch=0ms entries=49ms commit=0ms]
I180731 05:30:32.238698 62666 storage/replica_command.go:745  [replicate,n2,s2,r79/2:/Table/74/1/5/{7-8}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r79:/Table/74/1/5/{7-8} [(n2,s2):2, next=3]
I180731 05:30:32.241696 62620 storage/store_snapshot.go:605  [replicate,n1,s1,r77/2:/Table/74/1/3/{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 17, rate-limit: 2.0 MiB/sec, 25ms
I180731 05:30:32.247848 62673 storage/replica_raftstorage.go:737  [n2,s2,r77/?:{-}] applying preemptive snapshot at index 27 (id=927b74ce, encoded size=4669, 1 rocksdb batches, 17 log entries)
I180731 05:30:32.248967 40209 storage/store.go:3638  [n2,s2,r78/2:/Table/74/1/{3/5-5}] added to replica GC queue (peer suggestion)
I180731 05:30:32.261981 62673 storage/replica_raftstorage.go:743  [n2,s2,r77/?:/Table/74/1/3/{4-5}] applied preemptive snapshot in 14ms [clear=0ms batch=0ms entries=2ms commit=11ms]
I180731 05:30:32.262056 62683 storage/store.go:2557  [replicaGC,n2,s2,r78/2:/Table/74/1/{3/5-5}] removing replica
I180731 05:30:32.265553 62683 storage/replica.go:844  [replicaGC,n2,s2,r78/2:/Table/74/1/{3/5-5}] removed 8 (0+8) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:32.266685 62620 storage/replica_command.go:745  [replicate,n1,s1,r77/2:/Table/74/1/3/{4-5}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r77:/Table/74/1/3/{4-5} [(n1,s1):2, next=3]
I180731 05:30:32.531362 62654 storage/store.go:2557  [replicaGC,n2,s2,r77/?:/Table/74/1/3/{4-5}] removing replica
I180731 05:30:32.551046 62666 storage/replica.go:3645  [n2,s2,r79/2:/Table/74/1/5/{7-8}] proposing ADD_REPLICA((n3,s3):3): updated=[(n2,s2):2 (n3,s3):3] next=4
I180731 05:30:32.553239 62654 storage/replica.go:844  [replicaGC,n2,s2,r77/?:/Table/74/1/3/{4-5}] removed 6 (0+6) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:32.646377 62727 storage/replica_range_lease.go:554  [replicate,n2,s2,r79/2:/Table/74/1/5/{7-8}] transferring lease to s3
I180731 05:30:32.740351 62727 storage/replica_range_lease.go:617  [replicate,n2,s2,r79/2:/Table/74/1/5/{7-8}] done transferring lease to s3: <nil>
I180731 05:30:32.747961 40506 storage/replica_proposal.go:222  [n3,s3,r79/3:/Table/74/1/5/{7-8}] new range lease repl=(n3,s3):3 seq=10 start=1533015032.646573299,0 epo=1 pro=1533015032.646620231,0 following repl=(n2,s2):2 seq=9 start=1533015015.670954455,0 epo=1 pro=1533015015.670970484,0
I180731 05:30:32.883692 62620 storage/replica.go:3645  [n1,s1,r77/2:/Table/74/1/3/{4-5}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):2 (n2,s2):3] next=4
I180731 05:30:32.893635 40578 sql/event_log.go:126  [n1,client=127.0.0.1:50052,user=root] Event: "set_zone_config", target: 74, info: {Target:data."multi col list partitioning - DEFAULT".p58 Config:constraints: [+n1] User:root}
I180731 05:30:33.053623 62777 storage/replica_raftstorage.go:520  [raftsnapshot,n1,s1,r77/2:/Table/74/1/3/{4-5}] generated Raft snapshot 076d36df at index 29
I180731 05:30:33.054581 62775 storage/replica_command.go:745  [replicate,n1,s1,r84/3:/Table/74/1{-/3/4}] change replicas (REMOVE_REPLICA (n2,s2):2): read existing descriptor r84:/Table/74/1{-/3/4} [(n2,s2):2, (n1,s1):3, next=4]
I180731 05:30:33.166764 62720 storage/replica_command.go:745  [replicate,n3,s3,r79/3:/Table/74/1/5/{7-8}] change replicas (REMOVE_REPLICA (n2,s2):2): read existing descriptor r79:/Table/74/1/5/{7-8} [(n2,s2):2, (n3,s3):3, next=4]
I180731 05:30:33.193005 62777 storage/store_snapshot.go:605  [raftsnapshot,n1,s1,r77/2:/Table/74/1/3/{4-5}] streamed snapshot to (n2,s2):3: kv pairs: 12, log entries: 19, rate-limit: 8.0 MiB/sec, 137ms
I180731 05:30:33.216784 62779 storage/replica_raftstorage.go:737  [n2,s2,r77/3:{-}] applying Raft snapshot at index 29 (id=076d36df, encoded size=6161, 1 rocksdb batches, 19 log entries)
I180731 05:30:33.246463 62779 storage/replica_raftstorage.go:743  [n2,s2,r77/3:/Table/74/1/3/{4-5}] applied Raft snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180731 05:30:33.505037 62720 storage/replica.go:3645  [n3,s3,r79/3:/Table/74/1/5/{7-8}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n3,s3):3] next=4
I180731 05:30:33.508490 62775 storage/replica.go:3645  [n1,s1,r84/3:/Table/74/1{-/3/4}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n1,s1):3] next=4
I180731 05:30:33.578101 42701 storage/store.go:3638  [n2,s2,r79/2:/Table/74/1/5/{7-8}] added to replica GC queue (peer suggestion)
I180731 05:30:33.594852 62899 storage/store.go:2557  [replicaGC,n2,s2,r79/2:/Table/74/1/5/{7-8}] removing replica
I180731 05:30:33.598070 62899 storage/replica.go:844  [replicaGC,n2,s2,r79/2:/Table/74/1/5/{7-8}] removed 7 (0+7) keys in 1ms [clear=0ms commit=0ms]
I180731 05:30:33.663765 62858 storage/replica_range_lease.go:554  [replicate,n1,s1,r77/2:/Table/74/1/3/{4-5}] transferring lease to s2
I180731 05:30:33.699737 40092 storage/replica_proposal.go:222  [n2,s2,r77/3:/Table/74/1/3/{4-5}] new range lease repl=(n2,s2):3 seq=10 start=1533015033.663922898,0 epo=1 pro=1533015033.663937717,0 following repl=(n1,s1):2 seq=9 start=1533015012.532911924,0 epo=1 pro=1533015012.532956849,0
I180731 05:30:33.703861 40209 storage/store.go:3638  [n2,s2,r84/2:/Table/74/1{-/3/4}] added to replica GC queue (peer suggestion)
I180731 05:30:33.716600 62858 storage/replica_range_lease.go:617  [replicate,n1,s1,r77/2:/Table/74/1/3/{4-5}] done transferring lease to s2: <nil>
E180731 05:30:33.732235 62872 storage/queue.go:778  [replicate,n2,s2,r77/3:/Table/74/1/3/{4-5}] no removable replicas from range that needs a removal: [raft progress unknown]
I180731 05:30:33.799672 62900 storage/store.go:2557  [replicaGC,n2,s2,r84/2:/Table/74/1{-/3/4}] removing replica
I180731 05:30:33.801719 62900 storage/replica.go:844  [replicaGC,n2,s2,r84/2:/Table/74/1{-/3/4}] removed 7 (0+7) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:33.834829 62863 storage/replica_raftstorage.go:520  [replicate,n3,s3,r80/1:/Table/74/1/5/{8-9}] generated preemptive snapshot 40fc80a6 at index 18
I180731 05:30:33.840068 62863 storage/store_snapshot.go:605  [replicate,n3,s3,r80/1:/Table/74/1/5/{8-9}] streamed snapshot to (n1,s1):?: kv pairs: 8, log entries: 8, rate-limit: 2.0 MiB/sec, 4ms
I180731 05:30:33.842920 62866 storage/replica_raftstorage.go:737  [n1,s1,r80/?:{-}] applying preemptive snapshot at index 18 (id=40fc80a6, encoded size=2283, 1 rocksdb batches, 8 log entries)
I180731 05:30:33.845360 62866 storage/replica_raftstorage.go:743  [n1,s1,r80/?:/Table/74/1/5/{8-9}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180731 05:30:33.868568 62845 storage/replica_command.go:745  [replicate,n1,s1,r82/3:/Table/74/{1/6-2}] change replicas (REMOVE_REPLICA (n2,s2):2): read existing descriptor r82:/Table/74/{1/6-2} [(n2,s2):2, (n1,s1):3, next=4]
I180731 05:30:33.899713 62863 storage/replica_command.go:745  [replicate,n3,s3,r80/1:/Table/74/1/5/{8-9}] change replicas (ADD_REPLICA (n1,s1):2): read existing descriptor r80:/Table/74/1/5/{8-9} [(n3,s3):1, next=2]
I180731 05:30:33.968034 40578 sql/event_log.go:126  [n1,client=127.0.0.1:50052,user=root] Event: "set_zone_config", target: 74, info: {Target:data."multi col list partitioning - DEFAULT".p5d Config:constraints: [+n2] User:root}
I180731 05:30:34.020076 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:34.161032 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:34.307564 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b = 7
I180731 05:30:34.320692 62845 storage/replica.go:3645  [n1,s1,r82/3:/Table/74/{1/6-2}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n1,s1):3] next=4
I180731 05:30:34.320861 39291 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:34.325124 62863 storage/replica.go:3645  [n3,s3,r80/1:/Table/74/1/5/{8-9}] proposing ADD_REPLICA((n1,s1):2): updated=[(n3,s3):1 (n1,s1):2] next=3
I180731 05:30:34.343236 40209 storage/store.go:3638  [n2,s2,r82/2:/Table/74/{1/6-2}] added to replica GC queue (peer suggestion)
I180731 05:30:34.344872 62907 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:34.353876 62878 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot e338ecd9 at index 107
I180731 05:30:34.370665 62878 storage/store_snapshot.go:605  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 64, log entries: 97, rate-limit: 2.0 MiB/sec, 16ms
I180731 05:30:34.378967 62881 storage/replica_raftstorage.go:737  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 107 (id=e338ecd9, encoded size=27146, 1 rocksdb batches, 97 log entries)
I180731 05:30:34.492343 40169 server/status/runtime.go:424  [n2] runtime stats: 1.0 GiB RSS, 626 goroutines, 40 MiB/33 MiB/98 MiB GO alloc/idle/total, 102 MiB/147 MiB CGO alloc/total, 1798.91cgo/sec, 0.94/0.04 %(u/s)time, 0.04 %gc (8x)
I180731 05:30:34.527260 62881 storage/replica_raftstorage.go:743  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 148ms [clear=83ms batch=0ms entries=64ms commit=0ms]
I180731 05:30:34.537900 62896 storage/replica_range_lease.go:554  [replicate,n3,s3,r80/1:/Table/74/1/5/{8-9}] transferring lease to s1
I180731 05:30:34.540950 62995 storage/store.go:2557  [replicaGC,n2,s2,r82/2:/Table/74/{1/6-2}] removing replica
I180731 05:30:34.547616 62995 storage/replica.go:844  [replicaGC,n2,s2,r82/2:/Table/74/{1/6-2}] removed 7 (0+7) keys in 1ms [clear=0ms commit=0ms]
I180731 05:30:34.541620 62878 storage/replica_command.go:745  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, next=2]
I180731 05:30:34.560706 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b = 8
I180731 05:30:34.563751 62896 storage/replica_range_lease.go:617  [replicate,n3,s3,r80/1:/Table/74/1/5/{8-9}] done transferring lease to s1: <nil>
I180731 05:30:34.596986 39463 storage/replica_proposal.go:222  [n1,s1,r80/2:/Table/74/1/5/{8-9}] new range lease repl=(n1,s1):2 seq=9 start=1533015034.545359205,0 epo=1 pro=1533015034.545386442,0 following repl=(n3,s3):1 seq=8 start=1533014978.890295763,0 epo=1 pro=1533014978.890325370,0
I180731 05:30:34.602062 39295 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n3 established
I180731 05:30:34.661774 63076 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180731 05:30:34.734598 62878 storage/replica.go:3645  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180731 05:30:34.817273 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b > 8
I180731 05:30:34.867868 62986 storage/replica_range_lease.go:554  [replicate,n1,s1,r8/1:/Table/1{1-2}] transferring lease to s2
I180731 05:30:34.886450 62986 storage/replica_range_lease.go:617  [replicate,n1,s1,r8/1:/Table/1{1-2}] done transferring lease to s2: <nil>
I180731 05:30:34.888434 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 3 AND b = 4
I180731 05:30:34.905734 40090 storage/replica_proposal.go:222  [n2,s2,r8/2:/Table/1{1-2}] new range lease repl=(n2,s2):2 seq=4 start=1533015034.868083060,0 epo=1 pro=1533015034.868108661,0 following repl=(n1,s1):1 seq=3 start=1533014816.884498646,0 epo=1 pro=1533014829.774112634,0
I180731 05:30:34.910174 63025 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/3:/Table/2{0-1}] generated preemptive snapshot 923b15e9 at index 37
I180731 05:30:34.918777 63025 storage/store_snapshot.go:605  [replicate,n1,s1,r17/3:/Table/2{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 13, log entries: 27, rate-limit: 2.0 MiB/sec, 8ms
I180731 05:30:34.926627 63108 storage/replica_raftstorage.go:737  [n2,s2,r17/?:{-}] applying preemptive snapshot at index 37 (id=923b15e9, encoded size=7824, 1 rocksdb batches, 27 log entries)
I180731 05:30:34.962944 63030 storage/replica_command.go:745  [replicate,n2,s2,r77/3:/Table/74/1/3/{4-5}] change replicas (REMOVE_REPLICA (n1,s1):2): read existing descriptor r77:/Table/74/1/3/{4-5} [(n1,s1):2, (n2,s2):3, next=4]
I180731 05:30:34.976093 63108 storage/replica_raftstorage.go:743  [n2,s2,r17/?:/Table/2{0-1}] applied preemptive snapshot in 16ms [clear=10ms batch=0ms entries=6ms commit=1ms]
I180731 05:30:34.987318 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:34.997157 63025 storage/replica_command.go:745  [replicate,n1,s1,r17/3:/Table/2{0-1}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r17:/Table/2{0-1} [(n1,s1):3, next=4]
I180731 05:30:35.181692 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:35.214456 63030 storage/replica.go:3645  [n2,s2,r77/3:/Table/74/1/3/{4-5}] proposing REMOVE_REPLICA((n1,s1):2): updated=[(n2,s2):3] next=4
I180731 05:30:35.295174 63088 storage/store.go:2557  [replicaGC,n1,s1,r77/2:/Table/74/1/3/{4-5}] removing replica
I180731 05:30:35.297341 63088 storage/replica.go:844  [replicaGC,n1,s1,r77/2:/Table/74/1/3/{4-5}] removed 7 (0+7) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:35.341169 63139 storage/replica_command.go:745  [replicate,n2,s2,r8/2:/Table/1{1-2}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, (n2,s2):2, next=3]
I180731 05:30:35.364305 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 3 AND b = 4
I180731 05:30:35.375927 39292 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:35.445262 62994 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:35.506205 63025 storage/replica.go:3645  [n1,s1,r17/3:/Table/2{0-1}] proposing ADD_REPLICA((n2,s2):4): updated=[(n1,s1):3 (n2,s2):4] next=5
I180731 05:30:35.527480 63127 storage/replica_command.go:745  [replicate,n1,s1,r80/2:/Table/74/1/5/{8-9}] change replicas (REMOVE_REPLICA (n3,s3):1): read existing descriptor r80:/Table/74/1/5/{8-9} [(n3,s3):1, (n1,s1):2, next=3]
I180731 05:30:35.530068 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:35.548679 63139 storage/replica.go:3645  [n2,s2,r8/2:/Table/1{1-2}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):2] next=3
I180731 05:30:35.597743 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:35.624804 40262 storage/store.go:3638  [n1,s1,r8/1:/Table/1{1-2}] added to replica GC queue (peer suggestion)
I180731 05:30:35.646783 40262 storage/store.go:3638  [n1,s1,r8/1:/Table/1{1-2}] added to replica GC queue (peer suggestion)
I180731 05:30:35.636974 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) < (3, 4)
I180731 05:30:35.644512 63052 storage/store.go:2557  [replicaGC,n1,s1,r8/1:/Table/1{1-2}] removing replica
I180731 05:30:35.648925 63052 storage/replica.go:844  [replicaGC,n1,s1,r8/1:/Table/1{1-2}] removed 36 (29+7) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:35.776327 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 3 AND b = 4
I180731 05:30:35.784710 39293 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:35.813539 63190 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:35.898269 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:35.955649 63127 storage/replica.go:3645  [n1,s1,r80/2:/Table/74/1/5/{8-9}] proposing REMOVE_REPLICA((n3,s3):1): updated=[(n1,s1):2] next=3
I180731 05:30:36.013634 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:36.087790 40686 storage/store.go:3638  [n3,s3,r80/1:/Table/74/1/5/{8-9}] added to replica GC queue (peer suggestion)
I180731 05:30:36.092348 63185 storage/store.go:2557  [replicaGC,n3,s3,r80/1:/Table/74/1/5/{8-9}] removing replica
I180731 05:30:36.093939 63201 storage/replica_range_lease.go:554  [replicate,n1,s1,r17/3:/Table/2{0-1}] transferring lease to s2
I180731 05:30:36.125133 40549 server/status/runtime.go:424  [n3] runtime stats: 1.0 GiB RSS, 608 goroutines, 51 MiB/24 MiB/98 MiB GO alloc/idle/total, 102 MiB/148 MiB CGO alloc/total, 1874.93cgo/sec, 0.98/0.04 %(u/s)time, 0.04 %gc (8x)
I180731 05:30:36.128832 63185 storage/replica.go:844  [replicaGC,n3,s3,r80/1:/Table/74/1/5/{8-9}] removed 7 (0+7) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:36.154694 40142 storage/replica_proposal.go:222  [n2,s2,r17/4:/Table/2{0-1}] new range lease repl=(n2,s2):4 seq=6 start=1533015036.099486832,0 epo=1 pro=1533015036.099512730,0 following repl=(n1,s1):3 seq=5 start=1533014951.295890364,0 epo=1 pro=1533014951.295918649,0
I180731 05:30:36.158790 63201 storage/replica_range_lease.go:617  [replicate,n1,s1,r17/3:/Table/2{0-1}] done transferring lease to s2: <nil>
I180731 05:30:36.207210 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b = 7
I180731 05:30:36.211962 39294 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n3 established
I180731 05:30:36.246693 63136 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180731 05:30:36.323636 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b = 8
I180731 05:30:36.327289 63252 storage/replica_raftstorage.go:520  [replicate,n1,s1,r81/2:/Table/74/1/{5/9-6}] generated preemptive snapshot 5321a406 at index 26
I180731 05:30:36.338226 63252 storage/store_snapshot.go:605  [replicate,n1,s1,r81/2:/Table/74/1/{5/9-6}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 16, rate-limit: 2.0 MiB/sec, 10ms
I180731 05:30:36.351369 63237 storage/replica_raftstorage.go:737  [n2,s2,r81/?:{-}] applying preemptive snapshot at index 26 (id=5321a406, encoded size=4633, 1 rocksdb batches, 16 log entries)
I180731 05:30:36.354917 63237 storage/replica_raftstorage.go:743  [n2,s2,r81/?:/Table/74/1/{5/9-6}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180731 05:30:36.366995 63299 storage/replica_command.go:745  [replicate,n2,s2,r17/4:/Table/2{0-1}] change replicas (REMOVE_REPLICA (n1,s1):3): read existing descriptor r17:/Table/2{0-1} [(n1,s1):3, (n2,s2):4, next=5]
I180731 05:30:36.385269 63252 storage/replica_command.go:745  [replicate,n1,s1,r81/2:/Table/74/1/{5/9-6}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r81:/Table/74/1/{5/9-6} [(n1,s1):2, next=3]
I180731 05:30:36.571467 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b > 8
W180731 05:30:36.577770 40171 server/node.go:873  [n2,summaries] health alerts detected: {Alerts:[{StoreID:2 Category:METRICS Description:queue.replicate.process.failure Value:1}]}
I180731 05:30:36.676797 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) < (3, 4)
I180731 05:30:36.724932 63252 storage/replica.go:3645  [n1,s1,r81/2:/Table/74/1/{5/9-6}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):2 (n2,s2):3] next=4
I180731 05:30:36.816075 63299 storage/replica.go:3645  [n2,s2,r17/4:/Table/2{0-1}] proposing REMOVE_REPLICA((n1,s1):3): updated=[(n2,s2):4] next=5
I180731 05:30:36.839721 40262 storage/store.go:3638  [n1,s1,r17/3:/Table/2{0-1}] added to replica GC queue (peer suggestion)
I180731 05:30:36.872346 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 3 AND b = 4
I180731 05:30:36.881603 63217 storage/replica_range_lease.go:554  [replicate,n1,s1,r81/2:/Table/74/1/{5/9-6}] transferring lease to s2
I180731 05:30:36.886097 39297 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:36.904158 40095 storage/replica_proposal.go:222  [n2,s2,r81/3:/Table/74/1/{5/9-6}] new range lease repl=(n2,s2):3 seq=10 start=1533015036.881765716,0 epo=1 pro=1533015036.881791259,0 following repl=(n1,s1):2 seq=9 start=1533015017.104152457,0 epo=1 pro=1533015017.104207434,0
I180731 05:30:36.935181 63217 storage/replica_range_lease.go:617  [replicate,n1,s1,r81/2:/Table/74/1/{5/9-6}] done transferring lease to s2: <nil>
I180731 05:30:36.972243 63246 storage/replica_raftstorage.go:520  [replicate,n1,s1,r129/2:/Table/74/1/5{-/7}] generated preemptive snapshot 79c437c5 at index 23
I180731 05:30:37.001040 63244 storage/store.go:2557  [replicaGC,n1,s1,r17/3:/Table/2{0-1}] removing replica
I180731 05:30:37.002457 63244 storage/replica.go:844  [replicaGC,n1,s1,r17/3:/Table/2{0-1}] removed 8 (0+8) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:37.017413 63349 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:37.033719 63246 storage/store_snapshot.go:605  [replicate,n1,s1,r129/2:/Table/74/1/5{-/7}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 13, rate-limit: 2.0 MiB/sec, 61ms
I180731 05:30:37.039702 63364 storage/replica_raftstorage.go:737  [n2,s2,r129/?:{-}] applying preemptive snapshot at index 23 (id=79c437c5, encoded size=3292, 1 rocksdb batches, 13 log entries)
I180731 05:30:37.042752 63364 storage/replica_raftstorage.go:743  [n2,s2,r129/?:/Table/74/1/5{-/7}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180731 05:30:37.049466 63246 storage/replica_command.go:745  [replicate,n1,s1,r129/2:/Table/74/1/5{-/7}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r129:/Table/74/1/5{-/7} [(n1,s1):2, next=3]
I180731 05:30:37.130983 39510 server/status/runtime.go:424  [n1] runtime stats: 1.0 GiB RSS, 605 goroutines, 45 MiB/28 MiB/98 MiB GO alloc/idle/total, 101 MiB/148 MiB CGO alloc/total, 1939.92cgo/sec, 1.00/0.04 %(u/s)time, 0.04 %gc (8x)
I180731 05:30:37.147322 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:37.256204 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:37.257657 63335 storage/store.go:2557  [replicaGC,n2,s2,r129/?:/Table/74/1/5{-/7}] removing replica
I180731 05:30:37.259824 63335 storage/replica.go:844  [replicaGC,n2,s2,r129/?:/Table/74/1/5{-/7}] removed 7 (0+7) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:37.342013 60142 ccl/partitionccl/partition_test.go:1331  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
[n1,s1,r129/2:/Table/74/1/5{-/7}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2593] executing ExecStmt: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7)
  [n1,client=127.0.0.1:50052,user=root] executing: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50052,user=root] [Open pos:2593] executing ExecStmt: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7)
  [n1,client=127.0.0.1:50052,user=root] executing: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7) in state: Open
  [n1,client=127.0.0.1:50052,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50052,user=root] generating optimizer plan
  [n1,client=127.0.0.1:50052,user=root] added table 'data.public."multi col list partitioning - DEFAULT"' to table collection
  [n1,client=127.0.0.1:50052,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50052,user=root] planning ends
  [n1,client=127.0.0.1:50052,user=root] checking distributability
  [n1,client=127.0.0.1:50052,user=root] distributable plan: true
  [n1,client=127.0.0.1:50052,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50052,user=root] creating DistSQL plan
  [n1,client=127.0.0.1:50052,user=root] querying next range at /Table/74/1/5
  [n1,client=127.0.0.1:50052,user=root] running DistSQL plan
   === SPAN START: flow ===
  [client=127.0.0.1:50052,user=root,n1] starting (1 processors, 0 startables)
   === SPAN START: table reader ===
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 1µs
cockroach.processorid: 0
  [client=127.0.0.1:50052,user=root,n1] Scan /Table/74/1/5{-/6/#}
   === SPAN START: dist sender ===
  [client=127.0.0.1:50052,user=root,txn=a3fb0a58,n1] querying next range at /Table/74/1/5
  [client=127.0.0.1:50052,user=root,txn=a3fb0a58,n1] r129: sending batch 1 Scan to (n1,s1):2
  [client=127.0.0.1:50052,user=root,txn=a3fb0a58,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Scan
  [n1,s1] executing 1 requests
  [n1,s1,r129/2:/Table/74/1/5{-/7}] read-only path
  [n1,s1,r129/2:/Table/74/1/5{-/7}] read has no clock uncertainty
  [n1,s1,r129/2:/Table/74/1/5{-/7}] command queue
  [n1,s1,r129/2:/Table/74/1/5{-/7}] waiting for read lock
  [n1,s1,r129/2:/Table/74/1/5{-/7}] read completed
   === SPAN START: ordered aggregator ===
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.stalltime: 265µs
cockroach.processorid: 1
cockroach.stat.aggregator.mem.max: 10 KiB
  [client=127.0.0.1:50052,user=root,n1,orderedAgg/1] accumulation complete
  [client=127.0.0.1:50052,user=root,n1,orderedAgg/1] exiting aggregator
  [n1,client=127.0.0.1:50052,user=root] execution ends
  [n1,client=127.0.0.1:50052,user=root] rows affected: 1
  [n1,client=127.0.0.1:50052,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50052,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2594] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50052,user=root] executing: SET TRACING = off in state: NoTxn
I180731 05:30:37.342297 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:37.494518 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:37.560197 63246 storage/replica.go:3645  [n1,s1,r129/2:/Table/74/1/5{-/7}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):2 (n2,s2):3] next=4
I180731 05:30:37.618067 63395 storage/replica_command.go:745  [replicate,n2,s2,r81/3:/Table/74/1/{5/9-6}] change replicas (REMOVE_REPLICA (n1,s1):2): read existing descriptor r81:/Table/74/1/{5/9-6} [(n1,s1):2, (n2,s2):3, next=4]
I180731 05:30:37.865848 60142 ccl/partitionccl/partition_test.go:1331  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
[n1,s1,r129/2:/Table/74/1/5{-/7}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2605] executing ExecStmt: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7)
  [n1,client=127.0.0.1:50052,user=root] executing: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50052,user=root] [Open pos:2605] executing ExecStmt: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7)
  [n1,client=127.0.0.1:50052,user=root] executing: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7) in state: Open
  [n1,client=127.0.0.1:50052,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50052,user=root] generating optimizer plan
  [n1,client=127.0.0.1:50052,user=root] added table 'data.public."multi col list partitioning - DEFAULT"' to table collection
  [n1,client=127.0.0.1:50052,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50052,user=root] planning ends
  [n1,client=127.0.0.1:50052,user=root] checking distributability
  [n1,client=127.0.0.1:50052,user=root] distributable plan: true
  [n1,client=127.0.0.1:50052,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50052,user=root] creating DistSQL plan
  [n1,client=127.0.0.1:50052,user=root] querying next range at /Table/74/1/5
  [n1,client=127.0.0.1:50052,user=root] running DistSQL plan
   === SPAN START: flow ===
  [client=127.0.0.1:50052,user=root,n1] starting (1 processors, 0 startables)
   === SPAN START: table reader ===
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 2µs
cockroach.processorid: 0
  [client=127.0.0.1:50052,user=root,n1] Scan /Table/74/1/5{-/6/#}
   === SPAN START: dist sender ===
  [client=127.0.0.1:50052,user=root,txn=a9d2607e,n1] querying next range at /Table/74/1/5
  [client=127.0.0.1:50052,user=root,txn=a9d2607e,n1] r129: sending batch 1 Scan to (n1,s1):2
  [client=127.0.0.1:50052,user=root,txn=a9d2607e,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Scan
  [n1,s1] executing 1 requests
  [n1,s1,r129/2:/Table/74/1/5{-/7}] read-only path
  [n1,s1,r129/2:/Table/74/1/5{-/7}] read has no clock uncertainty
  [n1,s1,r129/2:/Table/74/1/5{-/7}] command queue
  [n1,s1,r129/2:/Table/74/1/5{-/7}] waiting for read lock
  [n1,s1,r129/2:/Table/74/1/5{-/7}] read completed
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.stalltime: 261µs
cockroach.stat.aggregator.mem.max: 10 KiB
  [client=127.0.0.1:50052,user=root,n1,orderedAgg/1] accumulation complete
  [client=127.0.0.1:50052,user=root,n1,orderedAgg/1] exiting aggregator
  [n1,client=127.0.0.1:50052,user=root] execution ends
  [n1,client=127.0.0.1:50052,user=root] rows affected: 1
  [n1,client=127.0.0.1:50052,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50052,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2606] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50052,user=root] executing: SET TRACING = off in state: NoTxn
I180731 05:30:37.866577 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 3 AND b = 4
I180731 05:30:37.906311 39296 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:37.915043 63338 storage/replica_raftstorage.go:520  [raftsnapshot,n1,s1,r129/2:/Table/74/1/5{-/7}] generated Raft snapshot 366147b9 at index 25
I180731 05:30:37.947310 63433 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:37.962209 63338 storage/store_snapshot.go:605  [raftsnapshot,n1,s1,r129/2:/Table/74/1/5{-/7}] streamed snapshot to (n2,s2):3: kv pairs: 12, log entries: 15, rate-limit: 8.0 MiB/sec, 9ms
I180731 05:30:37.972745 63438 storage/replica_raftstorage.go:737  [n2,s2,r129/3:{-}] applying Raft snapshot at index 25 (id=366147b9, encoded size=4771, 1 rocksdb batches, 15 log entries)
I180731 05:30:37.976086 63438 storage/replica_raftstorage.go:743  [n2,s2,r129/3:/Table/74/1/5{-/7}] applied Raft snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180731 05:30:38.015751 63395 storage/replica.go:3645  [n2,s2,r81/3:/Table/74/1/{5/9-6}] proposing REMOVE_REPLICA((n1,s1):2): updated=[(n2,s2):3] next=4
I180731 05:30:38.038531 40262 storage/store.go:3638  [n1,s1,r81/2:/Table/74/1/{5/9-6}] added to replica GC queue (peer suggestion)
I180731 05:30:38.070229 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:38.079106 63444 storage/replica_range_lease.go:554  [replicate,n1,s1,r129/2:/Table/74/1/5{-/7}] transferring lease to s2
I180731 05:30:38.086441 63444 storage/replica_range_lease.go:617  [replicate,n1,s1,r129/2:/Table/74/1/5{-/7}] done transferring lease to s2: <nil>
I180731 05:30:38.090288 40129 storage/replica_proposal.go:222  [n2,s2,r129/3:/Table/74/1/5{-/7}] new range lease repl=(n2,s2):3 seq=11 start=1533015038.079305775,0 epo=1 pro=1533015038.079330977,0 following repl=(n1,s1):2 seq=10 start=1533015016.546405349,0 epo=1 pro=1533015016.546446929,0
I180731 05:30:38.100511 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:38.218118 63376 storage/store.go:2557  [replicaGC,n1,s1,r81/2:/Table/74/1/{5/9-6}] removing replica
I180731 05:30:38.220235 63376 storage/replica.go:844  [replicaGC,n1,s1,r81/2:/Table/74/1/{5/9-6}] removed 7 (0+7) keys in 1ms [clear=0ms commit=0ms]
I180731 05:30:38.350057 60142 ccl/partitionccl/partition_test.go:1331  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
[n3,s3,r1/5:/{Min-System/}] read completed
[n3,s3,r1/5:/{Min-System/}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2623] executing ExecStmt: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7)
  [n1,client=127.0.0.1:50052,user=root] executing: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50052,user=root] [Open pos:2623] executing ExecStmt: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7)
  [n1,client=127.0.0.1:50052,user=root] executing: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b < 7) in state: Open
  [n1,client=127.0.0.1:50052,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50052,user=root] generating optimizer plan
  [n1,client=127.0.0.1:50052,user=root] added table 'data.public."multi col list partitioning - DEFAULT"' to table collection
  [n1,client=127.0.0.1:50052,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50052,user=root] planning ends
  [n1,client=127.0.0.1:50052,user=root] checking distributability
  [n1,client=127.0.0.1:50052,user=root] distributable plan: true
  [n1,client=127.0.0.1:50052,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50052,user=root] creating DistSQL plan
  [n1,client=127.0.0.1:50052,user=root] querying next range at /Table/74/1/5
  [n1,client=127.0.0.1:50052,user=root] running DistSQL plan
   === SPAN START: flow ===
  [client=127.0.0.1:50052,user=root,n1] starting (1 processors, 0 startables)
   === SPAN START: table reader ===
cockroach.stat.tablereader.stalltime: 2µs
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
  [client=127.0.0.1:50052,user=root,n1] Scan /Table/74/1/5{-/6/#}
   === SPAN START: dist sender ===
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] querying next range at /Table/74/1/5
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] r129: sending batch 1 Scan to (n1,s1):2
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Scan
  [n1,s1] executing 1 requests
  [n1,s1,r129/2:/Table/74/1/5{-/7}] read-only path
  [n1,s1,r129/2:/Table/74/1/5{-/7}] replica.Send got error: [NotLeaseHolderError] r129: replica (n1,s1):2 not lease holder; current lease is repl=(n2,s2):3 seq=11 start=1533015038.079305775,0 epo=1 pro=1533015038.079330977,0
  [n1] *roachpb.NotLeaseHolderError
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] reply error [txn: cbefc598], Scan [/Table/74/1/5,/Table/74/1/5/6/#): r129 was not found
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] evicting range descriptor on send error and backoff for re-lookup
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] evicting cached range descriptor
   === SPAN START: range lookup ===
   === SPAN START: dist sender ===
  [client=127.0.0.1:50052,user=root,txn=cbefc598,range-lookup=/Table/74/1/5,n1] querying next range at /Meta2/Table/74/1/5/NULL
   === SPAN START: range lookup ===
   === SPAN START: dist sender ===
  [client=127.0.0.1:50052,user=root,txn=cbefc598,range-lookup=/Table/74/1/5,range-lookup=/Meta2/Table/74/1/5/NULL,n1] querying next range at /Meta1/Table/74/1/5/NULL/NULL
   === SPAN START: range lookup ===
  [client=127.0.0.1:50052,user=root,txn=cbefc598,range-lookup=/Table/74/1/5,range-lookup=/Meta2/Table/74/1/5/NULL,n1] looked up range descriptor
  [client=127.0.0.1:50052,user=root,txn=cbefc598,range-lookup=/Table/74/1/5,range-lookup=/Meta2/Table/74/1/5/NULL,n1] r1: sending batch 1 Scan to (n3,s3):5
  [client=127.0.0.1:50052,user=root,txn=cbefc598,range-lookup=/Table/74/1/5,range-lookup=/Meta2/Table/74/1/5/NULL,n1] sending request to 127.0.0.1:43437
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n3] 1 Scan
  [n3,s3] executing 1 requests
  [n3,s3,r1/5:/{Min-System/}] read-only path
  [n3,s3,r1/5:/{Min-System/}] command queue
  [n3,s3,r1/5:/{Min-System/}] operation accepts inconsistent results
  [n3,s3,r1/5:/{Min-System/}] waiting for read lock
  [n3,s3,r1/5:/{Min-System/}] read completed
  [client=127.0.0.1:50052,user=root,txn=cbefc598,range-lookup=/Table/74/1/5,n1] looked up range descriptor
  [client=127.0.0.1:50052,user=root,txn=cbefc598,range-lookup=/Table/74/1/5,n1] r1: sending batch 1 Scan to (n3,s3):5
  [client=127.0.0.1:50052,user=root,txn=cbefc598,range-lookup=/Table/74/1/5,n1] sending request to 127.0.0.1:43437
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n3] 1 Scan
  [n3,s3] executing 1 requests
  [n3,s3,r1/5:/{Min-System/}] read-only path
  [n3,s3,r1/5:/{Min-System/}] command queue
  [n3,s3,r1/5:/{Min-System/}] operation accepts inconsistent results
  [n3,s3,r1/5:/{Min-System/}] waiting for read lock
  [n3,s3,r1/5:/{Min-System/}] read completed
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] looked up range descriptor
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] r129: sending batch 1 Scan to (n2,s2):3
  [client=127.0.0.1:50052,user=root,txn=cbefc598,n1] sending request to 127.0.0.1:39957
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r129/3:/Table/74/1/5{-/7}] read-only path
  [n2,s2,r129/3:/Table/74/1/5{-/7}] command queue
  [n2,s2,r129/3:/Table/74/1/5{-/7}] waiting for read lock
  [n2,s2,r129/3:/Table/74/1/5{-/7}] read completed
   === SPAN START: ordered aggregator ===
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.stalltime: 866µs
cockroach.processorid: 1
  [client=127.0.0.1:50052,user=root,n1,orderedAgg/1] accumulation complete
  [client=127.0.0.1:50052,user=root,n1,orderedAgg/1] exiting aggregator
  [n1,client=127.0.0.1:50052,user=root] execution ends
  [n1,client=127.0.0.1:50052,user=root] rows affected: 1
  [n1,client=127.0.0.1:50052,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50052,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2624] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50052,user=root] executing: SET TRACING = off in state: NoTxn
I180731 05:30:38.350479 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) < (3, 4)
I180731 05:30:38.415427 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 3 AND b = 4
I180731 05:30:38.441617 39298 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:38.484103 63389 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:38.541986 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:38.594538 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:38.599085 39300 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:38.603873 63468 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:38.746373 63473 storage/replica_command.go:745  [replicate,n2,s2,r129/3:/Table/74/1/5{-/7}] change replicas (REMOVE_REPLICA (n1,s1):2): read existing descriptor r129:/Table/74/1/5{-/7} [(n1,s1):2, (n2,s2):3, next=4]
I180731 05:30:38.953215 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b = 7
I180731 05:30:38.966424 39299 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n3 established
I180731 05:30:38.979182 63457 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180731 05:30:39.043658 63473 storage/replica.go:3645  [n2,s2,r129/3:/Table/74/1/5{-/7}] proposing REMOVE_REPLICA((n1,s1):2): updated=[(n2,s2):3] next=4
I180731 05:30:39.209743 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b = 8
I180731 05:30:39.210598 40262 storage/store.go:3638  [n1,s1,r129/2:/Table/74/1/5{-/7}] added to replica GC queue (peer suggestion)
I180731 05:30:39.232020 40250 rpc/nodedialer/nodedialer.go:92  [intExec=adopt-job] connection to n2 established
I180731 05:30:39.263629 63515 rpc/nodedialer/nodedialer.go:92  [n2] connection to n3 established
I180731 05:30:39.296601 63560 storage/store.go:2557  [replicaGC,n1,s1,r129/2:/Table/74/1/5{-/7}] removing replica
I180731 05:30:39.298699 63560 storage/replica.go:844  [replicaGC,n1,s1,r129/2:/Table/74/1/5{-/7}] removed 8 (0+8) keys in 1ms [clear=0ms commit=1ms]
I180731 05:30:39.336680 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b > 8
I180731 05:30:39.689786 60142 ccl/partitionccl/partition_test.go:1331  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b > 8
[n3,s3,r1/5:/{Min-System/}] read completed
[n3,s3,r1/5:/{Min-System/}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2665] executing ExecStmt: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b > 8)
  [n1,client=127.0.0.1:50052,user=root] executing: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b > 8) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50052,user=root] [Open pos:2665] executing ExecStmt: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b > 8)
  [n1,client=127.0.0.1:50052,user=root] executing: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a = 5) AND (b > 8) in state: Open
  [n1,client=127.0.0.1:50052,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50052,user=root] generating optimizer plan
  [n1,client=127.0.0.1:50052,user=root] added table 'data.public."multi col list partitioning - DEFAULT"' to table collection
  [n1,client=127.0.0.1:50052,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50052,user=root] planning ends
  [n1,client=127.0.0.1:50052,user=root] checking distributability
  [n1,client=127.0.0.1:50052,user=root] distributable plan: true
  [n1,client=127.0.0.1:50052,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50052,user=root] creating DistSQL plan
  [n1,client=127.0.0.1:50052,user=root] querying next range at /Table/74/1/5/9
  [n1,client=127.0.0.1:50052,user=root] running DistSQL plan
   === SPAN START: flow ===
  [client=127.0.0.1:50052,user=root,n1] starting (1 processors, 0 startables)
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 2µs
  [client=127.0.0.1:50052,user=root,n1] Scan /Table/74/1/{5/9-6}
   === SPAN START: dist sender ===
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] querying next range at /Table/74/1/5/9
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] r81: sending batch 1 Scan to (n1,s1):2
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Scan
  [n1,s1] executing 1 requests
  [n1] *roachpb.RangeNotFoundError
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] reply error [txn: 3f961fc4], Scan [/Table/74/1/5/9,/Table/74/1/6): r81 was not found
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] evicting range descriptor on send error and backoff for re-lookup
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] evicting cached range descriptor
   === SPAN START: range lookup ===
   === SPAN START: dist sender ===
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,range-lookup=/Table/74/1/5/9,n1] querying next range at /Meta2/Table/74/1/5/9/NULL
   === SPAN START: range lookup ===
   === SPAN START: dist sender ===
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,range-lookup=/Table/74/1/5/9,range-lookup=/Meta2/Table/74/1/5/9/NULL,n1] querying next range at /Meta1/Table/74/1/5/9/NULL/NULL
   === SPAN START: range lookup ===
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,range-lookup=/Table/74/1/5/9,range-lookup=/Meta2/Table/74/1/5/9/NULL,n1] looked up range descriptor
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,range-lookup=/Table/74/1/5/9,range-lookup=/Meta2/Table/74/1/5/9/NULL,n1] r1: sending batch 1 Scan to (n3,s3):5
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,range-lookup=/Table/74/1/5/9,range-lookup=/Meta2/Table/74/1/5/9/NULL,n1] sending request to 127.0.0.1:43437
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n3] 1 Scan
  [n3,s3] executing 1 requests
  [n3,s3,r1/5:/{Min-System/}] read-only path
  [n3,s3,r1/5:/{Min-System/}] command queue
  [n3,s3,r1/5:/{Min-System/}] operation accepts inconsistent results
  [n3,s3,r1/5:/{Min-System/}] waiting for read lock
  [n3,s3,r1/5:/{Min-System/}] read completed
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,range-lookup=/Table/74/1/5/9,n1] looked up range descriptor
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,range-lookup=/Table/74/1/5/9,n1] r1: sending batch 1 Scan to (n3,s3):5
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,range-lookup=/Table/74/1/5/9,n1] sending request to 127.0.0.1:43437
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n3] 1 Scan
  [n3,s3] executing 1 requests
  [n3,s3,r1/5:/{Min-System/}] read-only path
  [n3,s3,r1/5:/{Min-System/}] command queue
  [n3,s3,r1/5:/{Min-System/}] operation accepts inconsistent results
  [n3,s3,r1/5:/{Min-System/}] waiting for read lock
  [n3,s3,r1/5:/{Min-System/}] read completed
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] looked up range descriptor
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] r81: sending batch 1 Scan to (n2,s2):3
  [client=127.0.0.1:50052,user=root,txn=3f961fc4,n1] sending request to 127.0.0.1:39957
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r81/3:/Table/74/1/{5/9-6}] read-only path
  [n2,s2,r81/3:/Table/74/1/{5/9-6}] command queue
  [n2,s2,r81/3:/Table/74/1/{5/9-6}] waiting for read lock
  [n2,s2,r81/3:/Table/74/1/{5/9-6}] read completed
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.stalltime: 1.005ms
cockroach.stat.aggregator.mem.max: 10 KiB
  [client=127.0.0.1:50052,user=root,n1,orderedAgg/1] accumulation complete
  [client=127.0.0.1:50052,user=root,n1,orderedAgg/1] exiting aggregator
  [n1,client=127.0.0.1:50052,user=root] execution ends
  [n1,client=127.0.0.1:50052,user=root] rows affected: 1
  [n1,client=127.0.0.1:50052,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50052,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50052,user=root] [NoTxn pos:2666] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50052,user=root] executing: SET TRACING = off in state: NoTxn
I180731 05:30:39.690148 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b = 7
I180731 05:30:39.701396 39301 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n3 established
I180731 05:30:39.711929 63596 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180731 05:30:39.801735 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b = 8
I180731 05:30:39.947623 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b > 8
I180731 05:30:39.992285 39303 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:39.997160 63606 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:40.122972 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a > 5
I180731 05:30:40.254652 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) < (3, 4)
I180731 05:30:40.513203 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 3 AND b = 4
I180731 05:30:40.627469 39302 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:40.633550 63616 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180731 05:30:40.744432 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE (a, b) > (3, 4) AND a < 5
I180731 05:30:40.925083 60142 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "multi col list partitioning - DEFAULT" WHERE a = 5 AND b < 7
I180731 05:30:40.932250 39305 rpc/nodedialer/nodedialer.go:92  [n1,client=127.0.0.1:50052,user=root] connection to n2 established
I180731 05:30:40.993197 63566 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
    --- FAIL: TestRepartitioning/multi_col_list_partitioning_-_DEFAULT_DEFAULT/multi_col_list_partitioning_-_DEFAULT (35.57s)
        testing.go:730: race detected during execution of test
cockroach-teamcity commented 6 years ago

SHA: https://github.com/cockroachdb/cockroach/commits/dda801b21f2668537221f58d06a9960d2c05555f

Parameters:

TAGS=
GOFLAGS=-race

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=806990&tab=buildLog

tbg commented 6 years ago

Fixed in #28085