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 test: TestChangefeedSchemaChangeAllowBackfill #32933

Closed
cockroach-teamcity opened this issue Dec 7, 2018 · 2 comments
Closed

teamcity: failed test: TestChangefeedSchemaChangeAllowBackfill #32933

cockroach-teamcity opened this issue Dec 7, 2018 · 2 comments
Assignees
@danhhz
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
[DEPRECATED] CDC
Milestone
19.1

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed on master (testrace): TestChangefeedSchemaChangeAllowBackfill/rangefeed/drop_column, TestChangefeedSchemaChangeAllowBackfill/enterprise/add_column_computed, TestChangefeedSchemaChangeAllowBackfill/sinkless/multiple_alters, TestChangefeedSchemaChangeAllowBackfill/sinkless/add_column_with_default, TestChangefeedSchemaChangeAllowBackfill/sinkless, TestChangefeedSchemaChangeAllowBackfill, TestChangefeedSchemaChangeAllowBackfill/rangefeed/add_column_with_default, TestChangefeedSchemaChangeAllowBackfill/rangefeed/multiple_alters, TestChangefeedSchemaChangeAllowBackfill/enterprise/add_column_with_default, TestChangefeedSchemaChangeAllowBackfill/enterprise/drop_column, TestChangefeedSchemaChangeAllowBackfill/sinkless/drop_column, TestChangefeedSchemaChangeAllowBackfill/sinkless/add_column_computed, TestChangefeedSchemaChangeAllowBackfill/rangefeed/add_column_computed, TestChangefeedSchemaChangeAllowBackfill/enterprise, TestChangefeedSchemaChangeAllowBackfill/enterprise/multiple_alters, TestChangefeedSchemaChangeAllowBackfill/rangefeed

You may want to check for open issues.

#1045910:

TestChangefeedSchemaChangeAllowBackfill/rangefeed/multiple_alters
.../cockroach/pkg/storage/idalloc.(*Allocator).start.func1(0x4492340, 0xc42160fad0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/idalloc/id_alloc.go:137 +0x8a9
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc42037e740, 0xc4220df440, 0xc42037e730)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x14b
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xbb

goroutine 22501 [select, 41 minutes]:
github.com/cockroachdb/cockroach/pkg/server.periodicallyPersistHLCUpperBound(0xc422270640, 0xc422274c40, 0xc420c30620, 0x3d07600, 0xc4211ef380, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/server/server.go:950 +0x20f
github.com/cockroachdb/cockroach/pkg/server.(*Server).startPersistingHLCUpperBound.func2(0x4492340, 0xc4207435f0)
	/go/src/github.com/cockroachdb/cockroach/pkg/server/server.go:1024 +0xdb
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc420c30630, 0xc4220df440, 0xc42092b590)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x14b
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xbb

goroutine 22427 [semacquire, 41 minutes]:
sync.runtime_notifyListWait(0xc4212d9550, 0x4a030abc000003be)
	/usr/local/go/src/runtime/sema.go:510 +0x11a
sync.(*Cond).Wait(0xc4212d9540)
	/usr/local/go/src/sync/cond.go:56 +0x8e
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc42184c1b0, 0x4492340, 0xc4208c6000)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:196 +0x9c
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x4492340, 0xc4208c6000)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:165 +0x56
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc42212fd20, 0xc4220df440, 0xc42212fd10)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x14b
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xbb

goroutine 22286 [select, 41 minutes]:
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).initRunners.func1(0x4492340, 0xc4221ea0f0)
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:94 +0x1a2
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc42212ea80, 0xc4220df440, 0xc42212ea70)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x14b
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xbb

goroutine 22513 [select]:
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).Start.func2(0x4492340, 0xc42092b920)
	/go/src/github.com/cockroachdb/cockroach/pkg/jobs/registry.go:299 +0x146
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc420c30960, 0xc4220df440, 0xc42092b740)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x14b
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xbb

goroutine 22498 [select, 41 minutes]:
github.com/cockroachdb/cockroach/pkg/storage/compactor.(*Compactor).Start.func1.1(0x4492340, 0xc42092b3e0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/compactor/compactor.go:127 +0x22d
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc420c303a0, 0xc4220df440, 0xc4213605e0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x14b
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xbb



TestChangefeedSchemaChangeAllowBackfill/sinkless/add_column_computed
...:43:26.834176 20057 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.571513800,0,1544193806.830102875,0] took 1.225907ms behind by 3.858055ms
I181207 14:43:26.834650 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.830102875,0 is behind by 4.436251ms
I181207 14:43:26.859021 20058 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.830102875,0,1544193806.834783179,0] took 1.291462ms behind by 24.039225ms
I181207 14:43:26.859515 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.834783179,0 is behind by 24.63685ms
I181207 14:43:26.866888 19732 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 3}]
I181207 14:43:26.873421 20059 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.834783179,0,1544193806.859653396,0] took 11.194808ms behind by 13.572357ms
I181207 14:43:26.873938 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.859653396,0 is behind by 14.179939ms
I181207 14:43:26.878650 20060 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.859653396,0,1544193806.874091018,0] took 1.220211ms behind by 4.367809ms
I181207 14:43:26.879142 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.874091018,0 is behind by 4.950046ms
I181207 14:43:26.899238 20061 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.874091018,0,1544193806.879349715,0] took 17.008775ms behind by 19.678421ms
I181207 14:43:26.899716 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.879349715,0 is behind by 20.251787ms
I181207 14:43:26.904158 20062 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.879349715,0,1544193806.900002919,0] took 1.307255ms behind by 3.973717ms
I181207 14:43:26.904630 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.900002919,0 is behind by 4.520932ms
I181207 14:43:26.911947 20063 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.900002919,0,1544193806.907870954,0] took 1.276588ms behind by 3.868787ms
I181207 14:43:26.912404 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.907870954,0 is behind by 4.430939ms
I181207 14:43:26.932245 20064 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.907870954,0,1544193806.928024601,0] took 1.310112ms behind by 4.016443ms
I181207 14:43:26.932732 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.928024601,0 is behind by 4.609074ms
I181207 14:43:26.973183 20087 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193806.928024601,0,1544193806.939766434,0] took 1.334913ms behind by 33.247899ms
I181207 14:43:26.975248 19840 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193806.939766434,0 is behind by 35.373108ms



