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 #33166

Closed
cockroach-teamcity opened this issue Dec 14, 2018 · 4 comments · Fixed by #33303
Closed

teamcity: failed test: TestChangefeedSchemaChangeAllowBackfill #33166

cockroach-teamcity opened this issue Dec 14, 2018 · 4 comments · Fixed by #33303
Assignees
@petermattis
Labels
A-cdc Change Data Capture 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/drop_column, TestChangefeedSchemaChangeAllowBackfill/sinkless/multiple_alters, TestChangefeedSchemaChangeAllowBackfill/sinkless/add_column_with_default, TestChangefeedSchemaChangeAllowBackfill/enterprise/add_column_with_default, TestChangefeedSchemaChangeAllowBackfill/rangefeed/multiple_alters, TestChangefeedSchemaChangeAllowBackfill/rangefeed/add_column_computed, TestChangefeedSchemaChangeAllowBackfill/sinkless/add_column_computed, TestChangefeedSchemaChangeAllowBackfill/enterprise, TestChangefeedSchemaChangeAllowBackfill/rangefeed, TestChangefeedSchemaChangeAllowBackfill/enterprise/multiple_alters, TestChangefeedSchemaChangeAllowBackfill/rangefeed/add_column_with_default, TestChangefeedSchemaChangeAllowBackfill, TestChangefeedSchemaChangeAllowBackfill/sinkless/drop_column, TestChangefeedSchemaChangeAllowBackfill/enterprise/add_column_computed, TestChangefeedSchemaChangeAllowBackfill/sinkless

You may want to check for open issues.

#1056354:

TestChangefeedSchemaChangeAllowBackfill/enterprise/multiple_alters
...alters") ver=7:1544804786.472821251,0, refcount=0
I181214 16:21:33.142087 21123 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 62 6}]
I181214 16:21:33.337768 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root] publish: descID=62 (multiple_alters) version=8 mtime=2018-12-14 16:21:33.317305783 +0000 UTC
I181214 16:21:33.450169 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,user=root] Event: "alter_table", target: 62, info: {TableName:d.public.multiple_alters Statement:ALTER TABLE multiple_alters ADD COLUMN d STRING DEFAULT 'dee' User:root MutationID:3 CascadeDroppedViews:[]}
I181214 16:21:33.478474 22123 sql/lease.go:864  new lease: 62("multiple_alters") ver=8:1544804725.305308040,0, refcount=0
I181214 16:21:33.638139 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root,scExec] publish: descID=62 (multiple_alters) version=9 mtime=2018-12-14 16:21:33.637033517 +0000 UTC
I181214 16:21:33.694709 22143 sql/lease.go:864  new lease: 62("multiple_alters") ver=9:1544804733.535986457,0, refcount=0
I181214 16:21:33.724831 21123 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 62 8}]
I181214 16:21:33.801486 21123 sql/backfill.go:131  [n1,client=127.0.0.1:46778,user=root,scExec] Running backfill for "multiple_alters", v=9, m=3
I181214 16:21:33.918833 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root,scExec] publish: descID=62 (multiple_alters) version=10 mtime=2018-12-14 16:21:33.91772177 +0000 UTC
I181214 16:21:34.020603 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,user=root,scExec] Event: "finish_schema_change", target: 62, info: {MutationID:3}
I181214 16:21:34.047002 22172 sql/lease.go:864  new lease: 62("multiple_alters") ver=10:1544804797.395124233,0, refcount=0
I181214 16:21:34.047046 21123 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 62 9}]
I181214 16:21:34.053405 22196 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
E181214 16:21:34.053773 22196 storage/queue.go:844  [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
I181214 16:21:34.104017 21123 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 62 9}]
I181214 16:21:34.452697 21925 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728667166507009 new resolved timestamp 1544804491.586186452,0 is behind by 2.866362132s
I181214 16:21:34.541445 21925 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728667166507009 new resolved timestamp 1544804491.730012337,0 is behind by 2.8113265s
I181214 16:21:34.692519 21925 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728667166507009 new resolved timestamp 1544804492.921139983,0 is behind by 1.771276316s
I181214 16:21:34.877485 21925 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728667166507009 new resolved timestamp 1544804493.917721770,0 is behind by 959.663625ms
I181214 16:21:34.997346 21925 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728667166507009 new resolved timestamp 1544804494.878141544,0 is behind by 119.091966ms
I181214 16:21:35.058636 21925 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728667166507009 new resolved timestamp 1544804494.894043686,0 is behind by 164.472055ms
I181214 16:21:35.256479 21925 ccl/changefeedccl/changefeed_stmt.go:433  [n1] CHANGEFEED job 408728667166507009 returning with error: cannot update progress on canceled job (id 408728667166507009)
I181214 16:21:35.256856 20494 util/stop/stopper.go:536  quiescing; tasks left:
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I181214 16:21:35.260704 20494 util/stop/stopper.go:536  quiescing; tasks left:
1      [async] transport racer
I181214 16:21:35.386735 20721 kv/transport_race.go:113  transport race promotion: ran 22 iterations on up to 4880 requests



