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.

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

teamcity: failed tests on master: test/TestChangefeedRetryableSinkError, testrace/TestChangefeedRetryableSinkError, roachtest/acceptance #30161

Closed
cockroach-teamcity opened this issue Sep 12, 2018 · 0 comments
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#901053:

--- FAIL: testrace/TestChangefeedRetryableSinkError (61.820s)
soon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10491 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc420932d80, 0x3df14a0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e51460, 0xc4210122d0, 0xc421210a70)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc4210122d0)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc4210122d0, 0x3776db0)
		/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 21:22:21.151177 10491 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 21:22:21.199612 10491 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180912 21:22:21.200194 10491 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 21:22:21.200290 10491 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 21:22:21.231205 10491 server/config.go:493  [n?] 1 storage engine initialized
I180912 21:22:21.231351 10491 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180912 21:22:21.231411 10491 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180912 21:22:21.330047 10491 server/node.go:374  [n?] **** cluster a2de5523-db10-4523-b0de-7b72041f6834 has been created
I180912 21:22:21.330219 10491 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:38313
I180912 21:22:21.331399 10491 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:38313" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-768-g0d49ee2" started_at:1536787341331007426 
I180912 21:22:21.332801 10551 gossip/gossip.go:942  [n1] gossip connectivity
 
I180912 21:22:21.356892 10491 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 21:22:21.370000 10491 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180912 21:22:21.370678 10491 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180912 21:22:21.370890 10491 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "a2de5523-db10-4523-b0de-7b72041f6834"
I180912 21:22:21.371370 10491 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180912 21:22:21.372660 10491 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180912 21:22:21.372771 10491 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180912 21:22:21.374946 10491 server/server.go:1550  [n1] starting https server at 127.0.0.1:41105 (use: 127.0.0.1:41105)
I180912 21:22:21.375137 10491 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:38313
I180912 21:22:21.375228 10491 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:38313
I180912 21:22:21.410689 10459 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180912 21:22:21.540730 10553 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180912 21:22:21.653412 10802 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180912 21:22:21.910621 10540 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 21:22:22.014497 10519 storage/replica_command.go:298  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
W180912 21:22:22.027214 10775 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=45e0d2b8 key=/Table/SystemConfigSpan/Start rw=true pri=0.05261959 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536787341.722278830,0 orig=1536787341.722278830,0 max=1536787341.722278830,0 wto=false rop=false seq=12
I180912 21:22:22.058138 10465 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 21:22:22.159009 10556 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180912 21:22:22.167781 10777 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 21:22:22.285170 10838 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 21:22:22.359530 10866 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 21:22:22.426129 10840 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 21:22:22.503402 10571 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:154bc73f-1ec5-4333-9775-366751c344d0 User:root}
I180912 21:22:22.510026 10871 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180912 21:22:22.594288 10844 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 21:22:22.657982 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]
I180912 21:22:22.680237 10827 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 21:22:22.725197 10901 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 21:22:22.764830 10885 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 21:22:22.812270 10931 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 21:22:22.819778 10491 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180912 21:22:22.819910 10491 server/server.go:1609  [n1] serving sql connections
I180912 21:22:22.834095 10491 server/testserver.go:420  had 12 ranges at startup, expected 22
I180912 21:22:22.874745 10962 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:38313} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-768-g0d49ee2 StartedAt:1536787341331007426 LocalityAddress:[]} ClusterID:a2de5523-db10-4523-b0de-7b72041f6834 StartedAt:1536787341331007426 LastUp:1536787341331007426}
I180912 21:22:22.909278 10832 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 21:22:22.924407 10864 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180912 21:22:22.951799 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.952555 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.953229 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.953811 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.959891 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.960627 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.962792 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.972383 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.973162 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.973838 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.974574 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.975320 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.975922 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.981119 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.981829 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.982516 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.983294 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.984122 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.986596 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.987853 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.989626 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.992680 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.999498 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:23.043316 10957 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 21:22:23.044379 10491 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 21:22:23.065410 10491 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 21:22:23.097482 10997 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 21:22:23.120290 10491 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:22:23.182605 10970 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 21:22:23.242442 10551 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180912 21:22:23.245982 10972 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 21:22:23.258642 10491 server/testserver.go:420  had 17 ranges at startup, expected 22
I180912 21:22:23.291453 11022 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 21:22:23.398268 10491 server/testserver.go:420  had 19 ranges at startup, expected 22
I180912 21:22:23.398730 10961 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 21:22:23.483144 11030 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 21:22:23.536263 11035 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 21:22:23.850869 11007 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 21:22:23.867721 11037 sql/event_log.go:126  [n1,client=127.0.0.1:60886,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180912 21:22:23.959935 11037 sql/event_log.go:126  [n1,client=127.0.0.1:60886,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 21:22:23.961278 10894 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 21:22:30.389981 10738 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787350.387046594,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.166532 10736 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.163541654,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.175182 10737 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.172243975,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.193888 10740 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.190751315,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.254285 11175 sql/event_log.go:126  [n1,client=127.0.0.1:60894,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 21:22:31.284469 10748 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.281632799,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.286978 11130 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 21:22:31.294698 10745 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.288776790,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.332919 10686 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.321333776,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.405229 10768 server/status/runtime.go:484  [n1] runtime stats: 413 MiB RSS, 206 goroutines, 19 MiB/10 MiB/43 MiB GO alloc/idle/total, 34 MiB/70 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (119x), 0.0/0.0/0 (%r/%w/q)disk, 12 MiB/12 MiB (r/w)net
I180912 21:22:31.417689 10690 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.408502614,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:32.431542 10716 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787352.418576767,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:33.423897 10718 storage/replica_proposal.go:211  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787353.411050795,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:35.467949 10724 storage/replica_proposal.go:211  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787355.453030705,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:39.880312 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:40.880672 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:41.418053 10768 server/status/runtime.go:484  [n1] runtime stats: 416 MiB RSS, 209 goroutines, 20 MiB/8.7 MiB/43 MiB GO alloc/idle/total, 35 MiB/72 MiB CGO alloc/total, 212.4 CGO/sec, 66.9/0.6 %(u/s)time, 0.5 %gc (3x), 1.5/481.3/0 (%r/%w/q)disk, 13 MiB/13 MiB (r/w)net
I180912 21:22:41.881022 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:42.435961 10724 storage/replica_proposal.go:211  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787362.424714462,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:42.881407 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:43.881742 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:44.430347 10739 storage/replica_proposal.go:211  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787364.427256550,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:44.892436 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:45.770639 11098 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382458093221117953 encountered retryable error: synthetic retryable error
I180912 21:22:45.892834 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:46.432797 10744 storage/replica_proposal.go:211  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787366.429859546,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:46.893207 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:47.434328 10746 storage/replica_proposal.go:211  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787367.431272412,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:47.893539 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:48.439517 10748 storage/replica_proposal.go:211  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787368.436627510,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:48.893851 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:49.894243 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:50.455344 10695 storage/replica_proposal.go:211  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787370.440643279,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:50.894605 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:51.420278 10768 server/status/runtime.go:484  [n1] runtime stats: 416 MiB RSS, 203 goroutines, 17 MiB/12 MiB/43 MiB GO alloc/idle/total, 34 MiB/72 MiB CGO alloc/total, 100.6 CGO/sec, 58.9/0.3 %(u/s)time, 1.0 %gc (3x), 5.6/54.5/0 (%r/%w/q)disk, 12 MiB/12 MiB (r/w)net
I180912 21:22:51.445444 10701 storage/replica_proposal.go:211  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787371.442514448,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:51.894972 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:52.446713 10710 storage/replica_proposal.go:211  [n1,s1,r22/1:/Table/5{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787372.443766961,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:52.895877 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:53.448180 10712 storage/replica_proposal.go:211  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787373.445188203,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:53.896222 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:54.896585 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:55.897308 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:56.897606 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:57.897963 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:58.898298 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:22:59.898619 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:00.898975 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:01.444898 10768 server/status/runtime.go:484  [n1] runtime stats: 417 MiB RSS, 210 goroutines, 20 MiB/9.5 MiB/43 MiB GO alloc/idle/total, 35 MiB/72 MiB CGO alloc/total, 63.2 CGO/sec, 57.8/0.2 %(u/s)time, 0.4 %gc (2x), 8.2/10.6/0 (%r/%w/q)disk, 12 MiB/12 MiB (r/w)net
I180912 21:23:01.899263 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:02.899605 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:03.900518 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:04.900907 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:05.901245 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:06.254995 11098 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382458093221117953 encountered retryable error: synthetic retryable error
I180912 21:23:06.901588 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:07.901953 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:08.902313 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:09.903027 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:10.903456 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:11.477067 10768 server/status/runtime.go:484  [n1] runtime stats: 418 MiB RSS, 204 goroutines, 20 MiB/9.5 MiB/43 MiB GO alloc/idle/total, 36 MiB/73 MiB CGO alloc/total, 55.0 CGO/sec, 54.7/0.4 %(u/s)time, 0.3 %gc (2x), 0.9/895.4/0 (%r/%w/q)disk, 13 MiB/13 MiB (r/w)net
I180912 21:23:11.903788 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:12.904233 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:13.904588 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:14.904947 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:15.905292 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:16.905645 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:17.906003 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:18.906423 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:19.906773 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:20.907163 10491 ccl/changefeedccl/changefeed_test.go:811  SucceedsSoon: insufficient sink error retries detected
I180912 21:23:21.372097 10764 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 21:23:21.492808 10768 server/status/runtime.go:484  [n1] runtime stats: 420 MiB RSS, 204 goroutines, 22 MiB/7.9 MiB/43 MiB GO alloc/idle/total, 36 MiB/73 MiB CGO alloc/total, 31.6 CGO/sec, 53.9/0.3 %(u/s)time, 0.8 %gc (3x), 0.5/14.7/0 (%r/%w/q)disk, 12 MiB/12 MiB (r/w)net
I180912 21:23:21.907855 10491 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: writing summary
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I180912 21:23:21.908040 10464 kv/transport_race.go:91  transport race promotion: ran 48 iterations on up to 1477 requests
I180912 21:23:21.915690 10491 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: writing summary
1      [async] closedts-rangefeed-subscriber
I180912 21:23:21.923152 10491 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
1      node.Node: writing summary
W180912 21:23:22.101089 10754 storage/store.go:1659  [n1,s1,r1/1:/{Min-System/}] could not gossip first range descriptor: node unavailable; try another peer
W180912 21:23:22.128885 10786 server/node.go:860  [n1,summaries] error recording status summaries: node unavailable; try another peer
I180912 21:23:22.128913 10491 util/stop/stopper.go:537  quiescing; tasks left:
1      ts.poller: poll
W180912 21:23:22.145432 10754 storage/store.go:1659  [n1,s1,r1/1:/{Min-System/}] could not gossip first range descriptor: node unavailable; try another peer
W180912 21:23:22.235311 10754 storage/store.go:1659  [n1,s1,r1/1:/{Min-System/}] could not gossip first range descriptor: node unavailable; try another peer
W180912 21:23:22.415150 10754 storage/store.go:1659  [n1,s1,r1/1:/{Min-System/}] could not gossip first range descriptor: node unavailable; try another peer
I180912 21:23:22.707468 11098 ccl/changefeedccl/changefeed_stmt.go:402  [n1] CHANGEFEED job 382458093221117953 returning with error: dial tcp 127.0.0.1:38313: connect: connection refused
W180912 21:23:22.790369 10754 storage/store.go:1659  [n1,s1,r1/1:/{Min-System/}] could not gossip first range descriptor: node unavailable; try another peer
W180912 21:23:22.847469 10769 ts/db.go:195  [n1,ts-poll] error writing time series data: node unavailable; try another peer
--- FAIL: roachtest/acceptance/bank/node-restart (60.296s)
	test.go:503,bank.go:291,bank.go:398,acceptance.go:59: stall detected at round 9, no forward progress for 30s

--- FAIL: roachtest/acceptance/bank/node-restart (60.296s)
	test.go:503,bank.go:291,bank.go:398,acceptance.go:59: stall detected at round 9, no forward progress for 30s

--- FAIL: test/TestChangefeedRetryableSinkError (64.050s)

------- Stdout: -------
W180912 21:20:17.483486 11022 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 21:20:17.499692 11022 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180912 21:20:17.500173 11022 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 21:20:17.500192 11022 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 21:20:17.502797 11022 server/config.go:493  [n?] 1 storage engine initialized
I180912 21:20:17.502838 11022 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180912 21:20:17.502859 11022 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180912 21:20:17.506447 11022 util/stop/stopper.go:537  [n?] quiescing; tasks left:
1      [async] closedts-rangefeed-subscriber
I180912 21:20:17.506799 11022 server/node.go:374  [n?] **** cluster 7436c9c0-3235-4703-99a0-b88923a6add8 has been created
I180912 21:20:17.506820 11022 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:37041
I180912 21:20:17.506955 11022 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:37041" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-768-g0d49ee2" started_at:1536787217506896453 
I180912 21:20:17.507339 11388 gossip/gossip.go:942  [n1] gossip connectivity
 
I180912 21:20:17.508061 11022 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 21:20:17.508117 11022 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180912 21:20:17.508183 11022 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180912 21:20:17.509586 11022 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "7436c9c0-3235-4703-99a0-b88923a6add8"
I180912 21:20:17.509626 11022 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180912 21:20:17.509886 11022 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180912 21:20:17.509933 11022 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180912 21:20:17.510038 11022 server/server.go:1550  [n1] starting https server at 127.0.0.1:43219 (use: 127.0.0.1:43219)
I180912 21:20:17.510072 11022 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:37041
I180912 21:20:17.510095 11022 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:37041
I180912 21:20:17.512322 11365 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180912 21:20:17.536115 11368 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180912 21:20:17.540617 11373 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180912 21:20:17.561066 11618 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 21:20:17.562664 11308 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 21:20:17.573441 11396 storage/replica_command.go:298  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
W180912 21:20:17.576360 11638 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=e75864c1 key=/Table/SystemConfigSpan/Start rw=true pri=0.02803952 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536787217.564659083,0 orig=1536787217.564659083,0 max=1536787217.564659083,0 wto=false rop=false seq=6
I180912 21:20:17.580078 11621 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 21:20:17.585860 11606 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180912 21:20:17.593826 11492 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 21:20:17.599207 11640 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 21:20:17.612731 11613 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 21:20:17.616865 11642 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 21:20:17.625083 11648 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 21:20:17.628947 11625 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:0f5701b4-5cde-422b-a76d-7067dcbcd0a9 User:root}
I180912 21:20:17.632543 11632 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 21:20:17.637764 11737 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 21:20:17.638933 11663 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 21:20:17.645348 11747 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 21:20:17.648153 11022 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180912 21:20:17.648185 11022 server/server.go:1609  [n1] serving sql connections
I180912 21:20:17.648568 11022 server/testserver.go:420  had 12 ranges at startup, expected 22
I180912 21:20:17.650767 11754 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180912 21:20:17.651073 11756 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:37041} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-768-g0d49ee2 StartedAt:1536787217506896453 LocalityAddress:[]} ClusterID:7436c9c0-3235-4703-99a0-b88923a6add8 StartedAt:1536787217506896453 LastUp:1536787217506896453}
I180912 21:20:17.651718 11763 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 21:20:17.652140 11022 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:20:17.652390 11022 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:20:17.653094 11022 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:20:17.653419 11022 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:20:17.656716 11692 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 21:20:17.660061 11022 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 21:20:17.663016 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.663235 11770 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 21:20:17.663339 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.663553 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.663966 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.664300 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.664449 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.664588 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.664728 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.664932 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.668522 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.669029 11022 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:20:17.672870 11783 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 21:20:17.673490 11022 server/testserver.go:420  had 16 ranges at startup, expected 22
I180912 21:20:17.674052 11022 server/testserver.go:420  had 16 ranges at startup, expected 22
I180912 21:20:17.674580 11022 server/testserver.go:420  had 16 ranges at startup, expected 22
I180912 21:20:17.675529 11022 server/testserver.go:420  had 16 ranges at startup, expected 22
I180912 21:20:17.676866 11022 server/testserver.go:420  had 16 ranges at startup, expected 22
I180912 21:20:17.680899 11742 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 21:20:17.682990 11022 server/testserver.go:420  had 17 ranges at startup, expected 22
I180912 21:20:17.685724 11831 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 21:20:17.688241 11022 server/testserver.go:420  had 18 ranges at startup, expected 22
I180912 21:20:17.691322 11703 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 21:20:17.696243 11713 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 21:20:17.697798 11022 server/testserver.go:420  had 20 ranges at startup, expected 22
I180912 21:20:17.700989 11879 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 21:20:17.739702 11802 sql/event_log.go:126  [n1,client=127.0.0.1:47784,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180912 21:20:17.741009 11893 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 21:20:17.743466 11802 sql/event_log.go:126  [n1,client=127.0.0.1:47784,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 21:20:17.745478 11902 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 21:20:18.032944 11926 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 21:20:18.040662 11956 sql/event_log.go:126  [n1,client=127.0.0.1:47794,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 21:20:18.451420 11920 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382457668897898497 encountered retryable error: synthetic retryable error
I180912 21:20:18.537522 11977 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180912 21:20:18.946456 11920 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382457668897898497 encountered retryable error: synthetic retryable error
I180912 21:20:19.416436 11920 ccl/changefeedccl/changefeed_stmt.go:382  [n1] CHANGEFEED job 382457668897898497 encountered retryable error: synthetic retryable error
I180912 21:20:19.503659 11388 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180912 21:20:19.576744 11022 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] closedts-rangefeed-subscriber
E180912 21:20:19.577582 11920 sql/distsqlrun/server.go:440  [n1] error setting up flow: EOF
I180912 21:20:19.577614 11920 ccl/changefeedccl/changefeed_stmt.go:402  [n1] CHANGEFEED job 382457668897898497 returning with error: EOFsoon.go:49: condition failed to evaluate within 45s: insufficient sink error retries detected
	goroutine 10491 [running]:
	runtime/debug.Stack(0xa7a358200, 0xc420932d80, 0x3df14a0)
		/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
	github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e51460, 0xc4210122d0, 0xc421210a70)
		/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedRetryableSinkError(0xc4210122d0)
		/go/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:811 +0xc79
	testing.tRunner(0xc4210122d0, 0x3776db0)
		/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 21:22:21.151177 10491 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 21:22:21.199612 10491 server/server.go:851  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180912 21:22:21.200194 10491 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 21:22:21.200290 10491 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180912 21:22:21.231205 10491 server/config.go:493  [n?] 1 storage engine initialized
I180912 21:22:21.231351 10491 server/config.go:496  [n?] RocksDB cache size: 128 MiB
I180912 21:22:21.231411 10491 server/config.go:496  [n?] store 0: in-memory, size 0 B
I180912 21:22:21.330047 10491 server/node.go:374  [n?] **** cluster a2de5523-db10-4523-b0de-7b72041f6834 has been created
I180912 21:22:21.330219 10491 server/server.go:1413  [n?] **** add additional nodes by specifying --join=127.0.0.1:38313
I180912 21:22:21.331399 10491 gossip/gossip.go:408  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:38313" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:13 > build_tag:"v2.2.0-alpha.00000000-768-g0d49ee2" started_at:1536787341331007426 
I180912 21:22:21.332801 10551 gossip/gossip.go:942  [n1] gossip connectivity
 
I180912 21:22:21.356892 10491 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 21:22:21.370000 10491 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180912 21:22:21.370678 10491 server/node.go:700  [n1] connecting to gossip network to verify cluster ID...
I180912 21:22:21.370890 10491 server/node.go:725  [n1] node connected via gossip and verified as part of cluster "a2de5523-db10-4523-b0de-7b72041f6834"
I180912 21:22:21.371370 10491 server/node.go:549  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180912 21:22:21.372660 10491 server/status/recorder.go:611  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180912 21:22:21.372771 10491 server/server.go:1804  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180912 21:22:21.374946 10491 server/server.go:1550  [n1] starting https server at 127.0.0.1:41105 (use: 127.0.0.1:41105)
I180912 21:22:21.375137 10491 server/server.go:1552  [n1] starting grpc/postgres server at 127.0.0.1:38313
I180912 21:22:21.375228 10491 server/server.go:1553  [n1] advertising CockroachDB node at 127.0.0.1:38313
I180912 21:22:21.410689 10459 storage/replica_command.go:298  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180912 21:22:21.540730 10553 storage/replica_command.go:298  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180912 21:22:21.653412 10802 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180912 21:22:21.910621 10540 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 21:22:22.014497 10519 storage/replica_command.go:298  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
W180912 21:22:22.027214 10775 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=45e0d2b8 key=/Table/SystemConfigSpan/Start rw=true pri=0.05261959 iso=SERIALIZABLE stat=PENDING epo=0 ts=1536787341.722278830,0 orig=1536787341.722278830,0 max=1536787341.722278830,0 wto=false rop=false seq=12
I180912 21:22:22.058138 10465 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 21:22:22.159009 10556 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180912 21:22:22.167781 10777 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 21:22:22.285170 10838 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 21:22:22.359530 10866 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 21:22:22.426129 10840 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 21:22:22.503402 10571 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:154bc73f-1ec5-4333-9775-366751c344d0 User:root}
I180912 21:22:22.510026 10871 rpc/nodedialer/nodedialer.go:92  [n1,consistencyChecker,s1,r1/1:/{Min-System/}] connection to n1 established
I180912 21:22:22.594288 10844 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 21:22:22.657982 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]
I180912 21:22:22.680237 10827 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 21:22:22.725197 10901 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 21:22:22.764830 10885 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 21:22:22.812270 10931 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 21:22:22.819778 10491 server/server.go:1606  [n1] done ensuring all necessary migrations have run
I180912 21:22:22.819910 10491 server/server.go:1609  [n1] serving sql connections
I180912 21:22:22.834095 10491 server/testserver.go:420  had 12 ranges at startup, expected 22
I180912 21:22:22.874745 10962 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:38313} Attrs: Locality: ServerVersion:2.0-13 BuildTag:v2.2.0-alpha.00000000-768-g0d49ee2 StartedAt:1536787341331007426 LocalityAddress:[]} ClusterID:a2de5523-db10-4523-b0de-7b72041f6834 StartedAt:1536787341331007426 LastUp:1536787341331007426}
I180912 21:22:22.909278 10832 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 21:22:22.924407 10864 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180912 21:22:22.951799 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.952555 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.953229 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.953811 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.959891 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.960627 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.962792 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.972383 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.973162 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.973838 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.974574 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.975320 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.975922 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.981119 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.981829 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.982516 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.983294 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.984122 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.986596 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.987853 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.989626 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.992680 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:22.999498 10491 server/testserver.go:420  had 13 ranges at startup, expected 22
I180912 21:22:23.043316 10957 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 21:22:23.044379 10491 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 21:22:23.065410 10491 server/testserver.go:420  had 14 ranges at startup, expected 22
I180912 21:22:23.097482 10997 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 21:22:23.120290 10491 server/testserver.go:420  had 15 ranges at startup, expected 22
I180912 21:22:23.182605 10970 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 21:22:23.242442 10551 gossip/gossip.go:942  [n1] gossip connectivity
  n1 [sentinel];
 