TestChangefeedSchemaChangeAllowBackfill/sinkless
...1207 14:43:22.604868 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.605093 19541 server/server_update.go:66  [n1] no need to upgrade, cluster already at the newest version
I181207 14:43:22.606049 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.611777 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.612567 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.613273 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.613973 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.614634 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.615324 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.616002 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.616661 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.617307 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.618129 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.619181 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.620247 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.621615 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.621767 19544 sql/event_log.go:125  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:37095} Attrs: Locality: ServerVersion:2.1-3 BuildTag:v2.2.0-alpha.20181119-592-geea1707 StartedAt:1544193800285335169 LocalityAddress:[]} ClusterID:2e6255be-82da-41d2-b55e-4362f646a2f2 StartedAt:1544193800285335169 LastUp:1544193800285335169}
I181207 14:43:22.623520 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.626386 19113 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:22.689258 19529 storage/replica_command.go:349  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I181207 14:43:22.696625 19113 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:22.708223 19113 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:22.753921 19550 storage/replica_command.go:349  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I181207 14:43:22.769332 19113 server/testserver.go:420  had 16 ranges at startup, expected 20
I181207 14:43:22.800722 19591 storage/replica_command.go:349  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I181207 14:43:22.843985 19113 server/testserver.go:420  had 17 ranges at startup, expected 20
I181207 14:43:22.912003 19473 storage/replica_command.go:349  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I181207 14:43:22.916875 19113 server/testserver.go:420  had 18 ranges at startup, expected 20
I181207 14:43:23.000841 19561 storage/replica_command.go:349  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I181207 14:43:23.295981 19604 sql/event_log.go:125  [n1,client=127.0.0.1:54948,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:00:00:00 User:root}
I181207 14:43:23.432607 19604 sql/event_log.go:125  [n1,client=127.0.0.1:54948,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:sql.defaults.results_buffer.size Value:0 User:root}
I181207 14:43:23.528065 19604 sql/event_log.go:125  [n1,client=127.0.0.1:54948,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}



TestChangefeedSchemaChangeAllowBackfill/rangefeed
...erver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.287847 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.288527 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.289202 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.289983 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.290723 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.291575 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.292502 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.293642 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.295884 22209 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:52.317913 22702 sql/event_log.go:125  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:44417} Attrs: Locality: ServerVersion:2.1-3 BuildTag:v2.2.0-alpha.20181119-592-geea1707 StartedAt:1544193830135688780 LocalityAddress:[]} ClusterID:ad9c8ccd-63ce-41f9-a648-fb900e5ed3fe StartedAt:1544193830135688780 LastUp:1544193830135688780}
I181207 14:43:52.335385 22786 storage/replica_command.go:349  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I181207 14:43:52.361637 22209 server/testserver.go:420  had 16 ranges at startup, expected 20
I181207 14:43:52.368808 22209 server/testserver.go:420  had 16 ranges at startup, expected 20
I181207 14:43:52.381121 22209 server/testserver.go:420  had 16 ranges at startup, expected 20
I181207 14:43:52.399397 22209 server/testserver.go:420  had 16 ranges at startup, expected 20
I181207 14:43:52.434010 22209 server/testserver.go:420  had 16 ranges at startup, expected 20
I181207 14:43:52.482649 22714 storage/replica_command.go:349  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I181207 14:43:52.503825 22209 server/testserver.go:420  had 17 ranges at startup, expected 20
I181207 14:43:52.558625 22749 storage/replica_command.go:349  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I181207 14:43:52.604657 22653 storage/replica_command.go:349  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I181207 14:43:52.640425 22209 server/testserver.go:420  had 19 ranges at startup, expected 20
I181207 14:43:53.258359 22818 sql/event_log.go:125  [n1,client=127.0.0.1:58478,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:00:00:00 User:root}
I181207 14:43:53.348401 22818 sql/event_log.go:125  [n1,client=127.0.0.1:58478,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:sql.defaults.results_buffer.size Value:0 User:root}
I181207 14:43:53.435859 22818 sql/event_log.go:125  [n1,client=127.0.0.1:58478,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I181207 14:43:53.671445 22764 sql/event_log.go:125  [n1,client=127.0.0.1:58484,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:kv.rangefeed.enabled Value:true User:root}
I181207 14:43:53.752468 22764 sql/event_log.go:125  [n1,client=127.0.0.1:58484,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:kv.closed_timestamp.target_duration Value:00:00:01 User:root}
I181207 14:43:56.889412 22209 ccl/changefeedccl/helpers_test.go:693  SucceedsSoon: r20:/{Table/23-Max} [(n1,s1):1, next=2, gen=0] does not have an epoch lease: should resolve in 2.295964815s
I181207 14:43:57.891726 22209 ccl/changefeedccl/helpers_test.go:693  SucceedsSoon: r20:/{Table/23-Max} [(n1,s1):1, next=2, gen=0] does not have an epoch lease: should resolve in 1.293653419s



TestChangefeedSchemaChangeAllowBackfill
--- FAIL: test/TestChangefeedSchemaChangeAllowBackfill (20.480s)
Test ended in panic.




TestChangefeedSchemaChangeAllowBackfill/rangefeed/add_column_computed
...a + 5) STORED) User:root}
I181207 14:44:02.031592 23059 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:58484,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193842.020117773,0,1544193842.020117773,0] took 1.748733ms behind by 11.275236ms
I181207 14:44:02.041041 22991 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193842.020117773,0 is behind by 20.60041ms
I181207 14:44:02.041858 22991 ccl/changefeedccl/changefeed_processors.go:539  [n1,client=127.0.0.1:58484,user=root] job 0 span [/Table/54/1,/Table/54/2) is behind by 20.60041ms
I181207 14:44:02.094318 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root] publish: descID=54 (add_col_comp) version=2 mtime=2018-12-07 14:44:02.049188266 +0000 UTC
I181207 14:44:02.260834 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root] publish: descID=54 (add_col_comp) version=2 mtime=2018-12-07 14:44:02.090608398 +0000 UTC
I181207 14:44:02.323893 22870 sql/event_log.go:125  [n1,client=127.0.0.1:58516,user=root] Event: "alter_table", target: 54, info: {TableName:d.public.add_col_comp Statement:ALTER TABLE add_col_comp ADD COLUMN c INT AS (a + 10) STORED User:root MutationID:1 CascadeDroppedViews:[]}
I181207 14:44:02.324051 22870 sql/event_log.go:125  [n1,client=127.0.0.1:58516,user=root] Event: "alter_table", target: 54, info: {TableName:d.public.add_col_comp Statement:ALTER TABLE add_col_comp ADD COLUMN c INT AS (a + 10) STORED User:root MutationID:1 CascadeDroppedViews:[]}
I181207 14:44:02.365102 23015 sql/lease.go:864  new lease: 54("add_col_comp") ver=2:1544194125.327116032,0, refcount=0
I181207 14:44:02.483643 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root,scExec] publish: descID=54 (add_col_comp) version=3 mtime=2018-12-07 14:44:02.482637446 +0000 UTC
I181207 14:44:02.530518 23006 sql/lease.go:864  new lease: 54("add_col_comp") ver=3:1544194186.349446393,0, refcount=0
I181207 14:44:02.544754 22870 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 2}]
I181207 14:44:02.648229 22870 sql/backfill.go:131  [n1,client=127.0.0.1:58516,user=root,scExec] Running backfill for "add_col_comp", v=3, m=1
I181207 14:44:02.851819 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root,scExec] publish: descID=54 (add_col_comp) version=4 mtime=2018-12-07 14:44:02.850915287 +0000 UTC
I181207 14:44:03.036725 22870 sql/event_log.go:125  [n1,client=127.0.0.1:58516,user=root,scExec] Event: "finish_schema_change", target: 54, info: {MutationID:1}
I181207 14:44:03.054984 23084 sql/lease.go:864  new lease: 54("add_col_comp") ver=4:1544194102.847850497,0, refcount=0
I181207 14:44:03.079811 22870 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 3}]
I181207 14:44:03.376903 22991 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193842.174696894,0 is behind by 1.202060851s
I181207 14:44:03.577061 22991 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193842.376138813,0 is behind by 1.200800466s
I181207 14:44:03.777298 22991 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193842.576340223,0 is behind by 1.200839693s
I181207 14:44:03.977662 22991 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193842.776544047,0 is behind by 1.200973527s
I181207 14:44:04.177949 22991 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193842.850915287,0 is behind by 1.326905001s
I181207 14:44:04.582050 23098 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:58484,user=root] finished ExportRequest [/Table/54/1,/Table/54/2) over (1544193842.850915287,0,1544193842.850915287,0] took 1.467472ms behind by 1.730926608s