TestChangefeedSchemaChangeAllowBackfill/rangefeed/drop_column
...=127.0.0.1:40818,user=root] publish: descID=55 (drop_column) version=2 mtime=2018-12-14 16:21:51.438778541 +0000 UTC
I181214 16:21:51.595383 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root] publish: descID=55 (drop_column) version=2 mtime=2018-12-14 16:21:51.475333969 +0000 UTC
I181214 16:21:51.680825 22989 sql/event_log.go:127  [n1,client=127.0.0.1:40818,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:[]}
I181214 16:21:51.680979 22989 sql/event_log.go:127  [n1,client=127.0.0.1:40818,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:[]}
I181214 16:21:51.698113 23238 ccl/changefeedccl/changefeed_processors.go:549  [n1,client=127.0.0.1:40798,user=root] sinkless feed span [/Table/55/1,/Table/55/2) is behind by 329.072748ms
I181214 16:21:51.753883 23212 sql/lease.go:864  new lease: 55("drop_column") ver=2:1544804849.258775550,0, refcount=0
I181214 16:21:52.039710 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=55 (drop_column) version=3 mtime=2018-12-14 16:21:52.02743157 +0000 UTC
I181214 16:21:52.072022 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=55 (drop_column) version=3 mtime=2018-12-14 16:21:52.038981169 +0000 UTC
I181214 16:21:52.093747 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=55 (drop_column) version=3 mtime=2018-12-14 16:21:52.074951739 +0000 UTC
I181214 16:21:52.166287 23269 sql/lease.go:864  new lease: 55("drop_column") ver=3:1544804886.385931559,0, refcount=0
I181214 16:21:52.191766 22989 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 2}]
I181214 16:21:52.251415 22989 sql/backfill.go:131  [n1,client=127.0.0.1:40818,user=root,scExec] Running backfill for "drop_column", v=3, m=1
I181214 16:21:52.473399 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=55 (drop_column) version=4 mtime=2018-12-14 16:21:52.472286851 +0000 UTC
I181214 16:21:52.599173 22989 sql/event_log.go:127  [n1,client=127.0.0.1:40818,user=root,scExec] Event: "finish_schema_change", target: 55, info: {MutationID:1}
I181214 16:21:52.657790 23180 sql/lease.go:864  new lease: 55("drop_column") ver=4:1544804744.308194388,0, refcount=0
I181214 16:21:52.676908 22989 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 3}]
I181214 16:21:52.701666 23238 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804511.498930516,0 is behind by 1.202537337s
I181214 16:21:52.902059 23238 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804511.700851599,0 is behind by 1.201073827s
I181214 16:21:53.102382 23238 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804511.901143948,0 is behind by 1.201105068s
I181214 16:21:53.302726 23238 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804512.101516044,0 is behind by 1.201025385s
I181214 16:21:53.503179 23238 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804512.301939034,0 is behind by 1.201086954s
I181214 16:21:53.703780 23238 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804512.472286851,0 is behind by 1.231346117s
I181214 16:21:53.911101 23238 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804512.702676457,0 is behind by 1.208311376s



TestChangefeedSchemaChangeAllowBackfill/rangefeed/multiple_alters
...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 22348 [chan receive, 41 minutes]:
github.com/cockroachdb/cockroach/pkg/util/log.(*loggingT).gcDaemon(0xc42252d040)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:1256 +0x8b
created by github.com/cockroachdb/cockroach/pkg/util/log.NewSecondaryLogger
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/secondary_log.go:81 +0x47c

goroutine 22497 [select, 41 minutes]:
github.com/cockroachdb/cockroach/pkg/storage.(*Store).Start.func2(0x45d80e0, 0xc42205f3b0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:1327 +0x14f
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc420521a60, 0xc421d00480, 0xc421ce4280)
	/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 22784 [semacquire, 41 minutes]:
sync.runtime_notifyListWait(0xc420c643d0, 0x3)
	/usr/local/go/src/runtime/sema.go:510 +0x11a
sync.(*Cond).Wait(0xc420c643c0)
	/usr/local/go/src/sync/cond.go:56 +0x8e
github.com/cockroachdb/cockroach/pkg/sql.(*StmtBuf).curCmd(0xc4201f0100, 0x0, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_io.go:432 +0xc3
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run(0xc42010db00, 0x45d8020, 0xc420c64440, 0xc4217e1788, 0x5400, 0x15000, 0xc4217e1828, 0xc420343d10, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1101 +0x643
github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn(0xc4219a3a40, 0x45d8020, 0xc420c64440, 0xc42010db00, 0x5400, 0x15000, 0xc4217e1828, 0xc420343d10, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:406 +0xee
github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).serveImpl.func4(0xc4219a3a40, 0x45d8020, 0xc420c64440, 0xc42010db00, 0x5400, 0x15000, 0xc4217e1828, 0xc420343d10, 0xc420343d20, 0xc421494210)
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:319 +0x95
created by github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).serveImpl
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:318 +0x1516

goroutine 22491 [semacquire, 41 minutes]:
sync.runtime_notifyListWait(0xc42005e690, 0xf4b36315000003be)
	/usr/local/go/src/runtime/sema.go:510 +0x11a
sync.(*Cond).Wait(0xc42005e680)
	/usr/local/go/src/sync/cond.go:56 +0x8e
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc420e3e1b0, 0x45d80e0, 0xc42205f290)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:196 +0x9c
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x45d80e0, 0xc42205f290)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:165 +0x56
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc420521980, 0xc421d00480, 0xc420521970)
	/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 22302 [select, 41 minutes]:
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).initRunners.func1(0x45d80e0, 0xc42133da10)
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:95 +0x1a2
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc4213947f0, 0xc421d00480, 0xc4213947e0)
	/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
--- FAIL: testrace/TestChangefeedSchemaChangeAllowBackfill/sinkless/add_column_computed (0.000s)
Test ended in panic.

------- Stdout: -------
I181214 16:21:07.182312 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root] Event: "create_table", target: 54, info: {TableName:d.public.add_col_comp Statement:CREATE TABLE add_col_comp (a INT8 PRIMARY KEY, b INT8 AS (a + 5) STORED) User:root}
I181214 16:21:07.186373 19943 storage/replica_command.go:349  [n1,split,s1,r22/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r23]
I181214 16:21:07.412362 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root] publish: descID=54 (add_col_comp) version=2 mtime=2018-12-14 16:21:07.364725357 +0000 UTC
I181214 16:21:07.561618 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root] publish: descID=54 (add_col_comp) version=2 mtime=2018-12-14 16:21:07.40630511 +0000 UTC
I181214 16:21:07.644303 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root] Event: "alter_table", target: 54, info: {TableName:d.public.add_col_comp Statement:ALTER TABLE add_col_comp ADD COLUMN c INT8 AS (a + 10) STORED User:root MutationID:1 CascadeDroppedViews:[]}
I181214 16:21:07.644485 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root] Event: "alter_table", target: 54, info: {TableName:d.public.add_col_comp Statement:ALTER TABLE add_col_comp ADD COLUMN c INT8 AS (a + 10) STORED User:root MutationID:1 CascadeDroppedViews:[]}
I181214 16:21:07.694356 19697 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804467.416461442,0 is behind by 277.778381ms
I181214 16:21:07.694611 19697 ccl/changefeedccl/changefeed_processors.go:549  [n1,client=127.0.0.1:40844,user=root] sinkless feed span [/Table/54/1,/Table/54/2) is behind by 277.778381ms
I181214 16:21:07.708143 19947 sql/lease.go:864  new lease: 54("add_col_comp") ver=2:1544804729.544378032,0, refcount=0
I181214 16:21:07.780455 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=54 (add_col_comp) version=3 mtime=2018-12-14 16:21:07.779425472 +0000 UTC
I181214 16:21:07.784360 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=54 (add_col_comp) version=3 mtime=2018-12-14 16:21:07.780356661 +0000 UTC
I181214 16:21:07.861242 19877 sql/lease.go:864  new lease: 54("add_col_comp") ver=3:1544804724.691862111,0, refcount=0
I181214 16:21:07.869532 19784 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 2}]
I181214 16:21:07.923664 19784 sql/backfill.go:131  [n1,client=127.0.0.1:40850,user=root,scExec] Running backfill for "add_col_comp", v=3, m=1
I181214 16:21:08.182018 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=54 (add_col_comp) version=4 mtime=2018-12-14 16:21:08.180978417 +0000 UTC
I181214 16:21:08.291618 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root,scExec] Event: "finish_schema_change", target: 54, info: {MutationID:1}
I181214 16:21:08.312826 19784 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 3}]
I181214 16:21:08.313369 20001 sql/lease.go:864  new lease: 54("add_col_comp") ver=4:1544804738.376258067,0, refcount=0
I181214 16:21:08.395254 19697 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804468.180978417,0 is behind by 214.132596ms



