Closed cockroach-teamcity closed 6 years ago
The following tests appear to have failed:
#805351:
--- FAIL: testrace/TestInitialPartitioning/secondary_index_-_NULL (0.000s) Test ended in panic. ------- Stdout: ------- I180730 18:39:30.780169 25100 storage/replica_command.go:745 [replicate,n1,s1,r205/2:/Table/74/2{-/4}] change replicas (REMOVE_REPLICA (n2,s2):1): read existing descriptor r205:/Table/74/2{-/4} [(n2,s2):1, (n1,s1):2, next=3] I180730 18:39:30.851684 2281 server/status/runtime.go:424 [n3] runtime stats: 906 MiB RSS, 598 goroutines, 34 MiB/25 MiB/81 MiB GO alloc/idle/total, 97 MiB/130 MiB CGO alloc/total, 3067.95cgo/sec, 1.72/0.09 %(u/s)time, 0.02 %gc (14x) I180730 18:39:31.131161 25100 storage/replica.go:3645 [n1,s1,r205/2:/Table/74/2{-/4}] proposing REMOVE_REPLICA((n2,s2):1): updated=[(n1,s1):2] next=3 I180730 18:39:31.151140 25073 storage/store.go:2557 [replicaGC,n2,s2,r205/1:/Table/74/2{-/4}] removing replica I180730 18:39:31.175337 2043 storage/store.go:3638 [n2,s2,r205/1:/Table/74/2{-/4}] added to replica GC queue (peer suggestion) I180730 18:39:31.177427 25073 storage/replica.go:844 [replicaGC,n2,s2,r205/1:/Table/74/2{-/4}] removed 8 (0+8) keys in 1ms [clear=0ms commit=1ms] I180730 18:39:31.191582 2050 storage/store.go:3657 [n1,s1,r205/2:/Table/74/2{-/4}] added to replica GC queue (contacted deleted peer) I180730 18:39:31.259851 2472 sql/event_log.go:126 [n1,client=127.0.0.1:45234,user=root] Event: "create_table", target: 75, info: {TableName:data.public."secondary index - NULL" Statement:CREATE TABLE "secondary index - NULL" (a INT PRIMARY KEY, b INT, INDEX b_idx (b) PARTITION BY LIST (b) (PARTITION pl1 VALUES IN (NULL, 1), PARTITION p3 VALUES IN (3))) User:root} I180730 18:39:31.370106 25103 storage/replica_command.go:279 [split,n2,s2,r204/1:/{Table/74/3-Max}] initiating a split of this range at key /Table/75 [r206] I180730 18:39:31.514129 1897 storage/replica_proposal.go:222 [n2,s2,r204/1:/{Table/74/3-Max}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:31.875735 2472 sql/event_log.go:126 [n1,client=127.0.0.1:45234,user=root] Event: "set_zone_config", target: 75, info: {Target:data."secondary index - NULL"@b_idx Config:constraints: [+n1] User:root} I180730 18:39:31.914008 25225 storage/replica_command.go:279 [split,n2,s2,r206/1:/{Table/75-Max}] initiating a split of this range at key /Table/75/2 [r207] I180730 18:39:32.305415 1920 storage/replica_proposal.go:222 [n2,s2,r206/1:/{Table/75-Max}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:32.328548 25261 storage/replica_command.go:279 [split,n2,s2,r207/1:/{Table/75/2-Max}] initiating a split of this range at key /Table/75/3 [r208] I180730 18:39:32.354438 2472 sql/event_log.go:126 [n1,client=127.0.0.1:45234,user=root] Event: "set_zone_config", target: 75, info: {Target:data."secondary index - NULL".pl1 Config:constraints: [+n2] User:root} I180730 18:39:32.567419 1929 storage/replica_proposal.go:222 [n2,s2,r207/1:/{Table/75/2-Max}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:32.583197 25361 storage/replica_command.go:279 [split,n2,s2,r207/1:/Table/75/{2-3}] initiating a split of this range at key /Table/75/2/NULL [r209] I180730 18:39:32.920874 2472 sql/event_log.go:126 [n1,client=127.0.0.1:45234,user=root] Event: "set_zone_config", target: 75, info: {Target:data."secondary index - NULL".p3 Config:constraints: [+n3] User:root} I180730 18:39:32.921958 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:32.998803 1931 storage/replica_proposal.go:222 [n2,s2,r207/1:/Table/75/{2-3}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:33.032009 25307 storage/replica_command.go:279 [split,n2,s2,r209/1:/Table/75/{2/NULL-3}] initiating a split of this range at key /Table/75/2/!NULL [r210] I180730 18:39:33.049202 25427 storage/replica_raftstorage.go:520 [replicate,n2,s2,r207/1:/Table/75/2{-/NULL}] generated preemptive snapshot 6e6ebc45 at index 19 I180730 18:39:33.056028 25427 storage/store_snapshot.go:605 [replicate,n2,s2,r207/1:/Table/75/2{-/NULL}] streamed snapshot to (n1,s1):?: kv pairs: 10, log entries: 9, rate-limit: 2.0 MiB/sec, 6ms I180730 18:39:33.059625 25415 storage/replica_raftstorage.go:737 [n1,s1,r207/?:{-}] applying preemptive snapshot at index 19 (id=6e6ebc45, encoded size=4103, 1 rocksdb batches, 9 log entries) I180730 18:39:33.072006 25415 storage/replica_raftstorage.go:743 [n1,s1,r207/?:/Table/75/2{-/NULL}] applied preemptive snapshot in 8ms [clear=5ms batch=0ms entries=1ms commit=0ms] I180730 18:39:33.091164 25427 storage/replica_command.go:745 [replicate,n2,s2,r207/1:/Table/75/2{-/NULL}] change replicas (ADD_REPLICA (n1,s1):2): read existing descriptor r207:/Table/75/2{-/NULL} [(n2,s2):1, next=2] I180730 18:39:33.191067 1095 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:33.209245 25463 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:33.247359 1877 storage/replica_proposal.go:222 [n2,s2,r209/1:/Table/75/{2/NULL-3}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:33.256344 25509 storage/replica_command.go:279 [split,n2,s2,r210/1:/Table/75/{2/!NULL-3}] initiating a split of this range at key /Table/75/2/1 [r211] I180730 18:39:33.356789 25427 storage/replica.go:3645 [n2,s2,r207/1:/Table/75/2{-/NULL}] proposing ADD_REPLICA((n1,s1):2): updated=[(n2,s2):1 (n1,s1):2] next=3 I180730 18:39:33.387489 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:33.392356 1096 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:33.397604 25539 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:33.465611 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL I180730 18:39:33.471310 1097 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:33.473955 25545 storage/replica_range_lease.go:554 [replicate,n2,s2,r207/1:/Table/75/2{-/NULL}] transferring lease to s1 I180730 18:39:33.483671 25521 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:33.510124 25545 storage/replica_range_lease.go:617 [replicate,n2,s2,r207/1:/Table/75/2{-/NULL}] done transferring lease to s1: <nil> I180730 18:39:33.512069 1085 storage/replica_proposal.go:222 [n1,s1,r207/2:/Table/75/2{-/NULL}] new range lease repl=(n1,s1):2 seq=6 start=1532975973.474121366,0 epo=1 pro=1532975973.474191315,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:33.515260 1891 storage/replica_proposal.go:222 [n2,s2,r210/1:/Table/75/{2/!NULL-3}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:33.531366 25548 storage/replica_command.go:279 [split,n2,s2,r211/1:/Table/75/{2/1-3}] initiating a split of this range at key /Table/75/2/2 [r212] I180730 18:39:33.587940 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:33.591837 25532 storage/replica_raftstorage.go:520 [replicate,n2,s2,r210/1:/Table/75/2/{!NULL-1}] generated preemptive snapshot 85fc316e at index 15 I180730 18:39:33.612975 1098 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:33.617171 25532 storage/store_snapshot.go:605 [replicate,n2,s2,r210/1:/Table/75/2/{!NULL-1}] streamed snapshot to (n1,s1):?: kv pairs: 9, log entries: 5, rate-limit: 2.0 MiB/sec, 20ms I180730 18:39:33.624897 25591 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:33.626340 25589 storage/replica_raftstorage.go:737 [n1,s1,r210/?:{-}] applying preemptive snapshot at index 15 (id=85fc316e, encoded size=2398, 1 rocksdb batches, 5 log entries) I180730 18:39:33.634151 25589 storage/replica_raftstorage.go:743 [n1,s1,r210/?:/Table/75/2/{!NULL-1}] applied preemptive snapshot in 8ms [clear=1ms batch=0ms entries=1ms commit=4ms] I180730 18:39:33.646427 25532 storage/replica_command.go:745 [replicate,n2,s2,r210/1:/Table/75/2/{!NULL-1}] change replicas (ADD_REPLICA (n1,s1):2): read existing descriptor r210:/Table/75/2/{!NULL-1} [(n2,s2):1, next=2] I180730 18:39:33.676503 25597 storage/replica_raftstorage.go:520 [replicate,n1,s1,r21/3:/Table/5{0-1}] generated preemptive snapshot 767f1f5f at index 34 I180730 18:39:33.694063 25597 storage/store_snapshot.go:605 [replicate,n1,s1,r21/3:/Table/5{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 24, rate-limit: 2.0 MiB/sec, 17ms I180730 18:39:33.698287 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:33.703758 1099 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:33.712229 25554 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:33.720538 25581 storage/replica_raftstorage.go:737 [n3,s3,r21/?:{-}] applying preemptive snapshot at index 34 (id=767f1f5f, encoded size=6958, 1 rocksdb batches, 24 log entries) I180730 18:39:33.740166 25581 storage/replica_raftstorage.go:743 [n3,s3,r21/?:/Table/5{0-1}] applied preemptive snapshot in 19ms [clear=0ms batch=0ms entries=18ms commit=1ms] I180730 18:39:33.773939 25597 storage/replica_command.go:745 [replicate,n1,s1,r21/3:/Table/5{0-1}] change replicas (ADD_REPLICA (n3,s3):4): read existing descriptor r21:/Table/5{0-1} [(n1,s1):3, next=4] I180730 18:39:33.825557 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:33.830603 1100 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:33.845547 25633 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:33.884517 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:33.893438 1927 storage/replica_proposal.go:222 [n2,s2,r211/1:/Table/75/{2/1-3}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:33.907491 1101 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:33.913306 25597 storage/replica.go:3645 [n1,s1,r21/3:/Table/5{0-1}] proposing ADD_REPLICA((n3,s3):4): updated=[(n1,s1):3 (n3,s3):4] next=5 I180730 18:39:33.918371 25673 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:33.922317 25688 storage/replica_command.go:279 [split,n2,s2,r212/1:/Table/75/{2/2-3}] initiating a split of this range at key /Table/75/2/3 [r213] I180730 18:39:33.982812 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:33.993391 25532 storage/replica.go:3645 [n2,s2,r210/1:/Table/75/2/{!NULL-1}] proposing ADD_REPLICA((n1,s1):2): updated=[(n2,s2):1 (n1,s1):2] next=3 I180730 18:39:34.000148 1102 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:34.003380 25748 storage/replica_range_lease.go:554 [replicate,n1,s1,r21/3:/Table/5{0-1}] transferring lease to s3 I180730 18:39:34.018152 25748 storage/replica_range_lease.go:617 [replicate,n1,s1,r21/3:/Table/5{0-1}] done transferring lease to s3: <nil> I180730 18:39:34.022135 2318 storage/replica_proposal.go:222 [n3,s3,r21/4:/Table/5{0-1}] new range lease repl=(n3,s3):4 seq=5 start=1532975974.004261721,0 epo=1 pro=1532975974.004278758,0 following repl=(n1,s1):3 seq=4 start=1532975949.955759270,0 epo=1 pro=1532975949.974871089,0 I180730 18:39:34.046712 25663 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:34.104924 25666 storage/replica_range_lease.go:554 [replicate,n2,s2,r210/1:/Table/75/2/{!NULL-1}] transferring lease to s1 I180730 18:39:34.139629 25666 storage/replica_range_lease.go:617 [replicate,n2,s2,r210/1:/Table/75/2/{!NULL-1}] done transferring lease to s1: <nil> I180730 18:39:34.143153 1261 storage/replica_proposal.go:222 [n1,s1,r210/2:/Table/75/2/{!NULL-1}] new range lease repl=(n1,s1):2 seq=6 start=1532975974.105100271,0 epo=1 pro=1532975974.105131958,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:34.151345 25757 storage/replica_raftstorage.go:520 [replicate,n2,s2,r158/1:/Table/69{-/1}] generated preemptive snapshot 384de396 at index 18 I180730 18:39:34.174379 25757 storage/store_snapshot.go:605 [replicate,n2,s2,r158/1:/Table/69{-/1}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 22ms I180730 18:39:34.174650 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:34.180818 25781 storage/replica_raftstorage.go:737 [n3,s3,r158/?:{-}] applying preemptive snapshot at index 18 (id=384de396, encoded size=2379, 1 rocksdb batches, 8 log entries) I180730 18:39:34.185308 25781 storage/replica_raftstorage.go:743 [n3,s3,r158/?:/Table/69{-/1}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=3ms commit=0ms] I180730 18:39:34.192298 25757 storage/replica_command.go:745 [replicate,n2,s2,r158/1:/Table/69{-/1}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r158:/Table/69{-/1} [(n2,s2):1, next=2] I180730 18:39:34.196845 1103 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:34.214606 25844 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:34.264157 1880 storage/replica_proposal.go:222 [n2,s2,r212/1:/Table/75/{2/2-3}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:34.291391 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:34.306543 1104 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:34.307261 25815 storage/replica_command.go:279 [split,n2,s2,r213/1:/Table/75/{2/3-3}] initiating a split of this range at key /Table/75/2/4 [r214] I180730 18:39:34.322276 25648 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:34.430018 25757 storage/replica.go:3645 [n2,s2,r158/1:/Table/69{-/1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n2,s2):1 (n3,s3):2] next=3 I180730 18:39:34.449800 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:34.454891 1105 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:34.459003 25822 storage/replica_command.go:745 [replicate,n1,s1,r207/2:/Table/75/2{-/NULL}] change replicas (REMOVE_REPLICA (n2,s2):1): read existing descriptor r207:/Table/75/2{-/NULL} [(n2,s2):1, (n1,s1):2, next=3] I180730 18:39:34.473462 25863 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:34.503904 25744 storage/replica_range_lease.go:554 [replicate,n2,s2,r158/1:/Table/69{-/1}] transferring lease to s3 I180730 18:39:34.542759 2310 storage/replica_proposal.go:222 [n3,s3,r158/2:/Table/69{-/1}] new range lease repl=(n3,s3):2 seq=6 start=1532975974.504040411,0 epo=1 pro=1532975974.504065010,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:34.558522 25744 storage/replica_range_lease.go:617 [replicate,n2,s2,r158/1:/Table/69{-/1}] done transferring lease to s3: <nil> I180730 18:39:34.595297 25869 storage/replica_raftstorage.go:520 [replicate,n2,s2,r204/1:/Table/7{4/3-5}] generated preemptive snapshot 49e46f64 at index 18 I180730 18:39:34.642270 1898 storage/replica_proposal.go:222 [n2,s2,r213/1:/Table/75/{2/3-3}] new range lease repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:34.651688 25869 storage/store_snapshot.go:605 [replicate,n2,s2,r204/1:/Table/7{4/3-5}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 56ms I180730 18:39:34.664554 25910 storage/replica_raftstorage.go:737 [n3,s3,r204/?:{-}] applying preemptive snapshot at index 18 (id=49e46f64, encoded size=2389, 1 rocksdb batches, 8 log entries) I180730 18:39:34.674215 25910 storage/replica_raftstorage.go:743 [n3,s3,r204/?:/Table/7{4/3-5}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms] I180730 18:39:34.712459 25869 storage/replica_command.go:745 [replicate,n2,s2,r204/1:/Table/7{4/3-5}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r204:/Table/7{4/3-5} [(n2,s2):1, next=2] I180730 18:39:34.752050 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL I180730 18:39:34.765547 1106 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:34.784690 25902 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:34.796301 25832 storage/replica_command.go:745 [replicate,n3,s3,r21/4:/Table/5{0-1}] change replicas (REMOVE_REPLICA (n1,s1):3): read existing descriptor r21:/Table/5{0-1} [(n1,s1):3, (n3,s3):4, next=5] I180730 18:39:34.807119 25822 storage/replica.go:3645 [n1,s1,r207/2:/Table/75/2{-/NULL}] proposing REMOVE_REPLICA((n2,s2):1): updated=[(n1,s1):2] next=3 I180730 18:39:34.865696 2043 storage/store.go:3638 [n2,s2,r207/1:/Table/75/2{-/NULL}] added to replica GC queue (peer suggestion) I180730 18:39:34.886759 25834 storage/store.go:2557 [replicaGC,n2,s2,r207/1:/Table/75/2{-/NULL}] removing replica I180730 18:39:34.889378 25834 storage/replica.go:844 [replicaGC,n2,s2,r207/1:/Table/75/2{-/NULL}] removed 8 (0+8) keys in 1ms [clear=0ms commit=1ms] I180730 18:39:34.918701 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:34.962604 1107 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:34.964121 25832 storage/replica.go:3645 [n3,s3,r21/4:/Table/5{0-1}] proposing REMOVE_REPLICA((n1,s1):3): updated=[(n3,s3):4] next=5 I180730 18:39:34.971286 25965 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:34.985936 2556 storage/store.go:3638 [n1,s1,r21/3:/Table/5{0-1}] added to replica GC queue (peer suggestion) I180730 18:39:34.991928 25869 storage/replica.go:3645 [n2,s2,r204/1:/Table/7{4/3-5}] proposing ADD_REPLICA((n3,s3):2): updated=[(n2,s2):1 (n3,s3):2] next=3 I180730 18:39:35.009327 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:35.055516 25983 storage/store.go:2557 [replicaGC,n1,s1,r21/3:/Table/5{0-1}] removing replica I180730 18:39:35.057044 25983 storage/replica.go:844 [replicaGC,n1,s1,r21/3:/Table/5{0-1}] removed 8 (0+8) keys in 1ms [clear=0ms commit=1ms] I180730 18:39:35.083406 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL I180730 18:39:35.089799 1108 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:35.090549 26035 storage/replica_range_lease.go:554 [replicate,n2,s2,r204/1:/Table/7{4/3-5}] transferring lease to s3 I180730 18:39:35.105307 26037 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:35.110448 26035 storage/replica_range_lease.go:617 [replicate,n2,s2,r204/1:/Table/7{4/3-5}] done transferring lease to s3: <nil> I180730 18:39:35.114202 2347 storage/replica_proposal.go:222 [n3,s3,r204/2:/Table/7{4/3-5}] new range lease repl=(n3,s3):2 seq=6 start=1532975975.090683433,0 epo=1 pro=1532975975.090707494,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:35.145456 25938 storage/replica_raftstorage.go:520 [replicate,n2,s2,r4/2:/System/{NodeLive…-tsd}] generated preemptive snapshot 3408fc9a at index 134 I180730 18:39:35.147309 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:35.163899 1093 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:35.171532 26000 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:35.191035 25938 storage/store_snapshot.go:605 [replicate,n2,s2,r4/2:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 85, log entries: 3, rate-limit: 2.0 MiB/sec, 45ms I180730 18:39:35.195025 26007 storage/replica_raftstorage.go:737 [n3,s3,r4/?:{-}] applying preemptive snapshot at index 134 (id=3408fc9a, encoded size=74920, 1 rocksdb batches, 3 log entries) I180730 18:39:35.201570 26007 storage/replica_raftstorage.go:743 [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=5ms commit=0ms] I180730 18:39:35.219664 25938 storage/replica_command.go:745 [replicate,n2,s2,r4/2:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n2,s2):2, next=3] I180730 18:39:35.284413 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:35.323725 25938 storage/replica.go:3645 [n2,s2,r4/2:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):3): updated=[(n2,s2):2 (n3,s3):3] next=4 I180730 18:39:35.364526 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL I180730 18:39:35.394299 1094 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:35.416123 26103 storage/replica_range_lease.go:554 [replicate,n2,s2,r4/2:/System/{NodeLive…-tsd}] transferring lease to s3 I180730 18:39:35.424390 26034 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:35.456227 26014 storage/replica_command.go:745 [replicate,n1,s1,r210/2:/Table/75/2/{!NULL-1}] change replicas (REMOVE_REPLICA (n2,s2):1): read existing descriptor r210:/Table/75/2/{!NULL-1} [(n2,s2):1, (n1,s1):2, next=3] I180730 18:39:35.480295 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:35.495553 1095 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:35.498614 26103 storage/replica_range_lease.go:617 [replicate,n2,s2,r4/2:/System/{NodeLive…-tsd}] done transferring lease to s3: <nil> I180730 18:39:35.499916 2255 storage/replica_proposal.go:222 [n3,s3,r4/3:/System/{NodeLive…-tsd}] new range lease repl=(n3,s3):3 seq=5 start=1532975975.416317407,0 epo=1 pro=1532975975.416348582,0 following repl=(n2,s2):2 seq=4 start=1532975897.965237469,0 epo=1 pro=1532975897.965262443,0 I180730 18:39:35.504614 26090 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:35.522132 26018 storage/replica_raftstorage.go:520 [replicate,n2,s2,r212/1:/Table/75/2/{2-3}] generated preemptive snapshot 724c6713 at index 18 I180730 18:39:35.580512 26018 storage/store_snapshot.go:605 [replicate,n2,s2,r212/1:/Table/75/2/{2-3}] streamed snapshot to (n1,s1):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 55ms I180730 18:39:35.584127 26134 storage/replica_raftstorage.go:737 [n1,s1,r212/?:{-}] applying preemptive snapshot at index 18 (id=724c6713, encoded size=2427, 1 rocksdb batches, 8 log entries) I180730 18:39:35.587507 26134 storage/replica_raftstorage.go:743 [n1,s1,r212/?:/Table/75/2/{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms] I180730 18:39:35.592171 26018 storage/replica_command.go:745 [replicate,n2,s2,r212/1:/Table/75/2/{2-3}] change replicas (ADD_REPLICA (n1,s1):2): read existing descriptor r212:/Table/75/2/{2-3} [(n2,s2):1, next=2] I180730 18:39:35.621802 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:35.643722 1096 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:35.652267 26136 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:35.670087 26097 storage/replica_command.go:745 [replicate,n3,s3,r158/2:/Table/69{-/1}] change replicas (REMOVE_REPLICA (n2,s2):1): read existing descriptor r158:/Table/69{-/1} [(n2,s2):1, (n3,s3):2, next=3] I180730 18:39:35.684199 26014 storage/replica.go:3645 [n1,s1,r210/2:/Table/75/2/{!NULL-1}] proposing REMOVE_REPLICA((n2,s2):1): updated=[(n1,s1):2] next=3 I180730 18:39:35.718119 2043 storage/store.go:3638 [n2,s2,r210/1:/Table/75/2/{!NULL-1}] added to replica GC queue (peer suggestion) I180730 18:39:35.739788 26140 storage/store.go:2557 [replicaGC,n2,s2,r210/1:/Table/75/2/{!NULL-1}] removing replica I180730 18:39:35.752793 26140 storage/replica.go:844 [replicaGC,n2,s2,r210/1:/Table/75/2/{!NULL-1}] removed 8 (0+8) keys in 5ms [clear=0ms commit=4ms] I180730 18:39:35.764473 26018 storage/replica.go:3645 [n2,s2,r212/1:/Table/75/2/{2-3}] proposing ADD_REPLICA((n1,s1):2): updated=[(n2,s2):1 (n1,s1):2] next=3 I180730 18:39:35.769464 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:35.823391 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL I180730 18:39:35.830005 1097 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:35.838599 26228 storage/replica_range_lease.go:554 [replicate,n2,s2,r212/1:/Table/75/2/{2-3}] transferring lease to s1 I180730 18:39:35.847455 26201 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:35.866384 26228 storage/replica_range_lease.go:617 [replicate,n2,s2,r212/1:/Table/75/2/{2-3}] done transferring lease to s1: <nil> I180730 18:39:35.869331 1231 storage/replica_proposal.go:222 [n1,s1,r212/2:/Table/75/2/{2-3}] new range lease repl=(n1,s1):2 seq=6 start=1532975975.843458820,0 epo=1 pro=1532975975.843502920,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:35.883136 26097 storage/replica.go:3645 [n3,s3,r158/2:/Table/69{-/1}] proposing REMOVE_REPLICA((n2,s2):1): updated=[(n3,s3):2] next=3 I180730 18:39:35.887132 26277 storage/replica_raftstorage.go:520 [replicate,n2,s2,r214/1:/Table/75/{2/4-3}] generated preemptive snapshot f8962032 at index 12 I180730 18:39:35.898497 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:35.910620 4886 storage/store.go:3638 [n2,s2,r158/1:/Table/69{-/1}] added to replica GC queue (peer suggestion) I180730 18:39:35.930610 26277 storage/store_snapshot.go:605 [replicate,n2,s2,r214/1:/Table/75/{2/4-3}] streamed snapshot to (n1,s1):?: kv pairs: 7, log entries: 2, rate-limit: 2.0 MiB/sec, 35ms I180730 18:39:35.934110 26291 storage/replica_raftstorage.go:737 [n1,s1,r214/?:{-}] applying preemptive snapshot at index 12 (id=f8962032, encoded size=375, 1 rocksdb batches, 2 log entries) I180730 18:39:35.939907 1098 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:35.942725 26291 storage/replica_raftstorage.go:743 [n1,s1,r214/?:/Table/75/{2/4-3}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms] I180730 18:39:35.947525 26277 storage/replica_command.go:745 [replicate,n2,s2,r214/1:/Table/75/{2/4-3}] change replicas (ADD_REPLICA (n1,s1):2): read existing descriptor r214:/Table/75/{2/4-3} [(n2,s2):1, next=2] I180730 18:39:35.948821 26206 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:35.985227 26186 storage/store.go:2557 [replicaGC,n2,s2,r158/1:/Table/69{-/1}] removing replica I180730 18:39:35.987351 26186 storage/replica.go:844 [replicaGC,n2,s2,r158/1:/Table/69{-/1}] removed 8 (0+8) keys in 1ms [clear=0ms commit=0ms] I180730 18:39:36.038587 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:36.046652 1099 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:36.049295 26262 storage/replica_command.go:745 [replicate,n3,s3,r204/2:/Table/7{4/3-5}] change replicas (REMOVE_REPLICA (n2,s2):1): read existing descriptor r204:/Table/7{4/3-5} [(n2,s2):1, (n3,s3):2, next=3] I180730 18:39:36.053157 26238 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:36.119402 25082 ccl/partitionccl/partition_test.go:1156 SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n2,s2,r213/1:/Table/75/2/{3-4}] read completed full trace: === SPAN START: session recording === [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2645] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: NoTxn === SPAN START: sql txn === [n1,client=127.0.0.1:45234,user=root] [Open pos:2645] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: Open [n1,client=127.0.0.1:45234,user=root] planning starts: SELECT [n1,client=127.0.0.1:45234,user=root] generating optimizer plan [n1,client=127.0.0.1:45234,user=root] added table 'data.public."secondary index - NULL"' to table collection [n1,client=127.0.0.1:45234,user=root] optimizer plan succeeded [n1,client=127.0.0.1:45234,user=root] planning ends [n1,client=127.0.0.1:45234,user=root] checking distributability [n1,client=127.0.0.1:45234,user=root] distributable plan: true [n1,client=127.0.0.1:45234,user=root] execution starts: distributed === SPAN START: consuming rows === [n1,client=127.0.0.1:45234,user=root] creating DistSQL plan [n1,client=127.0.0.1:45234,user=root] querying next range at /Table/75/2/3 [n1,client=127.0.0.1:45234,user=root] running DistSQL plan [n1,client=127.0.0.1:45234,user=root] connection to n2 established === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow === === SPAN START: outbox === cockroach.stat.outbox.bytes_sent: ݣ cockroach.streamid: 1 === SPAN START: table reader === cockroach.processorid: 0 cockroach.stat.tablereader.input.rows: 0 cockroach.stat.tablereader.stalltime: 2µs [n2] Scan /Table/75/2/{3-4} === SPAN START: dist sender === [txn=86629f7e,n2] querying next range at /Table/75/2/3 [txn=86629f7e,n2] r213: sending batch 1 Scan to (n2,s2):1 [txn=86629f7e,n2] sending request to local server === SPAN START: /cockroach.roachpb.Internal/Batch === [n2] 1 Scan [n2,s2] executing 1 requests [n2,s2,r213/1:/Table/75/2/{3-4}] read-only path [n2] connection to n1 established [n2,s2,r213/1:/Table/75/2/{3-4}] command queue [n2,s2,r213/1:/Table/75/2/{3-4}] waiting for read lock [n2,s2,r213/1:/Table/75/2/{3-4}] read completed === SPAN START: [async] drain === === SPAN START: ordered aggregator === cockroach.stat.aggregator.stalltime: 314µs cockroach.processorid: 1 cockroach.stat.aggregator.input.rows: 0 cockroach.stat.aggregator.mem.max: 10 KiB [n2,orderedAgg/1] accumulation complete === SPAN START: flow === [client=127.0.0.1:45234,user=root,n1] starting (1 processors, 0 startables) === SPAN START: noop === cockroach.processorid: 2 [n1,client=127.0.0.1:45234,user=root] execution ends [n1,client=127.0.0.1:45234,user=root] rows affected: 1 [n1,client=127.0.0.1:45234,user=root] AutoCommit. err: <nil> [n1,client=127.0.0.1:45234,user=root] releasing 1 tables [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2646] executing ExecStmt: SET TRACING = off [n1,client=127.0.0.1:45234,user=root] executing: SET TRACING = off in state: NoTxn I180730 18:39:36.121256 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL I180730 18:39:36.127280 1100 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:36.138267 26324 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:36.182728 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:36.197314 1101 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:36.205837 26329 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:36.216186 26262 storage/replica.go:3645 [n3,s3,r204/2:/Table/7{4/3-5}] proposing REMOVE_REPLICA((n2,s2):1): updated=[(n3,s3):2] next=3 I180730 18:39:36.226102 26277 storage/replica.go:3645 [n2,s2,r214/1:/Table/75/{2/4-3}] proposing ADD_REPLICA((n1,s1):2): updated=[(n2,s2):1 (n1,s1):2] next=3 I180730 18:39:36.240039 4886 storage/store.go:3638 [n2,s2,r204/1:/Table/7{4/3-5}] added to replica GC queue (peer suggestion) I180730 18:39:36.342981 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:36.365990 4886 storage/store.go:3638 [n2,s2,r204/1:/Table/7{4/3-5}] added to replica GC queue (peer suggestion) I180730 18:39:36.372606 1102 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:36.405440 26316 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:36.419051 26306 storage/replica_range_lease.go:554 [replicate,n2,s2,r214/1:/Table/75/{2/4-3}] transferring lease to s1 I180730 18:39:36.455083 26306 storage/replica_range_lease.go:617 [replicate,n2,s2,r214/1:/Table/75/{2/4-3}] done transferring lease to s1: <nil> I180730 18:39:36.479282 26274 storage/store.go:2557 [replicaGC,n2,s2,r204/1:/Table/7{4/3-5}] removing replica I180730 18:39:36.481709 1261 storage/replica_proposal.go:222 [n1,s1,r214/2:/Table/75/{2/4-3}] new range lease repl=(n1,s1):2 seq=6 start=1532975976.419216906,0 epo=1 pro=1532975976.419248587,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:36.489193 26274 storage/replica.go:844 [replicaGC,n2,s2,r204/1:/Table/7{4/3-5}] removed 8 (0+8) keys in 6ms [clear=0ms commit=5ms] I180730 18:39:36.521442 26395 storage/replica_raftstorage.go:520 [replicate,n2,s2,r213/1:/Table/75/2/{3-4}] generated preemptive snapshot 7e285a2a at index 18 I180730 18:39:36.539815 26395 storage/store_snapshot.go:605 [replicate,n2,s2,r213/1:/Table/75/2/{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 10ms I180730 18:39:36.545050 26338 storage/replica_raftstorage.go:737 [n3,s3,r213/?:{-}] applying preemptive snapshot at index 18 (id=7e285a2a, encoded size=2427, 1 rocksdb batches, 8 log entries) I180730 18:39:36.547701 26338 storage/replica_raftstorage.go:743 [n3,s3,r213/?:/Table/75/2/{3-4}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms] I180730 18:39:36.550235 25082 ccl/partitionccl/partition_test.go:1156 SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n2,s2,r213/1:/Table/75/2/{3-4}] read completed full trace: === SPAN START: session recording === [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2663] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: NoTxn === SPAN START: sql txn === [n1,client=127.0.0.1:45234,user=root] [Open pos:2663] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: Open [n1,client=127.0.0.1:45234,user=root] planning starts: SELECT [n1,client=127.0.0.1:45234,user=root] generating optimizer plan [n1,client=127.0.0.1:45234,user=root] added table 'data.public."secondary index - NULL"' to table collection [n1,client=127.0.0.1:45234,user=root] optimizer plan succeeded [n1,client=127.0.0.1:45234,user=root] planning ends [n1,client=127.0.0.1:45234,user=root] checking distributability [n1,client=127.0.0.1:45234,user=root] distributable plan: true [n1,client=127.0.0.1:45234,user=root] execution starts: distributed === SPAN START: consuming rows === [n1,client=127.0.0.1:45234,user=root] creating DistSQL plan [n1,client=127.0.0.1:45234,user=root] querying next range at /Table/75/2/3 [n1,client=127.0.0.1:45234,user=root] running DistSQL plan [n1,client=127.0.0.1:45234,user=root] connection to n2 established === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow === === SPAN START: outbox === cockroach.stat.outbox.bytes_sent: ݳ cockroach.streamid: 1 === SPAN START: table reader === cockroach.stat.tablereader.input.rows: 0 cockroach.stat.tablereader.stalltime: 2µs cockroach.processorid: 0 === SPAN START: flow === [client=127.0.0.1:45234,user=root,n1] starting (1 processors, 0 startables) === SPAN START: noop === cockroach.processorid: 2 [n2] Scan /Table/75/2/{3-4} === SPAN START: dist sender === [txn=486f4b38,n2] querying next range at /Table/75/2/3 [txn=486f4b38,n2] r213: sending batch 1 Scan to (n2,s2):1 [txn=486f4b38,n2] sending request to local server === SPAN START: /cockroach.roachpb.Internal/Batch === [n2] 1 Scan [n2,s2] executing 1 requests [n2,s2,r213/1:/Table/75/2/{3-4}] read-only path [n2,s2,r213/1:/Table/75/2/{3-4}] command queue [n2,s2,r213/1:/Table/75/2/{3-4}] waiting for read lock [n2,s2,r213/1:/Table/75/2/{3-4}] read completed === SPAN START: ordered aggregator === cockroach.processorid: 1 cockroach.stat.aggregator.input.rows: 0 cockroach.stat.aggregator.mem.max: 10 KiB cockroach.stat.aggregator.stalltime: 7.845ms [n2] connection to n1 established === SPAN START: [async] drain === [n2] Consumer sent handshake. Consuming flow scheduled: true [n2,orderedAgg/1] accumulation complete [n1,client=127.0.0.1:45234,user=root] execution ends [n1,client=127.0.0.1:45234,user=root] rows affected: 1 [n1,client=127.0.0.1:45234,user=root] AutoCommit. err: <nil> [n1,client=127.0.0.1:45234,user=root] releasing 1 tables [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2664] executing ExecStmt: SET TRACING = off [n1,client=127.0.0.1:45234,user=root] executing: SET TRACING = off in state: NoTxn I180730 18:39:36.550974 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:36.563899 26393 storage/replica_command.go:745 [replicate,n1,s1,r212/2:/Table/75/2/{2-3}] change replicas (REMOVE_REPLICA (n2,s2):1): read existing descriptor r212:/Table/75/2/{2-3} [(n2,s2):1, (n1,s1):2, next=3] I180730 18:39:36.565705 1103 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:36.580394 26425 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:36.593131 26395 storage/replica_command.go:745 [replicate,n2,s2,r213/1:/Table/75/2/{3-4}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r213:/Table/75/2/{3-4} [(n2,s2):1, next=2] I180730 18:39:36.677306 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:36.704342 1104 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:36.736119 26458 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:36.736160 26452 storage/replica_command.go:745 [replicate,n3,s3,r4/3:/System/{NodeLive…-tsd}] change replicas (REMOVE_REPLICA (n2,s2):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n2,s2):2, (n3,s3):3, next=4] I180730 18:39:36.787735 26395 storage/replica.go:3645 [n2,s2,r213/1:/Table/75/2/{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n2,s2):1 (n3,s3):2] next=3 I180730 18:39:36.826734 26393 storage/replica.go:3645 [n1,s1,r212/2:/Table/75/2/{2-3}] proposing REMOVE_REPLICA((n2,s2):1): updated=[(n1,s1):2] next=3 I180730 18:39:36.872698 25082 ccl/partitionccl/partition_test.go:1156 SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n2,s2,r213/1:/Table/75/2/{3-4}] read completed full trace: === SPAN START: session recording === [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2675] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: NoTxn === SPAN START: sql txn === [n1,client=127.0.0.1:45234,user=root] [Open pos:2675] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: Open [n1,client=127.0.0.1:45234,user=root] planning starts: SELECT [n1,client=127.0.0.1:45234,user=root] generating optimizer plan [n1,client=127.0.0.1:45234,user=root] added table 'data.public."secondary index - NULL"' to table collection [n1,client=127.0.0.1:45234,user=root] optimizer plan succeeded [n1,client=127.0.0.1:45234,user=root] planning ends [n1,client=127.0.0.1:45234,user=root] checking distributability [n1,client=127.0.0.1:45234,user=root] distributable plan: true [n1,client=127.0.0.1:45234,user=root] execution starts: distributed === SPAN START: consuming rows === [n1,client=127.0.0.1:45234,user=root] creating DistSQL plan [n1,client=127.0.0.1:45234,user=root] querying next range at /Table/75/2/3 [n1,client=127.0.0.1:45234,user=root] running DistSQL plan [n1,client=127.0.0.1:45234,user=root] connection to n2 established === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow === === SPAN START: outbox === cockroach.stat.outbox.bytes_sent: ݱ cockroach.streamid: 1 === SPAN START: table reader === cockroach.processorid: 0 cockroach.stat.tablereader.input.rows: 0 cockroach.stat.tablereader.stalltime: 2µs [n2] connection to n1 established === SPAN START: flow === [client=127.0.0.1:45234,user=root,n1] starting (1 processors, 0 startables) === SPAN START: noop === cockroach.processorid: 2 === SPAN START: [async] drain === [n2] Scan /Table/75/2/{3-4} === SPAN START: dist sender === [txn=fcc4c38f,n2] querying next range at /Table/75/2/3 [txn=fcc4c38f,n2] r213: sending batch 1 Scan to (n2,s2):1 [txn=fcc4c38f,n2] sending request to local server === SPAN START: /cockroach.roachpb.Internal/Batch === [n2] 1 Scan [n2,s2] executing 1 requests [n2,s2,r213/1:/Table/75/2/{3-4}] read-only path [n2,s2,r213/1:/Table/75/2/{3-4}] command queue [n2,s2,r213/1:/Table/75/2/{3-4}] waiting for read lock [n2,s2,r213/1:/Table/75/2/{3-4}] read completed === SPAN START: ordered aggregator === cockroach.processorid: 1 cockroach.stat.aggregator.input.rows: 0 cockroach.stat.aggregator.mem.max: 10 KiB cockroach.stat.aggregator.stalltime: 400µs [n2] Consumer sent handshake. Consuming flow scheduled: true [n2,orderedAgg/1] accumulation complete [n1,client=127.0.0.1:45234,user=root] execution ends [n1,client=127.0.0.1:45234,user=root] rows affected: 1 [n1,client=127.0.0.1:45234,user=root] AutoCommit. err: <nil> [n1,client=127.0.0.1:45234,user=root] releasing 1 tables [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2676] executing ExecStmt: SET TRACING = off [n1,client=127.0.0.1:45234,user=root] executing: SET TRACING = off in state: NoTxn I180730 18:39:36.903204 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:36.903663 2043 storage/store.go:3638 [n2,s2,r212/1:/Table/75/2/{2-3}] added to replica GC queue (peer suggestion) I180730 18:39:36.923760 26381 storage/store.go:2557 [replicaGC,n2,s2,r212/1:/Table/75/2/{2-3}] removing replica I180730 18:39:36.925621 26452 storage/replica.go:3645 [n3,s3,r4/3:/System/{NodeLive…-tsd}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n3,s3):3] next=4 I180730 18:39:36.931418 26381 storage/replica.go:844 [replicaGC,n2,s2,r212/1:/Table/75/2/{2-3}] removed 8 (0+8) keys in 6ms [clear=0ms commit=6ms] I180730 18:39:36.933291 26382 storage/replica_range_lease.go:554 [replicate,n2,s2,r213/1:/Table/75/2/{3-4}] transferring lease to s3 I180730 18:39:36.963573 4886 storage/store.go:3638 [n2,s2,r4/2:/System/{NodeLive…-tsd}] added to replica GC queue (peer suggestion) I180730 18:39:36.967598 2322 storage/replica_proposal.go:222 [n3,s3,r213/2:/Table/75/2/{3-4}] new range lease repl=(n3,s3):2 seq=6 start=1532975976.933439051,0 epo=1 pro=1532975976.933477879,0 following repl=(n2,s2):1 seq=5 start=1532975932.281749864,0 epo=1 pro=1532975932.281779108,0 I180730 18:39:36.968071 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL I180730 18:39:36.971528 26382 storage/replica_range_lease.go:617 [replicate,n2,s2,r213/1:/Table/75/2/{3-4}] done transferring lease to s3: <nil> I180730 18:39:36.972949 1105 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:36.977485 26503 storage/store.go:2557 [replicaGC,n2,s2,r4/2:/System/{NodeLive…-tsd}] removing replica I180730 18:39:36.989470 26503 storage/replica.go:844 [replicaGC,n2,s2,r4/2:/System/{NodeLive…-tsd}] removed 29 (20+9) keys in 1ms [clear=0ms commit=1ms] I180730 18:39:36.992257 26506 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:37.035561 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:37.040758 1106 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:37.047866 26532 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:37.088970 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:37.100570 1215 server/status/runtime.go:424 [n1] runtime stats: 919 MiB RSS, 595 goroutines, 39 MiB/21 MiB/82 MiB GO alloc/idle/total, 98 MiB/132 MiB CGO alloc/total, 3203.00cgo/sec, 1.75/0.10 %(u/s)time, 0.02 %gc (14x) I180730 18:39:37.106957 1107 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:37.117683 26498 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:37.244788 25082 ccl/partitionccl/partition_test.go:1156 SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,s1,r1/3:/{Min-System/}] read completed [n1,s1,r1/3:/{Min-System/}] read completed full trace: === SPAN START: session recording === [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2699] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: NoTxn === SPAN START: sql txn === [n1,client=127.0.0.1:45234,user=root] [Open pos:2699] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: Open [n1,client=127.0.0.1:45234,user=root] planning starts: SELECT [n1,client=127.0.0.1:45234,user=root] generating optimizer plan [n1,client=127.0.0.1:45234,user=root] added table 'data.public."secondary index - NULL"' to table collection [n1,client=127.0.0.1:45234,user=root] optimizer plan succeeded [n1,client=127.0.0.1:45234,user=root] planning ends [n1,client=127.0.0.1:45234,user=root] checking distributability [n1,client=127.0.0.1:45234,user=root] distributable plan: true [n1,client=127.0.0.1:45234,user=root] execution starts: distributed === SPAN START: consuming rows === [n1,client=127.0.0.1:45234,user=root] creating DistSQL plan [n1,client=127.0.0.1:45234,user=root] querying next range at /Table/75/2/3 [n1,client=127.0.0.1:45234,user=root] running DistSQL plan [n1,client=127.0.0.1:45234,user=root] connection to n2 established === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow === === SPAN START: table reader === cockroach.processorid: 0 cockroach.stat.tablereader.input.rows: 0 cockroach.stat.tablereader.stalltime: 5µs [n2] Scan /Table/75/2/{3-4} === SPAN START: dist sender === [txn=feae684f,n2] querying next range at /Table/75/2/3 [txn=feae684f,n2] r213: sending batch 1 Scan to (n2,s2):1 [txn=feae684f,n2] sending request to local server === SPAN START: /cockroach.roachpb.Internal/Batch === [n2] 1 Scan [n2,s2] executing 1 requests [n2,s2,r213/1:/Table/75/2/{3-4}] read-only path [n2,s2,r213/1:/Table/75/2/{3-4}] replica.Send got error: [NotLeaseHolderError] r213: replica (n2,s2):1 not lease holder; current lease is repl=(n3,s3):2 seq=6 start=1532975976.933439051,0 epo=1 pro=1532975976.933477879,0 [n2] *roachpb.NotLeaseHolderError [txn=feae684f,n2] reply error [txn: feae684f], Scan [/Table/75/2/3,/Table/75/2/4): r213 was not found [txn=feae684f,n2] evicting range descriptor on send error and backoff for re-lookup [txn=feae684f,n2] evicting cached range descriptor === SPAN START: outbox === cockroach.stat.outbox.bytes_sent: ᯛ cockroach.streamid: 1 === SPAN START: flow === [client=127.0.0.1:45234,user=root,n1] starting (1 processors, 0 startables) === SPAN START: noop === cockroach.processorid: 2 [n2] connection to n1 established === SPAN START: [async] drain === [n2] Consumer sent handshake. Consuming flow scheduled: true === SPAN START: range lookup === === SPAN START: dist sender === [txn=feae684f,range-lookup=/Table/75/2/3,n2] querying next range at /Meta2/Table/75/2/3/NULL === SPAN START: range lookup === === SPAN START: dist sender === [txn=feae684f,range-lookup=/Table/75/2/3,range-lookup=/Meta2/Table/75/2/3/NULL,n2] querying next range at /Meta1/Table/75/2/3/NULL/NULL === SPAN START: range lookup === [txn=feae684f,range-lookup=/Table/75/2/3,range-lookup=/Meta2/Table/75/2/3/NULL,n2] looked up range descriptor [txn=feae684f,range-lookup=/Table/75/2/3,range-lookup=/Meta2/Table/75/2/3/NULL,n2] r1: sending batch 1 Scan to (n1,s1):3 [txn=feae684f,range-lookup=/Table/75/2/3,range-lookup=/Meta2/Table/75/2/3/NULL,n2] sending request to 127.0.0.1:33961 === SPAN START: /cockroach.roachpb.Internal/Batch === === SPAN START: /cockroach.roachpb.Internal/Batch === [n1] 1 Scan [n1,s1] executing 1 requests [n1,s1,r1/3:/{Min-System/}] read-only path [n1,s1,r1/3:/{Min-System/}] command queue [n1,s1,r1/3:/{Min-System/}] operation accepts inconsistent results [n1,s1,r1/3:/{Min-System/}] waiting for read lock [n1,s1,r1/3:/{Min-System/}] read completed [txn=feae684f,range-lookup=/Table/75/2/3,n2] looked up range descriptor [txn=feae684f,range-lookup=/Table/75/2/3,n2] r1: sending batch 1 Scan to (n1,s1):3 [txn=feae684f,range-lookup=/Table/75/2/3,n2] sending request to 127.0.0.1:33961 === SPAN START: /cockroach.roachpb.Internal/Batch === === SPAN START: /cockroach.roachpb.Internal/Batch === [n1] 1 Scan [n1,s1] executing 1 requests [n1,s1,r1/3:/{Min-System/}] read-only path [n1,s1,r1/3:/{Min-System/}] command queue [n1,s1,r1/3:/{Min-System/}] operation accepts inconsistent results [n1,s1,r1/3:/{Min-System/}] waiting for read lock [n1,s1,r1/3:/{Min-System/}] read completed [txn=feae684f,n2] looked up range descriptor [txn=feae684f,n2] r213: sending batch 1 Scan to (n3,s3):2 [txn=feae684f,n2] sending request to 127.0.0.1:42943 === SPAN START: /cockroach.roachpb.Internal/Batch === === SPAN START: /cockroach.roachpb.Internal/Batch === [n3] 1 Scan [n3,s3] executing 1 requests [n3,s3,r213/2:/Table/75/2/{3-4}] read-only path [n3,s3,r213/2:/Table/75/2/{3-4}] command queue [n3,s3,r213/2:/Table/75/2/{3-4}] waiting for read lock [n3,s3,r213/2:/Table/75/2/{3-4}] read completed === SPAN START: ordered aggregator === cockroach.stat.aggregator.stalltime: 1.021ms cockroach.processorid: 1 cockroach.stat.aggregator.input.rows: 0 cockroach.stat.aggregator.mem.max: 10 KiB [n2,orderedAgg/1] accumulation complete [n1,client=127.0.0.1:45234,user=root] execution ends [n1,client=127.0.0.1:45234,user=root] rows affected: 1 [n1,client=127.0.0.1:45234,user=root] AutoCommit. err: <nil> [n1,client=127.0.0.1:45234,user=root] releasing 1 tables [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2700] executing ExecStmt: SET TRACING = off [n1,client=127.0.0.1:45234,user=root] executing: SET TRACING = off in state: NoTxn I180730 18:39:37.245327 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = -1 I180730 18:39:37.307360 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL I180730 18:39:37.328840 1108 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:37.335442 26554 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:37.365221 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b IS NULL OR b = 1 I180730 18:39:37.398788 1093 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n2 established I180730 18:39:37.403808 26539 rpc/nodedialer/nodedialer.go:92 [n2] connection to n1 established I180730 18:39:37.443935 25082 ccl/partitionccl/partition_test.go:200 query: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 I180730 18:39:37.456877 1094 rpc/nodedialer/nodedialer.go:92 [n1,client=127.0.0.1:45234,user=root] connection to n3 established I180730 18:39:37.465165 26527 rpc/nodedialer/nodedialer.go:92 [n3] connection to n1 established I180730 18:39:37.494489 26583 storage/replica_command.go:745 [replicate,n1,s1,r214/2:/Table/75/{2/4-3}] change replicas (REMOVE_REPLICA (n2,s2):1): read existing descriptor r214:/Table/75/{2/4-3} [(n2,s2):1, (n1,s1):2, next=3] I180730 18:39:37.578592 26585 storage/replica_command.go:745 [replicate,n3,s3,r213/2:/Table/75/2/{3-4}] change replicas (REMOVE_REPLICA (n2,s2):1): read existing descriptor r213:/Table/75/2/{3-4} [(n2,s2):1, (n3,s3):2, next=3] I180730 18:39:37.603228 25082 ccl/partitionccl/partition_test.go:1156 SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,s1,r1/3:/{Min-System/}] read completed [n1,s1,r1/3:/{Min-System/}] read completed full trace: === SPAN START: session recording === [n1,client=127.0.0.1:45234,user=root] [NoTxn pos:2723] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: NoTxn === SPAN START: sql txn === [n1,client=127.0.0.1:45234,user=root] [Open pos:2723] executing ExecStmt: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 [n1,client=127.0.0.1:45234,user=root] executing: SELECT count(*) FROM "secondary index - NULL" WHERE b = 3 in state: Open [n1,client=127.0.0.1:45234,user=root] planning starts: SELECT [n1,client=127.0.0.1:45234,user=root] generating optimizer plan [n1,client=127.0.0.1:45234,user=root] added table 'data.public."secondary index - NULL"' to table collection [n1,client=127.0.0.1:45234,user=root] optimizer plan succeeded [n1,client=127.0.0.1:45234,user=root] planning ends [n1,client=127.0.0.1:45234,user=root] checking distributability [n1,client=127.0.0.1:45234,user=root] distributable plan: true [n1,client=127.0.0.1:45234,user=root] execution starts: distributed === SPAN START: consuming rows === [n1,client=127.0.0.1:45234,user=root] creating DistSQL plan [n1,client=127.0.0.1:45234,user=root] querying next range at /Table/75/2/3 [n1,client=127.0.0.1:45234,user=root] running DistSQL plan [n1,client=127.0.0.1:45234,user=root] connection to n3 established === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow === === SPAN START: table reader === cockroach.processorid: 0 cockroach.stat.tablereader.input.rows: 0 cockroach.stat.tablereader.stalltime: 2µs [n3] Scan /Table/75/2/{3-4} === SPAN START: outbox === cockroach.stat.outbox.bytes_sent: ᯈ cockroach.streamid: 1 === SPAN START: dist sender === [txn=583b6401,n3] querying next range at /Table/75/2/3 [txn=583b6401,n3] r213: sending batch 1 Scan to (n2,s2):1 [n3] connection to n1 established [txn=583b6401,n3] sending request to 127.0.0.1:41341 === SPAN START: /cockroach.roachpb.Internal/Batch === === SPAN START: [async] drain === === SPAN START: flow === [client=127.0.0.1:45234,user=root,n1] starting (1 processors, 0 startables) === SPAN START: noop === cockroach.processorid: 2 [n3] Consumer sent handshake. Consuming flow scheduled: true === SPAN START: /cockroach.roachpb.Internal/Batch === [n2] 1 Scan [n2,s2] executing 1 requests [n2,s2,r213/1:/Table/75/2/{3-4}] read-only path [n2,s2,r213/1:/Table/75/2/{3-4}] replica.Send got error: [NotLeaseHolderError] r213: replica (n2,s2):1 not lease holder; current lease is repl=(n3,s3):2 seq=6 start=1
Please assign, take a look and update the issue accordingly.
Data race fixed in #28085
tbg
commented
6 years ago tbg
commented
6 years ago
The following tests appear to have failed:
#805351:
Please assign, take a look and update the issue accordingly.