TestChangefeedSchemaChangeAllowBackfill/enterprise/add_column_computed
....117221945,0] took 1.371004ms behind by 7.132067ms
I181207 14:43:40.220641 21200 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727618423291905 new resolved timestamp 1544193820.005308379,0 is behind by 215.21431ms
I181207 14:43:40.224987 21525 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193820.117221945,0,1544193820.220919237,0] took 1.319058ms behind by 3.894315ms
I181207 14:43:40.311700 21200 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727618423291905 new resolved timestamp 1544193820.117221945,0 is behind by 194.370742ms
I181207 14:43:40.319535 21555 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193820.220919237,0,1544193820.315057546,0] took 1.22882ms behind by 4.285074ms
I181207 14:43:40.366573 21040 sql/lease.go:335  [n1,client=127.0.0.1:43058,user=root,scExec] publish: descID=56 (add_col_comp) version=4 mtime=2018-12-07 14:43:40.365533512 +0000 UTC
I181207 14:43:40.432848 21200 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727618423291905 new resolved timestamp 1544193820.220919237,0 is behind by 211.814505ms
I181207 14:43:40.483012 21556 storage/split_queue.go:214  [n1,split,s1,r7/1:/Table/{SystemCon…-11}] initiating a split based on load at key /Table/3/1/1/2/1
E181207 14:43:40.483439 21556 storage/queue.go:836  [n1,split,s1,r7/1:/Table/{SystemCon…-11}] unable to split [n1,s1,r7/1:/Table/{SystemCon…-11}] at key /Table/3/1/1/2/1: cannot split range at key /Table/3/1/1/2/1
I181207 14:43:40.489590 21040 sql/event_log.go:125  [n1,client=127.0.0.1:43058,user=root,scExec] Event: "finish_schema_change", target: 56, info: {MutationID:1}
I181207 14:43:40.519311 21040 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 56 3}]
I181207 14:43:40.529895 21571 sql/lease.go:864  [n1] new lease: 56("add_col_comp") ver=4:1544194178.615877551,0, refcount=0
I181207 14:43:40.533000 21499 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193820.315057546,0,1544193820.365533512,0] took 1.225453ms behind by 167.255737ms
I181207 14:43:40.540068 21200 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727618423291905 new resolved timestamp 1544193820.315057546,0 is behind by 224.904802ms
I181207 14:43:40.572636 21545 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193820.365533512,0,1544193820.365533512,0] took 1.27612ms behind by 206.918005ms
I181207 14:43:40.599303 21040 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 56 3}]
I181207 14:43:40.655332 21200 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727618423291905 new resolved timestamp 1544193820.365533512,0 is behind by 289.692711ms
I181207 14:43:40.667762 21548 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193820.365533512,0,1544193820.657875062,0] took 7.1025ms behind by 9.686311ms
I181207 14:43:40.674930 21514 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193820.657875062,0,1544193820.670987560,0] took 1.106504ms behind by 3.720335ms
I181207 14:43:40.748780 21200 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727618423291905 new resolved timestamp 1544193820.657875062,0 is behind by 90.79834ms
I181207 14:43:40.760093 21552 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193820.670987560,0,1544193820.755538213,0] took 1.25113ms behind by 4.376484ms
I181207 14:43:40.818512 21200 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727618423291905 new resolved timestamp 1544193820.670987560,0 is behind by 147.414832ms
I181207 14:43:40.823928 21530 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193820.755538213,0,1544193820.820158738,0] took 1.132001ms behind by 3.600362ms