TestChangefeedSchemaChangeAllowBackfill/enterprise/add_column_with_default
...lsink (topic STRING, partition INT8, message_id INT8, key BYTES, value BYTES, resolved BYTES, PRIMARY KEY (topic, partition, message_id)) User:root}
I181214 16:21:21.334242 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root] publish: descID=53 (add_column_def) version=2 mtime=2018-12-14 16:21:21.295170354 +0000 UTC
I181214 16:21:21.363210 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804480.377171133,0 is behind by 985.918559ms
I181214 16:21:21.363447 20971 ccl/changefeedccl/changefeed_processors.go:546  [n1] job 408728635513503745 span [/Table/53/1,/Table/53/2) is behind by 985.918559ms
I181214 16:21:21.429944 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,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:[]}
I181214 16:21:21.436850 21266 sql/lease.go:864  new lease: 53("add_column_def") ver=2:1544804840.429998256,0, refcount=0
I181214 16:21:21.465317 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804481.221871069,0 is behind by 243.331573ms
I181214 16:21:21.581731 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804481.365211573,0 is behind by 216.396157ms
I181214 16:21:21.680744 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root,scExec] publish: descID=53 (add_column_def) version=3 mtime=2018-12-14 16:21:21.679632927 +0000 UTC
I181214 16:21:21.685930 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804481.466857419,0 is behind by 218.961931ms
I181214 16:21:21.754920 21193 sql/lease.go:864  new lease: 53("add_column_def") ver=3:1544804741.952313655,0, refcount=0
I181214 16:21:21.758771 21123 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 2}]
I181214 16:21:21.830374 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804481.583404893,0 is behind by 246.860867ms
I181214 16:21:21.859951 21123 sql/backfill.go:131  [n1,client=127.0.0.1:46778,user=root,scExec] Running backfill for "add_column_def", v=3, m=1
I181214 16:21:21.964701 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804481.695883092,0 is behind by 268.677206ms
I181214 16:21:22.052235 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root,scExec] publish: descID=53 (add_column_def) version=4 mtime=2018-12-14 16:21:22.051246725 +0000 UTC
I181214 16:21:22.126268 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804481.843327391,0 is behind by 282.825768ms
I181214 16:21:22.218603 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804481.965347795,0 is behind by 253.137383ms
I181214 16:21:22.270814 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,user=root,scExec] Event: "finish_schema_change", target: 53, info: {MutationID:1}
I181214 16:21:22.286339 21123 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181214 16:21:22.303514 21287 sql/lease.go:864  new lease: 53("add_column_def") ver=4:1544804807.943052259,0, refcount=0
I181214 16:21:22.347919 21123 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181214 16:21:22.412813 21123 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181214 16:21:22.470782 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804482.051246725,0 is behind by 419.41312ms
I181214 16:21:22.631202 20971 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728635513503745 new resolved timestamp 1544804482.490194810,0 is behind by 140.879185ms



TestChangefeedSchemaChangeAllowBackfill/sinkless/multiple_alters
...:21:13.964421 19784 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 56 6}]
I181214 16:21:13.967050 20396 sql/lease.go:864  new lease: 56("multiple_alters") ver=7:1544804726.051127826,0, refcount=0
I181214 16:21:14.250619 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root] publish: descID=56 (multiple_alters) version=8 mtime=2018-12-14 16:21:14.193515983 +0000 UTC
I181214 16:21:14.339834 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root] Event: "alter_table", target: 56, info: {TableName:d.public.multiple_alters Statement:ALTER TABLE multiple_alters ADD COLUMN d STRING DEFAULT 'dee' User:root MutationID:3 CascadeDroppedViews:[]}
I181214 16:21:14.421453 20398 sql/lease.go:864  new lease: 56("multiple_alters") ver=8:1544804822.514445076,0, refcount=0
I181214 16:21:14.511438 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=56 (multiple_alters) version=9 mtime=2018-12-14 16:21:14.510381188 +0000 UTC
I181214 16:21:14.570318 20401 sql/lease.go:864  new lease: 56("multiple_alters") ver=9:1544804795.074842480,0, refcount=0
I181214 16:21:14.672568 19784 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 56 8}]
I181214 16:21:14.708372 19784 sql/backfill.go:131  [n1,client=127.0.0.1:40850,user=root,scExec] Running backfill for "multiple_alters", v=9, m=3
I181214 16:21:14.909674 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=56 (multiple_alters) version=10 mtime=2018-12-14 16:21:14.908608224 +0000 UTC
I181214 16:21:15.053813 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root,scExec] Event: "finish_schema_change", target: 56, info: {MutationID:3}
I181214 16:21:15.121892 20546 sql/lease.go:864  new lease: 56("multiple_alters") ver=10:1544804763.212765857,0, refcount=0
I181214 16:21:15.163451 19784 sql/lease.go:307  publish (1 leases): desc=[{multiple_alters 56 9}]
I181214 16:21:15.328471 20273 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804471.775669229,0 is behind by 3.552660428s
I181214 16:21:15.481608 20273 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804472.118791157,0 is behind by 3.362705264s
I181214 16:21:15.493947 20273 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804473.645979525,0 is behind by 1.847852347s
I181214 16:21:15.519254 20273 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804474.908608224,0 is behind by 610.46679ms
I181214 16:21:15.530450 19143 util/stop/stopper.go:536  quiescing; tasks left:
1      node.Node: batch
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
1      [async] closedts-rangefeed-subscriber
I181214 16:21:15.538871 19143 util/stop/stopper.go:536  quiescing; tasks left:
1      node.Node: batch
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
I181214 16:21:15.541921 19143 util/stop/stopper.go:536  quiescing; tasks left:
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
W181214 16:21:15.542654 20562 internal/client/txn.go:507  [intExec=lease-release] failure aborting transaction: node unavailable; try another peer; abort caused by: result is ambiguous (server shutdown)
W181214 16:21:15.543495 20537 sql/lease.go:255  error releasing lease &{'8' '\n' {{%!q(uint64=570893000) %!q(int64=63680401561) %!q(*time.Location=<nil>)}}}: lease-release: result is ambiguous (server shutdown)
I181214 16:21:15.543816 19143 util/stop/stopper.go:536  quiescing; tasks left:
1      [async] transport racer
I181214 16:21:15.888898 19427 kv/transport_race.go:113  transport race promotion: ran 47 iterations on up to 3446 requests



