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, test/TestChangefeedRetryableSinkError #30174

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

teamcity: failed tests on master: testrace/TestChangefeedRetryableSinkError, test/TestChangefeedRetryableSinkError #30174

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:

#901425:

--- FAIL: testrace/TestChangefeedRetryableSinkError (63.280s)
soon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10806 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc421e33c50, 0x3dddee0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e3d780, 0xc420648e10, 0xc421822820)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc420648e10)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc420648e10, 0x3779270)
		/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 02:37:34.037211 10806 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 02:37:34.123891 10806 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180913 02:37:34.129648 10806 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 02:37:34.129761 10806 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 02:37:34.159695 10806 server/config.go:493  [n?] 1 storage engine initialized
I180913 02:37:34.159806 10806 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180913 02:37:34.159884 10806 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180913 02:37:34.291435 10806 server/node.go:374  [n?] **** cluster a73d3a56-eefc-4304-b083-1de3750eed64 has been created
I180913 02:37:34.291551 10806 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:46007
I180913 02:37:34.292505 10806 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46007" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-778-gc1f0980" started_at:1536806254292192548 
I180913 02:37:34.296064 10851 gossip/gossip.go:942  [n1] gossip connectivity
 
I180913 02:37:34.309299 10806 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 02:37:34.310141 10806 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180913 02:37:34.310849 10806 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180913 02:37:34.311273 10806 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "a73d3a56-eefc-4304-b083-1de3750eed64"
I180913 02:37:34.312430 10806 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180913 02:37:34.315478 10806 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180913 02:37:34.315781 10806 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180913 02:37:34.326936 10806 server/server.go:1550  [n1] starting https server at 127.0.0.1:36667 (use: 127.0.0.1:36667)
I180913 02:37:34.333215 10806 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:46007
I180913 02:37:34.333290 10806 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:46007
I180913 02:37:34.354345 10649 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180913 02:37:34.466895 11027 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180913 02:37:34.782912 10653 storage/replica_command.go:298  [n1,split,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
W180913 02:37:34.792347 10929 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=deb88bdd key=/Table/SystemConfigSpan/Start rw=true pri=0.00831429 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536806254.373687227,0 orig=1536806254.373687227,0 max=1536806254.373687227,0 wto=false rop=false seq=6
I180913 02:37:34.819166 10815 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180913 02:37:34.913782 10762 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 02:37:34.995924 11022 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 02:37:35.009913 10765 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 02:37:35.121606 11045 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 02:37:35.201650 11049 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 02:37:35.235603 11079 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180913 02:37:35.313432 11122 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 02:37:35.382994 11101 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 02:37:35.468064 11089 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 02:37:35.468313 11095 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180913 02:37:35.550058 11034 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:41a823b3-1166-4d1f-893b-25bc848713e3 User:root}
I180913 02:37:35.555707 11172 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 02:37:35.624385 11115 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 02:37:35.665048 11189 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 02:37:35.708071 11104 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 02:37:35.743004 11195 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 02:37:35.762412 10806 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180913 02:37:35.762528 10806 server/server.go:1609  [n1] serving sql connections
I180913 02:37:35.789225 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.790126 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.790810 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.791486 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.792253 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.792831 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.793446 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.794057 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.794663 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.797350 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.797600 11184 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180913 02:37:35.798100 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.800790 11234 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46007} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-778-gc1f0980 StartedAt:1536806254292192548 LocalityAddress:[]} ClusterID:a73d3a56-eefc-4304-b083-1de3750eed64 StartedAt:1536806254292192548 LastUp:1536806254292192548}
I180913 02:37:35.807519 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.808217 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.808841 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.809507 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.851976 11149 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 02:37:35.860808 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.869443 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.870251 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.871092 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.872109 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.873371 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.875180 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.878034 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.883003 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.892366 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.940172 11134 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 02:37:35.971008 10806 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 02:37:36.034167 10806 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 02:37:36.034644 11229 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 02:37:36.094557 11267 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 02:37:36.114864 10806 server/testserver.go:420  had 17 ranges at startup, expected 22
I180913 02:37:36.152825 11160 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 02:37:36.161663 10851 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180913 02:37:36.207299 11280 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 02:37:36.250060 10806 server/testserver.go:420  had 19 ranges at startup, expected 22
I180913 02:37:36.270162 11300 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 02:37:36.304714 11318 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 02:37:36.747709 11312 sql/event_log.go:126  [n1,client=127.0.0.1:38548,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180913 02:37:36.754486 11363 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 02:37:36.831012 11312 sql/event_log.go:126  [n1,client=127.0.0.1:38548,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 02:37:36.834836 11211 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 02:37:43.357123 10964 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806263.353928852,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:44.327545 10800 server/status/runtime.go:484  [n1] runtime stats: 464 MiB RSS, 204 goroutines, 18 MiB/12 MiB/44 MiB GO alloc/idle/total, 33 MiB/71 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (119x), 0.0/0.0/0 (%r/%w/q)disk, 1.8 MiB/1.8 MiB (r/w)net
I180913 02:37:44.358189 10972 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806264.355269057,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.146374 10975 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.125569805,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.359789 10937 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.356797655,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.366192 10783 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.363245284,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.425393 10983 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.410784776,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.526396 11430 sql/event_log.go:126  [n1,client=127.0.0.1:38566,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 02:37:45.532694 11402 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 02:37:45.567159 10933 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.560040041,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.598574 10934 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.595511307,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:46.360867 10961 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806266.358118217,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:47.367252 10957 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806267.362932146,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:48.367279 10965 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806268.364310451,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:49.368468 10971 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806269.365579157,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:52.371957 10963 storage/replica_proposal.go:211  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806272.369187372,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:54.347442 10800 server/status/runtime.go:484  [n1] runtime stats: 465 MiB RSS, 202 goroutines, 20 MiB/12 MiB/44 MiB GO alloc/idle/total, 33 MiB/72 MiB CGO alloc/total, 224.2 CGO/sec, 63.1/0.6 %(u/s)time, 1.1 %gc (3x), 0.0/462.2/0 (%r/%w/q)disk, 3.7 MiB/3.7 MiB (r/w)net
I180913 02:37:54.374378 10967 storage/replica_proposal.go:211  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806274.371573744,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:54.721355 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:37:55.721691 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:37:56.379984 10977 storage/replica_proposal.go:211  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806276.374791591,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:56.722993 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:37:57.723310 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:37:58.723621 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:37:58.979103 10983 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806278.976117985,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:58.983831 11164 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382520068193288193 encountered retryable error: synthetic retryable error
I180913 02:37:59.381562 10785 storage/replica_proposal.go:211  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806279.378547598,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:59.724002 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:00.724367 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:01.724710 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:02.729285 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:03.729619 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:04.354199 10800 server/status/runtime.go:484  [n1] runtime stats: 466 MiB RSS, 204 goroutines, 17 MiB/13 MiB/44 MiB GO alloc/idle/total, 34 MiB/73 MiB CGO alloc/total, 109.0 CGO/sec, 67.6/0.5 %(u/s)time, 0.3 %gc (3x), 0.9/309.9/56 (%r/%w/q)disk, 2.6 MiB/2.6 MiB (r/w)net
I180913 02:38:04.388283 10934 storage/replica_proposal.go:211  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806284.385426919,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:38:04.729954 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:05.418398 10948 storage/replica_proposal.go:211  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806285.415471988,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:38:05.749237 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:06.435734 10958 storage/replica_proposal.go:211  [n1,s1,r22/1:/Table/5{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806286.432848111,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:38:06.749569 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:07.749933 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:08.750239 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:09.750572 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:10.750888 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:11.751262 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:12.751632 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:13.751948 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:14.356641 10800 server/status/runtime.go:484  [n1] runtime stats: 467 MiB RSS, 210 goroutines, 22 MiB/8.6 MiB/44 MiB GO alloc/idle/total, 34 MiB/73 MiB CGO alloc/total, 64.6 CGO/sec, 54.8/0.4 %(u/s)time, 0.3 %gc (2x), 0.0/282.0/0 (%r/%w/q)disk, 3.3 MiB/3.3 MiB (r/w)net
I180913 02:38:14.752279 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:15.753476 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:16.753821 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:17.754129 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:18.754458 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:18.902096 11164 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382520068193288193 encountered retryable error: synthetic retryable error
I180913 02:38:19.754901 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:20.755235 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:21.755576 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:22.755997 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:23.756335 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:24.358781 10800 server/status/runtime.go:484  [n1] runtime stats: 468 MiB RSS, 204 goroutines, 17 MiB/13 MiB/44 MiB GO alloc/idle/total, 34 MiB/74 MiB CGO alloc/total, 76.0 CGO/sec, 59.0/0.4 %(u/s)time, 0.3 %gc (3x), 0.0/501.7/0 (%r/%w/q)disk, 3.5 MiB/3.5 MiB (r/w)net
I180913 02:38:24.756678 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:25.757157 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:26.757436 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:27.757780 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:28.758172 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:29.758547 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:30.758887 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:31.759233 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:32.759581 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:33.759962 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:34.317840 10796 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 02:38:34.361830 10800 server/status/runtime.go:484  [n1] runtime stats: 468 MiB RSS, 205 goroutines, 13 MiB/16 MiB/44 MiB GO alloc/idle/total, 35 MiB/74 MiB CGO alloc/total, 22.4 CGO/sec, 54.7/0.3 %(u/s)time, 0.3 %gc (3x), 0.0/15.2/0 (%r/%w/q)disk, 4.1 MiB/4.1 MiB (r/w)net
I180913 02:38:34.760372 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:35.760706 10806 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 02:38:36.761325 10806 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I180913 02:38:36.765305 10806 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
I180913 02:38:37.165293 10926 kv/transport_race.go:91  transport race promotion: ran 46 iterations on up to 1557 requests
W180913 02:38:37.172694 11164 ccl/changefeedccl/changefeed_processors.go:230  [n1] error closing sink. goroutines may have leaked: write tcp 127.0.0.1:38802->127.0.0.1:46007: write: broken pipe
I180913 02:38:37.173002 11164 ccl/changefeedccl/changefeed_stmt.go:402  [n1] CHANGEFEED job 382520068193288193 returning with error: EOF
--- FAIL: test/TestChangefeedRetryableSinkError (67.250s)

------- Stdout: -------
W180913 02:36:34.673402 12093 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 02:36:34.678827 12093 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180913 02:36:34.678974 12093 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 02:36:34.678995 12093 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 02:36:34.681003 12093 server/config.go:493  [n?] 1 storage engine initialized
I180913 02:36:34.681059 12093 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180913 02:36:34.681076 12093 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180913 02:36:34.684802 12093 server/node.go:374  [n?] **** cluster 42cfc93d-b6f9-4d4e-8de7-488b7734c6aa has been created
I180913 02:36:34.684850 12093 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:39599
I180913 02:36:34.685013 12093 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:39599" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-778-gc1f0980" started_at:1536806194684956362 
I180913 02:36:34.685318 12171 gossip/gossip.go:942  [n1] gossip connectivity
 
I180913 02:36:34.687182 12093 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 02:36:34.687266 12093 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180913 02:36:34.687343 12093 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180913 02:36:34.689614 12093 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "42cfc93d-b6f9-4d4e-8de7-488b7734c6aa"
I180913 02:36:34.689661 12093 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180913 02:36:34.689930 12093 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180913 02:36:34.689955 12093 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180913 02:36:34.690039 12093 server/server.go:1550  [n1] starting https server at 127.0.0.1:44719 (use: 127.0.0.1:44719)
I180913 02:36:34.690062 12093 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:39599
I180913 02:36:34.690077 12093 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:39599
I180913 02:36:34.696653 12388 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180913 02:36:34.707130 12393 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180913 02:36:34.714536 11881 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180913 02:36:34.732038 12253 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 02:36:34.740871 12406 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 02:36:34.753105 12412 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 02:36:34.765236 12435 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 02:36:34.767399 12250 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 02:36:34.774382 12377 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180913 02:36:34.780588 12385 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 02:36:34.786344 12353 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 02:36:34.791870 12473 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 02:36:34.800827 12487 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 02:36:34.804417 12483 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:5c291672-d777-4f20-9c94-17091d769d73 User:root}
I180913 02:36:34.830351 12493 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 02:36:34.831948 12033 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 02:36:34.835164 12530 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 02:36:34.836499 12556 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 02:36:34.838536 12093 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180913 02:36:34.838567 12093 server/server.go:1609  [n1] serving sql connections
W180913 02:36:34.841276 12582 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "split" id=a9ad8795 key=/Local/Range/Table/15/RangeDescriptor rw=true pri=0.00005877 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536806194.836518036,0 orig=1536806194.836518036,0 max=1536806194.836518036,0 wto=false rop=false seq=1
I180913 02:36:34.842324 12585 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 02:36:34.852778 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.853014 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.853154 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.853322 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.853449 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.853608 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.853748 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.853872 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.853995 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.854121 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.854257 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.854439 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.854588 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.855161 12568 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:39599} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-778-gc1f0980 StartedAt:1536806194684956362 LocalityAddress:[]} ClusterID:42cfc93d-b6f9-4d4e-8de7-488b7734c6aa StartedAt:1536806194684956362 LastUp:1536806194684956362}
I180913 02:36:34.855425 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.855596 12093 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:36:34.857799 12596 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 02:36:34.860208 12093 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:36:34.860255 12566 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180913 02:36:34.861510 12536 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 02:36:34.861921 12093 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 02:36:34.863168 12093 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 02:36:34.863582 12093 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 02:36:34.866386 12627 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 02:36:34.869769 12093 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 02:36:34.870558 12093 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 02:36:34.871835 12093 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 02:36:34.875360 12611 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 02:36:34.875659 12093 server/testserver.go:420  had 17 ranges at startup, expected 22
I180913 02:36:34.883580 12643 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 02:36:34.885572 12093 server/testserver.go:420  had 18 ranges at startup, expected 22
I180913 02:36:34.892147 12545 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 02:36:34.894414 12093 server/testserver.go:420  had 19 ranges at startup, expected 22
I180913 02:36:34.899146 12693 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 02:36:34.905116 12653 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 02:36:34.913825 12093 server/testserver.go:420  had 21 ranges at startup, expected 22
I180913 02:36:34.974907 12705 sql/event_log.go:126  [n1,client=127.0.0.1:47144,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180913 02:36:34.975414 12706 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 02:36:34.979759 12705 sql/event_log.go:126  [n1,client=127.0.0.1:47144,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 02:36:34.981184 12657 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 02:36:35.339540 12758 sql/event_log.go:126  [n1,client=127.0.0.1:47160,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 02:36:35.340517 12761 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 02:36:35.709828 12778 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180913 02:36:35.727309 12688 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382519853562789889 encountered retryable error: synthetic retryable error
I180913 02:36:36.219124 12688 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382519853562789889 encountered retryable error: synthetic retryable error
I180913 02:36:36.682460 12171 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180913 02:36:36.687577 12688 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382519853562789889 encountered retryable error: synthetic retryable error
I180913 02:36:37.190274 12688 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382519853562789889 encountered retryable error: synthetic retryable error
I180913 02:36:37.789833 12093 util/stop/stopper.go:537  quiescing; tasks left:
1      node.Node: batch
1      [async] closedts-rangefeed-subscriber
W180913 02:36:37.790072 12688 internal/client/txn.go:532  [n1] failure aborting transaction: node unavailable; try another peer; abort caused by: job-update: node unavailable; try another peer
I180913 02:36:37.790099 12093 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] closedts-rangefeed-subscriber
W180913 02:36:38.610423 12688 ccl/changefeedccl/changefeed_processors.go:230  [n1] error closing sink. goroutines may have leaked: write tcp 127.0.0.1:47216->127.0.0.1:39599: write: broken pipe
W180913 02:36:38.610529 12688 ccl/changefeedccl/changefeed_processors.go:449  [n1] error closing sink. goroutines may have leaked: write tcp 127.0.0.1:47220->127.0.0.1:39599: write: broken pipe
I180913 02:36:38.610570 12688 ccl/changefeedccl/changefeed_stmt.go:402  [n1] CHANGEFEED job 382519853562789889 returning with error: job-update: node unavailable; try another peersoon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10806 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc421e33c50, 0x3dddee0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e3d780, 0xc420648e10, 0xc421822820)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc420648e10)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc420648e10, 0x3779270)
		/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 02:37:34.037211 10806 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 02:37:34.123891 10806 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180913 02:37:34.129648 10806 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 02:37:34.129761 10806 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 02:37:34.159695 10806 server/config.go:493  [n?] 1 storage engine initialized