TestChangefeedSchemaChangeAllowBackfill/sinkless/add_column_with_default
...2) over (1544193805.470263550,0,1544193805.474174005,0] took 1.130662ms behind by 3.333309ms
I181207 14:43:25.481551 19835 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.474174005,0,1544193805.477903029,0] took 1.143189ms behind by 3.460805ms
I181207 14:43:25.482000 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.474174005,0 is behind by 7.724422ms
I181207 14:43:25.482299 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.477903029,0 is behind by 4.316387ms
I181207 14:43:25.486216 19836 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.477903029,0,1544193805.482475384,0] took 1.278705ms behind by 3.550548ms
I181207 14:43:25.486629 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.482475384,0 is behind by 4.051869ms
I181207 14:43:25.491063 19837 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.482475384,0,1544193805.486501215,0] took 1.136737ms behind by 4.360642ms
I181207 14:43:25.491639 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.486501215,0 is behind by 4.937554ms
I181207 14:43:25.498586 19838 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.486501215,0,1544193805.494195028,0] took 1.300035ms behind by 4.212404ms
I181207 14:43:25.499029 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.494195028,0 is behind by 4.734677ms
I181207 14:43:25.503068 19878 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.494195028,0,1544193805.498833646,0] took 1.148968ms behind by 3.866238ms
I181207 14:43:25.503489 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.498833646,0 is behind by 4.563972ms
I181207 14:43:25.510454 19879 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.498833646,0,1544193805.503612923,0] took 4.203291ms behind by 6.646313ms
I181207 14:43:25.511258 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.503612923,0 is behind by 7.534385ms
I181207 14:43:25.514880 19880 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.503612923,0,1544193805.510769104,0] took 1.144399ms behind by 3.930226ms
I181207 14:43:25.516828 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.510769104,0 is behind by 5.945143ms
I181207 14:43:25.519832 19881 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.510769104,0,1544193805.515185090,0] took 1.142885ms behind by 4.446823ms
I181207 14:43:25.523527 19683 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193805.515185090,0 is behind by 8.247594ms
I181207 14:43:25.552642 19893 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193805.515185090,0,1544193805.523232224,0] took 1.335417ms behind by 29.194706ms



TestChangefeedSchemaChangeAllowBackfill/rangefeed/drop_column
....0.1:58516,user=root] publish: descID=55 (drop_column) version=2 mtime=2018-12-07 14:44:04.791899557 +0000 UTC
I181207 14:44:04.963439 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root] publish: descID=55 (drop_column) version=2 mtime=2018-12-07 14:44:04.848097365 +0000 UTC
I181207 14:44:05.051863 22870 sql/event_log.go:125  [n1,client=127.0.0.1:58516,user=root] Event: "alter_table", target: 55, info: {TableName:d.public.drop_column Statement:ALTER TABLE drop_column DROP COLUMN b User:root MutationID:1 CascadeDroppedViews:[]}
I181207 14:44:05.052033 22870 sql/event_log.go:125  [n1,client=127.0.0.1:58516,user=root] Event: "alter_table", target: 55, info: {TableName:d.public.drop_column Statement:ALTER TABLE drop_column DROP COLUMN b User:root MutationID:1 CascadeDroppedViews:[]}
I181207 14:44:05.096321 23205 sql/lease.go:864  new lease: 55("drop_column") ver=2:1544194128.671908012,0, refcount=0
I181207 14:44:05.346538 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root,scExec] publish: descID=55 (drop_column) version=3 mtime=2018-12-07 14:44:05.344904935 +0000 UTC
I181207 14:44:05.433454 22870 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 2}]
I181207 14:44:05.499390 22870 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 2}]
I181207 14:44:05.499471 23235 sql/lease.go:864  new lease: 55("drop_column") ver=3:1544194163.584213121,0, refcount=0
I181207 14:44:05.566240 22870 sql/backfill.go:131  [n1,client=127.0.0.1:58516,user=root,scExec] Running backfill for "drop_column", v=3, m=1
I181207 14:44:05.772180 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root,scExec] publish: descID=55 (drop_column) version=4 mtime=2018-12-07 14:44:05.770190174 +0000 UTC
I181207 14:44:05.899753 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root,scExec] publish: descID=55 (drop_column) version=4 mtime=2018-12-07 14:44:05.779735053 +0000 UTC
I181207 14:44:05.980350 23088 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193844.779383389,0 is behind by 1.200835141s
I181207 14:44:06.078447 22870 sql/event_log.go:125  [n1,client=127.0.0.1:58516,user=root,scExec] Event: "finish_schema_change", target: 55, info: {MutationID:1}
I181207 14:44:06.127277 22870 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 3}]
I181207 14:44:06.127630 23161 sql/lease.go:864  new lease: 55("drop_column") ver=4:1544194126.024164934,0, refcount=0
I181207 14:44:06.160829 22870 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 3}]
I181207 14:44:06.185459 23088 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193844.979610611,0 is behind by 1.205727984s
I181207 14:44:06.380843 23088 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193845.179839907,0 is behind by 1.200858379s
I181207 14:44:06.581195 23088 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193845.380052423,0 is behind by 1.200984788s
I181207 14:44:06.787688 23088 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193845.580269563,0 is behind by 1.207295094s
I181207 14:44:06.988112 23088 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193845.779735053,1 is behind by 1.208242136s
I181207 14:44:07.392734 23200 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:58484,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193845.779735053,1,1544193845.779735053,1] took 1.343041ms behind by 1.612780232s
I181207 14:44:07.396900 23088 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193846.188211830,0 is behind by 1.20855965s



