Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

teamcity: failed tests on master: testrace/TestChangefeedRetryableSinkError #30176

Closed
cockroach-teamcity opened this issue Sep 13, 2018 · 1 comment
Closed

teamcity: failed tests on master: testrace/TestChangefeedRetryableSinkError #30176

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

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#901472:

--- FAIL: testrace/TestChangefeedRetryableSinkError (64.190s)
soon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10715 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc42185a240, 0x3dde6c0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e3df60, 0xc4210b6000, 0xc421f9f360)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc4210b6000)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc4210b6000, 0x3779930)
		/usr/local/go/src/testing/testing.go:777 +0x16e
	created by testing.(*T).Run
		/usr/local/go/src/testing/testing.go:824 +0x565
------- Stdout: -------
W180913 03:07:07.679894 10715 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180913 03:07:07.732807 10715 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180913 03:07:07.733310 10715 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 03:07:07.733416 10715 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 03:07:07.738179 10715 server/config.go:493  [n?] 1 storage engine initialized
I180913 03:07:07.738249 10715 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180913 03:07:07.738312 10715 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180913 03:07:07.781572 10715 util/stop/stopper.go:537  [n?] quiescing; tasks left:
1      [async] storage.pendingLeaseRequest: requesting lease
I180913 03:07:07.785485 10715 server/node.go:374  [n?] **** cluster fe7a24b3-c02c-457c-848c-2e7c97e532d3 has been created
I180913 03:07:07.785705 10715 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:41053
I180913 03:07:07.786882 10715 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:41053" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-780-g4d3d9f7" started_at:1536808027786422539 
I180913 03:07:07.788238 10867 gossip/gossip.go:942  [n1] gossip connectivity
 