I180912 21:22:23.245982 10972 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 21:22:23.258642 10491 server/testserver.go:420  had 17 ranges at startup, expected 22
I180912 21:22:23.291453 11022 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 21:22:23.398268 10491 server/testserver.go:420  had 19 ranges at startup, expected 22
I180912 21:22:23.398730 10961 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 21:22:23.483144 11030 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 21:22:23.536263 11035 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 21:22:23.850869 11007 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 21:22:23.867721 11037 sql/event_log.go:126  [n1,client=127.0.0.1:60886,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180912 21:22:23.959935 11037 sql/event_log.go:126  [n1,client=127.0.0.1:60886,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 21:22:23.961278 10894 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 21:22:30.389981 10738 storage/replica_proposal.go:211  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787350.387046594,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.166532 10736 storage/replica_proposal.go:211  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.163541654,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.175182 10737 storage/replica_proposal.go:211  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.172243975,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.193888 10740 storage/replica_proposal.go:211  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.190751315,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.254285 11175 sql/event_log.go:126  [n1,client=127.0.0.1:60894,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 21:22:31.284469 10748 storage/replica_proposal.go:211  [n1,s1,r24/1:/{Table/53-Max}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.281632799,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.286978 11130 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 21:22:31.294698 10745 storage/replica_proposal.go:211  [n1,s1,r23/1:/Table/5{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.288776790,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.332919 10686 storage/replica_proposal.go:211  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.321333776,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:31.405229 10768 server/status/runtime.go:484  [n1] runtime stats: 413 MiB RSS, 206 goroutines, 19 MiB/10 MiB/43 MiB GO alloc/idle/total, 34 MiB/70 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (119x), 0.0/0.0/0 (%r/%w/q)disk, 12 MiB/12 MiB (r/w)net
I180912 21:22:31.417689 10690 storage/replica_proposal.go:211  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787351.408502614,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:32.431542 10716 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1536787341.335955357,0 epo=1 pro=1536787352.418576767,0 following repl=(n1,s1):1 seq=2 start=1536787341.335955357,0 exp=1536787350.350838425,0 pro=1536787341.350874155,0
I180912 21:22:33

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 added a commit to benesch/cockroach that referenced this issue Sep 13, 2018
TestChangefeedRetryableSinkError was performing many rounds of bcrypt,
which is excruciatingly slow when the race detector is on. Put its test
cluster into insecure mode to skip bcrypt hashing.

Fix cockroachdb#30156.
Fix cockroachdb#30161.

Release note: None
benesch added a commit to benesch/cockroach that referenced this issue Sep 13, 2018
TestChangefeedRetryableSinkError was performing many rounds of bcrypt,
which is excruciatingly slow when the race detector is on. Put its test
cluster into insecure mode to skip bcrypt hashing.

Fix cockroachdb#30156.
Fix cockroachdb#30161.

Release note: None
craig bot pushed a commit that referenced this issue Sep 13, 2018
30172: changefeedccl: deflake TestChangefeedRetryableSinkError r=nvanbenschoten,arjunravinarayan,mrtracy a=benesch

TestChangefeedRetryableSinkError was performing many rounds of bcrypt,
which is excruciatingly slow when the race detector is on. Put its test
cluster into insecure mode to skip bcrypt hashing.

Fix #30156.
Fix #30161.

Release note: None

Co-authored-by: Nikhil Benesch <nikhil.benesch@gmail.com>
@craig craig bot closed this as completed in #30172 Sep 13, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Development

No branches or pull requests

1 participant