TestChangefeedSchemaChangeAllowBackfill/rangefeed/add_column_with_default
...tement:ALTER TABLE add_column_def ADD COLUMN b STRING DEFAULT 'd' User:root MutationID:1 CascadeDroppedViews:[]}
I181207 14:43:59.581781 22870 sql/event_log.go:125  [n1,client=127.0.0.1:58516,user=root] Event: "alter_table", target: 53, info: {TableName:d.public.add_column_def Statement:ALTER TABLE add_column_def ADD COLUMN b STRING DEFAULT 'd' User:root MutationID:1 CascadeDroppedViews:[]}
I181207 14:43:59.608761 22901 sql/lease.go:864  new lease: 53("add_column_def") ver=2:1544194108.372551333,0, refcount=0
I181207 14:43:59.779642 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root,scExec] publish: descID=53 (add_column_def) version=3 mtime=2018-12-07 14:43:59.778713865 +0000 UTC
I181207 14:43:59.853879 22865 sql/lease.go:864  new lease: 53("add_column_def") ver=3:1544194203.858373550,0, refcount=0
I181207 14:43:59.861150 22870 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 2}]
I181207 14:43:59.939778 22870 sql/backfill.go:131  [n1,client=127.0.0.1:58516,user=root,scExec] Running backfill for "add_column_def", v=3, m=1
I181207 14:44:00.107758 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root,scExec] publish: descID=53 (add_column_def) version=4 mtime=2018-12-07 14:44:00.106694163 +0000 UTC
I181207 14:44:00.176898 22870 sql/lease.go:335  [n1,client=127.0.0.1:58516,user=root,scExec] publish: descID=53 (add_column_def) version=4 mtime=2018-12-07 14:44:00.108661541 +0000 UTC
I181207 14:44:00.255451 22504 server/status/runtime.go:464  [n1] runtime stats: 490 MiB RSS, 245 goroutines, 19 MiB/22 MiB/55 MiB GO alloc/idle/total, 38 MiB/78 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (255x), 2.9 MiB/2.9 MiB (r/w)net
I181207 14:44:00.285202 22870 sql/event_log.go:125  [n1,client=127.0.0.1:58516,user=root,scExec] Event: "finish_schema_change", target: 53, info: {MutationID:1}
I181207 14:44:00.294153 22890 storage/split_queue.go:214  [n1,split,s1,r7/1:/Table/{SystemCon…-11}] initiating a split based on load at key /Table/3/1/1/2/1
E181207 14:44:00.297459 22890 storage/queue.go:836  [n1,split,s1,r7/1:/Table/{SystemCon…-11}] unable to split [n1,s1,r7/1:/Table/{SystemCon…-11}] at key /Table/3/1/1/2/1: cannot split range at key /Table/3/1/1/2/1
I181207 14:44:00.309575 22955 sql/lease.go:864  [n1,client=127.0.0.1:58484,user=root] new lease: 53("add_column_def") ver=4:1544194156.632786557,0, refcount=0
I181207 14:44:00.329594 22870 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181207 14:44:00.362264 22795 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193839.161197926,0 is behind by 1.200930441s
I181207 14:44:00.365210 22870 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181207 14:44:00.562479 22795 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193839.361448852,0 is behind by 1.200917091s
I181207 14:44:00.762712 22795 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193839.561720083,0 is behind by 1.200873701s
I181207 14:44:00.963024 22795 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193839.761994278,0 is behind by 1.200886207s
I181207 14:44:01.163186 22795 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193839.962256624,0 is behind by 1.200811337s
I181207 14:44:01.363581 22795 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:58484,user=root] job 0 new resolved timestamp 1544193840.108661541,1 is behind by 1.25479113s
I181207 14:44:01.771421 22904 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:58484,user=root] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193840.108661541,1,1544193840.108661541,1] took 1.302577ms behind by 1.662573656s



TestChangefeedSchemaChangeAllowBackfill/enterprise/add_column_with_default
...s behind by 154.656908ms
I181207 14:43:37.428006 21299 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193817.350834309,0,1544193817.397861709,0] took 27.211689ms behind by 29.911028ms
I181207 14:43:37.497230 21171 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727610430259201 new resolved timestamp 1544193817.350834309,0 is behind by 146.287801ms
I181207 14:43:37.504267 21194 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193817.397861709,0,1544193817.498852247,0] took 1.330902ms behind by 5.217078ms
I181207 14:43:37.533754 21040 sql/lease.go:335  [n1,client=127.0.0.1:43058,user=root,scExec] publish: descID=53 (add_column_def) version=4 mtime=2018-12-07 14:43:37.53292375 +0000 UTC
I181207 14:43:37.583719 21171 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727610430259201 new resolved timestamp 1544193817.397861709,0 is behind by 185.737282ms
I181207 14:43:37.637119 21171 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727610430259201 new resolved timestamp 1544193817.498852247,0 is behind by 138.144107ms
I181207 14:43:37.681850 21231 storage/split_queue.go:214  [n1,split,s1,r7/1:/Table/{SystemCon…-11}] initiating a split based on load at key /Table/3/1/1/2/1
E181207 14:43:37.682260 21231 storage/queue.go:836  [n1,split,s1,r7/1:/Table/{SystemCon…-11}] unable to split [n1,s1,r7/1:/Table/{SystemCon…-11}] at key /Table/3/1/1/2/1: cannot split range at key /Table/3/1/1/2/1
I181207 14:43:37.683541 21040 sql/event_log.go:125  [n1,client=127.0.0.1:43058,user=root,scExec] Event: "finish_schema_change", target: 53, info: {MutationID:1}
I181207 14:43:37.729828 21040 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181207 14:43:37.733701 21230 sql/lease.go:864  new lease: 53("add_column_def") ver=4:1544194163.642957927,0, refcount=0
I181207 14:43:37.772176 21330 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193817.498852247,0,1544193817.532923750,0] took 9.635411ms behind by 239.088895ms
I181207 14:43:37.788612 21040 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181207 14:43:37.800062 21272 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193817.532923750,0,1544193817.532923750,0] took 1.347813ms behind by 266.973938ms
I181207 14:43:37.883565 21171 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727610430259201 new resolved timestamp 1544193817.532923750,0 is behind by 350.272604ms
I181207 14:43:37.896996 21297 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193817.532923750,0,1544193817.892206023,0] took 1.327732ms behind by 4.614527ms
I181207 14:43:37.914988 21347 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193817.892206023,0,1544193817.910485329,0] took 1.341754ms behind by 4.269487ms
I181207 14:43:37.990751 21171 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727610430259201 new resolved timestamp 1544193817.892206023,0 is behind by 98.438253ms
I181207 14:43:38.000193 21275 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193817.910485329,0,1544193817.994984821,0] took 1.221123ms behind by 3.8865ms
I181207 14:43:38.065084 21171 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727610430259201 new resolved timestamp 1544193817.910485329,0 is behind by 154.49416ms
I181207 14:43:38.075521 21340 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/53/1,/Table/53/2) over (1544193817.994984821,0,1544193818.071266599,0] took 1.323601ms behind by 4.096196ms
I181207 14:43:38.206918 21171 ccl/changefeedccl/changefeed_stmt.go:433  [n1] CHANGEFEED job 406727610430259201 returning with error: cannot update progress on canceled job (id 406727610430259201)



