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

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

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

cockroach-teamcity opened this issue Sep 12, 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:

#901234:

--- FAIL: testrace/TestChangefeedRetryableSinkError (62.320s)
soon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10379 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc4209bec00, 0x3ddd8a0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e3d140, 0xc42093a000, 0xc421da6220)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc42093a000)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc42093a000, 0x3778c70)
		/usr/local/go/src/testing/testing.go:777 +0x16e
	created by testing.(*T).Run
		/usr/local/go/src/testing/testing.go:824 +0x565
------- Stdout: -------
W180912 22:05:56.821254 10379 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180912 22:05:56.936788 10379 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180912 22:05:56.937516 10379 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 22:05:56.937691 10379 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 22:05:56.943770 10379 server/config.go:493  [n?] 1 storage engine initialized
I180912 22:05:56.944920 10379 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180912 22:05:56.945062 10379 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180912 22:05:57.009605 10379 server/node.go:374  [n?] **** cluster 25808af6-9dbc-42f3-aec0-f2936d8f3c11 has been created
I180912 22:05:57.009750 10379 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:35813
I180912 22:05:57.010825 10379 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:35813" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-774-g692954f" started_at:1536789957010497042 
I180912 22:05:57.012215 10577 gossip/gossip.go:942  [n1] gossip connectivity
 