TestChangefeedSchemaChangeAllowBackfill/enterprise
...es at startup, expected 21
I181214 16:21:18.808365 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.809341 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.810361 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.811386 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.812341 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.829349 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.836160 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.844233 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.852113 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.855992 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.857079 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.858382 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.860186 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.871328 21004 server/server_update.go:66  [n1] no need to upgrade, cluster already at the newest version
I181214 16:21:18.871910 20494 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:18.880863 21034 sql/event_log.go:127  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:44699} Attrs: Locality: ServerVersion:2.1-3 BuildTag:v2.2.0-alpha.20181119-768-g542db5a StartedAt:1544804476591438237 LocalityAddress:[]} ClusterID:c96465dd-1270-449c-aa44-c14e72da4428 StartedAt:1544804476591438237 LastUp:1544804476591438237}
I181214 16:21:18.902732 20630 gossip/gossip.go:1513  [n1] node has connected to cluster via gossip
I181214 16:21:18.903278 20630 storage/stores.go:261  [n1] wrote 0 node addresses to persistent storage
I181214 16:21:18.938241 21019 storage/replica_command.go:349  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I181214 16:21:18.977947 20494 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:18.988807 20941 storage/replica_command.go:349  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I181214 16:21:18.991643 20494 server/testserver.go:420  had 16 ranges at startup, expected 21
I181214 16:21:19.009547 20494 server/testserver.go:420  had 16 ranges at startup, expected 21
I181214 16:21:19.073035 20945 storage/replica_command.go:349  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I181214 16:21:19.102674 20494 server/testserver.go:420  had 17 ranges at startup, expected 21
I181214 16:21:19.187910 21081 storage/replica_command.go:349  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I181214 16:21:19.194827 20494 server/testserver.go:420  had 18 ranges at startup, expected 21
I181214 16:21:19.253795 20987 storage/replica_command.go:349  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I181214 16:21:19.362558 20494 server/testserver.go:420  had 19 ranges at startup, expected 21
I181214 16:21:19.383017 21087 storage/replica_command.go:349  [n1,split,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/24 [r21]
I181214 16:21:19.873214 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:00:00:00.01 User:root}
I181214 16:21:19.957545 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}



TestChangefeedSchemaChangeAllowBackfill/enterprise/add_column_computed
...solved timestamp 1544804484.270399443,0 is behind by 220.463831ms
I181214 16:21:24.599600 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,user=root] Event: "alter_table", target: 56, info: {TableName:d.public.add_col_comp Statement:ALTER TABLE add_col_comp ADD COLUMN c INT8 AS (a + 10) STORED User:root MutationID:1 CascadeDroppedViews:[]}
I181214 16:21:24.654051 21522 sql/lease.go:864  new lease: 56("add_col_comp") ver=2:1544804778.864257918,0, refcount=0
I181214 16:21:24.654545 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804484.384298869,0 is behind by 270.100549ms
I181214 16:21:24.775052 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804484.491298299,0 is behind by 283.636936ms
I181214 16:21:24.835359 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804484.656260609,0 is behind by 178.836645ms
I181214 16:21:24.907479 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root,scExec] publish: descID=56 (add_col_comp) version=3 mtime=2018-12-14 16:21:24.906303889 +0000 UTC
I181214 16:21:24.953198 21321 sql/lease.go:864  new lease: 56("add_col_comp") ver=3:1544804725.848659328,0, refcount=0
I181214 16:21:24.955707 21123 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 56 2}]
I181214 16:21:24.976546 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804484.778143947,0 is behind by 198.280327ms
I181214 16:21:25.095650 21123 sql/backfill.go:131  [n1,client=127.0.0.1:46778,user=root,scExec] Running backfill for "add_col_comp", v=3, m=1
I181214 16:21:25.167036 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804484.839012496,0 is behind by 327.907719ms
I181214 16:21:25.292230 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804484.976868868,0 is behind by 315.250259ms
I181214 16:21:25.358547 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804485.168740886,0 is behind by 189.688588ms
I181214 16:21:25.455435 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804485.298777345,0 is behind by 156.537578ms
I181214 16:21:25.502912 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804485.359746994,0 is behind by 143.04792ms
I181214 16:21:25.565032 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root,scExec] publish: descID=56 (add_col_comp) version=4 mtime=2018-12-14 16:21:25.563953771 +0000 UTC
I181214 16:21:25.593973 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804485.459428614,0 is behind by 134.435818ms
I181214 16:21:25.689989 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,user=root,scExec] Event: "finish_schema_change", target: 56, info: {MutationID:1}
I181214 16:21:25.714435 21123 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 56 3}]
I181214 16:21:25.719396 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804485.505367351,0 is behind by 213.92214ms
I181214 16:21:25.751289 21423 sql/lease.go:864  [n1] new lease: 56("add_col_comp") ver=4:1544804853.594961776,0, refcount=0
I181214 16:21:25.788948 21123 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 56 3}]
I181214 16:21:25.898356 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804485.563953771,0 is behind by 334.290684ms
I181214 16:21:26.041116 21056 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728644897439745 new resolved timestamp 1544804485.899495921,0 is behind by 141.505637ms



