{"action":"created","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/16439","repository_url":"https://api.github.com/repos/cockroachdb/cockroach","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/16439/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/16439/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/16439/events","html_url":"https://github.com/cockroachdb/cockroach/issues/16439","id":234984555,"number":16439,"title":"sql/logictest: TestParallel failed under stress","user":{"login":"cockroach-teamcity","id":20559710,"avatar_url":"https://avatars0.githubusercontent.com/u/20559710?v=4","gravatar_id":"","url":"https://api.github.com/users/cockroach-teamcity","html_url":"https://github.com/cockroach-teamcity","followers_url":"https://api.github.com/users/cockroach-teamcity/followers","following_url":"https://api.github.com/users/cockroach-teamcity/following{/other_user}","gists_url":"https://api.github.com/users/cockroach-teamcity/gists{/gist_id}","starred_url":"https://api.github.com/users/cockroach-teamcity/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cockroach-teamcity/subscriptions","organizations_url":"https://api.github.com/users/cockroach-teamcity/orgs","repos_url":"https://api.github.com/users/cockroach-teamcity/repos","events_url":"https://api.github.com/users/cockroach-teamcity/events{/privacy}","received_events_url":"https://api.github.com/users/cockroach-teamcity/received_events","type":"User","site_admin":false},"labels":[{"id":335217860,"url":"https://api.github.com/repos/cockroachdb/cockroach/labels/Robot","name":"Robot","color":"5319e7","default":false},{"id":191587409,"url":"https://api.github.com/repos/cockroachdb/cockroach/labels/test-failure","name":"test-failure","color":"e11d21","default":false}],"state":"open","locked":false,"assignee":{"login":"RaduBerinde","id":16544120,"avatar_url":"https://avatars1.githubusercontent.com/u/16544120?v=4","gravatar_id":"","url":"https://api.github.com/users/RaduBerinde","html_url":"https://github.com/RaduBerinde","followers_url":"https://api.github.com/users/RaduBerinde/followers","following_url":"https://api.github.com/users/RaduBerinde/following{/other_user}","gists_url":"https://api.github.com/users/RaduBerinde/gists{/gist_id}","starred_url":"https://api.github.com/users/RaduBerinde/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/RaduBerinde/subscriptions","organizations_url":"https://api.github.com/users/RaduBerinde/orgs","repos_url":"https://api.github.com/users/RaduBerinde/repos","events_url":"https://api.github.com/users/RaduBerinde/events{/privacy}","received_events_url":"https://api.github.com/users/RaduBerinde/received_events","type":"User","site_admin":false},"assignees":[{"login":"RaduBerinde","id":16544120,"avatar_url":"https://avatars1.githubusercontent.com/u/16544120?v=4","gravatar_id":"","url":"https://api.github.com/users/RaduBerinde","html_url":"https://github.com/RaduBerinde","followers_url":"https://api.github.com/users/RaduBerinde/followers","following_url":"https://api.github.com/users/RaduBerinde/following{/other_user}","gists_url":"https://api.github.com/users/RaduBerinde/gists{/gist_id}","starred_url":"https://api.github.com/users/RaduBerinde/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/RaduBerinde/subscriptions","organizations_url":"https://api.github.com/users/RaduBerinde/orgs","repos_url":"https://api.github.com/users/RaduBerinde/repos","events_url":"https://api.github.com/users/RaduBerinde/events{/privacy}","received_events_url":"https://api.github.com/users/RaduBerinde/received_events","type":"User","site_admin":false}],"milestone":null,"comments":23,"created_at":"2017-06-10T06:40:11Z","updated_at":"2018-02-06T08:02:44Z","closed_at":null,"author_association":"MEMBER","body":"SHA: https://github.com/cockroachdb/cockroach/commits/64c341f1d005db6b70f3eccf103f1dde6d61f94f\n\nParameters:\n```\nTAGS=\nGOFLAGS=\n```\n\nStress build found a failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=268830&tab=buildLog\n\n```\nI170610 06:40:04.052145 1874 gossip/client.go:131  [n?] started gossip client to 127.0.0.1:54084\nI170610 06:40:04.094349 2009 gossip/server.go:234  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:46604}\nI170610 06:40:04.095124 2037 storage/stores.go:312  [n?] wrote 1 node addresses to persistent storage\nI170610 06:40:04.095154 2037 storage/stores.go:312  [n?] wrote 2 node addresses to persistent storage\nI170610 06:40:04.095262 1066 server/node.go:634  [n?] node connected via gossip and verified as part of cluster \"fe9a87be-660b-4a88-901b-52a8e2b936f4\"\nI170610 06:40:04.095700 1433 storage/store.go:3386  [replicate,n1,s1,r6/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 6, rate-limit: 8.0 MiB/sec, 45ms\nI170610 06:40:04.095842 1691 sql/event_log.go:101  [n2] Event: \"node_join\", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:43231} Attrs: Locality:} ClusterID:fe9a87be-660b-4a88-901b-52a8e2b936f4 StartedAt:1497076803929903449 LastUp:1497076803929903449}\nI170610 06:40:04.096184 1975 storage/replica_raftstorage.go:639  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 16 (id=fef4807f, encoded size=5314, 1 rocksdb batches, 6 log entries)\nI170610 06:40:04.096285 1066 kv/dist_sender.go:370  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping\nI170610 06:40:04.096464 1975 storage/replica_raftstorage.go:647  [n2,s2,r6/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.096828 1066 server/node.go:345  [n?] new node allocated ID 3\nI170610 06:40:04.096868 1066 gossip/gossip.go:297  [n3] NodeDescriptor set to node_id:3 address:<network_field:\"tcp\" address_field:\"127.0.0.1:46604\" > attrs:<> locality:<> \nI170610 06:40:04.096911 1066 server/node.go:406  [n3] node=3: started with [[]=] engine(s) and attributes []\nI170610 06:40:04.096959 1066 sql/executor.go:358  [n3] creating distSQLPlanner with address {tcp 127.0.0.1:46604}\nI170610 06:40:04.097346 2053 storage/stores.go:312  [n1] wrote 2 node addresses to persistent storage\nI170610 06:40:04.097545 2054 storage/stores.go:312  [n2] wrote 2 node addresses to persistent storage\nI170610 06:40:04.099297 1433 storage/replica_command.go:3599  [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r6:/Table/1{1-2} [(n1,s1):1, next=2]\nI170610 06:40:04.099432 1066 server/server.go:760  [n3] starting https server at 127.0.0.1:37220\nI170610 06:40:04.099450 1066 server/server.go:761  [n3] starting grpc/postgres server at 127.0.0.1:46604\nI170610 06:40:04.099463 1066 server/server.go:762  [n3] advertising CockroachDB node at 127.0.0.1:46604\nI170610 06:40:04.100059 1066 server/server.go:875  [n3] done ensuring all necessary migrations have run\nI170610 06:40:04.100080 1066 server/server.go:877  [n3] serving sql connections\nI170610 06:40:04.108311 2028 server/node.go:590  [n3] bootstrapped store [n3,s3]\nW170610 06:40:04.110508 1066 server/status/runtime.go:111  Could not parse build timestamp: parsing time \"\" as \"2006/01/02 15:04:05\": cannot parse \"\" as \"2006\"\nW170610 06:40:04.111002 1066 gossip/gossip.go:1196  [n?] no incoming or outgoing connections\nI170610 06:40:04.111678 1066 server/config.go:479  [n?] 1 storage engine initialized\nI170610 06:40:04.111697 1066 server/config.go:481  [n?] RocksDB cache size: 512 MiB\nI170610 06:40:04.111709 1066 server/config.go:481  [n?] store 0: in-memory, size 100 MiB\nI170610 06:40:04.111984 1066 server/node.go:455  [n?] store [n0,s0] not bootstrapped\nI170610 06:40:04.112069 1066 storage/stores.go:296  [n?] read 0 node addresses from persistent storage\nI170610 06:40:04.112091 1066 server/node.go:609  [n?] connecting to gossip network to verify cluster ID...\nI170610 06:40:04.176474 1433 storage/replica_command.go:3599  [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r6:/Table/1{1-2} [(n1,s1):1, next=2]\nI170610 06:40:04.184663 2045 gossip/client.go:131  [n?] started gossip client to 127.0.0.1:54084\nI170610 06:40:04.185216 2236 gossip/server.go:234  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:43728}\nI170610 06:40:04.185484 1066 server/node.go:634  [n?] node connected via gossip and verified as part of cluster \"fe9a87be-660b-4a88-901b-52a8e2b936f4\"\nI170610 06:40:04.185724 2237 storage/stores.go:312  [n?] wrote 1 node addresses to persistent storage\nI170610 06:40:04.185769 2237 storage/stores.go:312  [n?] wrote 2 node addresses to persistent storage\nI170610 06:40:04.185803 2237 storage/stores.go:312  [n?] wrote 3 node addresses to persistent storage\nI170610 06:40:04.188333 2295 storage/replica.go:2865  [n1,s1,r6/1:/Table/1{1-2}] proposing ADD_REPLICA (n2,s2):2: [(n1,s1):1 (n2,s2):2]\nI170610 06:40:04.188798 1433 storage/replica_raftstorage.go:442  [replicate,n1,s1,r8/1:/Table/1{3-4}] generated preemptive snapshot 23d4c2a7 at index 28\nI170610 06:40:04.203340 1066 kv/dist_sender.go:370  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping\nI170610 06:40:04.204032 1066 server/node.go:345  [n?] new node allocated ID 4\nI170610 06:40:04.204073 1066 gossip/gossip.go:297  [n4] NodeDescriptor set to node_id:4 address:<network_field:\"tcp\" address_field:\"127.0.0.1:43728\" > attrs:<> locality:<> \nI170610 06:40:04.204124 1066 server/node.go:406  [n4] node=4: started with [[]=] engine(s) and attributes []\nI170610 06:40:04.204181 1066 sql/executor.go:358  [n4] creating distSQLPlanner with address {tcp 127.0.0.1:43728}\nI170610 06:40:04.206690 1066 server/server.go:760  [n4] starting https server at 127.0.0.1:55402\nI170610 06:40:04.206708 1066 server/server.go:761  [n4] starting grpc/postgres server at 127.0.0.1:43728\nI170610 06:40:04.206716 1066 server/server.go:762  [n4] advertising CockroachDB node at 127.0.0.1:43728\nI170610 06:40:04.208525 2281 storage/stores.go:312  [n1] wrote 3 node addresses to persistent storage\nI170610 06:40:04.208951 2199 storage/stores.go:312  [n2] wrote 3 node addresses to persistent storage\nI170610 06:40:04.209355 2202 storage/stores.go:312  [n3] wrote 3 node addresses to persistent storage\nI170610 06:40:04.209468 1066 server/server.go:875  [n4] done ensuring all necessary migrations have run\nI170610 06:40:04.209486 1066 server/server.go:877  [n4] serving sql connections\nI170610 06:40:04.211367 1995 sql/event_log.go:101  [n3] Event: \"node_join\", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:46604} Attrs: Locality:} ClusterID:fe9a87be-660b-4a88-901b-52a8e2b936f4 StartedAt:1497076804096898490 LastUp:1497076804096898490}\nW170610 06:40:04.215286 1066 server/status/runtime.go:111  Could not parse build timestamp: parsing time \"\" as \"2006/01/02 15:04:05\": cannot parse \"\" as \"2006\"\nI170610 06:40:04.215540 2203 sql/event_log.go:101  [n4] Event: \"node_join\", target: 4, info: {Descriptor:{NodeID:4 Address:{NetworkField:tcp AddressField:127.0.0.1:43728} Attrs: Locality:} ClusterID:fe9a87be-660b-4a88-901b-52a8e2b936f4 StartedAt:1497076804204112363 LastUp:1497076804204112363}\nI170610 06:40:04.227087 1433 storage/store.go:3386  [replicate,n1,s1,r8/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 103, log entries: 18, rate-limit: 8.0 MiB/sec, 6ms\nI170610 06:40:04.227399 2509 storage/replica_raftstorage.go:639  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 28 (id=23d4c2a7, encoded size=27887, 1 rocksdb batches, 18 log entries)\nI170610 06:40:04.228255 2509 storage/replica_raftstorage.go:647  [n3,s3,r8/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]\nI170610 06:40:04.228839 1981 server/node.go:590  [n4] bootstrapped store [n4,s4]\nI170610 06:40:04.228954 1433 storage/replica_command.go:3599  [replicate,n1,s1,r8/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r8:/Table/1{3-4} [(n1,s1):1, next=2]\nW170610 06:40:04.235902 1066 gossip/gossip.go:1196  [n?] no incoming or outgoing connections\nI170610 06:40:04.263032 1066 server/config.go:479  [n?] 1 storage engine initialized\nI170610 06:40:04.263057 1066 server/config.go:481  [n?] RocksDB cache size: 512 MiB\nI170610 06:40:04.263072 1066 server/config.go:481  [n?] store 0: in-memory, size 100 MiB\nI170610 06:40:04.264635 1066 server/node.go:455  [n?] store [n0,s0] not bootstrapped\nI170610 06:40:04.264655 1066 storage/stores.go:296  [n?] read 0 node addresses from persistent storage\nI170610 06:40:04.264669 1066 server/node.go:609  [n?] connecting to gossip network to verify cluster ID...\nI170610 06:40:04.272112 2531 storage/replica.go:2865  [n1,s1,r8/1:/Table/1{3-4}] proposing ADD_REPLICA (n3,s3):2: [(n1,s1):1 (n3,s3):2]\nI170610 06:40:04.272620 1433 storage/replica_raftstorage.go:442  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 306c0190 at index 87\nI170610 06:40:04.273256 1433 storage/store.go:3386  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 39, log entries: 16, rate-limit: 8.0 MiB/sec, 1ms\nI170610 06:40:04.275471 2581 storage/replica_raftstorage.go:639  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 87 (id=306c0190, encoded size=10389, 1 rocksdb batches, 16 log entries)\nI170610 06:40:04.275730 2581 storage/replica_raftstorage.go:647  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.276293 2516 gossip/client.go:131  [n?] started gossip client to 127.0.0.1:54084\nI170610 06:40:04.276724 1433 storage/replica_command.go:3599  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2]\nI170610 06:40:04.279058 2265 gossip/server.go:234  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:60597}\nI170610 06:40:04.279464 1066 server/node.go:634  [n?] node connected via gossip and verified as part of cluster \"fe9a87be-660b-4a88-901b-52a8e2b936f4\"\nI170610 06:40:04.279767 2266 storage/stores.go:312  [n?] wrote 1 node addresses to persistent storage\nI170610 06:40:04.279842 2266 storage/stores.go:312  [n?] wrote 2 node addresses to persistent storage\nI170610 06:40:04.279898 2266 storage/stores.go:312  [n?] wrote 3 node addresses to persistent storage\nI170610 06:40:04.279927 2266 storage/stores.go:312  [n?] wrote 4 node addresses to persistent storage\nI170610 06:40:04.281295 1066 kv/dist_sender.go:370  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping\nI170610 06:40:04.282016 1066 server/node.go:345  [n?] new node allocated ID 5\nI170610 06:40:04.282070 1066 gossip/gossip.go:297  [n5] NodeDescriptor set to node_id:5 address:<network_field:\"tcp\" address_field:\"127.0.0.1:60597\" > attrs:<> locality:<> \nI170610 06:40:04.282117 1066 server/node.go:406  [n5] node=5: started with [[]=] engine(s) and attributes []\nI170610 06:40:04.282162 1066 sql/executor.go:358  [n5] creating distSQLPlanner with address {tcp 127.0.0.1:60597}\nI170610 06:40:04.291589 2674 storage/raft_transport.go:436  [n3] raft transport stream to node 1 established\nI170610 06:40:04.294273 2540 storage/replica.go:2865  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA (n3,s3):2: [(n1,s1):1 (n3,s3):2]\nI170610 06:40:04.294752 1433 storage/replica_raftstorage.go:442  [replicate,n1,s1,r7/1:/Table/1{2-3}] generated preemptive snapshot 6e933aa6 at index 23\nI170610 06:40:04.295736 2265 gossip/server.go:285  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:46604})\nI170610 06:40:04.295934 2682 storage/stores.go:312  [n1] wrote 4 node addresses to persistent storage\nI170610 06:40:04.296251 2698 storage/stores.go:312  [n2] wrote 4 node addresses to persistent storage\nI170610 06:40:04.296403 2699 storage/stores.go:312  [n4] wrote 4 node addresses to persistent storage\nI170610 06:40:04.296529 2700 storage/stores.go:312  [n3] wrote 4 node addresses to persistent storage\nI170610 06:40:04.296994 2627 server/node.go:590  [n5] bootstrapped store [n5,s5]\nI170610 06:40:04.297130 2516 gossip/client.go:136  [n5] closing client to node 1 (127.0.0.1:54084): received forward from node 1 to 3 (127.0.0.1:46604)\nI170610 06:40:04.297180 2556 gossip/gossip.go:1210  [n5] node has connected to cluster via gossip\nI170610 06:40:04.297280 2556 storage/stores.go:312  [n5] wrote 4 node addresses to persistent storage\nI170610 06:40:04.308231 1066 server/server.go:760  [n5] starting https server at 127.0.0.1:45930\nI170610 06:40:04.308251 1066 server/server.go:761  [n5] starting grpc/postgres server at 127.0.0.1:60597\nI170610 06:40:04.308261 1066 server/server.go:762  [n5] advertising CockroachDB node at 127.0.0.1:60597\nI170610 06:40:04.313293 1066 server/server.go:875  [n5] done ensuring all necessary migrations have run\nI170610 06:40:04.313314 1066 server/server.go:877  [n5] serving sql connections\nI170610 06:40:04.320513 2851 sql/event_log.go:101  [n5] Event: \"node_join\", target: 5, info: {Descriptor:{NodeID:5 Address:{NetworkField:tcp AddressField:127.0.0.1:60597} Attrs: Locality:} ClusterID:fe9a87be-660b-4a88-901b-52a8e2b936f4 StartedAt:1497076804282104317 LastUp:1497076804282104317}\nI170610 06:40:04.324983 2791 gossip/client.go:131  [n5] started gossip client to 127.0.0.1:46604\nI170610 06:40:04.332531 1433 storage/store.go:3386  [replicate,n1,s1,r7/1:/Table/1{2-3}] streamed snapshot to (n4,s4):?: kv pairs: 34, log entries: 13, rate-limit: 8.0 MiB/sec, 1ms\nI170610 06:40:04.332602 2717 storage/replica_raftstorage.go:639  [n4,s4,r7/?:{-}] applying preemptive snapshot at index 23 (id=6e933aa6, encoded size=16125, 1 rocksdb batches, 13 log entries)\nI170610 06:40:04.332956 2717 storage/replica_raftstorage.go:647  [n4,s4,r7/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.333773 1433 storage/replica_command.go:3599  [replicate,n1,s1,r7/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r7:/Table/1{2-3} [(n1,s1):1, next=2]\nI170610 06:40:04.340557 2913 storage/replica.go:2865  [n1,s1,r7/1:/Table/1{2-3}] proposing ADD_REPLICA (n4,s4):2: [(n1,s1):1 (n4,s4):2]\nI170610 06:40:04.341023 1433 storage/replica_raftstorage.go:442  [replicate,n1,s1,r2/1:/System/{-tsd}] generated preemptive snapshot a00d0150 at index 39\nI170610 06:40:04.350176 2952 storage/raft_transport.go:436  [n4] raft transport stream to node 1 established\nI170610 06:40:04.352034 1433 storage/store.go:3386  [replicate,n1,s1,r2/1:/System/{-tsd}] streamed snapshot to (n4,s4):?: kv pairs: 38, log entries: 12, rate-limit: 8.0 MiB/sec, 11ms\nI170610 06:40:04.377150 2936 storage/replica_raftstorage.go:639  [n4,s4,r2/?:{-}] applying preemptive snapshot at index 39 (id=a00d0150, encoded size=153652, 1 rocksdb batches, 12 log entries)\nI170610 06:40:04.378165 2936 storage/replica_raftstorage.go:647  [n4,s4,r2/?:/System/{-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]\nI170610 06:40:04.384335 1433 storage/replica_command.go:3599  [replicate,n1,s1,r2/1:/System/{-tsd}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r2:/System/{-tsd} [(n1,s1):1, next=2]\nI170610 06:40:04.387452 2847 storage/replica.go:2865  [n1,s1,r2/1:/System/{-tsd}] proposing ADD_REPLICA (n4,s4):2: [(n1,s1):1 (n4,s4):2]\nI170610 06:40:04.387899 1433 storage/replica_raftstorage.go:442  [replicate,n1,s1,r10/1:/{Table/15-Max}] generated preemptive snapshot 92dfe68d at index 11\nI170610 06:40:04.398473 1433 storage/store.go:3386  [replicate,n1,s1,r10/1:/{Table/15-Max}] streamed snapshot to (n5,s5):?: kv pairs: 8, log entries: 1, rate-limit: 8.0 MiB/sec, 0ms\nI170610 06:40:04.398909 2984 storage/replica_raftstorage.go:639  [n5,s5,r10/?:{-}] applying preemptive snapshot at index 11 (id=92dfe68d, encoded size=472, 1 rocksdb batches, 1 log entries)\nI170610 06:40:04.399357 2984 storage/replica_raftstorage.go:647  [n5,s5,r10/?:/{Table/15-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.400223 1433 storage/replica_command.go:3599  [replicate,n1,s1,r10/1:/{Table/15-Max}] change replicas (ADD_REPLICA (n5,s5):2): read existing descriptor r10:/{Table/15-Max} [(n1,s1):1, next=2]\nI170610 06:40:04.409789 3003 storage/replica.go:2865  [n1,s1,r10/1:/{Table/15-Max}] proposing ADD_REPLICA (n5,s5):2: [(n1,s1):1 (n5,s5):2]\nI170610 06:40:04.410096 1433 storage/queue.go:719  [n1,replicate] purgatory is now empty\nI170610 06:40:04.410292 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r9/1:/Table/1{4-5}] generated preemptive snapshot c60d72db at index 18\nI170610 06:40:04.411554 1069 storage/store.go:3386  [replicate,n1,s1,r9/1:/Table/1{4-5}] streamed snapshot to (n5,s5):?: kv pairs: 10, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms\nI170610 06:40:04.411819 3017 storage/replica_raftstorage.go:639  [n5,s5,r9/?:{-}] applying preemptive snapshot at index 18 (id=c60d72db, encoded size=5704, 1 rocksdb batches, 8 log entries)\nI170610 06:40:04.412072 3017 storage/replica_raftstorage.go:647  [n5,s5,r9/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.412450 1069 storage/replica_command.go:3599  [replicate,n1,s1,r9/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n5,s5):3): read existing descriptor r9:/Table/1{4-5} [(n1,s1):1, (n2,s2):2, next=3]\nI170610 06:40:04.421544 3046 storage/raft_transport.go:436  [n5] raft transport stream to node 1 established\nI170610 06:40:04.424180 2832 storage/replica.go:2865  [n1,s1,r9/1:/Table/1{4-5}] proposing ADD_REPLICA (n5,s5):3: [(n1,s1):1 (n2,s2):2 (n5,s5):3]\nI170610 06:40:04.425347 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r6/1:/Table/1{1-2}] generated preemptive snapshot c4bc0a4a at index 24\nI170610 06:40:04.426633 3052 storage/replica_raftstorage.go:639  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 24 (id=c4bc0a4a, encoded size=9816, 1 rocksdb batches, 14 log entries)\nI170610 06:40:04.426879 3052 storage/replica_raftstorage.go:647  [n3,s3,r6/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.427547 1069 storage/store.go:3386  [replicate,n1,s1,r6/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 14, rate-limit: 8.0 MiB/sec, 2ms\nI170610 06:40:04.427995 1069 storage/replica_command.go:3599  [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r6:/Table/1{1-2} [(n1,s1):1, (n2,s2):2, next=3]\nI170610 06:40:04.439581 2971 storage/replica.go:2865  [n1,s1,r6/1:/Table/1{1-2}] proposing ADD_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n3,s3):3]\nI170610 06:40:04.440793 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r5/1:/Table/{0-11}] generated preemptive snapshot 06d72648 at index 19\nI170610 06:40:04.442940 1069 storage/store.go:3386  [replicate,n1,s1,r5/1:/Table/{0-11}] streamed snapshot to (n5,s5):?: kv pairs: 38, log entries: 9, rate-limit: 8.0 MiB/sec, 2ms\nI170610 06:40:04.447815 3060 storage/replica_raftstorage.go:639  [n5,s5,r5/?:{-}] applying preemptive snapshot at index 19 (id=06d72648, encoded size=13203, 1 rocksdb batches, 9 log entries)\nI170610 06:40:04.448112 3060 storage/replica_raftstorage.go:647  [n5,s5,r5/?:/Table/{0-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.448392 1069 storage/replica_command.go:3599  [replicate,n1,s1,r5/1:/Table/{0-11}] change replicas (ADD_REPLICA (n5,s5):3): read existing descriptor r5:/Table/{0-11} [(n1,s1):1, (n2,s2):2, next=3]\nI170610 06:40:04.456267 3009 storage/replica.go:2865  [n1,s1,r5/1:/Table/{0-11}] proposing ADD_REPLICA (n5,s5):3: [(n1,s1):1 (n2,s2):2 (n5,s5):3]\nI170610 06:40:04.458995 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r7/1:/Table/1{2-3}] generated preemptive snapshot eca2395b at index 28\nI170610 06:40:04.459596 1069 storage/store.go:3386  [replicate,n1,s1,r7/1:/Table/1{2-3}] streamed snapshot to (n5,s5):?: kv pairs: 40, log entries: 18, rate-limit: 8.0 MiB/sec, 1ms\nI170610 06:40:04.460212 3094 storage/replica_raftstorage.go:639  [n5,s5,r7/?:{-}] applying preemptive snapshot at index 28 (id=eca2395b, encoded size=21319, 1 rocksdb batches, 18 log entries)\nI170610 06:40:04.460562 3094 storage/replica_raftstorage.go:647  [n5,s5,r7/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.462168 1069 storage/replica_command.go:3599  [replicate,n1,s1,r7/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n5,s5):3): read existing descriptor r7:/Table/1{2-3} [(n1,s1):1, (n4,s4):2, next=3]\nI170610 06:40:04.465322 3089 storage/replica.go:2865  [n1,s1,r7/1:/Table/1{2-3}] proposing ADD_REPLICA (n5,s5):3: [(n1,s1):1 (n4,s4):2 (n5,s5):3]\nI170610 06:40:04.467504 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot e5d64de7 at index 104\nI170610 06:40:04.468861 1069 storage/store.go:3386  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n4,s4):?: kv pairs: 49, log entries: 33, rate-limit: 8.0 MiB/sec, 1ms\nI170610 06:40:04.469111 3123 storage/replica_raftstorage.go:639  [n4,s4,r1/?:{-}] applying preemptive snapshot at index 104 (id=e5d64de7, encoded size=19697, 1 rocksdb batches, 33 log entries)\nI170610 06:40:04.469439 3123 storage/replica_raftstorage.go:647  [n4,s4,r1/?:/{Min-System/}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.469739 1069 storage/replica_command.go:3599  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n4,s4):3): read existing descriptor r1:/{Min-System/} [(n1,s1):1, (n3,s3):2, next=3]\nI170610 06:40:04.472229 3102 storage/replica.go:2865  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA (n4,s4):3: [(n1,s1):1 (n3,s3):2 (n4,s4):3]\nI170610 06:40:04.473897 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r3/1:/System/ts{d-e}] generated preemptive snapshot 705a056f at index 25\nI170610 06:40:04.486500 1069 storage/store.go:3386  [replicate,n1,s1,r3/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 1403, log entries: 3, rate-limit: 8.0 MiB/sec, 13ms\nI170610 06:40:04.487081 3109 storage/replica_raftstorage.go:639  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 25 (id=705a056f, encoded size=200476, 1 rocksdb batches, 3 log entries)\nI170610 06:40:04.488370 3109 storage/replica_raftstorage.go:647  [n3,s3,r3/?:/System/ts{d-e}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]\nI170610 06:40:04.488994 1069 storage/replica_command.go:3599  [replicate,n1,s1,r3/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r3:/System/ts{d-e} [(n1,s1):1, (n2,s2):2, next=3]\nI170610 06:40:04.492325 3141 storage/replica.go:2865  [n1,s1,r3/1:/System/ts{d-e}] proposing ADD_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n3,s3):3]\nI170610 06:40:04.494770 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r8/1:/Table/1{3-4}] generated preemptive snapshot bc563c7d at index 55\nI170610 06:40:04.495727 1069 storage/store.go:3386  [replicate,n1,s1,r8/1:/Table/1{3-4}] streamed snapshot to (n4,s4):?: kv pairs: 145, log entries: 45, rate-limit: 8.0 MiB/sec, 1ms\nI170610 06:40:04.496432 3160 storage/replica_raftstorage.go:639  [n4,s4,r8/?:{-}] applying preemptive snapshot at index 55 (id=bc563c7d, encoded size=57888, 1 rocksdb batches, 45 log entries)\nI170610 06:40:04.496986 3160 storage/replica_raftstorage.go:647  [n4,s4,r8/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.497604 1069 storage/replica_command.go:3599  [replicate,n1,s1,r8/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n4,s4):3): read existing descriptor r8:/Table/1{3-4} [(n1,s1):1, (n3,s3):2, next=3]\nI170610 06:40:04.500837 3226 storage/replica.go:2865  [n1,s1,r8/1:/Table/1{3-4}] proposing ADD_REPLICA (n4,s4):3: [(n1,s1):1 (n3,s3):2 (n4,s4):3]\nI170610 06:40:04.504835 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] generated preemptive snapshot b6030c4b at index 19\nI170610 06:40:04.507884 1069 storage/store.go:3386  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] streamed snapshot to (n4,s4):?: kv pairs: 10, log entries: 9, rate-limit: 8.0 MiB/sec, 3ms\nI170610 06:40:04.508200 3145 storage/replica_raftstorage.go:639  [n4,s4,r4/?:{-}] applying preemptive snapshot at index 19 (id=b6030c4b, encoded size=7494, 1 rocksdb batches, 9 log entries)\nI170610 06:40:04.508477 3145 storage/replica_raftstorage.go:647  [n4,s4,r4/?:/{System/tse-Table/0}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.508835 1069 storage/replica_command.go:3599  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] change replicas (ADD_REPLICA (n4,s4):3): read existing descriptor r4:/{System/tse-Table/0} [(n1,s1):1, (n2,s2):2, next=3]\nI170610 06:40:04.512127 3116 storage/replica.go:2865  [n1,s1,r4/1:/{System/tse-Table/0}] proposing ADD_REPLICA (n4,s4):3: [(n1,s1):1 (n2,s2):2 (n4,s4):3]\nI170610 06:40:04.513126 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r10/1:/{Table/15-Max}] generated preemptive snapshot 2502890b at index 14\nI170610 06:40:04.520137 1069 storage/store.go:3386  [replicate,n1,s1,r10/1:/{Table/15-Max}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 4, rate-limit: 8.0 MiB/sec, 7ms\nI170610 06:40:04.520396 3167 storage/replica_raftstorage.go:639  [n4,s4,r10/?:{-}] applying preemptive snapshot at index 14 (id=2502890b, encoded size=2516, 1 rocksdb batches, 4 log entries)\nI170610 06:40:04.520595 3167 storage/replica_raftstorage.go:647  [n4,s4,r10/?:/{Table/15-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.520940 1069 storage/replica_command.go:3599  [replicate,n1,s1,r10/1:/{Table/15-Max}] change replicas (ADD_REPLICA (n4,s4):3): read existing descriptor r10:/{Table/15-Max} [(n1,s1):1, (n5,s5):2, next=3]\nI170610 06:40:04.524761 3180 storage/replica.go:2865  [n1,s1,r10/1:/{Table/15-Max}] proposing ADD_REPLICA (n4,s4):3: [(n1,s1):1 (n5,s5):2 (n4,s4):3]\nI170610 06:40:04.527556 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r2/1:/System/{-tsd}] generated preemptive snapshot b1a4ebfa at index 42\nI170610 06:40:04.528734 1069 storage/store.go:3386  [replicate,n1,s1,r2/1:/System/{-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 39, log entries: 15, rate-limit: 8.0 MiB/sec, 1ms\nI170610 06:40:04.529205 3169 storage/replica_raftstorage.go:639  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 42 (id=b1a4ebfa, encoded size=155704, 1 rocksdb batches, 15 log entries)\nI170610 06:40:04.531990 3169 storage/replica_raftstorage.go:647  [n3,s3,r2/?:/System/{-tsd}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=1ms]\nI170610 06:40:04.532810 1069 storage/replica_command.go:3599  [replicate,n1,s1,r2/1:/System/{-tsd}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r2:/System/{-tsd} [(n1,s1):1, (n4,s4):2, next=3]\nI170610 06:40:04.538387 3182 storage/replica.go:2865  [n1,s1,r2/1:/System/{-tsd}] proposing ADD_REPLICA (n3,s3):3: [(n1,s1):1 (n4,s4):2 (n3,s3):3]\nI170610 06:40:04.540649 2405 storage/replica_proposal.go:397  [n4,s4,r10/3:/{Table/15-Max}] new range lease repl=(n4,s4):3 start=1497076804.539870982,0 epo=1 pro=1497076804.539872882,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497076812.734198500,0 pro=1497076803.734213300,0\nI170610 06:40:04.540856 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r2/1:/System/{-tsd}] generated preemptive snapshot f9ca9302 at index 44\nI170610 06:40:04.542157 1069 storage/store.go:3386  [replicate,n1,s1,r2/1:/System/{-tsd}] streamed snapshot to (n5,s5):?: kv pairs: 41, log entries: 17, rate-limit: 2.0 MiB/sec, 1ms\nI170610 06:40:04.542605 3276 storage/replica_raftstorage.go:639  [n5,s5,r2/?:{-}] applying preemptive snapshot at index 44 (id=f9ca9302, encoded size=157706, 1 rocksdb batches, 17 log entries)\nI170610 06:40:04.543579 3276 storage/replica_raftstorage.go:647  [n5,s5,r2/?:/System/{-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.543904 1069 storage/replica_command.go:3599  [replicate,n1,s1,r2/1:/System/{-tsd}] change replicas (ADD_REPLICA (n5,s5):4): read existing descriptor r2:/System/{-tsd} [(n1,s1):1, (n4,s4):2, (n3,s3):3, next=4]\nI170610 06:40:04.572369 3189 storage/replica.go:2865  [n1,s1,r2/1:/System/{-tsd}] proposing ADD_REPLICA (n5,s5):4: [(n1,s1):1 (n4,s4):2 (n3,s3):3 (n5,s5):4]\nI170610 06:40:04.577772 1072 storage/replica_raftstorage.go:442  [raftsnapshot,n1,s1,r2/1:/System/{-tsd}] generated Raft snapshot e4d2aaba at index 48\nI170610 06:40:04.585476 1072 storage/store.go:3386  [raftsnapshot,n1,s1,r2/1:/System/{-tsd}] streamed snapshot to (n5,s5):4: kv pairs: 42, log entries: 3, rate-limit: 8.0 MiB/sec, 8ms\nI170610 06:40:04.585677 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r8/1:/Table/1{3-4}] generated preemptive snapshot e7190743 at index 67\nI170610 06:40:04.585774 3197 storage/replica_raftstorage.go:639  [n5,s5,r2/?:/System/{-tsd}] applying Raft snapshot at index 48 (id=e4d2aaba, encoded size=80730, 1 rocksdb batches, 3 log entries)\nI170610 06:40:04.586332 3197 storage/replica_raftstorage.go:647  [n5,s5,r2/4:/System/{-tsd}] applied Raft snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.588367 1069 storage/store.go:3386  [replicate,n1,s1,r8/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 171, log entries: 57, rate-limit: 2.0 MiB/sec, 3ms\nI170610 06:40:04.588803 3302 storage/replica_raftstorage.go:639  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 67 (id=e7190743, encoded size=72556, 1 rocksdb batches, 57 log entries)\nI170610 06:40:04.589380 3302 storage/replica_raftstorage.go:647  [n2,s2,r8/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.590347 1069 storage/replica_command.go:3599  [replicate,n1,s1,r8/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r8:/Table/1{3-4} [(n1,s1):1, (n3,s3):2, (n4,s4):3, next=4]\nI170610 06:40:04.593631 3303 storage/replica.go:2865  [n1,s1,r8/1:/Table/1{3-4}] proposing ADD_REPLICA (n2,s2):4: [(n1,s1):1 (n3,s3):2 (n4,s4):3 (n2,s2):4]\nI170610 06:40:04.597187 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] generated preemptive snapshot f769c965 at index 22\nI170610 06:40:04.598181 2433 storage/replica_proposal.go:397  [n4,s4,r8/3:/Table/1{3-4}] new range lease repl=(n4,s4):3 start=1497076804.594452639,0 epo=1 pro=1497076804.594454939,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497076812.734198500,0 pro=1497076803.734213300,0\nI170610 06:40:04.598478 3411 storage/raft_transport.go:436  [n4] raft transport stream to node 2 established\nI170610 06:40:04.604395 1069 storage/store.go:3386  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 12, rate-limit: 2.0 MiB/sec, 7ms\nI170610 06:40:04.604678 3397 storage/replica_raftstorage.go:639  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 22 (id=f769c965, encoded size=9623, 1 rocksdb batches, 12 log entries)\nI170610 06:40:04.604939 3397 storage/replica_raftstorage.go:647  [n3,s3,r4/?:/{System/tse-Table/0}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.605301 1069 storage/replica_command.go:3599  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] change replicas (ADD_REPLICA (n3,s3):4): read existing descriptor r4:/{System/tse-Table/0} [(n1,s1):1, (n2,s2):2, (n4,s4):3, next=4]\nI170610 06:40:04.609206 3281 storage/raft_transport.go:436  [n4] raft transport stream to node 3 established\nI170610 06:40:04.610859 3378 storage/raft_transport.go:436  [n4] raft transport stream to node 5 established\nI170610 06:40:04.621777 3289 storage/raft_transport.go:436  [n2] raft transport stream to node 4 established\nI170610 06:40:04.631125 3459 storage/raft_transport.go:436  [n5] raft transport stream to node 4 established\nI170610 06:40:04.631789 3445 storage/raft_transport.go:436  [n3] raft transport stream to node 4 established\nI170610 06:40:04.633460 3328 storage/replica.go:2865  [n1,s1,r4/1:/{System/tse-Table/0}] proposing ADD_REPLICA (n3,s3):4: [(n1,s1):1 (n2,s2):2 (n4,s4):3 (n3,s3):4]\nI170610 06:40:04.637371 1799 storage/replica_proposal.go:397  [n2,s2,r4/2:/{System/tse-Table/0}] new range lease repl=(n2,s2):2 start=1497076804.634845496,0 epo=1 pro=1497076804.634847796,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497076812.734198500,0 pro=1497076803.734213300,0\nI170610 06:40:04.637732 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r5/1:/Table/{0-11}] generated preemptive snapshot 696535b3 at index 24\nI170610 06:40:04.638950 3501 storage/replica_raftstorage.go:639  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 24 (id=696535b3, encoded size=16238, 1 rocksdb batches, 14 log entries)\nI170610 06:40:04.639257 3501 storage/replica_raftstorage.go:647  [n3,s3,r5/?:/Table/{0-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.639679 1069 storage/store.go:3386  [replicate,n1,s1,r5/1:/Table/{0-11}] streamed snapshot to (n3,s3):?: kv pairs: 40, log entries: 14, rate-limit: 2.0 MiB/sec, 2ms\nI170610 06:40:04.639891 1069 storage/replica_command.go:3599  [replicate,n1,s1,r5/1:/Table/{0-11}] change replicas (ADD_REPLICA (n3,s3):4): read existing descriptor r5:/Table/{0-11} [(n1,s1):1, (n2,s2):2, (n5,s5):3, next=4]\nI170610 06:40:04.644884 3574 storage/replica.go:2865  [n1,s1,r5/1:/Table/{0-11}] proposing ADD_REPLICA (n3,s3):4: [(n1,s1):1 (n2,s2):2 (n5,s5):3 (n3,s3):4]\nI170610 06:40:04.647613 1815 storage/replica_proposal.go:397  [n2,s2,r5/2:/Table/{0-11}] new range lease repl=(n2,s2):2 start=1497076804.646615445,0 epo=1 pro=1497076804.646617245,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497076812.734198500,0 pro=1497076803.734213300,0\nI170610 06:40:04.648102 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r9/1:/Table/1{4-5}] generated preemptive snapshot 5ef4d75c at index 21\nI170610 06:40:04.648529 1069 storage/store.go:3386  [replicate,n1,s1,r9/1:/Table/1{4-5}] streamed snapshot to (n4,s4):?: kv pairs: 11, log entries: 11, rate-limit: 2.0 MiB/sec, 0ms\nI170610 06:40:04.648800 3604 storage/replica_raftstorage.go:639  [n4,s4,r9/?:{-}] applying preemptive snapshot at index 21 (id=5ef4d75c, encoded size=7776, 1 rocksdb batches, 11 log entries)\nI170610 06:40:04.649042 3604 storage/replica_raftstorage.go:647  [n4,s4,r9/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.649359 1069 storage/replica_command.go:3599  [replicate,n1,s1,r9/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n4,s4):4): read existing descriptor r9:/Table/1{4-5} [(n1,s1):1, (n2,s2):2, (n5,s5):3, next=4]\nI170610 06:40:04.663752 2477 storage/replica_command.go:3599  [replicate,n4,s4,r2/2:/System/{-tsd}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r2:/System/{-tsd} [(n1,s1):1, (n4,s4):2, (n3,s3):3, (n5,s5):4, next=5]\nI170610 06:40:04.665706 3554 storage/raft_transport.go:436  [n2] raft transport stream to node 3 established\nI170610 06:40:04.672081 3592 storage/raft_transport.go:436  [n2] raft transport stream to node 5 established\nI170610 06:40:04.672511 3675 storage/raft_transport.go:436  [n5] raft transport stream to node 2 established\nI170610 06:40:04.675971 1066 sql/logictest/parallel_test.go:207  Setting range split size: 32768\nI170610 06:40:04.693247 3599 storage/replica.go:2865  [n1,s1,r9/1:/Table/1{4-5}] proposing ADD_REPLICA (n4,s4):4: [(n1,s1):1 (n2,s2):2 (n5,s5):3 (n4,s4):4]\nI170610 06:40:04.694615 3682 storage/replica.go:2865  [n4,s4,r2/2:/System/{-tsd}] proposing REMOVE_REPLICA (n1,s1):1: [(n5,s5):4 (n4,s4):2 (n3,s3):3]\nI170610 06:40:04.703338 1070 storage/store.go:2152  [replicaGC,n1,s1,r2/1:/System/{-tsd}] removing replica\nI170610 06:40:04.703477 1070 storage/replica.go:714  [replicaGC,n1,s1,r2/1:/System/{-tsd}] removed 30 (19+11) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:04.705814 2703 storage/replica_proposal.go:397  [n5,s5,r9/3:/Table/1{4-5}] new range lease repl=(n5,s5):3 start=1497076804.702516930,0 epo=1 pro=1497076804.702518630,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497076812.734198500,0 pro=1497076803.734213300,0\nI170610 06:40:04.706523 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r3/1:/System/ts{d-e}] generated preemptive snapshot 8d9b894c at index 28\nI170610 06:40:04.716635 3762 storage/raft_transport.go:436  [n3] raft transport stream to node 2 established\nI170610 06:40:04.722658 3642 storage/replica_raftstorage.go:639  [n5,s5,r3/?:{-}] applying preemptive snapshot at index 28 (id=8d9b894c, encoded size=202617, 1 rocksdb batches, 6 log entries)\nI170610 06:40:04.724186 3642 storage/replica_raftstorage.go:647  [n5,s5,r3/?:/System/ts{d-e}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=1ms]\nI170610 06:40:04.724421 1069 storage/store.go:3386  [replicate,n1,s1,r3/1:/System/ts{d-e}] streamed snapshot to (n5,s5):?: kv pairs: 1404, log entries: 6, rate-limit: 2.0 MiB/sec, 18ms\nI170610 06:40:04.728009 1069 storage/replica_command.go:3599  [replicate,n1,s1,r3/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n5,s5):4): read existing descriptor r3:/System/ts{d-e} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4]\nI170610 06:40:04.734066 3696 storage/replica.go:2865  [n1,s1,r3/1:/System/ts{d-e}] proposing ADD_REPLICA (n5,s5):4: [(n1,s1):1 (n2,s2):2 (n3,s3):3 (n5,s5):4]\nI170610 06:40:04.744132 1800 storage/replica_proposal.go:397  [n2,s2,r3/2:/System/ts{d-e}] new range lease repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497076812.734198500,0 pro=1497076803.734213300,0\nI170610 06:40:04.748616 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r7/1:/Table/1{2-3}] generated preemptive snapshot da613120 at index 31\nI170610 06:40:04.749852 1069 storage/store.go:3386  [replicate,n1,s1,r7/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 41, log entries: 21, rate-limit: 2.0 MiB/sec, 1ms\nI170610 06:40:04.750183 3831 storage/replica_raftstorage.go:639  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 31 (id=da613120, encoded size=23391, 1 rocksdb batches, 21 log entries)\nI170610 06:40:04.750547 3831 storage/replica_raftstorage.go:647  [n2,s2,r7/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.751026 1069 storage/replica_command.go:3599  [replicate,n1,s1,r7/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r7:/Table/1{2-3} [(n1,s1):1, (n4,s4):2, (n5,s5):3, next=4]\nI170610 06:40:04.752721 1066 sql/logictest/parallel_test.go:221  Creating database\nI170610 06:40:04.797050 3664 storage/replica.go:2865  [n1,s1,r7/1:/Table/1{2-3}] proposing ADD_REPLICA (n2,s2):4: [(n1,s1):1 (n4,s4):2 (n5,s5):3 (n2,s2):4]\nI170610 06:40:04.807009 2476 storage/replica_command.go:2694  [split,n4,s4,r2/2:/System/{-tsd}] initiating a split of this range at key /System/StatusNode/2 [r21]\nI170610 06:40:04.807442 1069 storage/replica_raftstorage.go:442  [replicate,n1,s1,r6/1:/Table/1{1-2}] generated preemptive snapshot 381a4d18 at index 27\nI170610 06:40:04.810970 376 storage/replica_command.go:2694  [split,n2,s2,r3/2:/System/ts{d-e}] initiating a split of this range at key /System/tsd/cr.node.round-trip-latency-p50/2/10s/2017-06-10T06:00:00Z [r31]\nI170610 06:40:04.815233 2761 storage/replica_proposal.go:397  [n5,s5,r7/3:/Table/1{2-3}] new range lease repl=(n5,s5):3 start=1497076804.804069084,0 epo=1 pro=1497076804.804071384,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497076812.734198500,0 pro=1497076803.734213300,0\nI170610 06:40:04.831659 1777 storage/replica_proposal.go:397  [n2,s2,r3/2:/System/ts{d-e}] new range lease repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:04.832389 1069 storage/store.go:3386  [replicate,n1,s1,r6/1:/Table/1{1-2}] streamed snapshot to (n5,s5):?: kv pairs: 12, log entries: 17, rate-limit: 2.0 MiB/sec, 25ms\nI170610 06:40:04.832498 2476 storage/replica_command.go:2694  [split,n4,s4,r21/2:/System/{StatusNo…-tsd}] initiating a split of this range at key /System/StatusNode/3 [r22]\nI170610 06:40:04.832890 376 storage/replica_command.go:2694  [split,n2,s2,r31/2:/System/ts{d/cr.no…-e}] initiating a split of this range at key /System/tsd/cr.node.sql.exec.latency-p50/5/10s/2017-06-10T06:00:00Z [r32]\nI170610 06:40:04.833458 377 storage/replica_command.go:3599  [replicate,n2,s2,r4/2:/{System/tse-Table/0}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r4:/{System/tse-Table/0} [(n1,s1):1, (n2,s2):2, (n4,s4):3, (n3,s3):4, next=5]\nI170610 06:40:04.840479 3880 storage/replica_raftstorage.go:639  [n5,s5,r6/?:{-}] applying preemptive snapshot at index 27 (id=381a4d18, encoded size=11888, 1 rocksdb batches, 17 log entries)\nI170610 06:40:04.840774 3880 storage/replica_raftstorage.go:647  [n5,s5,r6/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.842348 1069 storage/replica_command.go:3599  [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n5,s5):4): read existing descriptor r6:/Table/1{1-2} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4]\nI170610 06:40:04.845442 3952 storage/replica.go:2865  [n2,s2,r4/2:/{System/tse-Table/0}] proposing REMOVE_REPLICA (n1,s1):1: [(n3,s3):4 (n2,s2):2 (n4,s4):3]\nI170610 06:40:04.847456 1942 storage/store.go:3193  [n1,s1,r4/1:/{System/tse-Table/0}] added to replica GC queue (peer suggestion)\nI170610 06:40:04.850876 1070 storage/store.go:2152  [replicaGC,n1,s1,r4/1:/{System/tse-Table/0}] removing replica\nI170610 06:40:04.851033 1070 storage/replica.go:714  [replicaGC,n1,s1,r4/1:/{System/tse-Table/0}] removed 10 (0+10) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:04.859779 377 storage/replica_command.go:3599  [replicate,n2,s2,r3/2:/System/tsd{-/cr.nod…}] change replicas (REMOVE_REPLICA (n3,s3):3): read existing descriptor r3:/System/tsd{-/cr.node.round-trip-latency-p50/2/10s/2017-06-10T06:00:00Z} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\nW170610 06:40:04.866793 1947 storage/store.go:3201  [n2,s2] got error from r4, replica (n1,s1):1: raft group deleted\nI170610 06:40:04.867474 4033 storage/replica.go:2865  [n1,s1,r6/1:/Table/1{1-2}] proposing ADD_REPLICA (n5,s5):4: [(n1,s1):1 (n2,s2):2 (n3,s3):3 (n5,s5):4]\nI170610 06:40:04.870670 1069 storage/replica_command.go:3599  [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (REMOVE_REPLICA (n5,s5):4): read existing descriptor r6:/Table/1{1-2} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\nI170610 06:40:04.871104 2476 storage/replica_command.go:2694  [split,n4,s4,r22/2:/System/{StatusNo…-tsd}] initiating a split of this range at key /System/StatusNode/4 [r23]\nI170610 06:40:04.879271 2480 storage/replica_raftstorage.go:442  [raftsnapshot,n4,s4,r22/2:/System/{StatusNo…-tsd}] generated Raft snapshot 4423c319 at index 13\nI170610 06:40:04.879350 4180 storage/replica.go:2865  [n1,s1,r6/1:/Table/1{1-2}] proposing REMOVE_REPLICA (n5,s5):4: [(n1,s1):1 (n2,s2):2 (n3,s3):3]\nI170610 06:40:04.885936 3048 storage/store.go:3193  [n5,s5,r6/4:/Table/1{1-2}] added to replica GC queue (peer suggestion)\nI170610 06:40:04.886333 1772 storage/replica_proposal.go:397  [n2,s2,r31/2:/System/ts{d/cr.no…-e}] new range lease repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:04.895484 2798 storage/store.go:2152  [replicaGC,n5,s5,r6/4:/Table/1{1-2}] removing replica\nI170610 06:40:04.895622 2798 storage/replica.go:714  [replicaGC,n5,s5,r6/4:/Table/1{1-2}] removed 10 (0+10) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:04.896580 2480 storage/store.go:3386  [raftsnapshot,n4,s4,r22/2:/System/{StatusNo…-tsd}] streamed snapshot to (n3,s3):3: kv pairs: 25, log entries: 3, rate-limit: 8.0 MiB/sec, 17ms\nI170610 06:40:04.896875 4153 storage/replica_raftstorage.go:639  [n3,s3,r22/3:/System/{StatusNo…-tsd}] applying Raft snapshot at index 13 (id=4423c319, encoded size=48982, 1 rocksdb batches, 3 log entries)\nI170610 06:40:04.897315 4153 storage/replica_raftstorage.go:647  [n3,s3,r22/3:/System/{StatusNo…-tsd}] applied Raft snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:04.897564 4260 storage/replica.go:2865  [n2,s2,r3/2:/System/tsd{-/cr.nod…}] proposing REMOVE_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n5,s5):4]\nI170610 06:40:04.899352 376 storage/replica_command.go:2694  [split,n2,s2,r32/2:/System/ts{d/cr.no…-e}] initiating a split of this range at key /System/tsd/cr.node.sql.mem.admin.txn.max-p99.99/4/10s/2017-06-10T06:00:00Z [r33]\nI170610 06:40:04.900394 3764 storage/store.go:3193  [n3,s3,r3/3:/System/tsd{-/cr.nod…}] added to replica GC queue (peer suggestion)\nI170610 06:40:04.901804 2180 storage/store.go:2152  [replicaGC,n3,s3,r3/3:/System/tsd{-/cr.nod…}] removing replica\nI170610 06:40:04.901938 2180 storage/replica.go:714  [replicaGC,n3,s3,r3/3:/System/tsd{-/cr.nod…}] removed 180 (171+9) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:04.902417 377 storage/replica_command.go:3599  [replicate,n2,s2,r31/2:/System/tsd/cr.node.{ro…-sq…}] change replicas (REMOVE_REPLICA (n3,s3):3): read existing descriptor r31:/System/tsd/cr.node.{round-trip-latency-p50/2/10s/2017-06-10T06:00:00Z-sql.exec.latency-p50/5/10s/2017-06-10T06:00:00Z} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\nI170610 06:40:04.912709 4254 storage/replica.go:2865  [n2,s2,r31/2:/System/tsd/cr.node.{ro…-sq…}] proposing REMOVE_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n5,s5):4]\nI170610 06:40:04.915477 3764 storage/store.go:3193  [n3,s3,r31/3:/System/tsd/cr.node.{ro…-sq…}] added to replica GC queue (peer suggestion)\nI170610 06:40:04.919534 1801 storage/replica_proposal.go:397  [n2,s2,r32/2:/System/ts{d/cr.no…-e}] new range lease repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:04.920137 377 storage/replica_command.go:3599  [replicate,n2,s2,r32/2:/System/tsd/cr.node.sql.…] change replicas (REMOVE_REPLICA (n3,s3):3): read existing descriptor r32:/System/tsd/cr.node.sql.{exec.latency-p50/5/10s/2017-06-10T06:00:00Z-mem.admin.txn.max-p99.99/4/10s/2017-06-10T06:00:00Z} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\nI170610 06:40:04.924536 3635 sql/event_log.go:101  [client=127.0.0.1:45690,user=root,n1] Event: \"create_database\", target: 50, info: {DatabaseName:test Statement:CREATE DATABASE test User:root}\nI170610 06:40:04.926449 2476 storage/replica_command.go:2694  [split,n4,s4,r10/3:/{Table/15-Max}] initiating a split of this range at key /Table/50 [r24]\nI170610 06:40:04.928608 376 storage/replica_command.go:2694  [split,n2,s2,r33/2:/System/ts{d/cr.no…-e}] initiating a split of this range at key /System/tsd/cr.node.sql.mem.conns.max-p90/1/10s/2017-06-10T06:00:00Z [r34]\nI170610 06:40:04.978435 2180 storage/store.go:2152  [replicaGC,n3,s3,r31/3:/System/tsd/cr.node.{ro…-sq…}] removing replica\nI170610 06:40:04.978564 2180 storage/replica.go:714  [replicaGC,n3,s3,r31/3:/System/tsd/cr.node.{ro…-sq…}] removed 172 (163+9) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:04.982649 4327 storage/replica.go:2865  [n2,s2,r32/2:/System/tsd/cr.node.sql.…] proposing REMOVE_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n5,s5):4]\nI170610 06:40:04.983051 2410 storage/replica_proposal.go:397  [n4,s4,r10/3:/{Table/15-Max}] new range lease repl=(n4,s4):3 start=1497076804.539870982,0 epo=1 pro=1497076804.539872882,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:04.986472 3764 storage/store.go:3193  [n3,s3,r32/3:/System/tsd/cr.node.sql.…] added to replica GC queue (peer suggestion)\nI170610 06:40:04.991595 2180 storage/store.go:2152  [replicaGC,n3,s3,r32/3:/System/tsd/cr.node.sql.…] removing replica\nI170610 06:40:04.991797 2180 storage/replica.go:714  [replicaGC,n3,s3,r32/3:/System/tsd/cr.node.sql.…] removed 173 (164+9) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:05.006785 1770 storage/replica_proposal.go:397  [n2,s2,r33/2:/System/ts{d/cr.no…-e}] new range lease repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:05.007461 377 storage/replica_command.go:3599  [replicate,n2,s2,r33/2:/System/tsd/cr.node.sql.mem.…] change replicas (REMOVE_REPLICA (n5,s5):4): read existing descriptor r33:/System/tsd/cr.node.sql.mem.{admin.txn.max-p99.99/4/10s/2017-06-10T06:00:00Z-conns.max-p90/1/10s/2017-06-10T06:00:00Z} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\nI170610 06:40:05.014691 376 storage/replica_command.go:2694  [split,n2,s2,r34/2:/System/ts{d/cr.no…-e}] initiating a split of this range at key /System/tsd/cr.node.sql.mem.internal.current/3/10s/2017-06-10T06:00:00Z [r35]\nI170610 06:40:05.025311 4590 storage/replica.go:2865  [n2,s2,r33/2:/System/tsd/cr.node.sql.mem.…] proposing REMOVE_REPLICA (n5,s5):4: [(n1,s1):1 (n2,s2):2 (n3,s3):3]\nI170610 06:40:05.025985 2476 storage/replica_command.go:2694  [split,n4,s4,r8/3:/Table/1{3-4}] initiating a split of this range at key /Table/13/1/2017-06-10T06:40:04.605099Z/252334586617102336 [r25]\nI170610 06:40:05.029400 3677 storage/store.go:3193  [n5,s5,r33/4:/System/tsd/cr.node.sql.mem.…] added to replica GC queue (peer suggestion)\nI170610 06:40:05.032006 1766 storage/replica_proposal.go:397  [n2,s2,r34/2:/System/ts{d/cr.no…-e}] new range lease repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:05.032603 377 storage/replica_command.go:3599  [replicate,n2,s2,r34/2:/System/tsd/cr.node.sql.mem.…] change replicas (REMOVE_REPLICA (n5,s5):4): read existing descriptor r34:/System/tsd/cr.node.sql.mem.{conns.max-p90/1/10s/2017-06-10T06:00:00Z-internal.current/3/10s/2017-06-10T06:00:00Z} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\nI170610 06:40:05.033812 376 storage/replica_command.go:2694  [split,n2,s2,r35/2:/System/ts{d/cr.no…-e}] initiating a split of this range at key /System/tsd/cr.node.sql.service.latency-p75/3/10s/2017-06-10T06:00:00Z [r36]\nI170610 06:40:05.036593 2798 storage/store.go:2152  [replicaGC,n5,s5,r33/4:/System/tsd/cr.node.sql.mem.…] removing replica\nI170610 06:40:05.040838 4494 storage/replica.go:2865  [n2,s2,r34/2:/System/tsd/cr.node.sql.mem.…] proposing REMOVE_REPLICA (n5,s5):4: [(n1,s1):1 (n2,s2):2 (n3,s3):3]\nI170610 06:40:05.041510 2798 storage/replica.go:714  [replicaGC,n5,s5,r33/4:/System/tsd/cr.node.sql.mem.…] removed 171 (162+9) keys in 5ms [clear=0ms commit=5ms]\nI170610 06:40:05.048518 1791 storage/replica_proposal.go:397  [n2,s2,r35/2:/System/ts{d/cr.no…-e}] new range lease repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:05.051310 1066 sql/logictest/parallel_test.go:230  Test setup done\nI170610 06:40:05.051330 1066 sql/logictest/parallel_test.go:162  testdata/parallel_test/subquery_retry_multinode/test.yaml: run list 0: 0:setup\nI170610 06:40:05.051528 376 storage/replica_command.go:2694  [split,n2,s2,r36/2:/System/ts{d/cr.no…-e}] initiating a split of this range at key /System/tsd/cr.node.txn.durations-p99/1/10s/2017-06-10T06:00:00Z [r37]\nI170610 06:40:05.051867 377 storage/replica_command.go:3599  [replicate,n2,s2,r35/2:/System/tsd/cr.node.sql.…] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r35:/System/tsd/cr.node.sql.{mem.internal.current/3/10s/2017-06-10T06:00:00Z-service.latency-p75/3/10s/2017-06-10T06:00:00Z} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\nI170610 06:40:05.054282 2448 storage/replica_proposal.go:397  [n4,s4,r8/3:/Table/1{3-4}] new range lease repl=(n4,s4):3 start=1497076804.594452639,0 epo=1 pro=1497076804.594454939,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:05.055100 2477 storage/replica_command.go:3599  [replicate,n4,s4,r8/3:/Table/13{-/1/2017-…}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r8:/Table/13{-/1/2017-06-10T06:40:04.605099Z/252334586617102336} [(n1,s1):1, (n3,s3):2, (n4,s4):3, (n2,s2):4, next=5]\nW170610 06:40:05.088070 3621 storage/store.go:3201  [n2,s2] got error from r32, replica (n3,s3):3: raft group deleted\nI170610 06:40:05.095031 2798 storage/store.go:2152  [replicaGC,n5,s5,r34/4:/System/tsd/cr.node.sql.mem.…] removing replica\nI170610 06:40:05.095167 2798 storage/replica.go:714  [replicaGC,n5,s5,r34/4:/System/tsd/cr.node.sql.mem.…] removed 171 (162+9) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:05.096568 4699 storage/replica.go:2865  [n2,s2,r35/2:/System/tsd/cr.node.sql.…] proposing REMOVE_REPLICA (n1,s1):1: [(n5,s5):4 (n2,s2):2 (n3,s3):3]\nI170610 06:40:05.103092 1942 storage/store.go:3193  [n1,s1,r35/1:/System/tsd/cr.node.sql.…] added to replica GC queue (peer suggestion)\nI170610 06:40:05.105416 1811 storage/replica_proposal.go:397  [n2,s2,r36/2:/System/ts{d/cr.no…-e}] new range lease repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:05.106382 377 storage/replica_command.go:3599  [replicate,n2,s2,r36/2:/System/tsd/cr.node.{sq…-tx…}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r36:/System/tsd/cr.node.{sql.service.latency-p75/3/10s/2017-06-10T06:00:00Z-txn.durations-p99/1/10s/2017-06-10T06:00:00Z} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\nI170610 06:40:05.108269 3635 sql/event_log.go:101  [client=127.0.0.1:45690,user=root,n1] Event: \"create_table\", target: 51, info: {TableName:t Statement:CREATE TABLE t (k INT, filler STRING) User:root}\nI170610 06:40:05.109933 2476 storage/replica_command.go:2694  [split,n4,s4,r24/3:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r26]\nI170610 06:40:05.123440 1070 storage/store.go:2152  [replicaGC,n1,s1,r35/1:/System/tsd/cr.node.sql.…] removing replica\nI170610 06:40:05.123553 1070 storage/replica.go:714  [replicaGC,n1,s1,r35/1:/System/tsd/cr.node.sql.…] removed 169 (160+9) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:05.130802 4925 storage/replica.go:2865  [n4,s4,r8/3:/Table/13{-/1/2017-…}] proposing REMOVE_REPLICA (n1,s1):1: [(n2,s2):4 (n3,s3):2 (n4,s4):3]\nI170610 06:40:05.134772 2477 storage/replica_command.go:3599  [replicate,n4,s4,r25/3:/Table/1{3/1/2017…-4}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r25:/Table/1{3/1/2017-06-10T06:40:04.605099Z/252334586617102336-4} [(n1,s1):1, (n3,s3):2, (n4,s4):3, (n2,s2):4, next=5]\nI170610 06:40:05.142542 4942 storage/replica.go:2865  [n2,s2,r36/2:/System/tsd/cr.node.{sq…-tx…}] proposing REMOVE_REPLICA (n1,s1):1: [(n5,s5):4 (n2,s2):2 (n3,s3):3]\nI170610 06:40:05.215555 1070 storage/store.go:2152  [replicaGC,n1,s1,r8/1:/Table/13{-/1/2017-…}] removing replica\nI170610 06:40:05.215920 1070 storage/replica.go:714  [replicaGC,n1,s1,r8/1:/Table/13{-/1/2017-…}] removed 174 (164+10) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:05.216407 377 storage/replica_command.go:3599  [replicate,n2,s2,r37/2:/System/ts{d/cr.no…-e}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r37:/System/ts{d/cr.node.txn.durations-p99/1/10s/2017-06-10T06:00:00Z-e} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]\n--- done: testdata/parallel_test/subquery_retry_multinode/setup: 2 tests, 0 failures\nI170610 06:40:05.219395 4758 sql/logictest/logic_test.go:587  --- done: testdata/parallel_test/subquery_retry_multinode/setup: 2 tests, 0 failures\nI170610 06:40:05.219420 1066 sql/logictest/parallel_test.go:162  testdata/parallel_test/subquery_retry_multinode/test.yaml: run list 1: 0:txn, 1:txn, 2:txn, 3:txn, 4:txn\nI170610 06:40:05.219930 2407 storage/replica_proposal.go:397  [n4,s4,r24/3:/{Table/50-Max}] new range lease repl=(n4,s4):3 start=1497076804.539870982,0 epo=1 pro=1497076804.539872882,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0\nI170610 06:40:05.224556 4990 storage/replica.go:2865  [n4,s4,r25/3:/Table/1{3/1/2017…-4}] proposing REMOVE_REPLICA (n1,s1):1: [(n2,s2):4 (n3,s3):2 (n4,s4):3]\n--- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\nI170610 06:40:05.230927 5069 sql/logictest/logic_test.go:587  --- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\nI170610 06:40:05.233391 5052 storage/replica.go:2865  [n2,s2,r37/2:/System/ts{d/cr.no…-e}] proposing REMOVE_REPLICA (n1,s1):1: [(n5,s5):4 (n2,s2):2 (n3,s3):3]\nI170610 06:40:05.235031 377 storage/replica_raftstorage.go:442  [replicate,n2,s2,r36/2:/System/tsd/cr.node.{sq…-tx…}] generated preemptive snapshot ae577ddd at index 21\n--- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\nI170610 06:40:05.288470 5072 sql/logictest/logic_test.go:587  --- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\nI170610 06:40:05.303580 377 storage/store.go:3386  [replicate,n2,s2,r36/2:/System/tsd/cr.node.{sq…-tx…}] streamed snapshot to (n4,s4):?: kv pairs: 189, log entries: 11, rate-limit: 2.0 MiB/sec, 68ms\nI170610 06:40:05.307323 5005 storage/replica_raftstorage.go:639  [n4,s4,r36/?:{-}] applying preemptive snapshot at index 21 (id=ae577ddd, encoded size=27613, 1 rocksdb batches, 11 log entries)\nI170610 06:40:05.307463 1070 storage/store.go:2152  [replicaGC,n1,s1,r36/1:/System/tsd/cr.node.{sq…-tx…}] removing replica\nI170610 06:40:05.307583 1070 storage/replica.go:714  [replicaGC,n1,s1,r36/1:/System/tsd/cr.node.{sq…-tx…}] removed 188 (178+10) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:05.307713 5005 storage/replica_raftstorage.go:647  [n4,s4,r36/?:/System/tsd/cr.node.{sq…-tx…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI170610 06:40:05.308347 377 storage/replica_command.go:3599  [replicate,n2,s2,r36/2:/System/tsd/cr.node.{sq…-tx…}] change replicas (ADD_REPLICA (n4,s4):5): read existing descriptor r36:/System/tsd/cr.node.{sql.service.latency-p75/3/10s/2017-06-10T06:00:00Z-txn.durations-p99/1/10s/2017-06-10T06:00:00Z} [(n5,s5):4, (n2,s2):2, (n3,s3):3, next=5]\nI170610 06:40:05.308808 1803 storage/replica_proposal.go:397  [n2,s2,r7/4:/Table/1{2-3}] new range lease repl=(n2,s2):4 start=1497076805.304140486,0 epo=1 pro=1497076805.304142786,0 following repl=(n5,s5):3 start=1497076804.804069084,0 epo=1 pro=1497076804.804071384,0\nI170610 06:40:05.318267 5133 storage/replica.go:2865  [n2,s2,r36/2:/System/tsd/cr.node.{sq…-tx…}] proposing ADD_REPLICA (n4,s4):5: [(n5,s5):4 (n2,s2):2 (n3,s3):3 (n4,s4):5]\nI170610 06:40:05.320540 377 storage/replica_command.go:3599  [replicate,n2,s2,r36/2:/System/tsd/cr.node.{sq…-tx…}] change replicas (REMOVE_REPLICA (n5,s5):4): read existing descriptor r36:/System/tsd/cr.node.{sql.service.latency-p75/3/10s/2017-06-10T06:00:00Z-txn.durations-p99/1/10s/2017-06-10T06:00:00Z} [(n5,s5):4, (n2,s2):2, (n3,s3):3, (n4,s4):5, next=6]\nI170610 06:40:05.327063 5380 storage/replica.go:2865  [n2,s2,r36/2:/System/tsd/cr.node.{sq…-tx…}] proposing REMOVE_REPLICA (n5,s5):4: [(n4,s4):5 (n2,s2):2 (n3,s3):3]\nI170610 06:40:05.330838 3677 storage/store.go:3193  [n5,s5,r36/4:/System/tsd/cr.node.{sq…-tx…}] added to replica GC queue (peer suggestion)\nI170610 06:40:05.336805 2798 storage/store.go:2152  [replicaGC,n5,s5,r36/4:/System/tsd/cr.node.{sq…-tx…}] removing replica\nI170610 06:40:05.336971 2798 storage/replica.go:714  [replicaGC,n5,s5,r36/4:/System/tsd/cr.node.{sq…-tx…}] removed 188 (178+10) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:05.348697 2728 storage/replica_proposal.go:397  [n5,s5,r37/4:/System/ts{d/cr.no…-e}] new range lease repl=(n5,s5):4 start=1497076805.345771569,0 epo=1 pro=1497076805.345774269,0 following repl=(n2,s2):2 start=1497076804.736959061,0 epo=1 pro=1497076804.736961361,0\nI170610 06:40:05.359270 1070 storage/store.go:2152  [replicaGC,n1,s1,r37/1:/System/ts{d/cr.no…-e}] removing replica\nI170610 06:40:05.359394 1070 storage/replica.go:714  [replicaGC,n1,s1,r37/1:/System/ts{d/cr.no…-e}] removed 242 (233+9) keys in 0ms [clear=0ms commit=0ms]\nI170610 06:40:05.360197 5509 storage/raft_transport.go:436  [n5] raft transport stream to node 3 established\nI170610 06:40:05.360542 5463 storage/raft_transport.go:436  [n3] raft transport stream to node 5 established\n--- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\nI170610 06:40:05.364826 5071 sql/logictest/logic_test.go:587  --- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\n--- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\nI170610 06:40:05.366313 5070 sql/logictest/logic_test.go:587  --- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\n--- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\nI170610 06:40:05.373108 5073 sql/logictest/logic_test.go:587  --- done: testdata/parallel_test/subquery_retry_multinode/txn: 1 tests, 0 failures\nI170610 06:40:05.373134 1066 sql/logictest/parallel_test.go:162  testdata/parallel_test/subquery_retry_multinode/test.yaml: run list 2: 0:final\n--- done: testdata/parallel_test/subquery_retry_multinode/final: 2 tests, 0 failures\nI170610 06:40:05.381052 5468 sql/logictest/logic_test.go:587  --- done: testdata/parallel_test/subquery_retry_multinode/final: 2 tests, 0 failures\nW170610 06:40:05.381220 3459 storage/raft_transport.go:442  [n5] raft transport stream to node 4 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381350 2929 storage/raft_transport.go:442  [n1] raft transport stream to node 5 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381470 3554 storage/raft_transport.go:442  [n2] raft transport stream to node 3 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381538 1940 storage/raft_transport.go:442  [n1] raft transport stream to node 2 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381556 5463 storage/raft_transport.go:442  [n3] raft transport stream to node 5 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381584 2492 storage/raft_transport.go:442  [n1] raft transport stream to node 3 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381817 3046 storage/raft_transport.go:442  [n5] raft transport stream to node 1 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381834 3592 storage/raft_transport.go:442  [n2] raft transport stream to node 5 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381858 1945 storage/raft_transport.go:442  [n2] raft transport stream to node 1 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381901 3675 storage/raft_transport.go:442  [n5] raft transport stream to node 2 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381973 3289 storage/raft_transport.go:442  [n2] raft transport stream to node 4 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.381987 2556 gossip/gossip.go:1196  [n5] no incoming or outgoing connections\nW170610 06:40:05.381995 5509 storage/raft_transport.go:442  [n5] raft transport stream to node 3 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.382823 2674 storage/raft_transport.go:442  [n3] raft transport stream to node 1 failed: rpc error: code = Internal desc = transport is closing\nI170610 06:40:05.382922 2047 vendor/google.golang.org/grpc/transport/http2_server.go:392  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:54084->127.0.0.1:45606: use of closed network connection\nW170610 06:40:05.383003 3281 storage/raft_transport.go:442  [n4] raft transport stream to node 3 failed: EOF\nW170610 06:40:05.383098 3762 storage/raft_transport.go:442  [n3] raft transport stream to node 2 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.383146 3445 storage/raft_transport.go:442  [n3] raft transport stream to node 4 failed: rpc error: code = Internal desc = transport is closing\nW170610 06:40:05.383396 3378 storage/raft_transport.go:442  [n4] raft transport stream to node 5 failed: EOF\nW170610 06:40:05.383414 3411 storage/raft_transport.go:442  [n4] raft transport stream to node 2 failed: EOF\nI170610 06:40:05.387628 9 sql/logictest/parallel_test.go:253  2 parallel tests passed\n```"},"comment":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/comments/363341415","html_url":"https://github.com/cockroachdb/cockroach/issues/16439#issuecomment-363341415","issue_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/16439","id":363341415,"user":{"login":"cockroach-teamcity","id":20559710,"avatar_url":"https://avatars0.githubusercontent.com/u/20559710?v=4","gravatar_id":"","url":"https://api.github.com/users/cockroach-teamcity","html_url":"https://github.com/cockroach-teamcity","followers_url":"https://api.github.com/users/cockroach-teamcity/followers","following_url":"https://api.github.com/users/cockroach-teamcity/following{/other_user}","gists_url":"https://api.github.com/users/cockroach-teamcity/gists{/gist_id}","starred_url":"https://api.github.com/users/cockroach-teamcity/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cockroach-teamcity/subscriptions","organizations_url":"https://api.github.com/users/cockroach-teamcity/orgs","repos_url":"https://api.github.com/users/cockroach-teamcity/repos","events_url":"https://api.github.com/users/cockroach-teamcity/events{/privacy}","received_events_url":"https://api.github.com/users/cockroach-teamcity/received_events","type":"User","site_admin":false},"created_at":"2018-02-06T08:02:44Z","updated_at":"2018-02-06T08:02:44Z","author_association":"MEMBER","body":"SHA: https://github.com/cockroachdb/cockroach/commits/4b2c64a7107e392229939b24b5bda303c1950a1f\n\nParameters:\n```\nTAGS=\nGOFLAGS=\n```\n\nStress build found a failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=507916&tab=buildLog"}}
{"actor":{"display_login":"cockroach-teamcity"}}