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