TestChangefeedSchemaChangeAllowBackfill/rangefeed
...4 16:21:38.217412 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.218106 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.219113 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.220046 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.220986 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.221950 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.224991 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.226321 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.228318 22294 server/testserver.go:420  had 13 ranges at startup, expected 21
I181214 16:21:38.292007 22736 storage/replica_command.go:349  [n1,split,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I181214 16:21:38.312086 22294 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:38.319059 22294 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:38.329010 22294 server/testserver.go:420  had 14 ranges at startup, expected 21
I181214 16:21:38.363552 22771 storage/replica_command.go:349  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I181214 16:21:38.415454 22294 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:38.433862 22776 storage/replica_command.go:349  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I181214 16:21:38.450278 22294 server/testserver.go:420  had 16 ranges at startup, expected 21
I181214 16:21:38.515874 22778 storage/replica_command.go:349  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I181214 16:21:38.522712 22294 server/testserver.go:420  had 17 ranges at startup, expected 21
I181214 16:21:38.610430 22818 storage/replica_command.go:349  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I181214 16:21:38.672932 22806 storage/replica_command.go:349  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I181214 16:21:38.683857 22294 server/testserver.go:420  had 19 ranges at startup, expected 21
I181214 16:21:38.717440 22829 storage/replica_command.go:349  [n1,split,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/24 [r21]
I181214 16:21:39.345643 22784 sql/event_log.go:127  [n1,client=127.0.0.1:40792,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:00:00:00.01 User:root}
I181214 16:21:39.433051 22784 sql/event_log.go:127  [n1,client=127.0.0.1:40792,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:sql.defaults.results_buffer.size Value:0 User:root}
I181214 16:21:39.501566 22784 sql/event_log.go:127  [n1,client=127.0.0.1:40792,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I181214 16:21:39.811968 22703 sql/event_log.go:127  [n1,client=127.0.0.1:40798,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:kv.rangefeed.enabled Value:true User:root}
I181214 16:21:39.917013 22703 sql/event_log.go:127  [n1,client=127.0.0.1:40798,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:kv.closed_timestamp.target_duration Value:00:00:01 User:root}
I181214 16:21:43.098313 22294 ccl/changefeedccl/helpers_test.go:693  SucceedsSoon: r21:/{Table/24-Max} [(n1,s1):1, next=2, gen=0] does not have an epoch lease: should resolve in 1.757691074s
I181214 16:21:44.100927 22294 ccl/changefeedccl/helpers_test.go:693  SucceedsSoon: r21:/{Table/24-Max} [(n1,s1):1, next=2, gen=0] does not have an epoch lease: should resolve in 755.085492ms



TestChangefeedSchemaChangeAllowBackfill/rangefeed/add_column_computed
...:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r23]
I181214 16:21:48.811497 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root] publish: descID=54 (add_col_comp) version=2 mtime=2018-12-14 16:21:48.752185098 +0000 UTC
I181214 16:21:48.877925 22996 ccl/changefeedccl/changefeed_processors.go:549  [n1,client=127.0.0.1:40798,user=root] sinkless feed span [/Table/54/1,/Table/54/2) is behind by 181.639517ms
I181214 16:21:48.977687 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root] publish: descID=54 (add_col_comp) version=2 mtime=2018-12-14 16:21:48.807366356 +0000 UTC
I181214 16:21:49.107908 22989 sql/event_log.go:127  [n1,client=127.0.0.1:40818,user=root] Event: "alter_table", target: 54, info: {TableName:d.public.add_col_comp Statement:ALTER TABLE add_col_comp ADD COLUMN c INT8 AS (a + 10) STORED User:root MutationID:1 CascadeDroppedViews:[]}
I181214 16:21:49.113178 22989 sql/event_log.go:127  [n1,client=127.0.0.1:40818,user=root] Event: "alter_table", target: 54, info: {TableName:d.public.add_col_comp Statement:ALTER TABLE add_col_comp ADD COLUMN c INT8 AS (a + 10) STORED User:root MutationID:1 CascadeDroppedViews:[]}
I181214 16:21:49.133392 23081 sql/lease.go:864  new lease: 54("add_col_comp") ver=2:1544804831.146936492,0, refcount=0
I181214 16:21:49.287825 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=54 (add_col_comp) version=3 mtime=2018-12-14 16:21:49.286549637 +0000 UTC
I181214 16:21:49.321718 23004 sql/lease.go:864  new lease: 54("add_col_comp") ver=3:1544804801.216500763,0, refcount=0
I181214 16:21:49.339321 22989 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 2}]
I181214 16:21:49.388120 22989 sql/backfill.go:131  [n1,client=127.0.0.1:40818,user=root,scExec] Running backfill for "add_col_comp", v=3, m=1
I181214 16:21:49.543004 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=54 (add_col_comp) version=4 mtime=2018-12-14 16:21:49.541858924 +0000 UTC
I181214 16:21:49.693353 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=54 (add_col_comp) version=4 mtime=2018-12-14 16:21:49.543320364 +0000 UTC
I181214 16:21:49.769312 22989 sql/event_log.go:127  [n1,client=127.0.0.1:40818,user=root,scExec] Event: "finish_schema_change", target: 54, info: {MutationID:1}
I181214 16:21:49.795674 22989 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 3}]
I181214 16:21:49.806345 23170 sql/lease.go:864  new lease: 54("add_col_comp") ver=4:1544804776.929643337,0, refcount=0
I181214 16:21:49.839859 22989 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 3}]
I181214 16:21:49.915686 22989 sql/lease.go:307  publish (1 leases): desc=[{add_col_comp 54 3}]
I181214 16:21:50.090834 22996 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804508.889644022,0 is behind by 1.201055842s
I181214 16:21:50.291548 22996 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804509.089943827,0 is behind by 1.20148051s
I181214 16:21:50.491855 22996 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804509.290809811,0 is behind by 1.200923555s
I181214 16:21:50.692108 22996 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804509.491050714,0 is behind by 1.200922407s
I181214 16:21:50.895977 22996 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804509.543320364,1 is behind by 1.352526311s
I181214 16:21:51.106854 22996 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804509.894927095,0 is behind by 1.211787541s



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