TestChangefeedSchemaChangeAllowBackfill/enterprise/drop_column
...gefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193822.469303437,0,1544193822.550301117,0] took 1.324428ms behind by 4.365289ms
I181207 14:43:42.587907 21521 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727627796971521 new resolved timestamp 1544193822.469303437,0 is behind by 118.484537ms
I181207 14:43:42.592475 21778 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193822.550301117,0,1544193822.588243402,0] took 1.347205ms behind by 4.05666ms
I181207 14:43:42.677326 20791 server/status/runtime.go:464  [n1] runtime stats: 487 MiB RSS, 243 goroutines, 32 MiB/9.6 MiB/54 MiB GO alloc/idle/total, 39 MiB/82 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (242x), 2.7 MiB/2.7 MiB (r/w)net
I181207 14:43:42.730356 21521 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727627796971521 new resolved timestamp 1544193822.550301117,0 is behind by 179.948884ms
I181207 14:43:42.748212 21781 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193822.588243402,0,1544193822.743750863,0] took 1.324123ms behind by 4.265068ms
I181207 14:43:42.783684 21040 sql/lease.go:335  [n1,client=127.0.0.1:43058,user=root,scExec] publish: descID=59 (drop_column) version=4 mtime=2018-12-07 14:43:42.782669225 +0000 UTC
I181207 14:43:42.843942 21521 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727627796971521 new resolved timestamp 1544193822.588243402,0 is behind by 255.589799ms
I181207 14:43:42.989324 21040 sql/event_log.go:125  [n1,client=127.0.0.1:43058,user=root,scExec] Event: "finish_schema_change", target: 59, info: {MutationID:1}
I181207 14:43:43.034529 21521 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727627796971521 new resolved timestamp 1544193822.743750863,0 is behind by 290.668955ms
I181207 14:43:43.052383 21040 sql/lease.go:307  publish (1 leases): desc=[{drop_column 59 3}]
I181207 14:43:43.089448 21826 sql/lease.go:864  new lease: 59("drop_column") ver=4:1544194097.798929797,0, refcount=0
I181207 14:43:43.120998 21040 sql/lease.go:307  publish (1 leases): desc=[{drop_column 59 3}]
I181207 14:43:43.154175 21790 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193822.743750863,0,1544193822.782669225,0] took 1.328869ms behind by 371.288926ms
I181207 14:43:43.186035 21739 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193822.782669225,0,1544193822.782669225,0] took 1.389891ms behind by 403.149708ms
I181207 14:43:43.387749 21521 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727627796971521 new resolved timestamp 1544193822.782669225,0 is behind by 604.983442ms
I181207 14:43:43.395471 21772 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193822.782669225,0,1544193823.390548803,0] took 1.499868ms behind by 4.722079ms
I181207 14:43:43.427979 21834 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193823.390548803,0,1544193823.423659661,0] took 1.314563ms behind by 4.12841ms
I181207 14:43:43.532723 21521 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727627796971521 new resolved timestamp 1544193823.390548803,0 is behind by 142.068364ms
I181207 14:43:43.537492 21744 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193823.423659661,0,1544193823.533025393,0] took 1.360037ms behind by 4.298836ms
I181207 14:43:43.635130 21521 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727627796971521 new resolved timestamp 1544193823.423659661,0 is behind by 211.357787ms
I181207 14:43:43.643072 21844 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/59/1,/Table/59/2) over (1544193823.533025393,0,1544193823.639089858,0] took 1.243503ms behind by 3.789725ms



