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

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

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

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:

#901523:

--- FAIL: testrace/TestChangefeedRetryableSinkError (62.010s)
soon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10553 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc420cbf350, 0x3dde6c0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e3df60, 0xc42155a5a0, 0xc421625870)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc42155a5a0)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc42155a5a0, 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 05:11:53.001837 10553 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 05:11:53.067059 10553 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180913 05:11:53.067605 10553 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 05:11:53.067725 10553 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 05:11:53.079508 10553 server/config.go:493  [n?] 1 storage engine initialized
I180913 05:11:53.079616 10553 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180913 05:11:53.079670 10553 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180913 05:11:53.144102 10553 server/node.go:374  [n?] **** cluster a74db374-927b-459e-bad3-7374bd1b3c52 has been created
I180913 05:11:53.144215 10553 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:46309
I180913 05:11:53.145233 10553 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46309" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-780-g4d3d9f7" started_at:1536815513144895326 
I180913 05:11:53.148750 10493 gossip/gossip.go:942  [n1] gossip connectivity
 
I180913 05:11:53.172054 10553 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 05:11:53.180371 10553 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180913 05:11:53.180841 10553 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180913 05:11:53.180993 10553 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "a74db374-927b-459e-bad3-7374bd1b3c52"
I180913 05:11:53.181454 10553 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180913 05:11:53.184698 10553 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180913 05:11:53.184789 10553 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180913 05:11:53.186679 10553 server/server.go:1550  [n1] starting https server at 127.0.0.1:34615 (use: 127.0.0.1:34615)
I180913 05:11:53.186773 10553 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:46309
I180913 05:11:53.186838 10553 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:46309
I180913 05:11:53.208386 10737 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180913 05:11:53.639412 10678 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180913 05:11:53.648658 10676 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=7872e46d key=/Table/SystemConfigSpan/Start rw=true pri=0.00329162 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536815513.266753552,0 orig=1536815513.266753552,0 max=1536815513.266753552,0 wto=false rop=false seq=6
I180913 05:11:53.737799 10820 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180913 05:11:53.745633 10513 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 05:11:53.911087 10540 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 05:11:53.989872 10828 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 05:11:54.091039 10853 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 05:11:54.101021 10824 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 05:11:54.238175 10869 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 05:11:54.326958 10812 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180913 05:11:54.442592 10793 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180913 05:11:54.464387 10873 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 05:11:54.532116 10880 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 05:11:54.622795 10915 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 05:11:54.659108 10862 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:1dc0bcaf-16ed-4f05-869d-541562fe7c32 User:root}
I180913 05:11:54.727028 10937 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 05:11:54.773680 10847 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 05:11:54.819648 10923 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 05:11:54.866394 10553 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180913 05:11:54.866526 10553 server/server.go:1609  [n1] serving sql connections
I180913 05:11:54.882361 10966 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 05:11:54.904250 10781 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180913 05:11:54.913311 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.914574 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.915318 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.915969 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.916598 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.918511 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.919155 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.919883 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.925602 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.926772 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.933409 10783 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46309} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-780-g4d3d9f7 StartedAt:1536815513144895326 LocalityAddress:[]} ClusterID:a74db374-927b-459e-bad3-7374bd1b3c52 StartedAt:1536815513144895326 LastUp:1536815513144895326}
I180913 05:11:54.972954 10969 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 05:11:54.989711 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.991885 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.992512 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.993073 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.993596 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.994280 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.994868 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.995565 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.996314 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.997218 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.998485 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:55.000239 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:55.003078 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:55.008078 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:55.063640 10979 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 05:11:55.083601 10553 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 05:11:55.085807 10493 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180913 05:11:55.101338 10553 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 05:11:55.116819 10981 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 05:11:55.151323 10553 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 05:11:55.219212 10890 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 05:11:55.236419 10553 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 05:11:55.276298 11031 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 05:11:55.335737 10894 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 05:11:55.372427 10553 server/testserver.go:420  had 18 ranges at startup, expected 22
I180913 05:11:55.410315 11059 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 05:11:55.476741 11090 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 05:11:55.525527 11014 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 05:11:55.851886 11015 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 05:11:55.853677 11067 sql/event_log.go:126  [n1,client=127.0.0.1:33410,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180913 05:11:55.959607 11067 sql/event_log.go:126  [n1,client=127.0.0.1:33410,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 05:11:55.962750 11039 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 05:12:02.217147 10728 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815522.208131867,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:03.204613 10760 server/status/runtime.go:484  [n1] runtime stats: 464 MiB RSS, 203 goroutines, 12 MiB/15 MiB/42 MiB GO alloc/idle/total, 34 MiB/74 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (122x), 0.0/0.0/0 (%r/%w/q)disk, 1.6 MiB/1.6 MiB (r/w)net
I180913 05:12:03.245417 10668 storage/replica_proposal.go:211  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815523.231117355,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.192777 10739 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.189528117,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.235851 10741 storage/replica_proposal.go:211  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.232489783,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.293047 10740 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.289988077,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.312789 10691 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.308458746,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.366725 10605 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.361359012,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.388100 11172 sql/event_log.go:126  [n1,client=127.0.0.1:33428,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 05:12:04.473911 10698 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.470361310,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.477646 11168 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 05:12:04.487562 10690 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.479543075,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.523246 10727 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.520221966,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:06.238452 10725 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815526.235330309,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:07.239791 10728 storage/replica_proposal.go:211  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815527.236642464,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:08.241142 10731 storage/replica_proposal.go:211  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815528.238023141,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:10.243989 10734 storage/replica_proposal.go:211  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815530.240921880,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:12.434455 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:13.208358 10760 server/status/runtime.go:484  [n1] runtime stats: 465 MiB RSS, 209 goroutines, 16 MiB/12 MiB/42 MiB GO alloc/idle/total, 34 MiB/75 MiB CGO alloc/total, 256.6 CGO/sec, 69.9/1.2 %(u/s)time, 0.4 %gc (3x), 0.0/62.1/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180913 05:12:13.435184 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:14.250074 10731 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815534.246690239,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:14.443240 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:15.252277 10691 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815535.248077310,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:15.443579 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:16.252283 10693 storage/replica_proposal.go:211  [n1,s1,r22/1:/Table/5{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815536.249287209,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:16.448910 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:17.449229 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:18.102530 11127 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382550409248243713 encountered retryable error: synthetic retryable error
I180913 05:12:18.449565 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:19.262486 10719 storage/replica_proposal.go:211  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815539.259678808,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:19.449919 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:20.263878 10695 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815540.260974197,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:20.450263 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:21.450570 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:22.450907 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:23.212035 10760 server/status/runtime.go:484  [n1] runtime stats: 466 MiB RSS, 204 goroutines, 13 MiB/14 MiB/42 MiB GO alloc/idle/total, 34 MiB/75 MiB CGO alloc/total, 121.6 CGO/sec, 63.8/0.4 %(u/s)time, 0.9 %gc (3x), 0.0/1187.1/118 (%r/%w/q)disk, 2.7 MiB/2.7 MiB (r/w)net
I180913 05:12:23.268204 10709 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815543.264633927,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:23.451233 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:24.451517 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:25.451849 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:26.452187 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:27.452516 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:28.452826 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:29.454356 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:30.454730 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:31.455023 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:32.455375 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:33.255424 10760 server/status/runtime.go:484  [n1] runtime stats: 469 MiB RSS, 203 goroutines, 12 MiB/14 MiB/42 MiB GO alloc/idle/total, 35 MiB/78 MiB CGO alloc/total, 40.1 CGO/sec, 47.3/0.2 %(u/s)time, 0.3 %gc (2x), 0.0/160.5/0 (%r/%w/q)disk, 3.7 MiB/3.7 MiB (r/w)net
I180913 05:12:33.455716 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:34.456013 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:35.456301 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:36.456603 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:37.456924 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:38.458203 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:38.644139 11127 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382550409248243713 encountered retryable error: synthetic retryable error
I180913 05:12:39.458575 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:40.458907 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:41.459239 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:42.464937 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:43.269374 10760 server/status/runtime.go:484  [n1] runtime stats: 469 MiB RSS, 204 goroutines, 20 MiB/8.2 MiB/42 MiB GO alloc/idle/total, 35 MiB/78 MiB CGO alloc/total, 81.5 CGO/sec, 60.4/0.6 %(u/s)time, 0.2 %gc (2x), 0.0/379.6/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180913 05:12:43.465278 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:44.475848 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:45.476189 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:46.476490 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:47.476862 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:48.477271 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:49.481211 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:50.481487 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:51.481805 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:52.482135 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:53.183859 10756 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 05:12:53.271527 10760 server/status/runtime.go:484  [n1] runtime stats: 471 MiB RSS, 211 goroutines, 14 MiB/13 MiB/42 MiB GO alloc/idle/total, 36 MiB/78 MiB CGO alloc/total, 47.1 CGO/sec, 59.8/0.2 %(u/s)time, 0.3 %gc (3x), 0.0/8.1/0 (%r/%w/q)disk, 3.2 MiB/3.2 MiB (r/w)net
I180913 05:12:53.482513 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:54.483164 10553 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: writing summary
1      node.Node: batch
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I180913 05:12:54.485795 10553 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: writing summary
1      node.Node: batch
1      [async] transport racer
W180913 05:12:54.486736 10761 ts/db.go:195  [n1,ts-poll] error writing time series data: result is ambiguous (server shutdown)
I180913 05:12:54.486906 10553 util/stop/stopper.go:537  quiescing; tasks left:
1      node.Node: writing summary
1      [async] transport racer
I180913 05:12:54.746396 10553 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
W180913 05:12:54.746555 10762 server/node.go:860  [n1,summaries] error recording status summaries: node unavailable; try another peer
I180913 05:12:54.887785 10465 kv/transport_race.go:91  transport race promotion: ran 63 iterations on up to 1358 requests
--- FAIL: testrace/TestChangefeedRetryableSinkError (65.140s)
soon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10553 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc420cbf350, 0x3dde6c0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e3df60, 0xc42155a5a0, 0xc421625870)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc42155a5a0)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc42155a5a0, 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 05:11:53.001837 10553 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 05:11:53.067059 10553 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180913 05:11:53.067605 10553 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 05:11:53.067725 10553 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180913 05:11:53.079508 10553 server/config.go:493  [n?] 1 storage engine initialized
I180913 05:11:53.079616 10553 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180913 05:11:53.079670 10553 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180913 05:11:53.144102 10553 server/node.go:374  [n?] **** cluster a74db374-927b-459e-bad3-7374bd1b3c52 has been created
I180913 05:11:53.144215 10553 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:46309
I180913 05:11:53.145233 10553 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46309" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-780-g4d3d9f7" started_at:1536815513144895326 
I180913 05:11:53.148750 10493 gossip/gossip.go:942  [n1] gossip connectivity
 
I180913 05:11:53.172054 10553 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 05:11:53.180371 10553 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180913 05:11:53.180841 10553 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180913 05:11:53.180993 10553 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "a74db374-927b-459e-bad3-7374bd1b3c52"
I180913 05:11:53.181454 10553 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180913 05:11:53.184698 10553 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180913 05:11:53.184789 10553 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180913 05:11:53.186679 10553 server/server.go:1550  [n1] starting https server at 127.0.0.1:34615 (use: 127.0.0.1:34615)
I180913 05:11:53.186773 10553 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:46309
I180913 05:11:53.186838 10553 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:46309
I180913 05:11:53.208386 10737 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180913 05:11:53.639412 10678 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180913 05:11:53.648658 10676 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=7872e46d key=/Table/SystemConfigSpan/Start rw=true pri=0.00329162 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536815513.266753552,0 orig=1536815513.266753552,0 max=1536815513.266753552,0 wto=false rop=false seq=6
I180913 05:11:53.737799 10820 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180913 05:11:53.745633 10513 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 05:11:53.911087 10540 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 05:11:53.989872 10828 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 05:11:54.091039 10853 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 05:11:54.101021 10824 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 05:11:54.238175 10869 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 05:11:54.326958 10812 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180913 05:11:54.442592 10793 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180913 05:11:54.464387 10873 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 05:11:54.532116 10880 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 05:11:54.622795 10915 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 05:11:54.659108 10862 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:1dc0bcaf-16ed-4f05-869d-541562fe7c32 User:root}
I180913 05:11:54.727028 10937 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 05:11:54.773680 10847 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 05:11:54.819648 10923 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 05:11:54.866394 10553 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180913 05:11:54.866526 10553 server/server.go:1609  [n1] serving sql connections
I180913 05:11:54.882361 10966 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 05:11:54.904250 10781 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180913 05:11:54.913311 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.914574 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.915318 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.915969 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.916598 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.918511 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.919155 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.919883 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.925602 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.926772 10553 server/testserver.go:420  had 12 ranges at startup, expected 22
I180913 05:11:54.933409 10783 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46309} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-780-g4d3d9f7 StartedAt:1536815513144895326 LocalityAddress:[]} ClusterID:a74db374-927b-459e-bad3-7374bd1b3c52 StartedAt:1536815513144895326 LastUp:1536815513144895326}
I180913 05:11:54.972954 10969 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 05:11:54.989711 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.991885 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.992512 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.993073 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.993596 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.994280 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.994868 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.995565 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.996314 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.997218 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:54.998485 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:55.000239 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:55.003078 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:55.008078 10553 server/testserver.go:420  had 13 ranges at startup, expected 22
I180913 05:11:55.063640 10979 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 05:11:55.083601 10553 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 05:11:55.085807 10493 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180913 05:11:55.101338 10553 server/testserver.go:420  had 14 ranges at startup, expected 22
I180913 05:11:55.116819 10981 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 05:11:55.151323 10553 server/testserver.go:420  had 15 ranges at startup, expected 22
I180913 05:11:55.219212 10890 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 05:11:55.236419 10553 server/testserver.go:420  had 16 ranges at startup, expected 22
I180913 05:11:55.276298 11031 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 05:11:55.335737 10894 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 05:11:55.372427 10553 server/testserver.go:420  had 18 ranges at startup, expected 22
I180913 05:11:55.410315 11059 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 05:11:55.476741 11090 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 05:11:55.525527 11014 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 05:11:55.851886 11015 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 05:11:55.853677 11067 sql/event_log.go:126  [n1,client=127.0.0.1:33410,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180913 05:11:55.959607 11067 sql/event_log.go:126  [n1,client=127.0.0.1:33410,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 05:11:55.962750 11039 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 05:12:02.217147 10728 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815522.208131867,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:03.204613 10760 server/status/runtime.go:484  [n1] runtime stats: 464 MiB RSS, 203 goroutines, 12 MiB/15 MiB/42 MiB GO alloc/idle/total, 34 MiB/74 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (122x), 0.0/0.0/0 (%r/%w/q)disk, 1.6 MiB/1.6 MiB (r/w)net
I180913 05:12:03.245417 10668 storage/replica_proposal.go:211  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815523.231117355,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.192777 10739 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.189528117,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.235851 10741 storage/replica_proposal.go:211  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.232489783,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.293047 10740 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.289988077,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.312789 10691 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.308458746,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.366725 10605 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.361359012,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.388100 11172 sql/event_log.go:126  [n1,client=127.0.0.1:33428,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 05:12:04.473911 10698 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.470361310,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.477646 11168 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 05:12:04.487562 10690 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.479543075,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:04.523246 10727 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815524.520221966,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:06.238452 10725 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815526.235330309,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:07.239791 10728 storage/replica_proposal.go:211  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815527.236642464,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:08.241142 10731 storage/replica_proposal.go:211  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815528.238023141,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:10.243989 10734 storage/replica_proposal.go:211  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815530.240921880,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:12.434455 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:13.208358 10760 server/status/runtime.go:484  [n1] runtime stats: 465 MiB RSS, 209 goroutines, 16 MiB/12 MiB/42 MiB GO alloc/idle/total, 34 MiB/75 MiB CGO alloc/total, 256.6 CGO/sec, 69.9/1.2 %(u/s)time, 0.4 %gc (3x), 0.0/62.1/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180913 05:12:13.435184 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:14.250074 10731 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815534.246690239,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:14.443240 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:15.252277 10691 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815535.248077310,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:15.443579 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:16.252283 10693 storage/replica_proposal.go:211  [n1,s1,r22/1:/Table/5{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815536.249287209,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:16.448910 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:17.449229 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:18.102530 11127 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382550409248243713 encountered retryable error: synthetic retryable error
I180913 05:12:18.449565 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:19.262486 10719 storage/replica_proposal.go:211  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815539.259678808,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:19.449919 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:20.263878 10695 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815540.260974197,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:20.450263 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:21.450570 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:22.450907 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:23.212035 10760 server/status/runtime.go:484  [n1] runtime stats: 466 MiB RSS, 204 goroutines, 13 MiB/14 MiB/42 MiB GO alloc/idle/total, 34 MiB/75 MiB CGO alloc/total, 121.6 CGO/sec, 63.8/0.4 %(u/s)time, 0.9 %gc (3x), 0.0/1187.1/118 (%r/%w/q)disk, 2.7 MiB/2.7 MiB (r/w)net
I180913 05:12:23.268204 10709 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536815513.148975801,0 epo=1 pro=1536815543.264633927,0 following repl=(n1,s1):1 seq=2 start=1536815513.148975801,0 exp=1536815522.172744042,0 pro=1536815513.172825497,0
I180913 05:12:23.451233 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:24.451517 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:25.451849 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:26.452187 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:27.452516 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:28.452826 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:29.454356 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:30.454730 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:31.455023 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:32.455375 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:33.255424 10760 server/status/runtime.go:484  [n1] runtime stats: 469 MiB RSS, 203 goroutines, 12 MiB/14 MiB/42 MiB GO alloc/idle/total, 35 MiB/78 MiB CGO alloc/total, 40.1 CGO/sec, 47.3/0.2 %(u/s)time, 0.3 %gc (2x), 0.0/160.5/0 (%r/%w/q)disk, 3.7 MiB/3.7 MiB (r/w)net
I180913 05:12:33.455716 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:34.456013 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:35.456301 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:36.456603 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:37.456924 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:38.458203 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:38.644139 11127 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382550409248243713 encountered retryable error: synthetic retryable error
I180913 05:12:39.458575 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:40.458907 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:41.459239 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:42.464937 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:43.269374 10760 server/status/runtime.go:484  [n1] runtime stats: 469 MiB RSS, 204 goroutines, 20 MiB/8.2 MiB/42 MiB GO alloc/idle/total, 35 MiB/78 MiB CGO alloc/total, 81.5 CGO/sec, 60.4/0.6 %(u/s)time, 0.2 %gc (2x), 0.0/379.6/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180913 05:12:43.465278 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:44.475848 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:45.476189 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:46.476490 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:47.476862 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:48.477271 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:49.481211 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:50.481487 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:51.481805 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:52.482135 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:53.183859 10756 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 05:12:53.271527 10760 server/status/runtime.go:484  [n1] runtime stats: 471 MiB RSS, 211 goroutines, 14 MiB/13 MiB/42 MiB GO alloc/idle/total, 36 MiB/78 MiB CGO alloc/total, 47.1 CGO/sec, 59.8/0.2 %(u/s)time, 0.3 %gc (3x), 0.0/8.1/0 (%r/%w/q)disk, 3.2 MiB/3.2 MiB (r/w)net
I180913 05:12:53.482513 10553 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180913 05:12:54.483164 10553 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: writing summary
1      node.Node: batch
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I180913 05:12:54.485795 10553 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: writing summary
1      node.Node: batch
1      [async] transport racer
W180913 05:12:54.486736 10761 ts/db.go:195  [n1,ts-poll] error writing time series data: result is ambiguous (server shutdown)
I180913 05:12:54.486906 10553 util/stop/stopper.go:537  quiescing; tasks left:
1      node.Node: writing summary
1      [async] transport racer
I180913 05:12:54.746396 10553 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
W180913 05:12:54.746555 10762 server/node.go:860  [n1,summaries] error recording status summaries: node unavailable; try another peer
I180913 05:12:54.887785 10465 kv/transport_race.go:91  transport race promotion: ran 63 iterations on up to 1358 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

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