------- Stdout: -------
I181214 16:21:04.999725 19632 storage/replica_command.go:349  [n1,split,s1,r21/1:/{Table/24-Max}] initiating a split of this range at key /Table/53 [r22]
I181214 16:21:05.002209 19748 sql/event_log.go:127  [n1,client=127.0.0.1:40844,user=root] Event: "create_table", target: 53, info: {TableName:d.public.add_column_def Statement:CREATE TABLE add_column_def (a INT8 PRIMARY KEY) User:root}
I181214 16:21:05.793223 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root] publish: descID=53 (add_column_def) version=2 mtime=2018-12-14 16:21:05.709192395 +0000 UTC
I181214 16:21:06.033341 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root] publish: descID=53 (add_column_def) version=2 mtime=2018-12-14 16:21:05.773524417 +0000 UTC
I181214 16:21:06.250173 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,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:[]}
I181214 16:21:06.250330 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,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:[]}
I181214 16:21:06.284869 19709 sql/lease.go:864  new lease: 53("add_column_def") ver=2:1544804834.813077936,0, refcount=0
I181214 16:21:06.290311 19754 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804465.808881329,0 is behind by 481.303607ms
I181214 16:21:06.290538 19754 ccl/changefeedccl/changefeed_processors.go:549  [n1,client=127.0.0.1:40844,user=root] sinkless feed span [/Table/53/1,/Table/53/2) is behind by 481.303607ms
I181214 16:21:06.460264 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=53 (add_column_def) version=3 mtime=2018-12-14 16:21:06.459272845 +0000 UTC
I181214 16:21:06.511020 19771 sql/lease.go:864  new lease: 53("add_column_def") ver=3:1544804839.571641384,0, refcount=0
I181214 16:21:06.537787 19784 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 2}]
I181214 16:21:06.601010 19784 sql/backfill.go:131  [n1,client=127.0.0.1:40850,user=root,scExec] Running backfill for "add_column_def", v=3, m=1
I181214 16:21:06.886297 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=53 (add_column_def) version=4 mtime=2018-12-14 16:21:06.885251895 +0000 UTC
I181214 16:21:06.969705 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root,scExec] Event: "finish_schema_change", target: 53, info: {MutationID:1}
I181214 16:21:06.981155 19777 sql/lease.go:864  new lease: 53("add_column_def") ver=4:1544804768.467867443,0, refcount=0
I181214 16:21:07.024295 19754 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804466.885251895,0 is behind by 138.925546ms



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

------- Stdout: -------
I181214 16:21:08.590628 19965 storage/replica_command.go:349  [n1,split,s1,r23/1:/{Table/54-Max}] initiating a split of this range at key /Table/55 [r24]
I181214 16:21:08.637064 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root] Event: "create_table", target: 55, info: {TableName:d.public.drop_column Statement:CREATE TABLE drop_column (a INT8 PRIMARY KEY, b STRING) User:root}
I181214 16:21:08.908263 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root] publish: descID=55 (drop_column) version=2 mtime=2018-12-14 16:21:08.833318545 +0000 UTC
I181214 16:21:09.097829 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root] publish: descID=55 (drop_column) version=2 mtime=2018-12-14 16:21:08.908579228 +0000 UTC
I181214 16:21:09.173123 20100 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804468.918718765,0 is behind by 254.280706ms
I181214 16:21:09.173335 20100 ccl/changefeedccl/changefeed_processors.go:549  [n1,client=127.0.0.1:40844,user=root] sinkless feed span [/Table/55/1,/Table/55/2) is behind by 254.280706ms
I181214 16:21:09.215666 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,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:[]}
I181214 16:21:09.216619 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,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:[]}
I181214 16:21:09.247861 20115 sql/lease.go:864  new lease: 55("drop_column") ver=2:1544804840.085055826,0, refcount=0
I181214 16:21:09.457952 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=55 (drop_column) version=3 mtime=2018-12-14 16:21:09.456789461 +0000 UTC
I181214 16:21:09.519439 20179 sql/lease.go:864  new lease: 55("drop_column") ver=3:1544804791.952134150,0, refcount=0
I181214 16:21:09.530527 19784 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 2}]
I181214 16:21:09.661047 19784 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 2}]
I181214 16:21:09.764190 19784 sql/backfill.go:131  [n1,client=127.0.0.1:40850,user=root,scExec] Running backfill for "drop_column", v=3, m=1
I181214 16:21:10.120148 19784 sql/lease.go:335  [n1,client=127.0.0.1:40850,user=root,scExec] publish: descID=55 (drop_column) version=4 mtime=2018-12-14 16:21:10.119203553 +0000 UTC
I181214 16:21:10.269499 20274 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
E181214 16:21:10.270000 20274 storage/queue.go:844  [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
I181214 16:21:10.282087 19784 sql/event_log.go:127  [n1,client=127.0.0.1:40850,user=root,scExec] Event: "finish_schema_change", target: 55, info: {MutationID:1}
I181214 16:21:10.321630 20129 sql/lease.go:864  new lease: 55("drop_column") ver=4:1544804708.446734243,0, refcount=0
I181214 16:21:10.360318 19784 sql/lease.go:307  publish (1 leases): desc=[{drop_column 55 3}]
I181214 16:21:10.418303 20100 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40844,user=root] sinkless feed new resolved timestamp 1544804470.119203553,0 is behind by 298.987483ms