TestChangefeedSchemaChangeAllowBackfill/enterprise/multiple_alters
.../2) over (1544193826.200134317,0,1544193826.200134317,0] took 17.544232ms behind by 2.748160145s
I181207 14:43:49.109530 21759 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727637365194753 new resolved timestamp 1544193826.200134317,0 is behind by 2.909285282s
I181207 14:43:49.121631 22199 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/62/1,/Table/62/2) over (1544193826.200134317,0,1544193827.179420592,0] took 6.600774ms behind by 1.942017836s
I181207 14:43:49.135713 22187 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/62/1,/Table/62/2) over (1544193827.179420592,0,1544193827.179420592,0] took 1.465616ms behind by 1.956105056s
I181207 14:43:49.263273 21759 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727637365194753 new resolved timestamp 1544193827.179420592,0 is behind by 2.083750084s
I181207 14:43:49.291025 22202 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/62/1,/Table/62/2) over (1544193827.179420592,0,1544193828.303234081,0] took 1.381533ms behind by 985.316351ms
I181207 14:43:49.296138 22219 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/62/1,/Table/62/2) over (1544193828.303234081,0,1544193828.303234081,0] took 1.261009ms behind by 992.720029ms
I181207 14:43:49.437448 21759 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727637365194753 new resolved timestamp 1544193828.303234081,0 is behind by 1.134099779s
I181207 14:43:49.444835 22235 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/62/1,/Table/62/2) over (1544193828.303234081,0,1544193829.440447459,0] took 1.275716ms behind by 4.197133ms
I181207 14:43:49.459545 22144 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/62/1,/Table/62/2) over (1544193829.440447459,0,1544193829.455253345,0] took 1.329662ms behind by 4.097324ms
I181207 14:43:49.516912 21759 ccl/changefeedccl/changefeed_processors.go:532  [n1] job 406727637365194753 new resolved timestamp 1544193829.440447459,0 is behind by 76.3715ms
I181207 14:43:49.521316 22145 ccl/changefeedccl/poller.go:456  [n1] finished ExportRequest [/Table/62/1,/Table/62/2) over (1544193829.455253345,0,1544193829.517143216,0] took 1.242278ms behind by 3.983175ms
I181207 14:43:49.628424 20544 util/stop/stopper.go:536  quiescing; tasks left:
1      node.Node: batch
1      [async] transport racer
1      [async] kv.TxnCoordSender: heartbeat loop
1      [async] job-406727637365194753
1      [async] closedts-rangefeed-subscriber
1      [async] changefeed-poller
I181207 14:43:49.638159 20544 util/stop/stopper.go:536  quiescing; tasks left:
1      node.Node: batch
1      [async] transport racer
1      [async] job-406727637365194753
1      [async] closedts-rangefeed-subscriber
1      [async] changefeed-poller
I181207 14:43:49.638298 20475 kv/transport_race.go:113  transport race promotion: ran 40 iterations on up to 5014 requests
I181207 14:43:49.638512 20544 util/stop/stopper.go:536  quiescing; tasks left:
1      node.Node: batch
1      [async] job-406727637365194753
1      [async] closedts-rangefeed-subscriber
1      [async] changefeed-poller
I181207 14:43:49.642418 20544 util/stop/stopper.go:536  quiescing; tasks left:
1      node.Node: batch
1      [async] job-406727637365194753
1      [async] changefeed-poller
I181207 14:43:49.643840 20544 util/stop/stopper.go:536  quiescing; tasks left:
1      [async] job-406727637365194753
1      [async] changefeed-poller
I181207 14:43:49.645695 21759 ccl/changefeedccl/changefeed_stmt.go:413  [n1] CHANGEFEED job 406727637365194753 encountered retryable error: job-update: node unavailable; try another peer
I181207 14:43:49.648087 21759 ccl/changefeedccl/changefeed_stmt.go:433  [n1] CHANGEFEED job 406727637365194753 returning with error: log-job: node unavailable; try another peer
I181207 14:43:49.657766 20544 util/stop/stopper.go:536  quiescing; tasks left:
1      [async] job-406727637365194753



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




TestChangefeedSchemaChangeAllowBackfill/sinkless/drop_column
...edccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193808.141048503,0 is behind by 4.575339ms
I181207 14:43:28.158187 20046 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193808.141048503,0,1544193808.146001015,0] took 1.632418ms behind by 11.940633ms
I181207 14:43:28.158826 20118 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193808.146001015,0 is behind by 12.666443ms
I181207 14:43:28.166077 19732 sql/lease.go:335  [n1,client=127.0.0.1:54952,user=root,scExec] publish: descID=55 (drop_column) version=4 mtime=2018-12-07 14:43:28.165158716 +0000 UTC
I181207 14:43:28.171299 20047 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193808.146001015,0,1544193808.160867382,0] took 1.333909ms behind by 10.240645ms
I181207 14:43:28.171762 20118 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193808.160867382,0 is behind by 10.798336ms
I181207 14:43:28.260351 19732 sql/event_log.go:125  [n1,client=127.0.0.1:54952,user=root,scExec] Event: "finish_schema_change", target: 55, info: {MutationID:1}
I181207 14:43:28.282806 20258 sql/lease.go:864  new lease: 55("drop_column") ver=4:1544194083.419640867,0, refcount=0
I181207 14:43:28.297087 19732 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 3}]
I181207 14:43:28.313994 20280 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193808.160867382,0,1544193808.165158716,0] took 1.411527ms behind by 148.55649ms
I181207 14:43:28.314461 20118 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193808.165158716,0 is behind by 149.196922ms
I181207 14:43:28.337325 20281 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193808.165158716,0,1544193808.165158716,0] took 1.557856ms behind by 171.705552ms
I181207 14:43:28.364220 20188 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193808.165158716,0,1544193808.359438203,0] took 1.441732ms behind by 4.558641ms
I181207 14:43:28.364730 20118 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193808.359438203,0 is behind by 5.176979ms
I181207 14:43:28.397618 20229 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193808.359438203,0,1544193808.365057668,0] took 1.460005ms behind by 32.317907ms
I181207 14:43:28.398231 20118 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193808.365057668,0 is behind by 33.047512ms
I181207 14:43:28.415296 20170 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193808.365057668,0,1544193808.397901357,0] took 1.39231ms behind by 17.203361ms
I181207 14:43:28.415844 20118 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193808.397901357,0 is behind by 17.832375ms
I181207 14:43:28.422518 20171 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/55/1,/Table/55/2) over (1544193808.397901357,0,1544193808.416011613,0] took 1.286528ms behind by 6.308087ms
I181207 14:43:28.423244 20118 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193808.416011613,0 is behind by 7.137887ms



