TestChangefeedSchemaChangeNoBackfill
--- FAIL: testrace/TestChangefeedSchemaChangeNoBackfill (5.490s)
Test ended in panic.




TestChangefeedSchemaChangeNoBackfill
--- FAIL: testrace/TestChangefeedSchemaChangeNoBackfill (0.000s)
Test ended in panic.




TestChangefeedSchemaChangeNoBackfill/sinkless
...erver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.412063 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.412649 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.413225 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.413844 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.414424 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.415037 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.415538 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.416007 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.416529 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.417081 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.420776 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.426144 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.426995 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.427867 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.430288 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.432127 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.435018 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.440350 10354 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46217} Attrs: Locality: ServerVersion:2.1-3 BuildTag:v2.2.0-alpha.00000000-2416-g9f54fc1 StartedAt:1542407838807004711 LocalityAddress:[]} ClusterID:c26dc637-7050-4fe5-abea-24809aab4e0c StartedAt:1542407838807004711 LastUp:1542407838807004711}
I181116 22:37:20.442162 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.451762 9839 server/testserver.go:426  had 14 ranges at startup, expected 20
I181116 22:37:20.494665 10371 storage/replica_command.go:306  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I181116 22:37:20.515434 9839 server/testserver.go:426  had 15 ranges at startup, expected 20
I181116 22:37:20.554673 10402 storage/replica_command.go:306  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I181116 22:37:20.558651 9839 server/testserver.go:426  had 16 ranges at startup, expected 20
I181116 22:37:20.640730 10286 storage/replica_command.go:306  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I181116 22:37:20.642963 9839 server/testserver.go:426  had 17 ranges at startup, expected 20
I181116 22:37:20.720726 10419 storage/replica_command.go:306  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I181116 22:37:20.767253 10434 storage/replica_command.go:306  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I181116 22:37:20.791190 9839 server/testserver.go:426  had 19 ranges at startup, expected 20
I181116 22:37:21.132862 9948 gossip/gossip.go:1510  [n1] node has connected to cluster via gossip
I181116 22:37:21.133437 9948 storage/stores.go:261  [n1] wrote 0 node addresses to persistent storage
I181116 22:37:21.288021 10468 sql/event_log.go:126  [n1,client=127.0.0.1:34850,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:0s User:root}
I181116 22:37:21.328283 10468 sql/event_log.go:126  [n1,client=127.0.0.1:34850,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}



TestChangefeedSchemaChangeNoBackfill/sinkless/historical
--- FAIL: testrace/TestChangefeedSchemaChangeNoBackfill/sinkless/historical (0.000s)
Test ended in panic.