TestChangefeedSchemaChangeAllowBackfill/rangefeed/add_column_with_default
....0.0.1:40818,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:[]}
I181214 16:21:45.901881 22989 sql/event_log.go:127  [n1,client=127.0.0.1:40818,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:[]}
I181214 16:21:45.945136 22967 sql/lease.go:864  new lease: 53("add_column_def") ver=2:1544804751.835146121,0, refcount=0
I181214 16:21:45.947786 22512 server/status/runtime.go:464  [n1] runtime stats: 492 MiB RSS, 247 goroutines, 13 MiB/25 MiB/56 MiB GO alloc/idle/total, 37 MiB/81 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (233x), 2.3 MiB/2.3 MiB (r/w)net
I181214 16:21:46.279762 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=53 (add_column_def) version=3 mtime=2018-12-14 16:21:46.278485718 +0000 UTC
I181214 16:21:46.326503 22989 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 2}]
I181214 16:21:46.359948 22938 sql/lease.go:864  new lease: 53("add_column_def") ver=3:1544804763.402465049,0, refcount=0
I181214 16:21:46.462116 22989 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 2}]
I181214 16:21:46.537913 22989 sql/backfill.go:131  [n1,client=127.0.0.1:40818,user=root,scExec] Running backfill for "add_column_def", v=3, m=1
I181214 16:21:46.654889 22897 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804505.453707184,0 is behind by 1.201052144s
I181214 16:21:46.751142 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=53 (add_column_def) version=4 mtime=2018-12-14 16:21:46.749926258 +0000 UTC
I181214 16:21:46.855073 22897 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804505.653960863,0 is behind by 1.200976268s
I181214 16:21:46.860287 22989 sql/lease.go:335  [n1,client=127.0.0.1:40818,user=root,scExec] publish: descID=53 (add_column_def) version=4 mtime=2018-12-14 16:21:46.751448324 +0000 UTC
I181214 16:21:47.043956 22989 sql/event_log.go:127  [n1,client=127.0.0.1:40818,user=root,scExec] Event: "finish_schema_change", target: 53, info: {MutationID:1}
I181214 16:21:47.055977 22897 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804505.854246662,0 is behind by 1.201574177s
I181214 16:21:47.165998 22989 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181214 16:21:47.169831 22862 sql/lease.go:864  new lease: 53("add_column_def") ver=4:1544804832.423102019,0, refcount=0
I181214 16:21:47.251766 22989 sql/lease.go:307  publish (1 leases): desc=[{add_column_def 53 3}]
I181214 16:21:47.258651 22897 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804506.054992384,0 is behind by 1.20346044s
I181214 16:21:47.459061 22897 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804506.257756128,0 is behind by 1.201162032s
I181214 16:21:47.660129 22897 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804506.458036270,0 is behind by 1.201965069s
I181214 16:21:47.860417 22897 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804506.659278075,0 is behind by 1.201006503s
I181214 16:21:48.060927 22897 ccl/changefeedccl/changefeed_processors.go:537  [n1,client=127.0.0.1:40798,user=root] sinkless feed new resolved timestamp 1544804506.751448324,1 is behind by 1.309356872s



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




TestChangefeedSchemaChangeAllowBackfill/sinkless
...er.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.613141 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.613855 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.614407 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.629701 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.636509 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.639212 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.639790 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.640313 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.640840 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.641403 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.641939 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.642700 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.643819 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.644457 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.645090 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.647680 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.648471 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.649363 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.650950 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.671261 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.674366 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.679487 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.688851 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.706556 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.741144 19143 server/testserver.go:420  had 15 ranges at startup, expected 21
I181214 16:21:03.771733 19583 storage/replica_command.go:349  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I181214 16:21:03.812815 19143 server/testserver.go:420  had 16 ranges at startup, expected 21
I181214 16:21:03.869246 19682 storage/replica_command.go:349  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I181214 16:21:03.951528 19143 server/testserver.go:420  had 17 ranges at startup, expected 21
I181214 16:21:04.014137 19661 storage/replica_command.go:349  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I181214 16:21:04.089772 19643 storage/replica_command.go:349  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I181214 16:21:04.196793 19672 storage/replica_command.go:349  [n1,split,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/24 [r21]
I181214 16:21:04.463046 19626 sql/event_log.go:127  [n1,client=127.0.0.1:40838,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:00:00:00.01 User:root}
I181214 16:21:04.556859 19626 sql/event_log.go:127  [n1,client=127.0.0.1:40838,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:sql.defaults.results_buffer.size Value:0 User:root}
I181214 16:21:04.640512 19626 sql/event_log.go:127  [n1,client=127.0.0.1:40838,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}



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




TestChangefeedSchemaChangeAllowBackfill/enterprise/drop_column
...ER TABLE drop_column DROP COLUMN b User:root MutationID:1 CascadeDroppedViews:[]}
I181214 16:21:27.864351 21641 sql/lease.go:864  new lease: 59("drop_column") ver=2:1544804741.819118887,0, refcount=0
I181214 16:21:28.036993 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804487.689631713,0 is behind by 347.252771ms
I181214 16:21:28.112318 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root,scExec] publish: descID=59 (drop_column) version=3 mtime=2018-12-14 16:21:28.087190557 +0000 UTC
I181214 16:21:28.131342 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804487.922984690,0 is behind by 208.225634ms
I181214 16:21:28.154645 21123 sql/lease.go:307  publish (1 leases): desc=[{drop_column 59 2}]
I181214 16:21:28.196509 21677 sql/lease.go:864  new lease: 59("drop_column") ver=3:1544804737.743211137,0, refcount=0
I181214 16:21:28.222933 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804488.049352477,0 is behind by 173.469761ms
I181214 16:21:28.251394 21123 sql/lease.go:307  publish (1 leases): desc=[{drop_column 59 2}]
I181214 16:21:28.308133 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804488.137651492,0 is behind by 170.382307ms
I181214 16:21:28.318503 21123 sql/backfill.go:131  [n1,client=127.0.0.1:46778,user=root,scExec] Running backfill for "drop_column", v=3, m=1
I181214 16:21:28.404266 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804488.226989565,0 is behind by 177.167527ms
I181214 16:21:28.549338 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804488.323375305,0 is behind by 225.842548ms
I181214 16:21:28.671557 21123 sql/lease.go:335  [n1,client=127.0.0.1:46778,user=root,scExec] publish: descID=59 (drop_column) version=4 mtime=2018-12-14 16:21:28.670505931 +0000 UTC
I181214 16:21:28.709844 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804488.415416429,0 is behind by 294.310214ms
I181214 16:21:28.803708 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804488.550358244,0 is behind by 253.214634ms
I181214 16:21:28.896436 21123 sql/event_log.go:127  [n1,client=127.0.0.1:46778,user=root,scExec] Event: "finish_schema_change", target: 59, info: {MutationID:1}
I181214 16:21:28.937693 21842 sql/lease.go:864  [n1] new lease: 59("drop_column") ver=4:1544804832.117216839,0, refcount=0
I181214 16:21:28.975019 21123 sql/lease.go:307  publish (1 leases): desc=[{drop_column 59 3}]
I181214 16:21:29.051381 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804488.670505931,0 is behind by 380.765042ms
I181214 16:21:29.056822 21123 sql/lease.go:307  publish (1 leases): desc=[{drop_column 59 3}]
I181214 16:21:29.272640 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804489.063296920,0 is behind by 209.220628ms
I181214 16:21:29.371261 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804489.086639333,0 is behind by 284.480019ms
I181214 16:21:29.420256 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804489.273688156,0 is behind by 146.463874ms
I181214 16:21:29.479727 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804489.372107482,0 is behind by 107.497576ms
I181214 16:21:29.552546 21687 ccl/changefeedccl/changefeed_processors.go:534  [n1] job 408728656723574785 new resolved timestamp 1544804489.420570601,0 is behind by 131.889727ms

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.2 milestone Dec 14, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Dec 14, 2018
@tbg tbg added the A-cdc Change Data Capture label Dec 17, 2018
This was referenced Dec 19, 2018
Closed
Closed
Closed
@petermattis petermattis assigned petermattis and unassigned danhhz Dec 19, 2018
@petermattis
Copy link
Collaborator