TestChangefeedSchemaChangeAllowBackfill/sinkless/multiple_alters
...1548,0, refcount=0
I181207 14:43:31.193304 19732 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 56 8}]
I181207 14:43:31.256130 19732 sql/backfill.go:131  [n1,client=127.0.0.1:54952,user=root,scExec] Running backfill for "multiple_alters", v=9, m=3
I181207 14:43:31.450301 19732 sql/lease.go:335  [n1,client=127.0.0.1:54952,user=root,scExec] publish: descID=56 (multiple_alters) version=10 mtime=2018-12-07 14:43:31.449261748 +0000 UTC
I181207 14:43:31.590350 19732 sql/event_log.go:125  [n1,client=127.0.0.1:54952,user=root,scExec] Event: "finish_schema_change", target: 56, info: {MutationID:3}
I181207 14:43:31.644935 20518 sql/lease.go:864  new lease: 56("multiple_alters") ver=10:1544194144.609848077,0, refcount=0
I181207 14:43:31.663639 19732 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 56 9}]
I181207 14:43:31.761025 20230 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193809.365321718,0 is behind by 2.395581108s
I181207 14:43:31.872557 20541 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193809.365321718,0,1544193809.445539632,0] took 1.237476ms behind by 2.426816912s
I181207 14:43:31.878515 20230 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193809.445539632,0 is behind by 2.432846485s
I181207 14:43:31.893711 20542 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193809.445539632,0,1544193809.445539632,0] took 10.018319ms behind by 2.447964595s
I181207 14:43:31.899877 20543 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193809.445539632,0,1544193810.382777018,0] took 1.33978ms behind by 1.516891548s
I181207 14:43:31.907387 20230 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193810.382777018,0 is behind by 1.524478864s
I181207 14:43:31.911753 20463 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193810.382777018,0,1544193810.382777018,0] took 1.328921ms behind by 1.528777511s
I181207 14:43:31.917559 20464 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193810.382777018,0,1544193811.449261748,0] took 1.279729ms behind by 468.114191ms
I181207 14:43:31.919106 20230 ccl/changefeedccl/changefeed_processors.go:532  [n1,client=127.0.0.1:54950,user=root] job 0 new resolved timestamp 1544193811.449261748,0 is behind by 469.723552ms
I181207 14:43:31.922880 20470 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193811.449261748,0,1544193811.449261748,0] took 1.251482ms behind by 473.422985ms
I181207 14:43:31.927984 20507 ccl/changefeedccl/poller.go:456  [n1,client=127.0.0.1:54950,user=root] finished ExportRequest [/Table/56/1,/Table/56/2) over (1544193811.449261748,0,1544193811.924742299,0] took 534.295µs behind by 3.029148ms
I181207 14:43:31.934134 19113 util/stop/stopper.go:536  quiescing; tasks left:
1      ts.poller: poll
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I181207 14:43:31.934451 19367 kv/transport_race.go:113  transport race promotion: ran 78 iterations on up to 3848 requests
I181207 14:43:31.938679 19113 util/stop/stopper.go:536  quiescing; tasks left:
1      ts.poller: poll
1      [async] closedts-rangefeed-subscriber
I181207 14:43:31.938950 19113 util/stop/stopper.go:536  quiescing; tasks left:
1      ts.poller: poll
W181207 14:43:32.213869 19343 ts/db.go:195  [n1,ts-poll] error writing time series data: node unavailable; try another peer



TestChangefeedSchemaChangeAllowBackfill/enterprise
... startup, expected 20
I181207 14:43:34.776182 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.776704 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.777237 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.777744 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.778312 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.779047 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.779650 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.780314 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.780944 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.781426 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.782040 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.782705 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.783353 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.785052 20600 gossip/gossip.go:1513  [n1] node has connected to cluster via gossip
I181207 14:43:34.785460 20600 storage/stores.go:261  [n1] wrote 0 node addresses to persistent storage
I181207 14:43:34.786555 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.787960 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.789825 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.789828 21029 sql/event_log.go:125  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:38883} Attrs: Locality: ServerVersion:2.1-3 BuildTag:v2.2.0-alpha.20181119-592-geea1707 StartedAt:1544193812562246790 LocalityAddress:[]} ClusterID:38b012bf-02ad-451e-95db-dc0fc5e365ea StartedAt:1544193812562246790 LastUp:1544193812562246790}
I181207 14:43:34.792837 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.797880 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.807216 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.825144 20544 server/testserver.go:420  had 14 ranges at startup, expected 20
I181207 14:43:34.857471 20925 storage/replica_command.go:349  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I181207 14:43:34.869606 20544 server/testserver.go:420  had 15 ranges at startup, expected 20
I181207 14:43:34.924562 20976 storage/replica_command.go:349  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I181207 14:43:34.939819 20544 server/testserver.go:420  had 16 ranges at startup, expected 20
I181207 14:43:35.024595 21059 storage/replica_command.go:349  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I181207 14:43:35.086352 21107 storage/replica_command.go:349  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I181207 14:43:35.099657 20544 server/testserver.go:420  had 18 ranges at startup, expected 20
I181207 14:43:35.161984 21031 storage/replica_command.go:349  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I181207 14:43:35.575889 21040 sql/event_log.go:125  [n1,client=127.0.0.1:43058,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:00:00:00 User:root}
I181207 14:43:35.663907 21040 sql/event_log.go:125  [n1,client=127.0.0.1:43058,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.2 milestone Dec 7, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Dec 7, 2018
@tbg
Copy link
Member

tbg commented Dec 11, 2018

cc @danhhz

@petermattis
Copy link
Collaborator

Duplicate of #33166.

@rolandcrosby rolandcrosby added this to Triage in [DEPRECATED] CDC Dec 19, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@danhhz danhhz

Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
[DEPRECATED] CDC
  
Triage
Milestone
19.1
Development

No branches or pull requests
4 participants
@danhhz @tbg @petermattis @cockroach-teamcity