gistfile1.txt

I200708 09:30:28.103616 1 rand.go:85  Random seed: -6507006206530939820
=== RUN   TestBasicHashShardedIndexes
I200708 09:30:28.126169 9 rpc/tls.go:234  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200708 09:30:28.126277 9 rpc/tls.go:280  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
W200708 09:30:28.127317 9 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I200708 09:30:28.149823 9 server/server.go:803  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I200708 09:30:28.155228 9 server/config.go:600  [n?] 1 storage engine initialized
I200708 09:30:28.155791 9 server/config.go:603  [n?] Pebble cache size: 128 MiB
I200708 09:30:28.156789 9 server/config.go:603  [n?] store 0: in-memory, size 0 B
I200708 09:30:28.181816 9 server/server.go:1301  [n?] **** add additional nodes by specifying --join=127.0.0.1:46335
I200708 09:30:28.181937 9 server/init.go:173  [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I200708 09:30:28.181978 9 server/init.go:193  [n?] **** cluster 51b72fae-98a5-43d4-ae63-b784fa7002ba has been created
I200708 09:30:28.182216 136 server/server.go:1383  [n1] connecting to gossip network to verify cluster ID "51b72fae-98a5-43d4-ae63-b784fa7002ba"
I200708 09:30:28.182116 9 gossip/gossip.go:403  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46335" > attrs:<> locality:<> ServerVersion:<major_val:20 minor_val:1 patch:0 unstable:9 > build_tag:"v20.2.0-alpha.1-982-g2c90761830" started_at:1594200628182045826 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:33407" > 
W200708 09:30:28.191451 227 kv/kvserver/store.go:1656  [n1,s1,r6/1:/Table/{SystemCon…-11}] could not gossip system config: [NotLeaseHolderError] r6: replica (n1,s1):1 not lease holder; lease holder unknown
I200708 09:30:28.192098 136 server/server.go:1386  [n1] node connected via gossip
I200708 09:30:28.192553 9 server/node.go:412  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=18 KiB), ranges=34, leases=0, queries=0.00, writes=0.00, bytesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=166.00 pMax=15517.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I200708 09:30:28.192743 9 kv/kvserver/stores.go:236  [n1] read 0 node addresses from persistent storage
I200708 09:30:28.192908 9 server/node.go:468  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I200708 09:30:28.193010 9 server/server.go:1482  [n1] starting https server at 127.0.0.1:37731 (use: 127.0.0.1:37731)
I200708 09:30:28.193042 9 server/server.go:1487  [n1] starting postgres server at 127.0.0.1:33407 (use: 127.0.0.1:33407)
I200708 09:30:28.193097 9 server/server.go:1489  [n1] starting grpc server at 127.0.0.1:46335
I200708 09:30:28.193122 9 server/server.go:1490  [n1] advertising CockroachDB node at 127.0.0.1:46335
I200708 09:30:28.217934 263 sql/temporary_schema.go:473  [n1] running temporary object cleanup background job
I200708 09:30:28.225215 286 kv/kvserver/replica_rangefeed.go:608  [n1,s1,r6/1:/Table/{SystemCon…-11}] RangeFeed closed timestamp is empty
I200708 09:30:28.227392 263 sql/temporary_schema.go:508  [n1] found 0 temporary schemas
I200708 09:30:28.227471 263 sql/temporary_schema.go:511  [n1] early exiting temporary schema cleaner as no temporary schemas were found
I200708 09:30:28.227507 263 sql/temporary_schema.go:512  [n1] completed temporary object cleanup job
I200708 09:30:28.227528 263 sql/temporary_schema.go:595  [n1] temporary object cleaner next scheduled to run at 2020-07-08 10:00:28.215513236 +0000 UTC
I200708 09:30:28.240845 262 sql/event_log.go:132  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:127.0.0.1:46335 Attrs: Locality: ServerVersion:20.1-9 BuildTag:v20.2.0-alpha.1-982-g2c90761830 StartedAt:1594200628182045826 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:33407} ClusterID:51b72fae-98a5-43d4-ae63-b784fa7002ba StartedAt:1594200628182045826 LastUp:1594200628182045826}
I200708 09:30:28.246977 309 sql/event_log.go:132  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I200708 09:30:28.261499 412 sql/event_log.go:132  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:20.1-9 User:root}
I200708 09:30:28.286287 771 sql/event_log.go:132  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:4170e8b2-b3b3-485b-a2e0-c4068b995cd0 User:root}
I200708 09:30:28.293355 778 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I200708 09:30:28.293573 261 server/server_update.go:55  [n1] no need to upgrade, cluster already at the newest version
I200708 09:30:28.297680 302 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I200708 09:30:28.322876 9 server/server_sql.go:643  [n1] done ensuring all necessary migrations have run
I200708 09:30:28.323069 9 server/server.go:1834  [n1] serving sql connections
I200708 09:30:28.323657 1014 sqlmigrations/migrations.go:727  [n1] starting wait for upgrade finalization before schema change job migration
I200708 09:30:28.324327 1014 sqlmigrations/migrations.go:759  [n1] starting schema change job migration
I200708 09:30:28.339908 1014 sqlmigrations/migrations.go:1177  [schema-change-job-migration] evaluating tables for creating jobs
I200708 09:30:28.339975 1014 sqlmigrations/migrations.go:779  [n1] schema change job migration completed
I200708 09:30:28.360229 935 sql/event_log.go:132  [n1,client=127.0.0.1:39956,hostssl,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
=== RUN   TestBasicHashShardedIndexes/primary
I200708 09:30:28.377012 935 sql/event_log.go:132  [n1,client=127.0.0.1:39956,hostssl,user=root] Event: "create_table", target: 53, info: {TableName:d.public.kv_primary Statement:CREATE TABLE kv_primary (k INT8 PRIMARY KEY USING HASH WITH BUCKET_COUNT=5, v BYTES, CHECK (crdb_internal_k_shard_5 IN (0, 1, 2, 3, 4))) User:root}
I200708 09:30:28.379966 1081 kv/kvserver/replica_command.go:414  [n1,split,s1,r34/1:/{Table/38-Max}] initiating a split of this range at key /Table/53 [r35] (zone config)
I200708 09:30:28.397359 935 sql/table.go:130  [n1,client=127.0.0.1:39956,hostssl,user=root] queued new schema change job 570589932379799553 for table 53, mutation 1
I200708 09:30:28.410338 935 sql/event_log.go:132  [n1,client=127.0.0.1:39956,hostssl,user=root] Event: "create_index", target: 53, info: {TableName:d.public.kv_primary IndexName:foo Statement:CREATE INDEX foo ON kv_primary (v) User:root MutationID:1}
I200708 09:30:28.410576 935 jobs/registry.go:284  [n1,client=127.0.0.1:39956,hostssl,user=root] scheduled jobs [570589932379799553]
I200708 09:30:28.432126 275 jobs/registry.go:1222  job 570589932379799553: resuming execution
I200708 09:30:28.434875 1230 jobs/registry.go:832  [n1] job 570589932379799553: stepping through state running with error: <nil>
I200708 09:30:28.435588 1230 sql/schema_changer.go:444  [n1,job=570589932379799553,scExec,table=53,mutation=1] schema change on "kv_primary" (v2) starting execution...
I200708 09:30:28.439095 1230 sql/schema_changer.go:661  [n1,job=570589932379799553,scExec,table=53,mutation=1] stepping through state machine
I200708 09:30:28.445578 1230 sql/schema_changer.go:721  [n1,job=570589932379799553,scExec,table=53,mutation=1] finished stepping through state machine
I200708 09:30:28.452564 1230 sql/schema_changer.go:737  [n1,job=570589932379799553,scExec,table=53,mutation=1] waiting for a single version...
I200708 09:30:28.459210 1230 sql/schema_changer.go:739  [n1,job=570589932379799553,scExec,table=53,mutation=1] waiting for a single version... done (at v 3)
I200708 09:30:28.472056 1230 sql/backfill.go:176  [n1,job=570589932379799553,scExec,table=53,mutation=1] Running backfill for "kv_primary", v=3
I200708 09:30:28.472232 1230 sql/backfill.go:1293  [n1,job=570589932379799553,scExec,table=53,mutation=1] backfilling 1 indexes
I200708 09:30:28.472662 1230 kv/kvserver/replica_command.go:414  [n1,s1,r35/1:/{Table/53-Max}] initiating a split of this range at key /Table/53/2 [r36] (manual)
I200708 09:30:28.491653 1230 sql/backfill.go:1314  [n1,job=570589932379799553,scExec,table=53,mutation=1] finished backfilling indexes
I200708 09:30:28.492217 1230 sql/backfill.go:991  [n1,job=570589932379799553,scExec,table=53,mutation=1] validating new indexes
I200708 09:30:28.505560 1449 sql/backfill.go:1233  [n1,job=570589932379799553,scExec,table=53,mutation=1] validation: index kv_primary/foo row count = 0, time so far 6.810435ms
I200708 09:30:28.506576 1450 sql/backfill.go:1277  [n1,job=570589932379799553,scExec,table=53,mutation=1] validation: table kv_primary row count = 0, took 9.096402ms
I200708 09:30:28.506938 1230 sql/backfill.go:1051  [n1,job=570589932379799553,scExec,table=53,mutation=1] finished validating new indexes
I200708 09:30:28.507220 1230 sql/backfill.go:291  [n1,job=570589932379799553,scExec,table=53,mutation=1] Completed backfill for "kv_primary", v=3
I200708 09:30:28.507488 1230 sql/schema_changer.go:1104  [n1,job=570589932379799553,scExec,table=53,mutation=1] marking schema change as complete
I200708 09:30:28.517876 1415 sql/catalog/lease/lease.go:956  [n1] new lease: 53("kv_primary") ver=4:1594200938.737875316,0, refcount=0
I200708 09:30:28.522643 1230 sql/event_log.go:132  [n1,job=570589932379799553,scExec,table=53,mutation=1] Event: "finish_schema_change", target: 53, info: {MutationID:1}
I200708 09:30:28.522879 1230 sql/schema_changer.go:737  [n1,job=570589932379799553,scExec,table=53,mutation=1] waiting for a single version...
I200708 09:30:28.529089 1230 sql/schema_changer.go:739  [n1,job=570589932379799553,scExec,table=53,mutation=1] waiting for a single version... done (at v 4)
I200708 09:30:28.529197 1230 jobs/registry.go:832  [n1] job 570589932379799553: stepping through state succeeded with error: <nil>
I200708 09:30:28.536740 1230 jobs/registry.go:988  [n1] job 570589932379799553: status succeeded after adoption finished
=== RUN   TestBasicHashShardedIndexes/secondary_in_create_table
I200708 09:30:28.599294 935 sql/event_log.go:132  [n1,client=127.0.0.1:39956,hostssl,user=root] Event: "create_table", target: 54, info: {TableName:d.public.kv_secondary Statement:CREATE TABLE kv_secondary (k INT8, v BYTES, INDEX sharded_secondary (crdb_internal_k_shard_12 ASC, k) USING HASH WITH BUCKET_COUNT = 12, CHECK (crdb_internal_k_shard_12 IN (0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11))) User:root}
I200708 09:30:28.602183 1641 kv/kvserver/replica_command.go:414  [n1,split,s1,r36/1:/{Table/53/2-Max}] initiating a split of this range at key /Table/54 [r37] (zone config)
=== RUN   TestBasicHashShardedIndexes/secondary_in_separate_ddl
I200708 09:30:28.621248 1722 kv/kvserver/replica_command.go:414  [n1,split,s1,r37/1:/{Table/54-Max}] initiating a split of this range at key /Table/55 [r38] (zone config)
I200708 09:30:28.618569 935 sql/event_log.go:132  [n1,client=127.0.0.1:39956,hostssl,user=root] Event: "create_table", target: 55, info: {TableName:d.public.kv_secondary2 Statement:CREATE TABLE kv_secondary2 (k INT8, v BYTES) User:root}
I200708 09:30:28.647341 935 sql/table.go:130  [n1,client=127.0.0.1:39956,hostssl,user=root] queued new schema change job 570589933177831425 for table 55, mutation 1
I200708 09:30:28.658774 935 sql/event_log.go:132  [n1,client=127.0.0.1:39956,hostssl,user=root] Event: "create_index", target: 55, info: {TableName:d.public.kv_secondary2 IndexName:sharded_secondary2 Statement:CREATE INDEX sharded_secondary2 ON kv_secondary2 (crdb_internal_k_shard_12 ASC, k) USING HASH WITH BUCKET_COUNT = 12 User:root MutationID:1}
I200708 09:30:28.658917 935 jobs/registry.go:284  [n1,client=127.0.0.1:39956,hostssl,user=root] scheduled jobs [570589933177831425]
I200708 09:30:28.674278 275 jobs/registry.go:1222  job 570589933177831425: resuming execution
I200708 09:30:28.679830 1772 jobs/registry.go:832  [n1] job 570589933177831425: stepping through state running with error: <nil>
I200708 09:30:28.680177 1772 sql/schema_changer.go:444  [n1,job=570589933177831425,scExec,table=55,mutation=1] schema change on "kv_secondary2" (v2) starting execution...
I200708 09:30:28.683640 1772 sql/schema_changer.go:661  [n1,job=570589933177831425,scExec,table=55,mutation=1] stepping through state machine
I200708 09:30:28.690410 1772 sql/schema_changer.go:721  [n1,job=570589933177831425,scExec,table=55,mutation=1] finished stepping through state machine
I200708 09:30:28.694050 1772 sql/schema_changer.go:737  [n1,job=570589933177831425,scExec,table=55,mutation=1] waiting for a single version...
I200708 09:30:28.701236 1772 sql/schema_changer.go:739  [n1,job=570589933177831425,scExec,table=55,mutation=1] waiting for a single version... done (at v 3)
I200708 09:30:28.704821 1772 sql/backfill.go:176  [n1,job=570589933177831425,scExec,table=55,mutation=1] Running backfill for "kv_secondary2", v=3
I200708 09:30:28.705898 1772 sql/backfill.go:1326  [n1,job=570589933177831425,scExec,table=55,mutation=1] clearing and backfilling columns
I200708 09:30:28.715023 1772 sql/backfill.go:1333  [n1,job=570589933177831425,scExec,table=55,mutation=1] finished clearing and backfilling columns
I200708 09:30:28.717394 1772 sql/backfill.go:1293  [n1,job=570589933177831425,scExec,table=55,mutation=1] backfilling 1 indexes
I200708 09:30:28.718036 1772 kv/kvserver/replica_command.go:414  [n1,s1,r38/1:/{Table/55-Max}] initiating a split of this range at key /Table/55/2 [r39] (manual)
I200708 09:30:28.733126 1772 sql/backfill.go:1314  [n1,job=570589933177831425,scExec,table=55,mutation=1] finished backfilling indexes
I200708 09:30:28.735223 1772 sql/backfill.go:991  [n1,job=570589933177831425,scExec,table=55,mutation=1] validating new indexes
I200708 09:30:28.743584 1977 sql/backfill.go:1233  [n1,job=570589933177831425,scExec,table=55,mutation=1] validation: index kv_secondary2/sharded_secondary2 row count = 0, time so far 3.174093ms
I200708 09:30:28.746697 1978 sql/backfill.go:1277  [n1,job=570589933177831425,scExec,table=55,mutation=1] validation: table kv_secondary2 row count = 0, took 6.351312ms
I200708 09:30:28.747214 1772 sql/backfill.go:1051  [n1,job=570589933177831425,scExec,table=55,mutation=1] finished validating new indexes
I200708 09:30:28.747611 1772 sql/backfill.go:410  [n1,job=570589933177831425,scExec,table=55,mutation=1] adding 1 constraints
I200708 09:30:28.756079 1851 sql/catalog/lease/lease.go:956  [n1] new lease: 55("kv_secondary2") ver=4:1594200926.430559047,0, refcount=0
I200708 09:30:28.778385 1772 sql/schema_changer.go:737  [n1,job=570589933177831425,scExec,table=55,mutation=1] waiting for a single version...
I200708 09:30:28.787183 1772 sql/schema_changer.go:739  [n1,job=570589933177831425,scExec,table=55,mutation=1] waiting for a single version... done (at v 4)
I200708 09:30:28.787760 1772 sql/backfill.go:501  [n1,job=570589933177831425,scExec,table=55,mutation=1] finished adding constraints
I200708 09:30:28.788272 1772 sql/backfill.go:516  [n1,job=570589933177831425,scExec,table=55,mutation=1] validating 1 new constraints
I200708 09:30:28.797525 2066 sql/check.go:58  [n1,job=570589933177831425,scExec,table=55,mutation=1] Validating check constraint "crdb_internal_k_shard_12 IN (0:::INT8, 1:::INT8, 2:::INT8, 3:::INT8, 4:::INT8, 5:::INT8, 6:::INT8, 7:::INT8, 8:::INT8, 9:::INT8, 10:::INT8, 11:::INT8)" with query "SELECT k, v, rowid, crdb_internal_k_shard_12 FROM [55 AS t] WHERE NOT (crdb_internal_k_shard_12 IN (0:::INT8, 1:::INT8, 2:::INT8, 3:::INT8, 4:::INT8, 5:::INT8, 6:::INT8, 7:::INT8, 8:::INT8, 9:::INT8, 10:::INT8, 11:::INT8)) LIMIT 1:::INT8"
I200708 09:30:28.798940 1772 sql/backfill.go:593  [n1,job=570589933177831425,scExec,table=55,mutation=1] finished validating new constraints
I200708 09:30:28.799001 1772 sql/backfill.go:291  [n1,job=570589933177831425,scExec,table=55,mutation=1] Completed backfill for "kv_secondary2", v=3
I200708 09:30:28.799025 1772 sql/schema_changer.go:1104  [n1,job=570589933177831425,scExec,table=55,mutation=1] marking schema change as complete
I200708 09:30:28.817862 1772 sql/event_log.go:132  [n1,job=570589933177831425,scExec,table=55,mutation=1] Event: "finish_schema_change", target: 55, info: {MutationID:1}
I200708 09:30:28.818754 1772 sql/schema_changer.go:737  [n1,job=570589933177831425,scExec,table=55,mutation=1] waiting for a single version...
I200708 09:30:28.823587 1738 sql/catalog/lease/lease.go:956  [n1] new lease: 55("kv_secondary2") ver=5:1594200934.972937217,0, refcount=0
I200708 09:30:28.825514 1772 sql/catalog/lease/lease.go:353  [n1,job=570589933177831425,scExec,table=55,mutation=1] waiting for 1 leases to expire: desc=[{kv_secondary2 55 4}]
I200708 09:30:28.848134 1772 sql/schema_changer.go:739  [n1,job=570589933177831425,scExec,table=55,mutation=1] waiting for a single version... done (at v 5)
I200708 09:30:28.848221 1772 jobs/registry.go:832  [n1] job 570589933177831425: stepping through state succeeded with error: <nil>
I200708 09:30:28.858250 1772 jobs/registry.go:988  [n1] job 570589933177831425: status succeeded after adoption finished
I200708 09:30:28.996168 9 util/stop/stopper.go:539  quiescing
W200708 09:30:28.996413 2179 kv/kvserver/intentresolver/intent_resolver.go:744  failed to gc transaction record: could not GC completed transaction anchored at /Table/SystemConfigSpan/Start: node unavailable; try another peer
--- PASS: TestBasicHashShardedIndexes (0.90s)
    --- PASS: TestBasicHashShardedIndexes/primary (0.22s)
    --- PASS: TestBasicHashShardedIndexes/secondary_in_create_table (0.01s)
    --- PASS: TestBasicHashShardedIndexes/secondary_in_separate_ddl (0.39s)
=== RUN   TestClusterID
I200708 09:30:29.007685 2174 rpc/tls.go:234  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200708 09:30:29.007884 2174 rpc/tls.go:280  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
W200708 09:30:29.008161 2174 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I200708 09:30:29.060602 2174 server/server.go:803  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I200708 09:30:29.061343 2174 server/config.go:600  [n?] 1 storage engine initialized
I200708 09:30:29.061405 2174 server/config.go:603  [n?] Pebble cache size: 128 MiB
I200708 09:30:29.061419 2174 server/config.go:603  [n?] store 0: in-memory, size 0 B
I200708 09:30:29.082070 2174 server/server.go:1301  [n?] **** add additional nodes by specifying --join=127.0.0.1:44191
I200708 09:30:29.082476 2174 server/init.go:173  [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I200708 09:30:29.082884 2174 server/init.go:193  [n?] **** cluster 88e9c746-31c0-46a5-a09b-773617759b5a has been created
I200708 09:30:29.083203 2252 server/server.go:1383  [n?] connecting to gossip network to verify cluster ID "88e9c746-31c0-46a5-a09b-773617759b5a"
I200708 09:30:29.083575 2174 gossip/gossip.go:403  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:44191" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc1" > > ServerVersion:<major_val:20 minor_val:1 patch:0 unstable:9 > build_tag:"v20.2.0-alpha.1-982-g2c90761830" started_at:1594200629083132712 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:33473" > 
W200708 09:30:29.103229 2327 kv/kvserver/store.go:1656  [n1,s1,r6/1:/Table/{SystemCon…-11}] could not gossip system config: [NotLeaseHolderError] r6: replica (n1,s1):1 not lease holder; lease holder unknown
I200708 09:30:29.104392 2252 server/server.go:1386  [n1] node connected via gossip
I200708 09:30:29.110247 2174 server/node.go:412  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=18 KiB), ranges=34, leases=2, queries=0.00, writes=0.00, bytesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=166.00 pMax=15517.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I200708 09:30:29.110667 2174 kv/kvserver/stores.go:236  [n1] read 0 node addresses from persistent storage
I200708 09:30:29.111008 2174 server/node.go:468  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I200708 09:30:29.111814 2174 server/server.go:1482  [n1] starting https server at 127.0.0.1:39041 (use: 127.0.0.1:39041)
I200708 09:30:29.120154 2174 server/server.go:1487  [n1] starting postgres server at 127.0.0.1:33473 (use: 127.0.0.1:33473)
I200708 09:30:29.120404 2174 server/server.go:1489  [n1] starting grpc server at 127.0.0.1:44191
I200708 09:30:29.120584 2174 server/server.go:1490  [n1] advertising CockroachDB node at 127.0.0.1:44191
I200708 09:30:29.141179 2372 sql/temporary_schema.go:473  [n1] running temporary object cleanup background job
I200708 09:30:29.142671 2372 sql/temporary_schema.go:508  [n1] found 0 temporary schemas
I200708 09:30:29.142718 2372 sql/temporary_schema.go:511  [n1] early exiting temporary schema cleaner as no temporary schemas were found
I200708 09:30:29.142735 2372 sql/temporary_schema.go:512  [n1] completed temporary object cleanup job
I200708 09:30:29.142750 2372 sql/temporary_schema.go:595  [n1] temporary object cleaner next scheduled to run at 2020-07-08 10:00:29.141141519 +0000 UTC
I200708 09:30:29.145567 2193 kv/kvserver/replica_rangefeed.go:608  [n1,s1,r6/1:/Table/{SystemCon…-11}] RangeFeed closed timestamp is empty
I200708 09:30:29.146505 2371 sql/event_log.go:132  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:127.0.0.1:44191 Attrs: Locality:region=test,dc=dc1 ServerVersion:20.1-9 BuildTag:v20.2.0-alpha.1-982-g2c90761830 StartedAt:1594200629083132712 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:33473} ClusterID:88e9c746-31c0-46a5-a09b-773617759b5a StartedAt:1594200629083132712 LastUp:1594200629083132712}
I200708 09:30:29.153672 2501 sql/event_log.go:132  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I200708 09:30:29.234596 2508 sql/event_log.go:132  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:20.1-9 User:root}
I200708 09:30:29.274672 2370 server/server_update.go:55  [n1] no need to upgrade, cluster already at the newest version
I200708 09:30:29.332150 2898 sql/event_log.go:132  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:d0861ac0-9ba4-498d-afac-a34116f20ff8 User:root}
I200708 09:30:29.342616 2905 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I200708 09:30:29.353634 2913 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I200708 09:30:29.384489 2174 server/server_sql.go:643  [n1] done ensuring all necessary migrations have run
I200708 09:30:29.384812 2174 server/server.go:1834  [n1] serving sql connections
I200708 09:30:29.385096 3174 sqlmigrations/migrations.go:727  [n1] starting wait for upgrade finalization before schema change job migration
I200708 09:30:29.385357 3174 sqlmigrations/migrations.go:759  [n1] starting schema change job migration
I200708 09:30:29.398768 2174 rpc/tls.go:234  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200708 09:30:29.398825 2174 rpc/tls.go:280  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200708 09:30:29.399801 3174 sqlmigrations/migrations.go:1177  [schema-change-job-migration] evaluating tables for creating jobs
I200708 09:30:29.400206 3174 sqlmigrations/migrations.go:779  [n1] schema change job migration completed
W200708 09:30:29.411644 2174 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I200708 09:30:29.433693 2174 server/server.go:803  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I200708 09:30:29.434297 2174 server/config.go:600  [n?] 1 storage engine initialized
I200708 09:30:29.441803 2174 server/config.go:603  [n?] Pebble cache size: 128 MiB
I200708 09:30:29.441992 2174 server/config.go:603  [n?] store 0: in-memory, size 0 B
W200708 09:30:29.442829 2174 gossip/gossip.go:1504  [n?] no incoming or outgoing connections
I200708 09:30:29.443056 2174 server/init.go:173  [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I200708 09:30:29.466102 2981 gossip/client.go:124  [n?] started gossip client to 127.0.0.1:44191
I200708 09:30:29.466874 3263 gossip/server.go:227  [n1] received initial cluster-verification connection from 127.0.0.1:35067
I200708 09:30:29.468504 3084 server/server.go:1383  [n?] connecting to gossip network to verify cluster ID "88e9c746-31c0-46a5-a09b-773617759b5a"
I200708 09:30:29.468582 3084 server/server.go:1386  [n?] node connected via gossip
I200708 09:30:29.468917 3263 gossip/server.go:227  [n1] received initial cluster-verification connection from 127.0.0.1:35067
I200708 09:30:29.549538 2174 server/node.go:365  [n?] new node allocated ID 2
I200708 09:30:29.549720 2174 gossip/gossip.go:403  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:35067" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc2" > > ServerVersion:<major_val:20 minor_val:1 patch:0 unstable:9 > build_tag:"v20.2.0-alpha.1-982-g2c90761830" started_at:1594200629549696971 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:40031" > 
I200708 09:30:29.550004 2174 kv/kvserver/stores.go:236  [n2] read 0 node addresses from persistent storage
I200708 09:30:29.550187 2174 kv/kvserver/stores.go:255  [n2] wrote 1 node addresses to persistent storage
I200708 09:30:29.552647 2174 server/node.go:568  [n2] bootstrapped store [n2,s2]
I200708 09:30:29.552768 2174 server/node.go:468  [n2] node=2: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I200708 09:30:29.553233 2174 server/server.go:1482  [n2] starting https server at 127.0.0.1:34893 (use: 127.0.0.1:34893)
I200708 09:30:29.553265 2174 server/server.go:1487  [n2] starting postgres server at 127.0.0.1:40031 (use: 127.0.0.1:40031)
I200708 09:30:29.553294 2174 server/server.go:1489  [n2] starting grpc server at 127.0.0.1:35067
I200708 09:30:29.553314 2174 server/server.go:1490  [n2] advertising CockroachDB node at 127.0.0.1:35067
I200708 09:30:29.553814 3406 server/server.go:1124  active cluster version is now 20.1-9 (up from 20.1)
I200708 09:30:29.576558 2828 sql/temporary_schema.go:466  [n2] skipping temporary object cleanup run as it is not the leaseholder
I200708 09:30:29.576690 2828 sql/temporary_schema.go:467  [n2] completed temporary object cleanup job
I200708 09:30:29.576717 2828 sql/temporary_schema.go:595  [n2] temporary object cleaner next scheduled to run at 2020-07-08 10:00:29.576523511 +0000 UTC
W200708 09:30:29.576811 2174 jobs/registry.go:561  [n2] unable to get node liveness: node not in the liveness table
I200708 09:30:29.577343 2177 kv/kvserver/stores.go:255  [n1] wrote 1 node addresses to persistent storage
I200708 09:30:29.598535 2174 server/server_sql.go:643  [n2] done ensuring all necessary migrations have run
I200708 09:30:29.598615 2174 server/server.go:1834  [n2] serving sql connections
I200708 09:30:29.600770 3435 sqlmigrations/migrations.go:727  [n2] starting wait for upgrade finalization before schema change job migration
I200708 09:30:29.605290 3435 sqlmigrations/migrations.go:753  [n2] schema change job migration already complete
I200708 09:30:29.617011 2174 rpc/tls.go:234  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200708 09:30:29.617204 2174 rpc/tls.go:280  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200708 09:30:29.622906 2826 server/server_update.go:55  [n2] no need to upgrade, cluster already at the newest version
W200708 09:30:29.623156 2174 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I200708 09:30:29.627041 2827 sql/event_log.go:132  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:127.0.0.1:35067 Attrs: Locality:region=test,dc=dc2 ServerVersion:20.1-9 BuildTag:v20.2.0-alpha.1-982-g2c90761830 StartedAt:1594200629549696971 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:40031} ClusterID:88e9c746-31c0-46a5-a09b-773617759b5a StartedAt:1594200629549696971 LastUp:1594200629549696971}
I200708 09:30:29.644191 2174 server/server.go:803  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I200708 09:30:29.645544 2174 server/config.go:600  [n?] 1 storage engine initialized
I200708 09:30:29.646049 2174 server/config.go:603  [n?] Pebble cache size: 128 MiB
I200708 09:30:29.646407 2174 server/config.go:603  [n?] store 0: in-memory, size 0 B
W200708 09:30:29.657180 2174 gossip/gossip.go:1504  [n?] no incoming or outgoing connections
I200708 09:30:29.657247 2174 server/init.go:173  [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I200708 09:30:29.682427 3573 gossip/client.go:124  [n?] started gossip client to 127.0.0.1:44191
I200708 09:30:29.683527 3473 gossip/server.go:227  [n1] received initial cluster-verification connection from 127.0.0.1:41067
I200708 09:30:29.686055 3587 server/server.go:1383  [n?] connecting to gossip network to verify cluster ID "88e9c746-31c0-46a5-a09b-773617759b5a"
I200708 09:30:29.686209 3587 server/server.go:1386  [n?] node connected via gossip
I200708 09:30:29.698263 3473 gossip/server.go:227  [n1] received initial cluster-verification connection from 127.0.0.1:41067
I200708 09:30:29.723423 2174 server/node.go:365  [n?] new node allocated ID 3
I200708 09:30:29.723521 2174 gossip/gossip.go:403  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:41067" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc3" > > ServerVersion:<major_val:20 minor_val:1 patch:0 unstable:9 > build_tag:"v20.2.0-alpha.1-982-g2c90761830" started_at:1594200629723508056 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:36823" > 
I200708 09:30:29.723661 2174 kv/kvserver/stores.go:236  [n3] read 0 node addresses from persistent storage
I200708 09:30:29.723710 2174 kv/kvserver/stores.go:255  [n3] wrote 2 node addresses to persistent storage
I200708 09:30:29.724278 2177 kv/kvserver/stores.go:255  [n1] wrote 2 node addresses to persistent storage
I200708 09:30:29.725252 3181 kv/kvserver/stores.go:255  [n2] wrote 2 node addresses to persistent storage
I200708 09:30:29.727428 2174 server/node.go:568  [n3] bootstrapped store [n3,s3]
I200708 09:30:29.727528 2174 server/node.go:468  [n3] node=3: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I200708 09:30:29.727597 2174 server/server.go:1482  [n3] starting https server at 127.0.0.1:45993 (use: 127.0.0.1:45993)
I200708 09:30:29.727624 2174 server/server.go:1487  [n3] starting postgres server at 127.0.0.1:36823 (use: 127.0.0.1:36823)
I200708 09:30:29.727652 2174 server/server.go:1489  [n3] starting grpc server at 127.0.0.1:41067
I200708 09:30:29.727673 2174 server/server.go:1490  [n3] advertising CockroachDB node at 127.0.0.1:41067
I200708 09:30:29.729176 3710 server/server.go:1124  active cluster version is now 20.1-9 (up from 20.1)
I200708 09:30:29.733646 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r19/1:/Table/2{3-4}] change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r19:/Table/2{3-4} [(n1,s1):1, next=2, gen=0]
I200708 09:30:29.750461 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r19/1:/Table/2{3-4}] proposing SIMPLE(l2) ADD_REPLICA[(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I200708 09:30:29.755236 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r19/1:/Table/2{3-4}] streamed LEARNER snapshot 5d858c24 at applied index 17 to (n3,s3):2LEARNER in 0.00s @ 0 B/s: kv pairs: 10, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:29.755582 3794 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r19/1:/Table/2{3-4}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I200708 09:30:29.755756 3736 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r19/2:{-}] applying LEARNER snapshot [id=5d858c24 index=17]
I200708 09:30:29.757112 3736 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r19/2:/Table/2{3-4}] applied LEARNER snapshot [total=1ms ingestion=4@1ms id=5d858c24 index=17]
I200708 09:30:29.758132 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r19/1:/Table/2{3-4}] change replicas (add [(n3,s3):2] remove []): existing descriptor r19:/Table/2{3-4} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I200708 09:30:29.760853 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r19/1:/Table/2{3-4}] proposing SIMPLE(v2) ADD_REPLICA[(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I200708 09:30:29.761731 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r19/1:/Table/2{3-4}] change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r19:/Table/2{3-4} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I200708 09:30:29.773394 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r19/1:/Table/2{3-4}] proposing SIMPLE(l3) ADD_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I200708 09:30:29.858319 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r19/1:/Table/2{3-4}] streamed LEARNER snapshot d4ad075e at applied index 21 to (n2,s2):3LEARNER in 0.00s @ 0 B/s: kv pairs: 14, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.01s
I200708 09:30:29.860603 3845 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r19/3:{-}] applying LEARNER snapshot [id=d4ad075e index=21]
I200708 09:30:29.862566 3845 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r19/3:/Table/2{3-4}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=d4ad075e index=21]
I200708 09:30:29.860568 3853 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r19/1:/Table/2{3-4}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):3LEARNER
I200708 09:30:29.863028 3862 sql/temporary_schema.go:466  [n3] skipping temporary object cleanup run as it is not the leaseholder
I200708 09:30:29.863167 3862 sql/temporary_schema.go:467  [n3] completed temporary object cleanup job
I200708 09:30:29.863188 3862 sql/temporary_schema.go:595  [n3] temporary object cleaner next scheduled to run at 2020-07-08 10:00:29.863008373 +0000 UTC
I200708 09:30:29.864894 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r19/1:/Table/2{3-4}] change replicas (add [(n2,s2):3] remove []): existing descriptor r19:/Table/2{3-4} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I200708 09:30:29.867463 2174 server/server_sql.go:643  [n3] done ensuring all necessary migrations have run
I200708 09:30:29.867503 2174 server/server.go:1834  [n3] serving sql connections
I200708 09:30:29.868603 2174 testutils/testcluster/testcluster.go:756  WaitForFullReplication
I200708 09:30:29.869117 3855 sqlmigrations/migrations.go:727  [n3] starting wait for upgrade finalization before schema change job migration
I200708 09:30:29.873164 3855 sqlmigrations/migrations.go:753  [n3] schema change job migration already complete
I200708 09:30:29.883292 3860 server/server_update.go:55  [n3] no need to upgrade, cluster already at the newest version
I200708 09:30:29.896937 3861 sql/event_log.go:132  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:127.0.0.1:41067 Attrs: Locality:region=test,dc=dc3 ServerVersion:20.1-9 BuildTag:v20.2.0-alpha.1-982-g2c90761830 StartedAt:1594200629723508056 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:36823} ClusterID:88e9c746-31c0-46a5-a09b-773617759b5a StartedAt:1594200629723508056 LastUp:1594200629723508056}
I200708 09:30:29.904123 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r19/1:/Table/2{3-4}] proposing SIMPLE(v3) ADD_REPLICA[(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I200708 09:30:29.909199 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r29/1:/Table/3{3-4}] change replicas (add [(n2,s2):2LEARNER] remove []): existing descriptor r29:/Table/3{3-4} [(n1,s1):1, next=2, gen=0]
I200708 09:30:29.917560 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r29/1:/Table/3{3-4}] proposing SIMPLE(l2) ADD_REPLICA[(n2,s2):2LEARNER]: after=[(n1,s1):1 (n2,s2):2LEARNER] next=3
I200708 09:30:29.919858 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r29/1:/Table/3{3-4}] streamed LEARNER snapshot 3da4e473 at applied index 18 to (n2,s2):2LEARNER in 0.00s @ 0 B/s: kv pairs: 8, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:29.919922 3975 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r29/1:/Table/3{3-4}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):2LEARNER
I200708 09:30:29.921021 3973 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r29/2:{-}] applying LEARNER snapshot [id=3da4e473 index=18]
I200708 09:30:29.922790 3973 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r29/2:/Table/3{3-4}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=3da4e473 index=18]
I200708 09:30:29.923977 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r29/1:/Table/3{3-4}] change replicas (add [(n2,s2):2] remove []): existing descriptor r29:/Table/3{3-4} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=1]
I200708 09:30:29.927278 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r29/1:/Table/3{3-4}] proposing SIMPLE(v2) ADD_REPLICA[(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I200708 09:30:29.928158 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r29/1:/Table/3{3-4}] change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r29:/Table/3{3-4} [(n1,s1):1, (n2,s2):2, next=3, gen=2]
I200708 09:30:29.942325 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r29/1:/Table/3{3-4}] proposing SIMPLE(l3) ADD_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
I200708 09:30:29.945120 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r29/1:/Table/3{3-4}] streamed LEARNER snapshot 64176a2b at applied index 22 to (n3,s3):3LEARNER in 0.00s @ 0 B/s: kv pairs: 12, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:29.945146 3967 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r29/1:/Table/3{3-4}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):3LEARNER
I200708 09:30:29.946122 3952 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r29/3:{-}] applying LEARNER snapshot [id=64176a2b index=22]
I200708 09:30:29.947472 3952 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r29/3:/Table/3{3-4}] applied LEARNER snapshot [total=1ms ingestion=4@1ms id=64176a2b index=22]
I200708 09:30:29.957716 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r29/1:/Table/3{3-4}] change replicas (add [(n3,s3):3] remove []): existing descriptor r29:/Table/3{3-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, next=4, gen=3]
I200708 09:30:29.960811 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r29/1:/Table/3{3-4}] proposing SIMPLE(v3) ADD_REPLICA[(n3,s3):3]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I200708 09:30:29.962673 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] change replicas (add [(n2,s2):2LEARNER] remove []): existing descriptor r6:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2, gen=0]
I200708 09:30:29.966028 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r6/1:/Table/{SystemCon…-11}] proposing SIMPLE(l2) ADD_REPLICA[(n2,s2):2LEARNER]: after=[(n1,s1):1 (n2,s2):2LEARNER] next=3
I200708 09:30:29.968547 4042 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r6/1:/Table/{SystemCon…-11}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):2LEARNER
I200708 09:30:29.969170 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] streamed LEARNER snapshot 43063d15 at applied index 30 to (n2,s2):2LEARNER in 0.00s @ 0 B/s: kv pairs: 59, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:29.970177 4040 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r6/2:{-}] applying LEARNER snapshot [id=43063d15 index=30]
I200708 09:30:29.971638 4040 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r6/2:/Table/{SystemCon…-11}] applied LEARNER snapshot [total=1ms ingestion=4@1ms id=43063d15 index=30]
I200708 09:30:29.972767 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] change replicas (add [(n2,s2):2] remove []): existing descriptor r6:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=1]
I200708 09:30:29.979785 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r6/1:/Table/{SystemCon…-11}] proposing SIMPLE(v2) ADD_REPLICA[(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I200708 09:30:29.981595 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r6:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n2,s2):2, next=3, gen=2]
I200708 09:30:29.988567 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r6/1:/Table/{SystemCon…-11}] proposing SIMPLE(l3) ADD_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
I200708 09:30:29.992303 4076 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r6/1:/Table/{SystemCon…-11}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):3LEARNER
I200708 09:30:29.992885 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] streamed LEARNER snapshot 3d648cf6 at applied index 34 to (n3,s3):3LEARNER in 0.00s @ 0 B/s: kv pairs: 63, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:29.993839 4074 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r6/3:{-}] applying LEARNER snapshot [id=3d648cf6 index=34]
I200708 09:30:29.996205 4074 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r6/3:/Table/{SystemCon…-11}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=3d648cf6 index=34]
I200708 09:30:29.997267 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] change replicas (add [(n3,s3):3] remove []): existing descriptor r6:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, next=4, gen=3]
I200708 09:30:30.000855 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r6/1:/Table/{SystemCon…-11}] proposing SIMPLE(v3) ADD_REPLICA[(n3,s3):3]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I200708 09:30:30.002685 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r31/1:/Table/3{5-6}] change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r31:/Table/3{5-6} [(n1,s1):1, next=2, gen=0]
I200708 09:30:30.005663 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r31/1:/Table/3{5-6}] proposing SIMPLE(l2) ADD_REPLICA[(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I200708 09:30:30.007692 4102 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r31/1:/Table/3{5-6}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I200708 09:30:30.008203 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r31/1:/Table/3{5-6}] streamed LEARNER snapshot d71b270a at applied index 16 to (n3,s3):2LEARNER in 0.00s @ 0 B/s: kv pairs: 6, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.009127 4085 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r31/2:{-}] applying LEARNER snapshot [id=d71b270a index=16]
I200708 09:30:30.010947 4085 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r31/2:/Table/3{5-6}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=d71b270a index=16]
I200708 09:30:30.012452 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r31/1:/Table/3{5-6}] change replicas (add [(n3,s3):2] remove []): existing descriptor r31:/Table/3{5-6} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I200708 09:30:30.015690 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r31/1:/Table/3{5-6}] proposing SIMPLE(v2) ADD_REPLICA[(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I200708 09:30:30.016538 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r31/1:/Table/3{5-6}] change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r31:/Table/3{5-6} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I200708 09:30:30.027447 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r31/1:/Table/3{5-6}] proposing SIMPLE(l3) ADD_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I200708 09:30:30.031319 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r31/1:/Table/3{5-6}] streamed LEARNER snapshot 7c6e8451 at applied index 20 to (n2,s2):3LEARNER in 0.00s @ 0 B/s: kv pairs: 10, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.032883 4147 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r31/3:{-}] applying LEARNER snapshot [id=7c6e8451 index=20]
I200708 09:30:30.034080 4147 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r31/3:/Table/3{5-6}] applied LEARNER snapshot [total=1ms ingestion=4@1ms id=7c6e8451 index=20]
I200708 09:30:30.034961 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r31/1:/Table/3{5-6}] change replicas (add [(n2,s2):3] remove []): existing descriptor r31:/Table/3{5-6} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I200708 09:30:30.040092 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r31/1:/Table/3{5-6}] proposing SIMPLE(v3) ADD_REPLICA[(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I200708 09:30:30.041504 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r4/1:/System{/tsd-tse}] change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r4:/System{/tsd-tse} [(n1,s1):1, next=2, gen=0]
I200708 09:30:30.047216 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r4/1:/System{/tsd-tse}] proposing SIMPLE(l2) ADD_REPLICA[(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I200708 09:30:30.050653 4122 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r4/1:/System{/tsd-tse}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I200708 09:30:30.105499 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r4/1:/System{/tsd-tse}] streamed LEARNER snapshot 0bb59367 at applied index 24 to (n3,s3):2LEARNER in 0.05s @ 0 B/s: kv pairs: 2226, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.112008 4120 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r4/2:{-}] applying LEARNER snapshot [id=0bb59367 index=24]
I200708 09:30:30.117032 4120 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r4/2:/System{/tsd-tse}] applied LEARNER snapshot [total=5ms ingestion=4@2ms id=0bb59367 index=24]
I200708 09:30:30.118058 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r4/1:/System{/tsd-tse}] change replicas (add [(n3,s3):2] remove []): existing descriptor r4:/System{/tsd-tse} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I200708 09:30:30.121143 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r4/1:/System{/tsd-tse}] proposing SIMPLE(v2) ADD_REPLICA[(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I200708 09:30:30.121965 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r4/1:/System{/tsd-tse}] change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r4:/System{/tsd-tse} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I200708 09:30:30.132014 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r4/1:/System{/tsd-tse}] proposing SIMPLE(l3) ADD_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I200708 09:30:30.134937 4157 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r4/1:/System{/tsd-tse}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):3LEARNER
I200708 09:30:30.151382 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r4/1:/System{/tsd-tse}] streamed LEARNER snapshot a6492a5b at applied index 28 to (n2,s2):3LEARNER in 0.02s @ 0 B/s: kv pairs: 2230, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.152191 4155 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r4/3:{-}] applying LEARNER snapshot [id=a6492a5b index=28]
I200708 09:30:30.155817 4155 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r4/3:/System{/tsd-tse}] applied LEARNER snapshot [total=3ms ingestion=4@2ms id=a6492a5b index=28]
I200708 09:30:30.156786 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r4/1:/System{/tsd-tse}] change replicas (add [(n2,s2):3] remove []): existing descriptor r4:/System{/tsd-tse} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I200708 09:30:30.159920 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r4/1:/System{/tsd-tse}] proposing SIMPLE(v3) ADD_REPLICA[(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I200708 09:30:30.161571 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r7/1:/Table/1{1-2}] change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r7:/Table/1{1-2} [(n1,s1):1, next=2, gen=0]
I200708 09:30:30.164482 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r7/1:/Table/1{1-2}] proposing SIMPLE(l2) ADD_REPLICA[(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I200708 09:30:30.166675 4094 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r7/1:/Table/1{1-2}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I200708 09:30:30.167611 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r7/1:/Table/1{1-2}] streamed LEARNER snapshot 3db20a08 at applied index 19 to (n3,s3):2LEARNER in 0.00s @ 0 B/s: kv pairs: 7, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.168160 4214 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r7/2:{-}] applying LEARNER snapshot [id=3db20a08 index=19]
I200708 09:30:30.170147 4214 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r7/2:/Table/1{1-2}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=3db20a08 index=19]
I200708 09:30:30.170942 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r7/1:/Table/1{1-2}] change replicas (add [(n3,s3):2] remove []): existing descriptor r7:/Table/1{1-2} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I200708 09:30:30.174814 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r7/1:/Table/1{1-2}] proposing SIMPLE(v2) ADD_REPLICA[(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I200708 09:30:30.175679 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r7/1:/Table/1{1-2}] change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r7:/Table/1{1-2} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I200708 09:30:30.184717 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r7/1:/Table/1{1-2}] proposing SIMPLE(l3) ADD_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I200708 09:30:30.187717 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r7/1:/Table/1{1-2}] streamed LEARNER snapshot 8ce8dcaf at applied index 23 to (n2,s2):3LEARNER in 0.00s @ 0 B/s: kv pairs: 11, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.187778 4248 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r7/1:/Table/1{1-2}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):3LEARNER
I200708 09:30:30.188400 4262 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r7/3:{-}] applying LEARNER snapshot [id=8ce8dcaf index=23]
I200708 09:30:30.190371 4262 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r7/3:/Table/1{1-2}] applied LEARNER snapshot [total=2ms ingestion=4@2ms id=8ce8dcaf index=23]
I200708 09:30:30.191057 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r7/1:/Table/1{1-2}] change replicas (add [(n2,s2):3] remove []): existing descriptor r7:/Table/1{1-2} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I200708 09:30:30.218955 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r7/1:/Table/1{1-2}] proposing SIMPLE(v3) ADD_REPLICA[(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I200708 09:30:30.222868 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r17/1:/Table/2{1-2}] change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r17:/Table/2{1-2} [(n1,s1):1, next=2, gen=0]
I200708 09:30:30.226352 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r17/1:/Table/2{1-2}] proposing SIMPLE(l2) ADD_REPLICA[(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I200708 09:30:30.237414 4291 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r17/1:/Table/2{1-2}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I200708 09:30:30.237641 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r17/1:/Table/2{1-2}] streamed LEARNER snapshot 47b90820 at applied index 21 to (n3,s3):2LEARNER in 0.00s @ 0 B/s: kv pairs: 11, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.01s
I200708 09:30:30.238356 4143 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r17/2:{-}] applying LEARNER snapshot [id=47b90820 index=21]
I200708 09:30:30.239928 4143 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r17/2:/Table/2{1-2}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=47b90820 index=21]
I200708 09:30:30.241426 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r17/1:/Table/2{1-2}] change replicas (add [(n3,s3):2] remove []): existing descriptor r17:/Table/2{1-2} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I200708 09:30:30.244514 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r17/1:/Table/2{1-2}] proposing SIMPLE(v2) ADD_REPLICA[(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I200708 09:30:30.245157 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r17/1:/Table/2{1-2}] change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r17:/Table/2{1-2} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I200708 09:30:30.253047 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r17/1:/Table/2{1-2}] proposing SIMPLE(l3) ADD_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I200708 09:30:30.255824 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r17/1:/Table/2{1-2}] streamed LEARNER snapshot ac552b3d at applied index 25 to (n2,s2):3LEARNER in 0.00s @ 0 B/s: kv pairs: 15, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.256271 4283 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r17/1:/Table/2{1-2}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):3LEARNER
I200708 09:30:30.256475 4296 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r17/3:{-}] applying LEARNER snapshot [id=ac552b3d index=25]
I200708 09:30:30.258618 4296 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r17/3:/Table/2{1-2}] applied LEARNER snapshot [total=2ms ingestion=4@2ms id=ac552b3d index=25]
I200708 09:30:30.259433 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r17/1:/Table/2{1-2}] change replicas (add [(n2,s2):3] remove []): existing descriptor r17:/Table/2{1-2} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I200708 09:30:30.262293 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r17/1:/Table/2{1-2}] proposing SIMPLE(v3) ADD_REPLICA[(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I200708 09:30:30.263451 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r11/1:/Table/1{5-6}] change replicas (add [(n2,s2):2LEARNER] remove []): existing descriptor r11:/Table/1{5-6} [(n1,s1):1, next=2, gen=0]
I200708 09:30:30.265891 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r11/1:/Table/1{5-6}] proposing SIMPLE(l2) ADD_REPLICA[(n2,s2):2LEARNER]: after=[(n1,s1):1 (n2,s2):2LEARNER] next=3
I200708 09:30:30.268635 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r11/1:/Table/1{5-6}] streamed LEARNER snapshot a627e39b at applied index 16 to (n2,s2):2LEARNER in 0.00s @ 0 B/s: kv pairs: 6, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.268703 4326 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r11/1:/Table/1{5-6}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):2LEARNER
I200708 09:30:30.269374 4318 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r11/2:{-}] applying LEARNER snapshot [id=a627e39b index=16]
I200708 09:30:30.271293 4318 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r11/2:/Table/1{5-6}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=a627e39b index=16]
I200708 09:30:30.274073 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r11/1:/Table/1{5-6}] change replicas (add [(n2,s2):2] remove []): existing descriptor r11:/Table/1{5-6} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=1]
I200708 09:30:30.276580 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r11/1:/Table/1{5-6}] proposing SIMPLE(v2) ADD_REPLICA[(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I200708 09:30:30.277216 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r11/1:/Table/1{5-6}] change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r11:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, next=3, gen=2]
I200708 09:30:30.288442 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r11/1:/Table/1{5-6}] proposing SIMPLE(l3) ADD_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
I200708 09:30:30.292132 4320 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r11/1:/Table/1{5-6}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):3LEARNER
I200708 09:30:30.292442 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r11/1:/Table/1{5-6}] streamed LEARNER snapshot 2a9d227e at applied index 20 to (n3,s3):3LEARNER in 0.00s @ 0 B/s: kv pairs: 10, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.293329 4357 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r11/3:{-}] applying LEARNER snapshot [id=2a9d227e index=20]
I200708 09:30:30.295235 4357 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r11/3:/Table/1{5-6}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=2a9d227e index=20]
I200708 09:30:30.296639 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r11/1:/Table/1{5-6}] change replicas (add [(n3,s3):3] remove []): existing descriptor r11:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, next=4, gen=3]
I200708 09:30:30.300729 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r11/1:/Table/1{5-6}] proposing SIMPLE(v3) ADD_REPLICA[(n3,s3):3]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I200708 09:30:30.302330 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r26/1:/NamespaceTable/{30-Max}] change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r26:/NamespaceTable/{30-Max} [(n1,s1):1, next=2, gen=0]
I200708 09:30:30.305420 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r26/1:/NamespaceTable/{30-Max}] proposing SIMPLE(l2) ADD_REPLICA[(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I200708 09:30:30.308224 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r26/1:/NamespaceTable/{30-Max}] streamed LEARNER snapshot 8f78560b at applied index 24 to (n3,s3):2LEARNER in 0.00s @ 0 B/s: kv pairs: 40, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.308520 4384 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r26/1:/NamespaceTable/{30-Max}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I200708 09:30:30.309143 4382 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r26/2:{-}] applying LEARNER snapshot [id=8f78560b index=24]
I200708 09:30:30.310855 4382 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r26/2:/NamespaceTable/{30-Max}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=8f78560b index=24]
I200708 09:30:30.312547 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r26/1:/NamespaceTable/{30-Max}] change replicas (add [(n3,s3):2] remove []): existing descriptor r26:/NamespaceTable/{30-Max} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I200708 09:30:30.315516 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r26/1:/NamespaceTable/{30-Max}] proposing SIMPLE(v2) ADD_REPLICA[(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I200708 09:30:30.316060 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r26/1:/NamespaceTable/{30-Max}] change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r26:/NamespaceTable/{30-Max} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I200708 09:30:30.323863 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r26/1:/NamespaceTable/{30-Max}] proposing SIMPLE(l3) ADD_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I200708 09:30:30.326868 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r26/1:/NamespaceTable/{30-Max}] streamed LEARNER snapshot fe777733 at applied index 28 to (n2,s2):3LEARNER in 0.00s @ 0 B/s: kv pairs: 44, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.326912 4348 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r26/1:/NamespaceTable/{30-Max}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):3LEARNER
I200708 09:30:30.327587 4337 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r26/3:{-}] applying LEARNER snapshot [id=fe777733 index=28]
I200708 09:30:30.329976 4337 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r26/3:/NamespaceTable/{30-Max}] applied LEARNER snapshot [total=2ms ingestion=4@2ms id=fe777733 index=28]
I200708 09:30:30.330629 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r26/1:/NamespaceTable/{30-Max}] change replicas (add [(n2,s2):3] remove []): existing descriptor r26:/NamespaceTable/{30-Max} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I200708 09:30:30.334733 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r26/1:/NamespaceTable/{30-Max}] proposing SIMPLE(v3) ADD_REPLICA[(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I200708 09:30:30.335838 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r8/1:/Table/1{2-3}] change replicas (add [(n2,s2):2LEARNER] remove []): existing descriptor r8:/Table/1{2-3} [(n1,s1):1, next=2, gen=0]
I200708 09:30:30.338581 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r8/1:/Table/1{2-3}] proposing SIMPLE(l2) ADD_REPLICA[(n2,s2):2LEARNER]: after=[(n1,s1):1 (n2,s2):2LEARNER] next=3
I200708 09:30:30.341177 4218 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r8/1:/Table/1{2-3}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):2LEARNER
I200708 09:30:30.341411 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r8/1:/Table/1{2-3}] streamed LEARNER snapshot fe7f7a9c at applied index 38 to (n2,s2):2LEARNER in 0.00s @ 0 B/s: kv pairs: 46, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.342023 4216 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r8/2:{-}] applying LEARNER snapshot [id=fe7f7a9c index=38]
I200708 09:30:30.344002 4216 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r8/2:/Table/1{2-3}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=fe7f7a9c index=38]
I200708 09:30:30.344569 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r8/1:/Table/1{2-3}] change replicas (add [(n2,s2):2] remove []): existing descriptor r8:/Table/1{2-3} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=1]
I200708 09:30:30.347218 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r8/1:/Table/1{2-3}] proposing SIMPLE(v2) ADD_REPLICA[(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I200708 09:30:30.347804 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r8/1:/Table/1{2-3}] change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r8:/Table/1{2-3} [(n1,s1):1, (n2,s2):2, next=3, gen=2]
I200708 09:30:30.361450 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r8/1:/Table/1{2-3}] proposing SIMPLE(l3) ADD_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
I200708 09:30:30.370389 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r8/1:/Table/1{2-3}] streamed LEARNER snapshot 364dcf44 at applied index 42 to (n3,s3):3LEARNER in 0.00s @ 0 B/s: kv pairs: 50, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.01s
I200708 09:30:30.370811 4441 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r8/1:/Table/1{2-3}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):3LEARNER
I200708 09:30:30.371273 4455 kv/kvserver/replica_raftstorage.go:791  [n3,s3,r8/3:{-}] applying LEARNER snapshot [id=364dcf44 index=42]
I200708 09:30:30.373277 4455 kv/kvserver/replica_raftstorage.go:812  [n3,s3,r8/3:/Table/1{2-3}] applied LEARNER snapshot [total=2ms ingestion=4@1ms id=364dcf44 index=42]
I200708 09:30:30.373835 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r8/1:/Table/1{2-3}] change replicas (add [(n3,s3):3] remove []): existing descriptor r8:/Table/1{2-3} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, next=4, gen=3]
I200708 09:30:30.378631 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r8/1:/Table/1{2-3}] proposing SIMPLE(v3) ADD_REPLICA[(n3,s3):3]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I200708 09:30:30.379784 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r27/1:/{NamespaceTab…-Table/32}] change replicas (add [(n2,s2):2LEARNER] remove []): existing descriptor r27:/{NamespaceTable/Max-Table/32} [(n1,s1):1, next=2, gen=0]
I200708 09:30:30.382845 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r27/1:/{NamespaceTab…-Table/32}] proposing SIMPLE(l2) ADD_REPLICA[(n2,s2):2LEARNER]: after=[(n1,s1):1 (n2,s2):2LEARNER] next=3
I200708 09:30:30.385916 2185 kv/kvserver/store_snapshot.go:988  [n1,replicate,s1,r27/1:/{NamespaceTab…-Table/32}] streamed LEARNER snapshot db273249 at applied index 16 to (n2,s2):2LEARNER in 0.00s @ 0 B/s: kv pairs: 6, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I200708 09:30:30.386018 4426 kv/kvserver/raft_snapshot_queue.go:129  [n1,raftsnapshot,s1,r27/1:/{NamespaceTab…-Table/32}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):2LEARNER
I200708 09:30:30.388619 4446 kv/kvserver/replica_raftstorage.go:791  [n2,s2,r27/2:{-}] applying LEARNER snapshot [id=db273249 index=16]
I200708 09:30:30.404785 4446 kv/kvserver/replica_raftstorage.go:812  [n2,s2,r27/2:/{NamespaceTab…-Table/32}] applied LEARNER snapshot [total=4ms ingestion=4@2ms id=db273249 index=16]
I200708 09:30:30.406416 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r27/1:/{NamespaceTab…-Table/32}] change replicas (add [(n2,s2):2] remove []): existing descriptor r27:/{NamespaceTable/Max-Table/32} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=1]
I200708 09:30:30.412556 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r27/1:/{NamespaceTab…-Table/32}] proposing SIMPLE(v2) ADD_REPLICA[(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I200708 09:30:30.414666 2185 kv/kvserver/replica_command.go:1609  [n1,replicate,s1,r27/1:/{NamespaceTab…-Table/32}] change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r27:/{NamespaceTable/Max-Table/32} [(n1,s1):1, (n2,s2):2, next=3, gen=2]
I200708 09:30:30.421471 2185 kv/kvserver/replica_raft.go:247  [n1,s1,r27/1:/{NamespaceTab…-Table/32}] proposing SIMPLE(l3) ADD_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
FAIL	github.com/cockroachdb/cockroach/pkg/sql/tests	2.886s