I'm investigating this failure as part of #29569.

@petermattis
Copy link
Collaborator

I think something is getting wedged in this test. We give the make testrace invocation a 45m timeout and the failures occur a little over 45m after the start of testing. I reproduced a timeout while running:

make roachprod-stress PKG=./ccl/changefeedccl/ TESTS=TestChangefeedSchemaChangeAllowBackfill CLUSTER=peter-stress

Something strange from the stack traces is that I can't find a goroutine still running the test. I do see a goroutine stuck in Stopper.Stop():

goroutine 2737 [semacquire, 7 minutes]:
sync.runtime_notifyListWait(0xc4215f0790, 0xc400000001)
	/usr/local/go/src/runtime/sema.go:510 +0x10b
sync.(*Cond).Wait(0xc4215f0780)
	/usr/local/go/src/sync/cond.go:56 +0x80
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Quiesce(0xc421000d80, 0x34c6620, 0xc4200da050)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:538 +0x1d1
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Stop(0xc421000d80, 0x34c6620, 0xc4200da050)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:475 +0x202
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.sinklessTest.func1(0xc420cd2870)
	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/helpers_test.go:758 +0x5e7
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.rangefeedTest.func1(0xc420cd2870)
	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/helpers_test.go:808 +0x8a
testing.tRunner(0xc420cd2870, 0xc42054af20)
	/usr/local/go/src/testing/testing.go:777 +0xd0
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:824 +0x2e0

Is something not getting shut down correctly?

@petermattis
Copy link
Collaborator

This looks like the offending goroutine:

goroutine 3697 [semacquire, 7 minutes]:
sync.runtime_Semacquire(0xc4216a0f14)
	/usr/local/go/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc4216a0f08)
	/usr/local/go/src/sync/waitgroup.go:129 +0x72
github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Wait(0xc4216a0f00, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:40 +0x31
github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.Wait(0xc4216a0f00, 0x34c65e0, 0xc4216a0ec0, 0xc4205422d0, 0xc4216a0ec0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:146 +0x57
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.(*poller).RunUsingRangefeeds(0xc421117a40, 0x34c65e0, 0xc4216a0e80, 0x9c1a99, 0xc421868d70)
	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/poller.go:199 +0x137
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.(*changeAggregator).Start.func1(0x34c65e0, 0xc4216a0e80)
	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_processors.go:173 +0xb7
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc421000d80, 0x34c65e0, 0xc4216a0e80, 0xc4203dbd40, 0x19, 0x34f6ea0, 0xc42054b020, 0xc42051b6d0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:323 +0xe6
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:318 +0x133

@petermattis
Copy link
Collaborator

More precisely:

goroutine 4017 [semacquire, 7 minutes]:
sync.runtime_Semacquire(0xc421030914)
	/usr/local/go/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc421030908)
	/usr/local/go/src/sync/waitgroup.go:129 +0x72
github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Wait(0xc421030900, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:40 +0x31
github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.Wait(0xc421030900, 0x34c65e0, 0xc4210308c0, 0xc421028cc0, 0xc4210308c0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:146 +0x57
github.com/cockroachdb/cockroach/pkg/kv.(*DistSender).RangeFeed(0xc4216f4a00, 0x34c65e0, 0xc421030740, 0xc421976240, 0xc421028b40, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/dist_sender_rangefeed.go:55 +0x332
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.(*poller).rangefeedImpl.func1(0x34c65e0, 0xc421030740, 0x0, 0xc420ff3790)
	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/poller.go:267 +0x50
github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1(0x8, 0x3068380)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:170 +0x3a
github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1(0xc4210307c0, 0xc420f92120)
	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57 +0x57
created by github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go
	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:54 +0x66

I'm not seeing anything here that looks for the stopper to be shut down.

This was referenced Dec 19, 2018
Closed
Closed
petermattis added a commit to petermattis/cockroach that referenced this issue Dec 19, 2018
@petermattis
ccl/changefeedccl: deflake TestChangefeedSchemaChangeAllowBackfill
0b1a649 
Any goroutine started via `Stopper.RunAsyncTask` needs to watch
`Stopper.ShouldQuiesce()` to determine if it should stop
processing. This wasn't being done properly for the "changefeed-poller"
task causing the test to fail to exit in rare circumstances.

Fixes cockroachdb#33166

Release note: None
@rolandcrosby rolandcrosby added this to Triage in [DEPRECATED] CDC Dec 19, 2018
This was referenced Dec 19, 2018
Closed
Closed
petermattis added a commit to petermattis/cockroach that referenced this issue Dec 20, 2018
@petermattis
storage: fix a deadlock in rangefeed teardown
8af894d 
Fix two related deadlocks in rangefeed teardown. The error
channel (`errC`) used by `Processor.Register` to indicate a rangefeed
processor is closed needs to be buffered because the caller of
`Processor.Register` is the reader of this channel. Similarly, we need
to consider that processing might have already placed on error on `errC`
and that a reader might never read the "closed" error that
`Processor.Register` is trying to send.

Fixes cockroachdb#33166

Release note: None
@petermattis petermattis mentioned this issue Dec 20, 2018
Merged
craig bot pushed a commit that referenced this issue Dec 20, 2018
@petermattis
Merge #33303
41fd36c 
33303: storage: fix a deadlock in rangefeed teardown r=mrtracy a=petermattis

Fix two related deadlocks in rangefeed teardown. The error
channel (`errC`) used by `Processor.Register` to indicate a rangefeed
processor is closed needs to be buffered because the caller of
`Processor.Register` is the reader of this channel. Similarly, we need
to consider that processing might have already placed on error on `errC`
and that a reader might never read the "closed" error that
`Processor.Register` is trying to send.

Fixes #33166

Release note: None

Co-authored-by: Peter Mattis <petermattis@gmail.com>
@craig craig bot closed this as completed in #33303 Dec 20, 2018
@danhhz danhhz mentioned this issue Dec 26, 2018
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@petermattis petermattis

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

Successfully merging a pull request may close this issue.

storage: fix a deadlock in rangefeed teardown petermattis/cockroach
4 participants
@danhhz @tbg @petermattis @cockroach-teamcity