I180913 03:07:07.840548 10715 server/node.go:477  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=1, queries=0.00, writes=0.00, bytesPerReplica={p10=7103.00 p25=7103.00 p50=7103.00 p75=7103.00 p90=7103.00 pMax=7103.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180913 03:07:07.840844 10715 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180913 03:07:07.842392 10715 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180913 03:07:07.842557 10715 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "fe7a24b3-c02c-457c-848c-2e7c97e532d3"
I180913 03:07:07.842911 10715 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180913 03:07:07.845562 10715 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180913 03:07:07.845670 10715 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180913 03:07:07.849809 10715 server/server.go:1550  [n1] starting https server at 127.0.0.1:45273 (use: 127.0.0.1:45273)
I180913 03:07:07.849914 10715 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:41053
I180913 03:07:07.850002 10715 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:41053
I180913 03:07:07.911124 10831 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180913 03:07:08.066114 11031 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180913 03:07:08.067623 11029 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=92d79f75 key=/Table/SystemConfigSpan/Start rw=true pri=0.02182066 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536808027.892618124,0 orig=1536808027.892618124,0 max=1536808027.892618124,0 wto=false rop=false seq=6
I180913 03:07:08.096252 10609 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180913 03:07:08.379858 11091 storage/replica_command.go:298  [n1,split,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180913 03:07:08.488002 10789 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-13 User:root}
I180913 03:07:08.532268 11036 storage/replica_command.go:298  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180913 03:07:08.633656 11065 storage/replica_command.go:298  [n1,split,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180913 03:07:08.705418 10957 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180913 03:07:08.738065 10810 storage/replica_command.go:298  [n1,split,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180913 03:07:08.922007 11083 storage/replica_command.go:298  [n1,split,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180913 03:07:09.039550 11157 storage/replica_command.go:298  [n1,split,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180913 03:07:09.095012 11112 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:7abcd4b4-11e7-4f10-97b4-8c3244530e22 User:root}
I180913 03:07:09.123007 11071 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180913 03:07:09.133555 11141 storage/replica_command.go:298  [n1,split,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180913 03:07:09.190145 11172 storage/replica_command.go:298  [n1,split,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180913 03:07:09.230916 11161 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180913 03:07:09.267583 11205 storage/replica_command.go:298  [n1,split,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180913 03:07:09.328985 11168 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180913 03:07:09.352532 11208 storage/replica_command.go:298  [n1,split,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180913 03:07:09.387666 10715 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180913 03:07:09.387801 10715 server/server.go:1609  [n1] serving sql connections
I180913 03:07:09.393116 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.393783 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.394608 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.395378 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.396116 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.396885 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.397714 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.398418 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.399044 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.399785 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.400444 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.401173 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.401889 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.402509 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.403202 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.403909 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.404603 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.405373 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.408288 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.424153 11214 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:41053} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-780-g4d3d9f7 StartedAt:1536808027786422539 LocalityAddress:[]} ClusterID:fe7a24b3-c02c-457c-848c-2e7c97e532d3 StartedAt:1536808027786422539 LastUp:1536808027786422539}
I180913 03:07:09.447811 11212 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180913 03:07:09.457556 11180 storage/replica_command.go:298  [n1,split,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180913 03:07:09.476900 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.478309 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.480179 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.483174 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.489529 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.498729 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.544949 11250 storage/replica_command.go:298  [n1,split,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180913 03:07:09.579480 10715 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 03:07:09.615569 11190 storage/replica_command.go:298  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180913 03:07:09.628880 10715 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 03:07:09.682976 11261 storage/replica_command.go:298  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180913 03:07:09.698182 10715 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 03:07:09.742347 10867 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180913 03:07:09.767012 11285 storage/replica_command.go:298  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180913 03:07:09.833495 10715 server/testserver.go:420  had 17 ranges at startup, expected 22
I180913 03:07:09.915730 11288 storage/replica_command.go:298  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180913 03:07:10.002984 11290 storage/replica_command.go:298  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180913 03:07:10.129489 11133 storage/replica_command.go:298  [n1,split,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180913 03:07:10.138837 10715 server/testserver.go:420  had 20 ranges at startup, expected 22
I180913 03:07:10.242310 11323 storage/replica_command.go:298  [n1,split,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180913 03:07:10.986739 11347 storage/replica_command.go:298  [n1,split,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180913 03:07:10.987802 11296 sql/event_log.go:126  [n1,client=127.0.0.1:51488,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180913 03:07:11.102231 11296 sql/event_log.go:126  [n1,client=127.0.0.1:51488,user=root] Event: "create_table", target: 53, info: {TableName:d.public.foo Statement:CREATE TABLE foo (a INT PRIMARY KEY, b STRING) User:root}
I180913 03:07:11.117242 11338 storage/replica_command.go:298  [n1,split,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180913 03:07:16.866848 11003 storage/replica_proposal.go:211  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808036.851380488,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:17.864523 11049 server/status/runtime.go:484  [n1] runtime stats: 476 MiB RSS, 204 goroutines, 18 MiB/17 MiB/48 MiB GO alloc/idle/total, 33 MiB/66 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (120x), 0.0/0.0/0 (%r/%w/q)disk, 1.8 MiB/1.8 MiB (r/w)net
I180913 03:07:17.870741 11006 storage/replica_proposal.go:211  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808037.867976163,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:18.665280 11014 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808038.656971451,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:18.872259 10874 storage/replica_proposal.go:211  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808038.869301791,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:19.680563 10873 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808039.668598655,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:19.875186 10962 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808039.870618265,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.741231 10964 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.738324723,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.780000 10966 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.776896435,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.822375 11413 sql/event_log.go:126  [n1,client=127.0.0.1:51510,user=sinkuser] Event: "create_table", target: 54, info: {TableName:d.public.sqlsink Statement:CREATE TABLE IF NOT EXISTS sqlsink (topic STRING, partition INT, message_id INT, key BYTES, value BYTES, resolved BYTES, PRIMARY KEY (topic, partition, message_id)) User:sinkuser}
I180913 03:07:20.847391 10978 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.825588752,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.849222 11466 storage/replica_command.go:298  [n1,split,s1,r24/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r25]
I180913 03:07:20.877527 10976 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.874740469,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.878794 10980 storage/replica_proposal.go:211  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.874060891,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:24.877505 11007 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808044.874230915,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:26.885188 10995 storage/replica_proposal.go:211  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808046.882310131,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:27.880071 11049 server/status/runtime.go:484  [n1] runtime stats: 478 MiB RSS, 202 goroutines, 17 MiB/16 MiB/48 MiB GO alloc/idle/total, 34 MiB/67 MiB CGO alloc/total, 241.2 CGO/sec, 71.3/0.7 %(u/s)time, 0.8 %gc (4x), 1.4/57.7/0 (%r/%w/q)disk, 2.7 MiB/2.7 MiB (r/w)net
I180913 03:07:27.909130 10998 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808047.883690290,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:29.244561 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:29.888769 11006 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808049.885963173,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:30.246550 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:30.889941 11012 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808050.887142345,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:31.259255 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:31.891032 10877 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808051.888292664,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:32.262115 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:32.892249 10871 storage/replica_proposal.go:211  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808052.889516340,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:33.262468 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:34.106243 11402 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382525883795144705 encountered retryable error: synthetic retryable error
I180913 03:07:34.262792 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:35.263133 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:36.263440 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:36.908832 10973 storage/replica_proposal.go:211  [n1,s1,r22/1:/Table/5{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808056.896665976,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:37.270158 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:37.906780 11049 server/status/runtime.go:484  [n1] runtime stats: 480 MiB RSS, 204 goroutines, 13 MiB/20 MiB/48 MiB GO alloc/idle/total, 34 MiB/68 MiB CGO alloc/total, 121.2 CGO/sec, 62.8/0.4 %(u/s)time, 1.0 %gc (3x), 1.3/1512.1/0 (%r/%w/q)disk, 3.4 MiB/3.4 MiB (r/w)net
I180913 03:07:37.909929 10976 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808057.907167727,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:38.270531 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:39.275314 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:40.275641 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:41.276821 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:42.277132 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:43.277534 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:44.278499 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:45.278855 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:46.279196 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:47.281931 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:47.908956 11049 server/status/runtime.go:484  [n1] runtime stats: 481 MiB RSS, 203 goroutines, 16 MiB/18 MiB/48 MiB GO alloc/idle/total, 34 MiB/68 MiB CGO alloc/total, 35.9 CGO/sec, 59.2/0.2 %(u/s)time, 0.1 %gc (2x), 0.1/20.5/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180913 03:07:48.282293 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:49.282636 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:50.282978 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:51.283283 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:52.285106 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:52.651134 11402 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382525883795144705 encountered retryable error: synthetic retryable error
I180913 03:07:53.286485 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:54.286828 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:55.287225 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:56.287554 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:57.287862 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:57.911041 11049 server/status/runtime.go:484  [n1] runtime stats: 483 MiB RSS, 205 goroutines, 14 MiB/20 MiB/48 MiB GO alloc/idle/total, 35 MiB/69 MiB CGO alloc/total, 71.9 CGO/sec, 60.9/0.5 %(u/s)time, 0.4 %gc (3x), 0.0/18.6/0 (%r/%w/q)disk, 3.8 MiB/3.8 MiB (r/w)net
I180913 03:07:58.288204 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:59.288533 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:00.288886 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:01.289258 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:02.289576 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:03.289916 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:04.290259 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:05.290591 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:06.290890 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:07.295281 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:07.849178 11045 gossip/gossip.go:564  [n1] gossip status (ok, 1 node)
gossip client (0/3 cur/max conns)
gossip server (0/3 cur/max conns, infos 0/0 sent/received, bytes 0B/0B sent/received)
gossip connectivity
  n1 [sentinel];
 
I180913 03:08:07.913425 11049 server/status/runtime.go:484  [n1] runtime stats: 485 MiB RSS, 211 goroutines, 15 MiB/19 MiB/48 MiB GO alloc/idle/total, 35 MiB/70 MiB CGO alloc/total, 60.1 CGO/sec, 68.1/0.5 %(u/s)time, 0.3 %gc (3x), 0.2/13.2/0 (%r/%w/q)disk, 3.0 MiB/3.0 MiB (r/w)net
I180913 03:08:08.295593 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:09.295917 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:10.296727 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:11.297298 10715 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I180913 03:08:11.300469 10715 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
I180913 03:08:11.530235 11402 ccl/changefeedccl/changefeed_stmt.go:402  [n1] CHANGEFEED job 382525883795144705 returning with error: pq: node unavailable; try another peer
I180913 03:08:11.767529 11028 kv/transport_race.go:91  transport race promotion: ran 85 iterations on up to 1385 requests
--- FAIL: testrace/TestChangefeedRetryableSinkError (67.320s)
soon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10715 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc42185a240, 0x3dde6c0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e3df60, 0xc4210b6000, 0xc421f9f360)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc4210b6000)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc4210b6000, 0x3779930)
		/usr/local/go/src/testing/testing.go:777 +0x16e
	created by testing.(*T).Run
		/usr/local/go/src/testing/testing.go:824 +0x565
------- Stdout: -------
W180913 03:07:07.679894 10715 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180913 03:07:07.732807 10715 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180913 03:07:07.733310 10715 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 03:07:07.733416 10715 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 03:07:07.738179 10715 server/config.go:493  [n?] 1 storage engine initialized
I180913 03:07:07.738249 10715 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180913 03:07:07.738312 10715 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180913 03:07:07.781572 10715 util/stop/stopper.go:537  [n?] quiescing; tasks left:
1      [async] storage.pendingLeaseRequest: requesting lease
I180913 03:07:07.785485 10715 server/node.go:374  [n?] **** cluster fe7a24b3-c02c-457c-848c-2e7c97e532d3 has been created
I180913 03:07:07.785705 10715 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:41053
I180913 03:07:07.786882 10715 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:41053" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-780-g4d3d9f7" started_at:1536808027786422539 
I180913 03:07:07.788238 10867 gossip/gossip.go:942  [n1] gossip connectivity
 
I180913 03:07:07.840548 10715 server/node.go:477  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=1, queries=0.00, writes=0.00, bytesPerReplica={p10=7103.00 p25=7103.00 p50=7103.00 p75=7103.00 p90=7103.00 pMax=7103.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180913 03:07:07.840844 10715 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180913 03:07:07.842392 10715 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180913 03:07:07.842557 10715 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "fe7a24b3-c02c-457c-848c-2e7c97e532d3"
I180913 03:07:07.842911 10715 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180913 03:07:07.845562 10715 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180913 03:07:07.845670 10715 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180913 03:07:07.849809 10715 server/server.go:1550  [n1] starting https server at 127.0.0.1:45273 (use: 127.0.0.1:45273)
I180913 03:07:07.849914 10715 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:41053
I180913 03:07:07.850002 10715 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:41053
I180913 03:07:07.911124 10831 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180913 03:07:08.066114 11031 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180913 03:07:08.067623 11029 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=92d79f75 key=/Table/SystemConfigSpan/Start rw=true pri=0.02182066 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536808027.892618124,0 orig=1536808027.892618124,0 max=1536808027.892618124,0 wto=false rop=false seq=6
I180913 03:07:08.096252 10609 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180913 03:07:08.379858 11091 storage/replica_command.go:298  [n1,split,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180913 03:07:08.488002 10789 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-13 User:root}
I180913 03:07:08.532268 11036 storage/replica_command.go:298  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180913 03:07:08.633656 11065 storage/replica_command.go:298  [n1,split,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180913 03:07:08.705418 10957 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180913 03:07:08.738065 10810 storage/replica_command.go:298  [n1,split,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180913 03:07:08.922007 11083 storage/replica_command.go:298  [n1,split,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180913 03:07:09.039550 11157 storage/replica_command.go:298  [n1,split,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180913 03:07:09.095012 11112 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:7abcd4b4-11e7-4f10-97b4-8c3244530e22 User:root}
I180913 03:07:09.123007 11071 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180913 03:07:09.133555 11141 storage/replica_command.go:298  [n1,split,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180913 03:07:09.190145 11172 storage/replica_command.go:298  [n1,split,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180913 03:07:09.230916 11161 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180913 03:07:09.267583 11205 storage/replica_command.go:298  [n1,split,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180913 03:07:09.328985 11168 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180913 03:07:09.352532 11208 storage/replica_command.go:298  [n1,split,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180913 03:07:09.387666 10715 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180913 03:07:09.387801 10715 server/server.go:1609  [n1] serving sql connections
I180913 03:07:09.393116 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.393783 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.394608 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.395378 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.396116 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.396885 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.397714 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.398418 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.399044 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.399785 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.400444 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.401173 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.401889 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.402509 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.403202 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.403909 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.404603 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.405373 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.408288 10715 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 03:07:09.424153 11214 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:41053} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-780-g4d3d9f7 StartedAt:1536808027786422539 LocalityAddress:[]} ClusterID:fe7a24b3-c02c-457c-848c-2e7c97e532d3 StartedAt:1536808027786422539 LastUp:1536808027786422539}
I180913 03:07:09.447811 11212 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180913 03:07:09.457556 11180 storage/replica_command.go:298  [n1,split,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180913 03:07:09.476900 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.478309 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.480179 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.483174 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.489529 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.498729 10715 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 03:07:09.544949 11250 storage/replica_command.go:298  [n1,split,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180913 03:07:09.579480 10715 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 03:07:09.615569 11190 storage/replica_command.go:298  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180913 03:07:09.628880 10715 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 03:07:09.682976 11261 storage/replica_command.go:298  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180913 03:07:09.698182 10715 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 03:07:09.742347 10867 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180913 03:07:09.767012 11285 storage/replica_command.go:298  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180913 03:07:09.833495 10715 server/testserver.go:420  had 17 ranges at startup, expected 22
I180913 03:07:09.915730 11288 storage/replica_command.go:298  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180913 03:07:10.002984 11290 storage/replica_command.go:298  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180913 03:07:10.129489 11133 storage/replica_command.go:298  [n1,split,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180913 03:07:10.138837 10715 server/testserver.go:420  had 20 ranges at startup, expected 22
I180913 03:07:10.242310 11323 storage/replica_command.go:298  [n1,split,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180913 03:07:10.986739 11347 storage/replica_command.go:298  [n1,split,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180913 03:07:10.987802 11296 sql/event_log.go:126  [n1,client=127.0.0.1:51488,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180913 03:07:11.102231 11296 sql/event_log.go:126  [n1,client=127.0.0.1:51488,user=root] Event: "create_table", target: 53, info: {TableName:d.public.foo Statement:CREATE TABLE foo (a INT PRIMARY KEY, b STRING) User:root}
I180913 03:07:11.117242 11338 storage/replica_command.go:298  [n1,split,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180913 03:07:16.866848 11003 storage/replica_proposal.go:211  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808036.851380488,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:17.864523 11049 server/status/runtime.go:484  [n1] runtime stats: 476 MiB RSS, 204 goroutines, 18 MiB/17 MiB/48 MiB GO alloc/idle/total, 33 MiB/66 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (120x), 0.0/0.0/0 (%r/%w/q)disk, 1.8 MiB/1.8 MiB (r/w)net
I180913 03:07:17.870741 11006 storage/replica_proposal.go:211  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808037.867976163,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:18.665280 11014 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808038.656971451,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:18.872259 10874 storage/replica_proposal.go:211  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808038.869301791,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:19.680563 10873 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808039.668598655,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:19.875186 10962 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808039.870618265,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.741231 10964 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.738324723,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.780000 10966 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.776896435,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.822375 11413 sql/event_log.go:126  [n1,client=127.0.0.1:51510,user=sinkuser] Event: "create_table", target: 54, info: {TableName:d.public.sqlsink Statement:CREATE TABLE IF NOT EXISTS sqlsink (topic STRING, partition INT, message_id INT, key BYTES, value BYTES, resolved BYTES, PRIMARY KEY (topic, partition, message_id)) User:sinkuser}
I180913 03:07:20.847391 10978 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.825588752,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.849222 11466 storage/replica_command.go:298  [n1,split,s1,r24/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r25]
I180913 03:07:20.877527 10976 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.874740469,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:20.878794 10980 storage/replica_proposal.go:211  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808040.874060891,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:24.877505 11007 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808044.874230915,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:26.885188 10995 storage/replica_proposal.go:211  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808046.882310131,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:27.880071 11049 server/status/runtime.go:484  [n1] runtime stats: 478 MiB RSS, 202 goroutines, 17 MiB/16 MiB/48 MiB GO alloc/idle/total, 34 MiB/67 MiB CGO alloc/total, 241.2 CGO/sec, 71.3/0.7 %(u/s)time, 0.8 %gc (4x), 1.4/57.7/0 (%r/%w/q)disk, 2.7 MiB/2.7 MiB (r/w)net
I180913 03:07:27.909130 10998 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808047.883690290,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:29.244561 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:29.888769 11006 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808049.885963173,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:30.246550 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:30.889941 11012 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808050.887142345,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:31.259255 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:31.891032 10877 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808051.888292664,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:32.262115 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:32.892249 10871 storage/replica_proposal.go:211  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808052.889516340,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:33.262468 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:34.106243 11402 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382525883795144705 encountered retryable error: synthetic retryable error
I180913 03:07:34.262792 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:35.263133 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:36.263440 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:36.908832 10973 storage/replica_proposal.go:211  [n1,s1,r22/1:/Table/5{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808056.896665976,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:37.270158 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:37.906780 11049 server/status/runtime.go:484  [n1] runtime stats: 480 MiB RSS, 204 goroutines, 13 MiB/20 MiB/48 MiB GO alloc/idle/total, 34 MiB/68 MiB CGO alloc/total, 121.2 CGO/sec, 62.8/0.4 %(u/s)time, 1.0 %gc (3x), 1.3/1512.1/0 (%r/%w/q)disk, 3.4 MiB/3.4 MiB (r/w)net
I180913 03:07:37.909929 10976 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536808027.791194244,0 epo=1 pro=1536808057.907167727,0 following repl=(n1,s1):1 seq=2 start=1536808027.791194244,0 exp=1536808036.812737442,0 pro=1536808027.812772978,0
I180913 03:07:38.270531 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:39.275314 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:40.275641 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:41.276821 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:42.277132 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:43.277534 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:44.278499 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:45.278855 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:46.279196 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:47.281931 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:47.908956 11049 server/status/runtime.go:484  [n1] runtime stats: 481 MiB RSS, 203 goroutines, 16 MiB/18 MiB/48 MiB GO alloc/idle/total, 34 MiB/68 MiB CGO alloc/total, 35.9 CGO/sec, 59.2/0.2 %(u/s)time, 0.1 %gc (2x), 0.1/20.5/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180913 03:07:48.282293 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:49.282636 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:50.282978 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:51.283283 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:52.285106 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:52.651134 11402 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382525883795144705 encountered retryable error: synthetic retryable error
I180913 03:07:53.286485 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:54.286828 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:55.287225 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:56.287554 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:57.287862 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:57.911041 11049 server/status/runtime.go:484  [n1] runtime stats: 483 MiB RSS, 205 goroutines, 14 MiB/20 MiB/48 MiB GO alloc/idle/total, 35 MiB/69 MiB CGO alloc/total, 71.9 CGO/sec, 60.9/0.5 %(u/s)time, 0.4 %gc (3x), 0.0/18.6/0 (%r/%w/q)disk, 3.8 MiB/3.8 MiB (r/w)net
I180913 03:07:58.288204 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:07:59.288533 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:00.288886 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:01.289258 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:02.289576 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:03.289916 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:04.290259 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:05.290591 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:06.290890 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:07.295281 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:07.849178 11045 gossip/gossip.go:564  [n1] gossip status (ok, 1 node)
gossip client (0/3 cur/max conns)
gossip server (0/3 cur/max conns, infos 0/0 sent/received, bytes 0B/0B sent/received)
gossip connectivity
  n1 [sentinel];
 
I180913 03:08:07.913425 11049 server/status/runtime.go:484  [n1] runtime stats: 485 MiB RSS, 211 goroutines, 15 MiB/19 MiB/48 MiB GO alloc/idle/total, 35 MiB/70 MiB CGO alloc/total, 60.1 CGO/sec, 68.1/0.5 %(u/s)time, 0.3 %gc (3x), 0.2/13.2/0 (%r/%w/q)disk, 3.0 MiB/3.0 MiB (r/w)net
I180913 03:08:08.295593 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:09.295917 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:10.296727 10715 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 03:08:11.297298 10715 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I180913 03:08:11.300469 10715 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
I180913 03:08:11.530235 11402 ccl/changefeedccl/changefeed_stmt.go:402  [n1] CHANGEFEED job 382525883795144705 returning with error: pq: node unavailable; try another peer
I180913 03:08:11.767529 11028 kv/transport_race.go:91  transport race promotion: ran 85 iterations on up to 1385 requests
------- Stdout: -------
W180913 03:04:07.655480 11419 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180913 03:04:07.668624 11419 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180913 03:04:07.668845 11419 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 03:04:07.668879 11419 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 03:04:07.671623 11419 server/config.go:493  [n?] 1 storage engine initialized
I180913 03:04:07.671660 11419 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180913 03:04:07.671673 11419 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180913 03:04:07.683145 11419 util/stop/stopper.go:537  [n?] quiescing; tasks left:
1      [async] closedts-rangefeed-subscriber
I180913 03:04:07.689976 11419 server/node.go:374  [n?] **** cluster 67724ffb-d80d-437b-9576-0ddc5996bf68 has been created
I180913 03:04:07.690018 11419 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:43857
I180913 03:04:07.690187 11419 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:43857" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-780-g4d3d9f7" started_at:1536807847690120344 
I180913 03:04:07.691295 11419 server/node.go:477  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, queries=0.00, writes=0.00, bytesPerReplica={p10=7103.00 p25=7103.00 p50=7103.00 p75=7103.00 p90=7103.00 pMax=7103.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180913 03:04:07.691350 11419 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180913 03:04:07.691409 11419 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180913 03:04:07.691508 11560 gossip/gossip.go:942  [n1] gossip connectivity
 
I180913 03:04:07.691945 11419 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "67724ffb-d80d-437b-9576-0ddc5996bf68"
I180913 03:04:07.691994 11419 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180913 03:04:07.692373 11419 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180913 03:04:07.692404 11419 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180913 03:04:07.692474 11419 server/server.go:1550  [n1] starting https server at 127.0.0.1:39337 (use: 127.0.0.1:39337)
I180913 03:04:07.692493 11419 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:43857
I180913 03:04:07.692509 11419 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:43857
I180913 03:04:07.696395 11733 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180913 03:04:07.722312 11561 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /S

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

benesch commented Sep 13, 2018

Fixed in #30172.

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

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