Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

teamcity: failed tests on master: test/TestRestoreDatabaseVersusTable, test/TestRestoreDatabaseVersusTable/incomplete-db, test/TestRestoreDatabaseVersusTable/db, testrace/TestRestoreDatabaseVersusTable, testrace/TestRestoreDatabaseVersusTable/incomplete-db, testrace/TestRestoreDatabaseVersusTable/db #21212

Closed
cockroach-teamcity opened this issue Jan 3, 2018 · 1 comment
Closed

teamcity: failed tests on master: test/TestRestoreDatabaseVersusTable, test/TestRestoreDatabaseVersusTable/incomplete-db, test/TestRestoreDatabaseVersusTable/db, testrace/TestRestoreDatabaseVersusTable, testrace/TestRestoreDatabaseVersusTable/incomplete-db, testrace/TestRestoreDatabaseVersusTable/db #21212

cockroach-teamcity opened this issue Jan 3, 2018 · 1 comment
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#465830:

--- FAIL: test/TestRestoreDatabaseVersusTable (0.000s)
Test ended in panic.

------- Stdout: -------
W180103 20:16:23.095476 149633 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180103 20:16:23.097271 149633 server/config.go:516  [n?] 1 storage engine initialized
I180103 20:16:23.097288 149633 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180103 20:16:23.097294 149633 server/config.go:519  [n?] store 0: in-memory, size 0 B
I180103 20:16:23.099484 149633 server/node.go:361  [n?] **** cluster 8e727ef5-3996-4cfa-a204-7537fbe298de has been created
I180103 20:16:23.099512 149633 server/server.go:934  [n?] **** add additional nodes by specifying --join=127.0.0.1:36379
I180103 20:16:23.100102 149633 storage/store.go:1208  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180103 20:16:23.100370 149633 server/node.go:486  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=3.2 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=3322.00 p25=3322.00 p50=3322.00 p75=3322.00 p90=3322.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00}
I180103 20:16:23.100402 149633 server/node.go:339  [n1] node ID 1 initialized
I180103 20:16:23.100458 149633 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:36379" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180103 20:16:23.100516 149633 storage/stores.go:331  [n1] read 0 node addresses from persistent storage
I180103 20:16:23.100598 149633 server/node.go:627  [n1] connecting to gossip network to verify cluster ID...
I180103 20:16:23.100618 149633 server/node.go:652  [n1] node connected via gossip and verified as part of cluster "8e727ef5-3996-4cfa-a204-7537fbe298de"
I180103 20:16:23.100646 149633 server/node.go:428  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180103 20:16:23.100689 149633 sql/distsql_physical_planner.go:122  [n1] creating DistSQLPlanner with address {tcp 127.0.0.1:36379}
I180103 20:16:23.102962 149924 storage/replica_command.go:819  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180103 20:16:23.106108 149633 server/server.go:1161  [n1] starting https server at 127.0.0.1:37691
I180103 20:16:23.106131 149633 server/server.go:1162  [n1] starting grpc/postgres server at 127.0.0.1:36379
I180103 20:16:23.106139 149633 server/server.go:1163  [n1] advertising CockroachDB node at 127.0.0.1:36379
I180103 20:16:23.115500 149924 storage/replica_command.go:819  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180103 20:16:23.120527 149924 storage/replica_command.go:819  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180103 20:16:23.121286 149633 sql/event_log.go:115  [n1] Event: "alter_table", target: 12, info: {TableName:eventlog Statement:ALTER TABLE system.eventlog ALTER COLUMN "uniqueID" SET DEFAULT uuid_v4() User:node MutationID:0 CascadeDroppedViews:[]}
I180103 20:16:23.124934 149924 storage/replica_command.go:819  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180103 20:16:23.125117 149633 sql/lease.go:348  [n1] publish: descID=12 (eventlog) version=2 mtime=2018-01-03 20:16:23.125002778 +0000 UTC
I180103 20:16:23.128326 149924 storage/replica_command.go:819  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180103 20:16:23.134016 149924 storage/replica_command.go:819  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180103 20:16:23.137286 149924 storage/replica_command.go:819  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180103 20:16:23.137986 149633 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180103 20:16:23.140732 149924 storage/replica_command.go:819  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
W180103 20:16:23.145946 150051 storage/intent_resolver.go:324  [n1,s1] failed to push during intent resolution: failed to push "split" id=e0e331b6 key=/Local/Range/Table/11/RangeDescriptor rw=true pri=0.02999054 iso=SERIALIZABLE stat=PENDING epo=0 ts=1515010583.140744220,0 orig=1515010583.140744220,0 max=1515010583.140744220,0 wto=false rop=false seq=3
I180103 20:16:23.146941 149924 storage/replica_command.go:819  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180103 20:16:23.148419 149633 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180103 20:16:23.150337 149924 storage/replica_command.go:819  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180103 20:16:23.151529 149633 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180103 20:16:23.153338 149924 storage/replica_command.go:819  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180103 20:16:23.155977 149924 storage/replica_command.go:819  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180103 20:16:23.158814 149924 storage/replica_command.go:819  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180103 20:16:23.161112 149633 sql/event_log.go:115  [n1] Event: "alter_table", target: 4, info: {TableName:users Statement:ALTER TABLE system.users ADD COLUMN IF NOT EXISTS "isRole" BOOL NOT NULL DEFAULT false User:node MutationID:1 CascadeDroppedViews:[]}
I180103 20:16:23.161382 149924 storage/replica_command.go:819  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180103 20:16:23.164083 149633 sql/lease.go:348  [n1] publish: descID=4 (users) version=2 mtime=2018-01-03 20:16:23.163715486 +0000 UTC
I180103 20:16:23.165409 149924 storage/replica_command.go:819  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180103 20:16:23.167992 149924 storage/replica_command.go:819  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180103 20:16:23.168748 149633 sql/lease.go:348  [n1] publish: descID=4 (users) version=3 mtime=2018-01-03 20:16:23.168657768 +0000 UTC
I180103 20:16:23.170844 149924 storage/replica_command.go:819  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180103 20:16:23.171979 149633 sql/backfill.go:132  [n1] Running backfill for "users", v=3, m=1
I180103 20:16:23.173474 149924 storage/replica_command.go:819  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180103 20:16:23.176074 149924 storage/replica_command.go:819  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180103 20:16:23.178851 149633 sql/lease.go:348  [n1] publish: descID=4 (users) version=4 mtime=2018-01-03 20:16:23.178769987 +0000 UTC
I180103 20:16:23.181581 149633 sql/event_log.go:115  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180103 20:16:23.182201 149633 sql/lease.go:274  publish (count leases): descID=4 name=users version=3 count=1
I180103 20:16:23.214549 149633 server/server.go:1232  [n1] done ensuring all necessary migrations have run
I180103 20:16:23.214580 149633 server/server.go:1235  [n1] serving sql connections
I180103 20:16:23.216338 150219 sql/event_log.go:115  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:36379} Attrs: Locality: ServerVersion:1.1-8} ClusterID:8e727ef5-3996-4cfa-a204-7537fbe298de StartedAt:1515010583100620410 LastUp:1515010583100620410}
I180103 20:16:23.226959 150243 sql/event_log.go:115  [client=127.0.0.1:53024,user=root,n1] Event: "create_database", target: 50, info: {DatabaseName:data Statement:CREATE DATABASE data User:root}
I180103 20:16:23.227280 149924 storage/replica_command.go:819  [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180103 20:16:23.229762 150243 sql/event_log.go:115  [client=127.0.0.1:53024,user=root,n1] Event: "create_table", target: 51, info: {TableName:bank Statement:CREATE TABLE bank (id INT PRIMARY KEY, balance INT, payload STRING, FAMILY (id, balance, payload)) User:root}
I180103 20:16:23.230345 149924 storage/replica_command.go:819  [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180103 20:16:23.234097 150243 sql/event_log.go:115  [client=127.0.0.1:53024,user=root,n1] Event: "create_database", target: 52, info: {DatabaseName:d2 Statement:CREATE DATABASE d2 User:root}
I180103 20:16:23.234409 149924 storage/replica_command.go:819  [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180103 20:16:23.236668 150243 sql/event_log.go:115  [client=127.0.0.1:53024,user=root,n1] Event: "create_database", target: 53, info: {DatabaseName:d3 Statement:CREATE DATABASE d3 User:root}
I180103 20:16:23.237262 149924 storage/replica_command.go:819  [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180103 20:16:23.239227 150243 sql/event_log.go:115  [client=127.0.0.1:53024,user=root,n1] Event: "create_table", target: 54, info: {TableName:d3.foo Statement:CREATE TABLE d3.foo (a INT) User:root}
I180103 20:16:23.240261 149924 storage/replica_command.go:819  [split,n1,s1,r24/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r25]
I180103 20:16:23.241743 150243 sql/event_log.go:115  [client=127.0.0.1:53024,user=root,n1] Event: "create_database", target: 55, info: {DatabaseName:d4 Statement:CREATE DATABASE d4 User:root}
I180103 20:16:23.243523 149924 storage/replica_command.go:819  [split,n1,s1,r25/1:/{Table/54-Max}] initiating a split of this range at key /Table/55 [r26]
I180103 20:16:23.245322 150243 sql/event_log.go:115  [client=127.0.0.1:53024,user=root,n1] Event: "create_table", target: 56, info: {TableName:d4.foo Statement:CREATE TABLE d4.foo (a INT) User:root}
I180103 20:16:23.248841 150243 sql/event_log.go:115  [client=127.0.0.1:53024,user=root,n1] Event: "create_table", target: 57, info: {TableName:d4.bar Statement:CREATE TABLE d4.bar (a INT) User:root}
I180103 20:16:23.249258 149924 storage/replica_command.go:819  [split,n1,s1,r26/1:/{Table/55-Max}] initiating a split of this range at key /Table/56 [r27]
I180103 20:16:23.252050 149924 storage/replica_command.go:819  [split,n1,s1,r27/1:/{Table/56-Max}] initiating a split of this range at key /Table/57 [r28]
I180103 20:16:23.255957 150238 ccl/storageccl/export.go:124  [n1,s1,r27/1:/Table/5{6-7}] export [/Table/56/1,/Table/56/2)
I180103 20:16:23.256165 150239 ccl/storageccl/export.go:124  [n1,s1,r28/1:/{Table/57-Max}] export [/Table/57/1,/Table/57/2)
I180103 20:16:23.256265 150237 ccl/storageccl/export.go:124  [n1,s1,r25/1:/Table/5{4-5}] export [/Table/54/1,/Table/54/2)
I180103 20:16:23.256393 150236 ccl/storageccl/export.go:124  [n1,s1,r22/1:/Table/5{1-2}] export [/Table/51/1,/Table/51/2)
I180103 20:16:23.274563 150371 ccl/storageccl/export.go:124  [n1,s1,r27/1:/Table/5{6-7}] export [/Table/56/1,/Table/56/2)
I180103 20:16:23.287071 150352 ccl/storageccl/export.go:124  [n1,s1,r28/1:/{Table/57-Max}] export [/Table/57/1,/Table/57/2)
I180103 20:16:23.287145 150351 ccl/storageccl/export.go:124  [n1,s1,r27/1:/Table/5{6-7}] export [/Table/56/1,/Table/56/2)
I180103 20:16:23.301197 150391 ccl/storageccl/export.go:124  [n1,s1,r28/1:/{Table/57-Max}] export [/Table/57/1,/Table/57/2)
I180103 20:16:23.301283 150390 ccl/storageccl/export.go:124  [n1,s1,r27/1:/Table/5{6-7}] export [/Table/56/1,/Table/56/2)
--- FAIL: test/TestRestoreDatabaseVersusTable/incomplete-db (0.000s)
Test ended in panic.

------- Stdout: -------
W180103 20:16:23.315706 150329 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180103 20:16:23.317463 150329 server/config.go:516  [n?] 1 storage engine initialized
I180103 20:16:23.317480 150329 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180103 20:16:23.317486 150329 server/config.go:519  [n?] store 0: in-memory, size 0 B
I180103 20:16:23.319570 150329 server/node.go:361  [n?] **** cluster 1ecb8183-a03f-449f-8af5-bcf187d26a6a has been created
I180103 20:16:23.319595 150329 server/server.go:934  [n?] **** add additional nodes by specifying --join=127.0.0.1:42259
I180103 20:16:23.320206 150329 storage/store.go:1208  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180103 20:16:23.320253 150329 server/node.go:486  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=3.2 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=3322.00 p25=3322.00 p50=3322.00 p75=3322.00 p90=3322.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00}
I180103 20:16:23.320284 150329 server/node.go:339  [n1] node ID 1 initialized
I180103 20:16:23.320327 150329 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:42259" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180103 20:16:23.320427 150329 storage/stores.go:331  [n1] read 0 node addresses from persistent storage
I180103 20:16:23.320470 150329 server/node.go:627  [n1] connecting to gossip network to verify cluster ID...
I180103 20:16:23.320528 150329 server/node.go:652  [n1] node connected via gossip and verified as part of cluster "1ecb8183-a03f-449f-8af5-bcf187d26a6a"
I180103 20:16:23.320548 150329 server/node.go:428  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180103 20:16:23.320602 150329 sql/distsql_physical_planner.go:122  [n1] creating DistSQLPlanner with address {tcp 127.0.0.1:42259}
I180103 20:16:23.321743 150567 storage/replica_command.go:819  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180103 20:16:23.325336 150329 server/server.go:1161  [n1] starting https server at 127.0.0.1:35969
I180103 20:16:23.325363 150329 server/server.go:1162  [n1] starting grpc/postgres server at 127.0.0.1:42259
I180103 20:16:23.325372 150329 server/server.go:1163  [n1] advertising CockroachDB node at 127.0.0.1:42259
I180103 20:16:23.331850 150567 storage/replica_command.go:819  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180103 20:16:23.335085 150567 storage/replica_command.go:819  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180103 20:16:23.335418 150329 sql/event_log.go:115  [n1] Event: "alter_table", target: 12, info: {TableName:eventlog Statement:ALTER TABLE system.eventlog ALTER COLUMN "uniqueID" SET DEFAULT uuid_v4() User:node MutationID:0 CascadeDroppedViews:[]}
I180103 20:16:23.339021 150567 storage/replica_command.go:819  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180103 20:16:23.339237 150329 sql/lease.go:348  [n1] publish: descID=12 (eventlog) version=2 mtime=2018-01-03 20:16:23.339092437 +0000 UTC
I180103 20:16:23.342760 150567 storage/replica_command.go:819  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180103 20:16:23.348180 150567 storage/replica_command.go:819  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180103 20:16:23.351456 150567 storage/replica_command.go:819  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180103 20:16:23.351954 150329 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180103 20:16:23.354915 150567 storage/replica_command.go:819  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180103 20:16:23.359534 150567 storage/replica_command.go:819  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180103 20:16:23.360949 150329 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180103 20:16:23.364131 150567 storage/replica_command.go:819  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180103 20:16:23.365033 150329 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180103 20:16:23.367271 150567 storage/replica_command.go:819  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180103 20:16:23.370350 150567 storage/replica_command.go:819  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180103 20:16:23.373239 150567 storage/replica_command.go:819  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180103 20:16:23.374769 150329 sql/event_log.go:115  [n1] Event: "alter_table", target: 4, info: {TableName:users Statement:ALTER TABLE system.users ADD COLUMN IF NOT EXISTS "isRole" BOOL NOT NULL DEFAULT false User:node MutationID:1 CascadeDroppedViews:[]}
I180103 20:16:23.376063 150567 storage/replica_command.go:819  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180103 20:16:23.376834 150329 sql/lease.go:348  [n1] publish: descID=4 (users) version=2 mtime=2018-01-03 20:16:23.376731089 +0000 UTC
I180103 20:16:23.378657 150567 storage/replica_command.go:819  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180103 20:16:23.380839 150329 sql/lease.go:348  [n1] publish: descID=4 (users) version=3 mtime=2018-01-03 20:16:23.380749984 +0000 UTC
I180103 20:16:23.381407 150567 storage/replica_command.go:819  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180103 20:16:23.383911 150567 storage/replica_command.go:819  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180103 20:16:23.383952 150329 sql/backfill.go:132  [n1] Running backfill for "users", v=3, m=1
I180103 20:16:23.386448 150567 storage/replica_command.go:819  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180103 20:16:23.389017 150567 storage/replica_command.go:819  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180103 20:16:23.390645 150329 sql/lease.go:348  [n1] publish: descID=4 (users) version=4 mtime=2018-01-03 20:16:23.390467582 +0000 UTC
I180103 20:16:23.396761 150329 sql/event_log.go:115  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180103 20:16:23.397364 150329 sql/lease.go:274  publish (count leases): descID=4 name=users version=3 count=1
I180103 20:16:23.425769 150329 server/server.go:1232  [n1] done ensuring all necessary migrations have run
I180103 20:16:23.425802 150329 server/server.go:1235  [n1] serving sql connections
I180103 20:16:23.427895 150914 sql/event_log.go:115  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:42259} Attrs: Locality: ServerVersion:1.1-8} ClusterID:1ecb8183-a03f-449f-8af5-bcf187d26a6a StartedAt:1515010583320534481 LastUp:1515010583320534481}
W180103 20:16:23.430255 150329 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180103 20:16:23.431958 150329 server/config.go:516  [n?] 1 storage engine initialized
I180103 20:16:23.431974 150329 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180103 20:16:23.431979 150329 server/config.go:519  [n?] store 0: in-memory, size 0 B
W180103 20:16:23.432013 150329 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180103 20:16:23.432037 150329 server/server.go:936  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180103 20:16:23.440954 150899 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:42259
I180103 20:16:23.441352 150874 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:40361}
I180103 20:16:23.442130 150329 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180103 20:16:23.442166 150329 storage/stores.go:350  [n?] wrote 1 node addresses to persistent storage
I180103 20:16:23.442177 150329 server/node.go:627  [n?] connecting to gossip network to verify cluster ID...
I180103 20:16:23.442196 150329 server/node.go:652  [n?] node connected via gossip and verified as part of cluster "1ecb8183-a03f-449f-8af5-bcf187d26a6a"
I180103 20:16:23.442397 150955 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180103 20:16:23.443096 150954 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180103 20:16:23.443785 150329 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180103 20:16:23.444474 150329 server/node.go:332  [n?] new node allocated ID 2
I180103 20:16:23.444537 150329 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:40361" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180103 20:16:23.444640 150329 server/node.go:414  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180103 20:16:23.444659 150329 server/node.go:428  [n2] node=2: started with [] engine(s) and attributes []
I180103 20:16:23.444703 150329 sql/distsql_physical_planner.go:122  [n2] creating DistSQLPlanner with address {tcp 127.0.0.1:40361}
I180103 20:16:23.448713 150994 storage/stores.go:350  [n1] wrote 1 node addresses to persistent storage
I180103 20:16:23.449860 150329 server/server.go:1161  [n2] starting https server at 127.0.0.1:43403
I180103 20:16:23.449882 150329 server/server.go:1162  [n2] starting grpc/postgres server at 127.0.0.1:40361
I180103 20:16:23.449891 150329 server/server.go:1163  [n2] advertising CockroachDB node at 127.0.0.1:40361
I180103 20:16:23.450194 150961 server/node.go:608  [n2] bootstrapped store [n2,s2]
I180103 20:16:23.450926 150329 server/server.go:1232  [n2] done ensuring all necessary migrations have run
I180103 20:16:23.450949 150329 server/server.go:1235  [n2] serving sql connections
I180103 20:16:23.455281 150861 sql/event_log.go:115  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:40361} Attrs: Locality: ServerVersion:1.1-8} ClusterID:1ecb8183-a03f-449f-8af5-bcf187d26a6a StartedAt:1515010583444650670 LastUp:1515010583444650670}
W180103 20:16:23.455829 150329 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180103 20:16:23.457576 150329 server/config.go:516  [n?] 1 storage engine initialized
I180103 20:16:23.457592 150329 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180103 20:16:23.457599 150329 server/config.go:519  [n?] store 0: in-memory, size 0 B
W180103 20:16:23.457632 150329 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180103 20:16:23.457662 150329 server/server.go:936  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180103 20:16:23.466130 150840 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:42259
I180103 20:16:23.466390 151104 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:34941}
I180103 20:16:23.467233 150329 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180103 20:16:23.467273 150329 storage/stores.go:350  [n?] wrote 2 node addresses to persistent storage
I180103 20:16:23.467285 150329 server/node.go:627  [n?] connecting to gossip network to verify cluster ID...
I180103 20:16:23.467300 150329 server/node.go:652  [n?] node connected via gossip and verified as part of cluster "1ecb8183-a03f-449f-8af5-bcf187d26a6a"
I180103 20:16:23.467465 151145 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180103 20:16:23.467999 151144 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180103 20:16:23.468480 150329 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180103 20:16:23.469022 150329 server/node.go:332  [n?] new node allocated ID 3
I180103 20:16:23.469075 150329 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:34941" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180103 20:16:23.469117 150329 server/node.go:414  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180103 20:16:23.469131 150329 server/node.go:428  [n3] node=3: started with [] engine(s) and attributes []
I180103 20:16:23.469166 150329 sql/distsql_physical_planner.go:122  [n3] creating DistSQLPlanner with address {tcp 127.0.0.1:34941}
I180103 20:16:23.469522 151137 storage/stores.go:350  [n1] wrote 2 node addresses to persistent storage
I180103 20:16:23.469805 150999 storage/stores.go:350  [n2] wrote 2 node addresses to persistent storage
I180103 20:16:23.474363 150329 server/server.go:1161  [n3] starting https server at 127.0.0.1:43331
I180103 20:16:23.474409 150329 server/server.go:1162  [n3] starting grpc/postgres server at 127.0.0.1:34941
I180103 20:16:23.474423 150329 server/server.go:1163  [n3] advertising CockroachDB node at 127.0.0.1:34941
I180103 20:16:23.474590 151109 server/node.go:608  [n3] bootstrapped store [n3,s3]
I180103 20:16:23.475619 150329 server/server.go:1232  [n3] done ensuring all necessary migrations have run
I180103 20:16:23.475639 150329 server/server.go:1235  [n3] serving sql connections
I180103 20:16:23.476100 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 20c38fbb at index 18
I180103 20:16:23.478070 150329 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180103 20:16:23.479656 151267 sql/event_log.go:115  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:34941} Attrs: Locality: ServerVersion:1.1-8} ClusterID:1ecb8183-a03f-449f-8af5-bcf187d26a6a StartedAt:1515010583469124780 LastUp:1515010583469124780}
I180103 20:16:23.485465 150603 storage/store.go:3563  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.485749 151335 storage/replica_raftstorage.go:745  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 18 (id=20c38fbb, encoded size=5499, 1 rocksdb batches, 8 log entries)
I180103 20:16:23.486400 151335 storage/replica_raftstorage.go:751  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180103 20:16:23.486696 150603 storage/replica_command.go:1741  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2]
I180103 20:16:23.488200 150603 storage/replica.go:3181  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.488606 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot ac84ee73 at index 15
I180103 20:16:23.489703 151245 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180103 20:16:23.492495 150329 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180103 20:16:23.497799 150603 storage/store.go:3563  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.498008 151344 storage/replica_raftstorage.go:745  [n3,s3,r14/?:{-}] applying preemptive snapshot at index 15 (id=ac84ee73, encoded size=2683, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.498596 151344 storage/replica_raftstorage.go:751  [n3,s3,r14/?:/Table/1{7-8}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.498970 150603 storage/replica_command.go:1741  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2]
I180103 20:16:23.500386 150603 storage/replica.go:3181  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.500803 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 5a4fc8f1 at index 12
I180103 20:16:23.501246 150603 storage/store.go:3563  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n3,s3):?: kv pairs: 15, log entries: 2, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.501478 151363 storage/replica_raftstorage.go:745  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 12 (id=5a4fc8f1, encoded size=1084, 1 rocksdb batches, 2 log entries)
I180103 20:16:23.501596 151363 storage/replica_raftstorage.go:751  [n3,s3,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.501634 151368 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180103 20:16:23.501938 150603 storage/replica_command.go:1741  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, next=2]
I180103 20:16:23.503211 150603 storage/replica.go:3181  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.503588 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot a83f44c0 at index 21
I180103 20:16:23.504215 150568 storage/store.go:3563  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 11, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.504593 151310 storage/replica_raftstorage.go:745  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 21 (id=a83f44c0, encoded size=6617, 1 rocksdb batches, 11 log entries)
I180103 20:16:23.504827 151310 storage/replica_raftstorage.go:751  [n3,s3,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.505142 150568 storage/replica_command.go:1741  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n2,s2):2, next=3]
I180103 20:16:23.506916 150568 storage/replica.go:3181  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180103 20:16:23.507633 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 7e85474d at index 18
I180103 20:16:23.508046 150603 storage/store.go:3563  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.508325 151289 storage/replica_raftstorage.go:745  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 18 (id=7e85474d, encoded size=5735, 1 rocksdb batches, 8 log entries)
I180103 20:16:23.508486 151289 storage/replica_raftstorage.go:751  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.508879 150603 storage/replica_command.go:1741  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2]
I180103 20:16:23.510135 150603 storage/replica.go:3181  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.510491 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 19f199e2 at index 30
I180103 20:16:23.511042 150603 storage/store.go:3563  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 57, log entries: 20, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.511389 151403 storage/replica_raftstorage.go:745  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 30 (id=19f199e2, encoded size=19692, 1 rocksdb batches, 20 log entries)
I180103 20:16:23.511646 151403 storage/replica_raftstorage.go:751  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.511912 150603 storage/replica_command.go:1741  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, next=2]
I180103 20:16:23.512516 150329 testutils/testcluster/testcluster.go:528  [n1,s1] has 19 underreplicated ranges
I180103 20:16:23.513233 150603 storage/replica.go:3181  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.513581 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot d8d3e83b at index 18
I180103 20:16:23.514052 150568 storage/store.go:3563  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 13, log entries: 8, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.514446 151359 storage/replica_raftstorage.go:745  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 18 (id=d8d3e83b, encoded size=3743, 1 rocksdb batches, 8 log entries)
I180103 20:16:23.514644 151359 storage/replica_raftstorage.go:751  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.515016 150568 storage/replica_command.go:1741  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, (n3,s3):2, next=3]
I180103 20:16:23.516640 150568 storage/replica.go:3181  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180103 20:16:23.517391 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 2286fdb6 at index 47
I180103 20:16:23.518060 150603 storage/store.go:3563  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 44, log entries: 2, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.518453 151428 storage/replica_raftstorage.go:745  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 47 (id=2286fdb6, encoded size=68752, 1 rocksdb batches, 2 log entries)
I180103 20:16:23.518875 151428 storage/replica_raftstorage.go:751  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.519185 150603 storage/replica_command.go:1741  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2]
I180103 20:16:23.520592 150603 storage/replica.go:3181  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.520987 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 29cf8a11 at index 24
I180103 20:16:23.521475 150603 storage/store.go:3563  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 14, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.521715 151297 storage/replica_raftstorage.go:745  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 24 (id=29cf8a11, encoded size=6464, 1 rocksdb batches, 14 log entries)
I180103 20:16:23.521893 151297 storage/replica_raftstorage.go:751  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.522164 150603 storage/replica_command.go:1741  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, next=2]
I180103 20:16:23.523436 150603 storage/replica.go:3181  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.523786 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot a466c0e1 at index 15
I180103 20:16:23.524240 150568 storage/store.go:3563  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n2,s2):?: kv pairs: 16, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.524492 151459 storage/replica_raftstorage.go:745  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 15 (id=a466c0e1, encoded size=2148, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.524649 151459 storage/replica_raftstorage.go:751  [n2,s2,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.524965 150568 storage/replica_command.go:1741  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, (n3,s3):2, next=3]
I180103 20:16:23.526660 150568 storage/replica.go:3181  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180103 20:16:23.527470 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot aabab4d9 at index 15
I180103 20:16:23.528015 150603 storage/store.go:3563  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.528325 151420 storage/replica_raftstorage.go:745  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 15 (id=aabab4d9, encoded size=2683, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.528466 151420 storage/replica_raftstorage.go:751  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.528777 150603 storage/replica_command.go:1741  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2]
I180103 20:16:23.530022 150603 storage/replica.go:3181  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.530375 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 368e5696 at index 25
I180103 20:16:23.530875 150603 storage/store.go:3563  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 22, log entries: 15, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.531097 151422 storage/replica_raftstorage.go:745  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 25 (id=368e5696, encoded size=8183, 1 rocksdb batches, 15 log entries)
I180103 20:16:23.531275 151422 storage/replica_raftstorage.go:751  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.531534 150603 storage/replica_command.go:1741  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2]
I180103 20:16:23.532760 150603 storage/replica.go:3181  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.533111 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 90fed994 at index 33
I180103 20:16:23.533713 150568 storage/store.go:3563  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 58, log entries: 23, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.534239 151491 storage/replica_raftstorage.go:745  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 33 (id=90fed994, encoded size=20752, 1 rocksdb batches, 23 log entries)
I180103 20:16:23.534493 151491 storage/replica_raftstorage.go:751  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.535035 150568 storage/replica_command.go:1741  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, (n2,s2):2, next=3]
I180103 20:16:23.537257 150568 storage/replica.go:3181  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180103 20:16:23.538115 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot e901f715 at index 15
I180103 20:16:23.538532 150603 storage/store.go:3563  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.538854 151450 storage/replica_raftstorage.go:745  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 15 (id=e901f715, encoded size=2683, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.539034 151450 storage/replica_raftstorage.go:751  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.539287 150603 storage/replica_command.go:1741  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2]
I180103 20:16:23.540654 150603 storage/replica.go:3181  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.541051 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot 0af28a10 at index 16
I180103 20:16:23.541459 150603 storage/store.go:3563  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 6, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.541699 151481 storage/replica_raftstorage.go:745  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 16 (id=0af28a10, encoded size=2752, 1 rocksdb batches, 6 log entries)
I180103 20:16:23.541828 151481 storage/replica_raftstorage.go:751  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.542091 150603 storage/replica_command.go:1741  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2]
I180103 20:16:23.543334 150603 storage/replica.go:3181  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.543675 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 6c752051 at index 50
I180103 20:16:23.546066 150568 storage/store.go:3563  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 45, log entries: 5, rate-limit: 8.0 MiB/sec, 2ms
I180103 20:16:23.547912 151514 storage/replica_raftstorage.go:745  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 50 (id=6c752051, encoded size=70026, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.548456 151514 storage/replica_raftstorage.go:751  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.548959 150568 storage/replica_command.go:1741  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n3,s3):2, next=3]
I180103 20:16:23.550759 150568 storage/replica.go:3181  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180103 20:16:23.551579 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot eaf7fb66 at index 65
I180103 20:16:23.552548 150603 storage/store.go:3563  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 211, log entries: 55, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.552954 150911 storage/replica_raftstorage.go:745  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 65 (id=eaf7fb66, encoded size=71308, 1 rocksdb batches, 55 log entries)
I180103 20:16:23.553624 150911 storage/replica_raftstorage.go:751  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.553943 150603 storage/replica_command.go:1741  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2]
I180103 20:16:23.555244 150603 storage/replica.go:3181  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.555640 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 241be39d at index 99
I180103 20:16:23.555877 150329 testutils/testcluster/testcluster.go:528  [n1,s1] has 15 underreplicated ranges
I180103 20:16:23.556368 150603 storage/store.go:3563  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 69, log entries: 76, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.556734 151519 storage/replica_raftstorage.go:745  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 99 (id=241be39d, encoded size=35386, 1 rocksdb batches, 76 log entries)
I180103 20:16:23.557113 151519 storage/replica_raftstorage.go:751  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.557487 150603 storage/replica_command.go:1741  [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]
I180103 20:16:23.559294 150603 storage/replica.go:3181  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.559777 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot f3afffcd at index 28
I180103 20:16:23.560263 150568 storage/store.go:3563  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 23, log entries: 18, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.560508 151487 storage/replica_raftstorage.go:745  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 28 (id=f3afffcd, encoded size=9243, 1 rocksdb batches, 18 log entries)
I180103 20:16:23.560723 151487 storage/replica_raftstorage.go:751  [n2,s2,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.561014 150568 storage/replica_command.go:1741  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, (n3,s3):2, next=3]
I180103 20:16:23.563390 150568 storage/replica.go:3181  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180103 20:16:23.564136 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot 63ba309d at index 55
I180103 20:16:23.564963 150603 storage/store.go:3563  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 85, log entries: 45, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.565270 151489 storage/replica_raftstorage.go:745  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 55 (id=63ba309d, encoded size=42912, 1 rocksdb batches, 45 log entries)
I180103 20:16:23.565730 151489 storage/replica_raftstorage.go:751  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.566000 150603 storage/replica_command.go:1741  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2]
I180103 20:16:23.568016 150603 storage/replica.go:3181  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.568386 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 2c7914b6 at index 15
I180103 20:16:23.568969 150603 storage/store.go:3563  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.569181 151602 storage/replica_raftstorage.go:745  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 15 (id=2c7914b6, encoded size=2683, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.569325 151602 storage/replica_raftstorage.go:751  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.569773 150603 storage/replica_command.go:1741  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2]
I180103 20:16:23.571888 150603 storage/replica.go:3181  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.572380 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 4f365800 at index 18
I180103 20:16:23.572979 150568 storage/store.go:3563  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.573178 151604 storage/replica_raftstorage.go:745  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 18 (id=4f365800, encoded size=3743, 1 rocksdb batches, 8 log entries)
I180103 20:16:23.573326 151604 storage/replica_raftstorage.go:751  [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.573573 150568 storage/replica_command.go:1741  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n2,s2):2, next=3]
I180103 20:16:23.575987 150568 storage/replica.go:3181  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180103 20:16:23.576788 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot cda75d11 at index 15
I180103 20:16:23.577202 150603 storage/store.go:3563  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.577422 151594 storage/replica_raftstorage.go:745  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 15 (id=cda75d11, encoded size=2683, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.577554 151594 storage/replica_raftstorage.go:751  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.577917 150603 storage/replica_command.go:1741  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2]
I180103 20:16:23.579769 150603 storage/replica.go:3181  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.580129 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 93a29af4 at index 15
I180103 20:16:23.580551 150603 storage/store.go:3563  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.580795 151607 storage/replica_raftstorage.go:745  [n2,s2,r17/?:{-}] applying preemptive snapshot at index 15 (id=93a29af4, encoded size=2683, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.580933 151607 storage/replica_raftstorage.go:751  [n2,s2,r17/?:/Table/2{0-1}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.581339 150603 storage/replica_command.go:1741  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2]
I180103 20:16:23.583143 150603 storage/replica.go:3181  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.583480 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot 4a22d0dd at index 19
I180103 20:16:23.584119 150568 storage/store.go:3563  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 9, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.584374 151575 storage/replica_raftstorage.go:745  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 19 (id=4a22d0dd, encoded size=3812, 1 rocksdb batches, 9 log entries)
I180103 20:16:23.584533 151575 storage/replica_raftstorage.go:751  [n3,s3,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.584848 150568 storage/replica_command.go:1741  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, (n2,s2):2, next=3]
I180103 20:16:23.587110 150568 storage/replica.go:3181  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180103 20:16:23.587829 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot ae727936 at index 15
I180103 20:16:23.588316 150603 storage/store.go:3563  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.588593 151457 storage/replica_raftstorage.go:745  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 15 (id=ae727936, encoded size=2683, 1 rocksdb batches, 5 log entries)
I180103 20:16:23.588757 151457 storage/replica_raftstorage.go:751  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.589120 150603 storage/replica_command.go:1741  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, next=2]
I180103 20:16:23.590926 150603 storage/replica.go:3181  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.591285 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 6a7ce1bf at index 22
I180103 20:16:23.591768 150603 storage/store.go:3563  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 15, log entries: 12, rate-limit: 8.0 MiB/sec, 0ms
I180103 20:16:23.592109 151470 storage/replica_raftstorage.go:745  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 22 (id=6a7ce1bf, encoded size=6069, 1 rocksdb batches, 12 log entries)
I180103 20:16:23.592275 151470 storage/replica_raftstorage.go:751  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.592532 150603 storage/replica_command.go:1741  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, next=2]
I180103 20:16:23.594575 150603 storage/replica.go:3181  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180103 20:16:23.594948 150568 storage/replica_raftstorage.go:539  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot f5b0b05b at index 90
I180103 20:16:23.595920 150568 storage/store.go:3563  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 267, log entries: 4, rate-limit: 8.0 MiB/sec, 1ms
I180103 20:16:23.596229 151627 storage/replica_raftstorage.go:745  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 90 (id=f5b0b05b, encoded size=37753, 1 rocksdb batches, 4 log entries)
I180103 20:16:23.596713 151627 storage/replica_raftstorage.go:751  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180103 20:16:23.596970 150568 storage/replica_command.go:1741  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n3,s3):2, next=3]
I180103 20:16:23.599172 150568 storage/replica.go:3181  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180103 20:16:23.599885 150603 storage/replica_raftstorage.go:539  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 437cf0f5 at index 26
I180103 20:16:23.603944 150603 storage/store.go:3563  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 953, log entries: 16, rate-limit: 8.0 MiB/sec, 4ms
I180103 20:16:23.604380 151682 storage/replica_raftstorage.go:745  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 26 (id=437cf0f5, encoded size=160560, 1 rocksdb batches, 16 log entries)
I180103 20:16:23.605600 151682 storage/replica_raftstorage.go:751  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180103 20:16:23.606104 150603 storage/replica_command.go:1741  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2]
I180103 20:16:23.608530 150603 storage/replica.go:3181  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180103 20:16:23.608801 150603 storage/queue.go:735  [n1,rep

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Jan 3, 2018
@benesch
Copy link
Contributor

benesch commented Jan 20, 2018

Timed out due to slow partitioning tests. Fixed by #21392.

@benesch benesch closed this as completed Jan 20, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@benesch @cockroach-teamcity