I180913 02:37:34.159806 10806 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180913 02:37:34.159884 10806 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180913 02:37:34.291435 10806 server/node.go:374  [n?] **** cluster a73d3a56-eefc-4304-b083-1de3750eed64 has been created
I180913 02:37:34.291551 10806 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:46007
I180913 02:37:34.292505 10806 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46007" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-778-gc1f0980" started_at:1536806254292192548 
I180913 02:37:34.296064 10851 gossip/gossip.go:942  [n1] gossip connectivity
 
I180913 02:37:34.309299 10806 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 02:37:34.310141 10806 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180913 02:37:34.310849 10806 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180913 02:37:34.311273 10806 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "a73d3a56-eefc-4304-b083-1de3750eed64"
I180913 02:37:34.312430 10806 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180913 02:37:34.315478 10806 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180913 02:37:34.315781 10806 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180913 02:37:34.326936 10806 server/server.go:1550  [n1] starting https server at 127.0.0.1:36667 (use: 127.0.0.1:36667)
I180913 02:37:34.333215 10806 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:46007
I180913 02:37:34.333290 10806 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:46007
I180913 02:37:34.354345 10649 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180913 02:37:34.466895 11027 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180913 02:37:34.782912 10653 storage/replica_command.go:298  [n1,split,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
W180913 02:37:34.792347 10929 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=deb88bdd key=/Table/SystemConfigSpan/Start rw=true pri=0.00831429 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536806254.373687227,0 orig=1536806254.373687227,0 max=1536806254.373687227,0 wto=false rop=false seq=6
I180913 02:37:34.819166 10815 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180913 02:37:34.913782 10762 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 02:37:34.995924 11022 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 02:37:35.009913 10765 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 02:37:35.121606 11045 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 02:37:35.201650 11049 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 02:37:35.235603 11079 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180913 02:37:35.313432 11122 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 02:37:35.382994 11101 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 02:37:35.468064 11089 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 02:37:35.468313 11095 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180913 02:37:35.550058 11034 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:41a823b3-1166-4d1f-893b-25bc848713e3 User:root}
I180913 02:37:35.555707 11172 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 02:37:35.624385 11115 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 02:37:35.665048 11189 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 02:37:35.708071 11104 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 02:37:35.743004 11195 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 02:37:35.762412 10806 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180913 02:37:35.762528 10806 server/server.go:1609  [n1] serving sql connections
I180913 02:37:35.789225 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.790126 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.790810 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.791486 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.792253 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.792831 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.793446 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.794057 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.794663 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.797350 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.797600 11184 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180913 02:37:35.798100 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.800790 11234 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46007} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-778-gc1f0980 StartedAt:1536806254292192548 LocalityAddress:[]} ClusterID:a73d3a56-eefc-4304-b083-1de3750eed64 StartedAt:1536806254292192548 LastUp:1536806254292192548}
I180913 02:37:35.807519 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.808217 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.808841 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.809507 10806 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 02:37:35.851976 11149 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 02:37:35.860808 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.869443 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.870251 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.871092 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.872109 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.873371 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.875180 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.878034 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.883003 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.892366 10806 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 02:37:35.940172 11134 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 02:37:35.971008 10806 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 02:37:36.034167 10806 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 02:37:36.034644 11229 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 02:37:36.094557 11267 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 02:37:36.114864 10806 server/testserver.go:420  had 17 ranges at startup, expected 22
I180913 02:37:36.152825 11160 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 02:37:36.161663 10851 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180913 02:37:36.207299 11280 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 02:37:36.250060 10806 server/testserver.go:420  had 19 ranges at startup, expected 22
I180913 02:37:36.270162 11300 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 02:37:36.304714 11318 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 02:37:36.747709 11312 sql/event_log.go:126  [n1,client=127.0.0.1:38548,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180913 02:37:36.754486 11363 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 02:37:36.831012 11312 sql/event_log.go:126  [n1,client=127.0.0.1:38548,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 02:37:36.834836 11211 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 02:37:43.357123 10964 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806263.353928852,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:44.327545 10800 server/status/runtime.go:484  [n1] runtime stats: 464 MiB RSS, 204 goroutines, 18 MiB/12 MiB/44 MiB GO alloc/idle/total, 33 MiB/71 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (119x), 0.0/0.0/0 (%r/%w/q)disk, 1.8 MiB/1.8 MiB (r/w)net
I180913 02:37:44.358189 10972 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806264.355269057,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.146374 10975 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.125569805,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.359789 10937 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.356797655,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.366192 10783 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.363245284,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.425393 10983 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.410784776,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.526396 11430 sql/event_log.go:126  [n1,client=127.0.0.1:38566,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 02:37:45.532694 11402 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 02:37:45.567159 10933 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.560040041,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:45.598574 10934 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806265.595511307,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:46.360867 10961 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806266.358118217,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:47.367252 10957 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806267.362932146,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:48.367279 10965 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806268.364310451,0 following repl=(n1,s1):1 seq=2 start=1536806254.296072342,0 exp=1536806263.310130578,0 pro=1536806254.310161842,0
I180913 02:37:49.368468 10971 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536806254.296072342,0 epo=1 pro=1536806269.365579157,0 fo

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