------- Stdout: -------
I181116 22:37:21.367201 10468 sql/event_log.go:126  [n1,client=127.0.0.1:34850,user=root] Event: "create_table", target: 53, info: {TableName:d.public.historical Statement:CREATE TABLE historical (a INT PRIMARY KEY, b STRING DEFAULT 'before') User:root}
I181116 22:37:21.370981 10475 storage/replica_command.go:306  [n1,split,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/53 [r21]
I181116 22:37:21.489778 10468 sql/lease.go:345  [n1,client=127.0.0.1:34850,user=root] publish: descID=53 (historical) version=2 mtime=2018-11-16 22:37:21.48382159 +0000 UTC
I181116 22:37:21.536957 10468 sql/event_log.go:126  [n1,client=127.0.0.1:34850,user=root] Event: "alter_table", target: 53, info: {TableName:d.public.historical Statement:ALTER TABLE historical ALTER COLUMN b SET DEFAULT 'after' User:root MutationID:0 CascadeDroppedViews:[]}
I181116 22:37:21.562166 10361 sql/lease.go:876  new lease: 53("historical") ver=2:1542408078.478024769,0, refcount=0
I181116 22:37:21.582065 10468 sql/lease.go:315  publish (1 leases): desc=[{historical 53 1}]
I181116 22:37:21.653794 10468 sql/lease.go:345  [n1,client=127.0.0.1:34850,user=root] publish: descID=53 (historical) version=3 mtime=2018-11-16 22:37:21.635235031 +0000 UTC
I181116 22:37:21.698416 10468 sql/event_log.go:126  [n1,client=127.0.0.1:34850,user=root] Event: "alter_table", target: 53, info: {TableName:d.public.historical Statement:ALTER TABLE historical ADD COLUMN c INT User:root MutationID:1 CascadeDroppedViews:[]}
I181116 22:37:21.814302 10366 sql/lease.go:876  new lease: 53("historical") ver=3:1542408184.911259692,0, refcount=0
I181116 22:37:21.847992 10468 sql/lease.go:315  publish (1 leases): desc=[{historical 53 2}]
I181116 22:37:21.909818 10468 sql/lease.go:345  [n1,client=127.0.0.1:34850,user=root,scExec] publish: descID=53 (historical) version=4 mtime=2018-11-16 22:37:21.908792241 +0000 UTC
I181116 22:37:21.950833 10468 sql/lease.go:315  publish (1 leases): desc=[{historical 53 3}]
I181116 22:37:21.954151 10503 sql/lease.go:876  new lease: 53("historical") ver=4:1542408170.372508754,0, refcount=0
I181116 22:37:21.985751 10468 sql/lease.go:315  publish (1 leases): desc=[{historical 53 3}]
I181116 22:37:22.044506 10468 sql/backfill.go:132  [n1,client=127.0.0.1:34850,user=root,scExec] Running backfill for "historical", v=4, m=1
I181116 22:37:22.062916 10468 sql/lease.go:345  [n1,client=127.0.0.1:34850,user=root,scExec] publish: descID=53 (historical) version=5 mtime=2018-11-16 22:37:22.06181898 +0000 UTC
I181116 22:37:22.179991 10468 sql/event_log.go:126  [n1,client=127.0.0.1:34850,user=root,scExec] Event: "finish_schema_change", target: 53, info: {MutationID:1}
I181116 22:37:22.199545 10468 sql/lease.go:315  publish (1 leases): desc=[{historical 53 4}]
I181116 22:37:22.229501 10506 sql/lease.go:876  new lease: 53("historical") ver=5:1542408167.251228944,0, refcount=0
I181116 22:37:22.248027 10468 sql/lease.go:315  publish (1 leases): desc=[{historical 53 4}]
I181116 22:37:22.417065 10468 sql/event_log.go:126  [n1,client=127.0.0.1:34850,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:0s User:root}



TestChangefeedSchemaChangeNoBackfill/sinkless/add_column
...r=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.004858745 +0000 UTC
I181116 23:16:56.206957 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.119329094 +0000 UTC
I181116 23:16:56.287884 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.203172421 +0000 UTC
I181116 23:16:56.372587 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.288143122 +0000 UTC
I181116 23:16:56.480239 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.372256485 +0000 UTC
I181116 23:16:56.586193 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.478376967 +0000 UTC
I181116 23:16:56.669399 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.582944427 +0000 UTC
I181116 23:16:56.778854 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.666364923 +0000 UTC
I181116 23:16:56.877560 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.779168997 +0000 UTC
I181116 23:16:56.963089 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.875147035 +0000 UTC
I181116 23:16:57.075289 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:56.962936682 +0000 UTC
I181116 23:16:57.153661 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.06996597 +0000 UTC
I181116 23:16:57.256324 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.153255774 +0000 UTC
I181116 23:16:57.339596 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.25675788 +0000 UTC
I181116 23:16:57.444444 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.335088405 +0000 UTC
I181116 23:16:57.526440 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.441861037 +0000 UTC
I181116 23:16:57.605306 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.523766105 +0000 UTC
I181116 23:16:57.688871 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.604514583 +0000 UTC
I181116 23:16:57.778474 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.689037724 +0000 UTC
I181116 23:16:57.889562 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.774988121 +0000 UTC
I181116 23:16:57.987328 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.889795278 +0000 UTC
I181116 23:16:58.072446 10538 sql/lease.go:345  [n1,client=127.0.0.1:34856,user=root] publish: descID=54 (add_column) version=2 mtime=2018-11-16 23:16:57.987119644 +0000 UTC
I181116 23:17:18.846824 10023 gossip/gossip.go:555  [n1] gossip status (ok, 1 node)
gossip client (0/3 cur/max conns)



***** Text was not loaded fully because its' size exceeds 2 MB, see full log for the whole text *****