I180912 22:05:57.035940 10379 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}
I180912 22:05:57.036267 10379 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180912 22:05:57.036700 10379 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180912 22:05:57.036896 10379 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "25808af6-9dbc-42f3-aec0-f2936d8f3c11"
I180912 22:05:57.037331 10379 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180912 22:05:57.038485 10379 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180912 22:05:57.038624 10379 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180912 22:05:57.040526 10379 server/server.go:1550  [n1] starting https server at 127.0.0.1:46781 (use: 127.0.0.1:46781)
I180912 22:05:57.040651 10379 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:35813
I180912 22:05:57.040739 10379 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:35813
I180912 22:05:57.085171 10584 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180912 22:05:57.234472 10792 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180912 22:05:57.303649 10810 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=f688d67a key=/Table/SystemConfigSpan/Start rw=true pri=0.01648753 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536789957.113673824,0 orig=1536789957.113673824,0 max=1536789957.113673824,0 wto=false rop=false seq=6
I180912 22:05:57.447526 10490 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180912 22:05:57.511855 10813 storage/replica_command.go:298  [n1,split,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180912 22:05:57.692753 10614 storage/replica_command.go:298  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180912 22:05:57.874164 10795 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-13 User:root}
I180912 22:05:57.899934 10616 storage/replica_command.go:298  [n1,split,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180912 22:05:58.021130 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]
I180912 22:05:58.078221 10834 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180912 22:05:58.125967 10870 storage/replica_command.go:298  [n1,split,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180912 22:05:58.216491 10860 storage/replica_command.go:298  [n1,split,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180912 22:05:58.239730 10882 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180912 22:05:58.320753 10919 storage/replica_command.go:298  [n1,split,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180912 22:05:58.389772 10926 storage/replica_command.go:298  [n1,split,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180912 22:05:58.475701 10909 storage/replica_command.go:298  [n1,split,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180912 22:05:58.477190 10878 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:1c7f9d11-fe8d-4467-bdae-7462ca193767 User:root}
I180912 22:05:58.573885 10979 storage/replica_command.go:298  [n1,split,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180912 22:05:58.580000 10865 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}
I180912 22:05:58.668783 10950 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}
I180912 22:05:58.670337 10956 storage/replica_command.go:298  [n1,split,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180912 22:05:58.719589 10379 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180912 22:05:58.719710 10379 server/server.go:1609  [n1] serving sql connections
I180912 22:05:58.753967 10891 storage/replica_command.go:298  [n1,split,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180912 22:05:58.757205 10911 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180912 22:05:58.761374 10913 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:35813} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-774-g692954f StartedAt:1536789957010497042 LocalityAddress:[]} ClusterID:25808af6-9dbc-42f3-aec0-f2936d8f3c11 StartedAt:1536789957010497042 LastUp:1536789957010497042}
I180912 22:05:58.773526 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.775712 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.795745 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.798664 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.799215 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.799680 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.800161 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.800625 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.801166 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.801672 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.802174 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.802674 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.803167 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.803708 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.804218 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.804732 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.805441 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.806345 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.811744 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.812749 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.814587 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.816336 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.838154 10990 storage/replica_command.go:298  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180912 22:05:58.847724 10379 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 22:05:58.852687 10379 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 22:05:58.861899 10379 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 22:05:58.902001 10997 storage/replica_command.go:298  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180912 22:05:58.907677 10379 server/testserver.go:420  had 16 ranges at startup, expected 22
I180912 22:05:58.950080 10577 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180912 22:05:58.954543 11078 storage/replica_command.go:298  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180912 22:05:58.959553 10379 server/testserver.go:420  had 17 ranges at startup, expected 22
I180912 22:05:59.005077 11061 storage/replica_command.go:298  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180912 22:05:59.030395 10379 server/testserver.go:420  had 18 ranges at startup, expected 22
I180912 22:05:59.077734 11065 storage/replica_command.go:298  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180912 22:05:59.132543 11068 storage/replica_command.go:298  [n1,split,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180912 22:05:59.165712 10379 server/testserver.go:420  had 20 ranges at startup, expected 22
I180912 22:05:59.185528 11108 storage/replica_command.go:298  [n1,split,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180912 22:05:59.622043 11038 sql/event_log.go:126  [n1,client=127.0.0.1:36814,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180912 22:05:59.641165 11128 storage/replica_command.go:298  [n1,split,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180912 22:05:59.668631 11038 sql/event_log.go:126  [n1,client=127.0.0.1:36814,user=root] Event: "create_table", target: 53, info: {TableName:d.public.foo Statement:CREATE TABLE foo (a INT PRIMARY KEY, b STRING) User:root}
I180912 22:05:59.709129 11000 storage/replica_command.go:298  [n1,split,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180912 22:06:06.052989 10740 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789966.050134066,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.043121 10781 server/status/runtime.go:484  [n1] runtime stats: 450 MiB RSS, 204 goroutines, 13 MiB/15 MiB/43 MiB GO alloc/idle/total, 33 MiB/63 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (121x), 0.0/0.0/0 (%r/%w/q)disk, 1.7 MiB/1.7 MiB (r/w)net
I180912 22:06:07.054568 10746 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.051534297,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.539030 10753 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.530159633,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.539172 10748 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.531825982,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.701009 11226 sql/event_log.go:126  [n1,client=127.0.0.1:36828,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}
I180912 22:06:07.708853 10757 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.705762809,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.712315 11175 storage/replica_command.go:298  [n1,split,s1,r24/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r25]
I180912 22:06:07.722429 10701 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.717067657,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.800127 10755 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.784699718,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:08.007390 10717 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789968.004117661,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:08.056004 10722 storage/replica_proposal.go:211  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789968.053053222,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:09.058116 10728 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789969.054677512,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:11.068413 10735 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789971.057293751,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:13.062731 10752 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789973.059802530,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:14.065884 10714 storage/replica_proposal.go:211  [n1,s1,r22/1:/Table/5{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789974.062811289,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:16.069104 10729 storage/replica_proposal.go:211  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789976.065746129,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:16.477514 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:17.079769 10781 server/status/runtime.go:484  [n1] runtime stats: 451 MiB RSS, 209 goroutines, 19 MiB/9.3 MiB/43 MiB GO alloc/idle/total, 34 MiB/64 MiB CGO alloc/total, 239.4 CGO/sec, 70.5/0.6 %(u/s)time, 0.5 %gc (3x), 0.0/19.1/0 (%r/%w/q)disk, 3.3 MiB/3.3 MiB (r/w)net
I180912 22:06:17.479877 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:18.480233 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:19.092401 10750 storage/replica_proposal.go:211  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789979.089437299,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:19.480588 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:20.484581 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:20.759203 11221 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382466666508451841 encountered retryable error: synthetic retryable error
I180912 22:06:21.095212 10757 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789981.092150759,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:21.484978 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:22.097787 10702 storage/replica_proposal.go:211  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789982.094698170,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:22.485273 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:23.489113 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:24.489428 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:25.489791 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:26.490131 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:27.091610 10781 server/status/runtime.go:484  [n1] runtime stats: 453 MiB RSS, 204 goroutines, 17 MiB/12 MiB/43 MiB GO alloc/idle/total, 33 MiB/65 MiB CGO alloc/total, 133.9 CGO/sec, 64.1/0.5 %(u/s)time, 0.5 %gc (3x), 0.0/433.1/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180912 22:06:27.104620 10711 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789987.101652818,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:27.490588 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:28.106095 10725 storage/replica_proposal.go:211  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789988.103052501,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:28.490948 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:29.491294 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:30.491621 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:31.491968 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:32.492347 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:33.492727 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:34.497116 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:35.497485 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:36.497825 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:37.103307 10781 server/status/runtime.go:484  [n1] runtime stats: 453 MiB RSS, 204 goroutines, 20 MiB/8.4 MiB/43 MiB GO alloc/idle/total, 33 MiB/65 MiB CGO alloc/total, 41.2 CGO/sec, 49.3/0.3 %(u/s)time, 0.3 %gc (2x), 0.0/420.1/0 (%r/%w/q)disk, 3.8 MiB/3.8 MiB (r/w)net
I180912 22:06:37.498173 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:38.498507 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:39.498887 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:40.499227 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:41.499532 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:42.501085 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:42.688586 11221 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382466666508451841 encountered retryable error: synthetic retryable error
I180912 22:06:43.503481 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:44.503908 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:45.505519 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:46.505898 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:47.105677 10781 server/status/runtime.go:484  [n1] runtime stats: 456 MiB RSS, 204 goroutines, 13 MiB/15 MiB/43 MiB GO alloc/idle/total, 34 MiB/66 MiB CGO alloc/total, 95.2 CGO/sec, 54.4/0.4 %(u/s)time, 0.6 %gc (3x), 0.0/378.3/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180912 22:06:47.506248 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:48.507565 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:49.507905 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:50.508231 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:51.510522 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:52.510883 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:53.511222 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:54.511593 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:55.511947 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:56.512262 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:57.041649 10777 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];
 
I180912 22:06:57.114776 10781 server/status/runtime.go:484  [n1] runtime stats: 457 MiB RSS, 205 goroutines, 22 MiB/7.5 MiB/43 MiB GO alloc/idle/total, 34 MiB/66 MiB CGO alloc/total, 30.6 CGO/sec, 59.2/0.4 %(u/s)time, 0.5 %gc (2x), 0.0/11.3/0 (%r/%w/q)disk, 3.8 MiB/3.8 MiB (r/w)net
I180912 22:06:57.513666 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:58.514316 10379 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: batch
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I180912 22:06:58.525292 10379 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: batch
1      [async] transport racer
W180912 22:06:58.549971 10782 ts/db.go:195  [n1,ts-poll] error writing time series data: result is ambiguous (server shutdown)
I180912 22:06:58.552565 10379 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      [async] transport racer
I180912 22:06:58.553519 10379 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
I180912 22:06:59.018073 10587 kv/transport_race.go:91  transport race promotion: ran 60 iterations on up to 1406 requests
--- FAIL: testrace/TestChangefeedRetryableSinkError (66.440s)
soon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10379 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc4209bec00, 0x3ddd8a0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e3d140, 0xc42093a000, 0xc421da6220)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc42093a000)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc42093a000, 0x3778c70)
		/usr/local/go/src/testing/testing.go:777 +0x16e
	created by testing.(*T).Run
		/usr/local/go/src/testing/testing.go:824 +0x565
------- Stdout: -------
W180912 22:05:56.821254 10379 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180912 22:05:56.936788 10379 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180912 22:05:56.937516 10379 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 22:05:56.937691 10379 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 22:05:56.943770 10379 server/config.go:493  [n?] 1 storage engine initialized
I180912 22:05:56.944920 10379 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180912 22:05:56.945062 10379 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180912 22:05:57.009605 10379 server/node.go:374  [n?] **** cluster 25808af6-9dbc-42f3-aec0-f2936d8f3c11 has been created
I180912 22:05:57.009750 10379 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:35813
I180912 22:05:57.010825 10379 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:35813" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-774-g692954f" started_at:1536789957010497042 
I180912 22:05:57.012215 10577 gossip/gossip.go:942  [n1] gossip connectivity
 
I180912 22:05:57.035940 10379 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}
I180912 22:05:57.036267 10379 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180912 22:05:57.036700 10379 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180912 22:05:57.036896 10379 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "25808af6-9dbc-42f3-aec0-f2936d8f3c11"
I180912 22:05:57.037331 10379 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180912 22:05:57.038485 10379 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180912 22:05:57.038624 10379 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180912 22:05:57.040526 10379 server/server.go:1550  [n1] starting https server at 127.0.0.1:46781 (use: 127.0.0.1:46781)
I180912 22:05:57.040651 10379 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:35813
I180912 22:05:57.040739 10379 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:35813
I180912 22:05:57.085171 10584 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180912 22:05:57.234472 10792 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180912 22:05:57.303649 10810 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=f688d67a key=/Table/SystemConfigSpan/Start rw=true pri=0.01648753 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536789957.113673824,0 orig=1536789957.113673824,0 max=1536789957.113673824,0 wto=false rop=false seq=6
I180912 22:05:57.447526 10490 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180912 22:05:57.511855 10813 storage/replica_command.go:298  [n1,split,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180912 22:05:57.692753 10614 storage/replica_command.go:298  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180912 22:05:57.874164 10795 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-13 User:root}
I180912 22:05:57.899934 10616 storage/replica_command.go:298  [n1,split,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180912 22:05:58.021130 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]
I180912 22:05:58.078221 10834 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180912 22:05:58.125967 10870 storage/replica_command.go:298  [n1,split,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180912 22:05:58.216491 10860 storage/replica_command.go:298  [n1,split,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180912 22:05:58.239730 10882 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180912 22:05:58.320753 10919 storage/replica_command.go:298  [n1,split,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180912 22:05:58.389772 10926 storage/replica_command.go:298  [n1,split,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180912 22:05:58.475701 10909 storage/replica_command.go:298  [n1,split,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180912 22:05:58.477190 10878 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:1c7f9d11-fe8d-4467-bdae-7462ca193767 User:root}
I180912 22:05:58.573885 10979 storage/replica_command.go:298  [n1,split,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180912 22:05:58.580000 10865 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}
I180912 22:05:58.668783 10950 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}
I180912 22:05:58.670337 10956 storage/replica_command.go:298  [n1,split,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180912 22:05:58.719589 10379 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180912 22:05:58.719710 10379 server/server.go:1609  [n1] serving sql connections
I180912 22:05:58.753967 10891 storage/replica_command.go:298  [n1,split,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180912 22:05:58.757205 10911 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180912 22:05:58.761374 10913 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:35813} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-774-g692954f StartedAt:1536789957010497042 LocalityAddress:[]} ClusterID:25808af6-9dbc-42f3-aec0-f2936d8f3c11 StartedAt:1536789957010497042 LastUp:1536789957010497042}
I180912 22:05:58.773526 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.775712 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.795745 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.798664 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.799215 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.799680 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.800161 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.800625 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.801166 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.801672 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.802174 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.802674 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.803167 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.803708 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.804218 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.804732 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.805441 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.806345 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.811744 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.812749 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.814587 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.816336 10379 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 22:05:58.838154 10990 storage/replica_command.go:298  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180912 22:05:58.847724 10379 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 22:05:58.852687 10379 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 22:05:58.861899 10379 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 22:05:58.902001 10997 storage/replica_command.go:298  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180912 22:05:58.907677 10379 server/testserver.go:420  had 16 ranges at startup, expected 22
I180912 22:05:58.950080 10577 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180912 22:05:58.954543 11078 storage/replica_command.go:298  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180912 22:05:58.959553 10379 server/testserver.go:420  had 17 ranges at startup, expected 22
I180912 22:05:59.005077 11061 storage/replica_command.go:298  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180912 22:05:59.030395 10379 server/testserver.go:420  had 18 ranges at startup, expected 22
I180912 22:05:59.077734 11065 storage/replica_command.go:298  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180912 22:05:59.132543 11068 storage/replica_command.go:298  [n1,split,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180912 22:05:59.165712 10379 server/testserver.go:420  had 20 ranges at startup, expected 22
I180912 22:05:59.185528 11108 storage/replica_command.go:298  [n1,split,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180912 22:05:59.622043 11038 sql/event_log.go:126  [n1,client=127.0.0.1:36814,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180912 22:05:59.641165 11128 storage/replica_command.go:298  [n1,split,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180912 22:05:59.668631 11038 sql/event_log.go:126  [n1,client=127.0.0.1:36814,user=root] Event: "create_table", target: 53, info: {TableName:d.public.foo Statement:CREATE TABLE foo (a INT PRIMARY KEY, b STRING) User:root}
I180912 22:05:59.709129 11000 storage/replica_command.go:298  [n1,split,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180912 22:06:06.052989 10740 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789966.050134066,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.043121 10781 server/status/runtime.go:484  [n1] runtime stats: 450 MiB RSS, 204 goroutines, 13 MiB/15 MiB/43 MiB GO alloc/idle/total, 33 MiB/63 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (121x), 0.0/0.0/0 (%r/%w/q)disk, 1.7 MiB/1.7 MiB (r/w)net
I180912 22:06:07.054568 10746 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.051534297,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.539030 10753 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.530159633,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.539172 10748 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.531825982,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.701009 11226 sql/event_log.go:126  [n1,client=127.0.0.1:36828,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}
I180912 22:06:07.708853 10757 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.705762809,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.712315 11175 storage/replica_command.go:298  [n1,split,s1,r24/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r25]
I180912 22:06:07.722429 10701 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.717067657,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:07.800127 10755 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789967.784699718,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:08.007390 10717 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789968.004117661,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:08.056004 10722 storage/replica_proposal.go:211  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789968.053053222,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:09.058116 10728 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789969.054677512,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:11.068413 10735 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789971.057293751,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:13.062731 10752 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789973.059802530,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:14.065884 10714 storage/replica_proposal.go:211  [n1,s1,r22/1:/Table/5{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789974.062811289,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:16.069104 10729 storage/replica_proposal.go:211  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789976.065746129,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:16.477514 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:17.079769 10781 server/status/runtime.go:484  [n1] runtime stats: 451 MiB RSS, 209 goroutines, 19 MiB/9.3 MiB/43 MiB GO alloc/idle/total, 34 MiB/64 MiB CGO alloc/total, 239.4 CGO/sec, 70.5/0.6 %(u/s)time, 0.5 %gc (3x), 0.0/19.1/0 (%r/%w/q)disk, 3.3 MiB/3.3 MiB (r/w)net
I180912 22:06:17.479877 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:18.480233 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:19.092401 10750 storage/replica_proposal.go:211  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789979.089437299,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:19.480588 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:20.484581 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:20.759203 11221 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382466666508451841 encountered retryable error: synthetic retryable error
I180912 22:06:21.095212 10757 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789981.092150759,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:21.484978 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:22.097787 10702 storage/replica_proposal.go:211  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789982.094698170,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:22.485273 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:23.489113 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:24.489428 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:25.489791 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:26.490131 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:27.091610 10781 server/status/runtime.go:484  [n1] runtime stats: 453 MiB RSS, 204 goroutines, 17 MiB/12 MiB/43 MiB GO alloc/idle/total, 33 MiB/65 MiB CGO alloc/total, 133.9 CGO/sec, 64.1/0.5 %(u/s)time, 0.5 %gc (3x), 0.0/433.1/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180912 22:06:27.104620 10711 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789987.101652818,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:27.490588 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:28.106095 10725 storage/replica_proposal.go:211  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1536789957.015101340,0 epo=1 pro=1536789988.103052501,0 following repl=(n1,s1):1 seq=2 start=1536789957.015101340,0 exp=1536789966.031510493,0 pro=1536789957.031547070,0
I180912 22:06:28.490948 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:29.491294 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:30.491621 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:31.491968 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:32.492347 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:33.492727 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:34.497116 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:35.497485 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:36.497825 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:37.103307 10781 server/status/runtime.go:484  [n1] runtime stats: 453 MiB RSS, 204 goroutines, 20 MiB/8.4 MiB/43 MiB GO alloc/idle/total, 33 MiB/65 MiB CGO alloc/total, 41.2 CGO/sec, 49.3/0.3 %(u/s)time, 0.3 %gc (2x), 0.0/420.1/0 (%r/%w/q)disk, 3.8 MiB/3.8 MiB (r/w)net
I180912 22:06:37.498173 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:38.498507 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:39.498887 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:40.499227 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:41.499532 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:42.501085 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:42.688586 11221 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382466666508451841 encountered retryable error: synthetic retryable error
I180912 22:06:43.503481 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:44.503908 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:45.505519 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:46.505898 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:47.105677 10781 server/status/runtime.go:484  [n1] runtime stats: 456 MiB RSS, 204 goroutines, 13 MiB/15 MiB/43 MiB GO alloc/idle/total, 34 MiB/66 MiB CGO alloc/total, 95.2 CGO/sec, 54.4/0.4 %(u/s)time, 0.6 %gc (3x), 0.0/378.3/0 (%r/%w/q)disk, 3.1 MiB/3.1 MiB (r/w)net
I180912 22:06:47.506248 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:48.507565 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:49.507905 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:50.508231 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:51.510522 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:52.510883 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:53.511222 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:54.511593 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:55.511947 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:56.512262 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:57.041649 10777 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];
 
I180912 22:06:57.114776 10781 server/status/runtime.go:484  [n1] runtime stats: 457 MiB RSS, 205 goroutines, 22 MiB/7.5 MiB/43 MiB GO alloc/idle/total, 34 MiB/66 MiB CGO alloc/total, 30.6 CGO/sec, 59.2/0.4 %(u/s)time, 0.5 %gc (2x), 0.0/11.3/0 (%r/%w/q)disk, 3.8 MiB/3.8 MiB (r/w)net
I180912 22:06:57.513666 10379 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 22:06:58.514316 10379 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: batch
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I180912 22:06:58.525292 10379 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: batch
1      [async] transport racer
W180912 22:06:58.549971 10782 ts/db.go:195  [n1,ts-poll] error writing time series data: result is ambiguous (server shutdown)
I180912 22:06:58.552565 10379 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      [async] transport racer
I180912 22:06:58.553519 10379 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
I180912 22:06:59.018073 10587 kv/transport_race.go:91  transport race promotion: ran 60 iterations on up to 1406 requests
------- Stdout: -------
W180912 22:03:51.572823 11861 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180912 22:03:51.591885 11861 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180912 22:03:51.592091 11861 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 22:03:51.592161 11861 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 22:03:51.605507 11861 server/config.go:493  [n?] 1 storage engine initialized
I180912 22:03:51.605544 11861 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180912 22:03:51.605553 11861 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180912 22:03:51.609192 11861 util/stop/stopper.go:537  [n?] quiescing; tasks left:
1      [async] closedts-rangefeed-subscriber
I180912 22:03:51.609462 11861 server/node.go:374  [n?] **** cluster daca19b9-e731-40dd-9db5-f6e0001a6ffd has been created
I180912 22:03:51.609485 11861 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:42085
I180912 22:03:51.609640 11861 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:42085" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-774-g692954f" started_at:1536789831609563921 
I180912 22:03:51.610560 11861 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}
I180912 22:03:51.610631 11861 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180912 22:03:51.610698 11861 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180912 22:03:51.610823 11958 gossip/gossip.go:942  [n1] gossip connectivity
 
I180912 22:03:51.611277 11861 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "daca19b9-e731-40dd-9db5-f6e0001a6ffd"
I180912 22:03:51.611308 11861 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180912 22:03:51.611565 11861 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180912 22:03:51.611602 11861 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180912 22:03:51.611675 11861 server/server.go:1550  [n1] starting https server at 127.0.0.1:42461 (use: 127.0.0.1:42461)
I180912 22:03:51.611694 11861 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:42085
I180912 22:03:51.611710 11861 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:42085
I180912 22:03:51.636033 11774 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180912 22:03:51.642426 11961 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180912 22:03:51.650811 11966 storage/replica_command.go:298  [n1,split,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180912 22:03:51.675374 12181 storage/replica_command.go:298  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180912 22:03:51.683977 12199 storage/replica_command.go:298  [n1,split,s1,r5/1:/{System/tsd-Max}] initiating a split of this r

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.2 milestone Sep 12, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Sep 12, 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