teamcity: failed tests on master: testrace/TestChangefeedTimestamps, test/TestChangefeedTimestamps #29271
Description
The following tests appear to have failed:
--- FAIL: test/TestChangefeedTimestamps (0.470s)
changefeed_test.go:188: error scanning '&{<nil> 0xc42124b200}': pq: restart transaction: HandledRetryableTxnError: TransactionRetryError: retry txn (RETRY_SERIALIZABLE): "sql txn" id=415c4e7f key=/Table/53/1/1/0 rw=true pri=0.00591776 iso=SERIALIZABLE stat=PENDING epo=0 ts=1535556719.293778058,1 orig=1535556719.286437264,0 max=1535556719.286437264,0 wto=false rop=false seq=3
------- Stdout: -------
W180829 15:31:58.849194 2853 server/status/runtime.go:310 [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180829 15:31:58.863026 2853 server/server.go:849 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180829 15:31:58.863237 2853 base/addr_validation.go:271 [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180829 15:31:58.863257 2853 base/addr_validation.go:311 [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180829 15:31:58.877696 2853 server/config.go:493 [n?] 1 storage engine initialized
I180829 15:31:58.877732 2853 server/config.go:496 [n?] RocksDB cache size: 128 MiB
I180829 15:31:58.877741 2853 server/config.go:496 [n?] store 0: in-memory, size 0 B
I180829 15:31:58.888340 2853 server/node.go:373 [n?] **** cluster 134ebbb7-0f04-47c8-b955-9320356cd647 has been created
I180829 15:31:58.888383 2853 server/server.go:1411 [n?] **** add additional nodes by specifying --join=127.0.0.1:42533
I180829 15:31:58.888574 2853 gossip/gossip.go:382 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:42533" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2118-gc1e0990" started_at:1535556718888495642
I180829 15:31:58.889752 2853 storage/store.go:1540 [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180829 15:31:58.889858 2853 server/node.go:476 [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}
I180829 15:31:58.889912 2853 storage/stores.go:242 [n1] read 0 node addresses from persistent storage
I180829 15:31:58.889993 2853 server/node.go:697 [n1] connecting to gossip network to verify cluster ID...
I180829 15:31:58.903684 2853 server/node.go:722 [n1] node connected via gossip and verified as part of cluster "134ebbb7-0f04-47c8-b955-9320356cd647"
I180829 15:31:58.903734 2853 server/node.go:546 [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180829 15:31:58.904035 2853 server/status/recorder.go:652 [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180829 15:31:58.904076 2853 server/server.go:1802 [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180829 15:31:58.904208 2853 server/server.go:1548 [n1] starting https server at 127.0.0.1:42089 (use: 127.0.0.1:42089)
I180829 15:31:58.904229 2853 server/server.go:1550 [n1] starting grpc/postgres server at 127.0.0.1:42533
I180829 15:31:58.904247 2853 server/server.go:1551 [n1] advertising CockroachDB node at 127.0.0.1:42533
I180829 15:31:58.907896 3145 storage/replica_command.go:298 [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180829 15:31:58.907959 3119 server/status/recorder.go:652 [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180829 15:31:58.925523 2881 sql/event_log.go:126 [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180829 15:31:58.938024 3157 storage/replica_command.go:298 [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180829 15:31:58.953820 3150 storage/replica_command.go:298 [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
W180829 15:31:58.958711 2951 storage/intent_resolver.go:668 [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=e91cd13a key=/Table/SystemConfigSpan/Start rw=true pri=0.01682788 iso=SERIALIZABLE stat=PENDING epo=0 ts=1535556718.941726190,0 orig=1535556718.941726190,0 max=1535556718.941726190,0 wto=false rop=false seq=12
I180829 15:31:58.964108 3171 sql/event_log.go:126 [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-12 User:root}
I180829 15:31:58.972533 3188 storage/replica_command.go:298 [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180829 15:31:58.981827 3177 sql/event_log.go:126 [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180829 15:31:58.983505 2026 storage/replica_command.go:298 [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180829 15:31:58.995316 3220 storage/replica_command.go:298 [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180829 15:31:59.006890 3212 sql/event_log.go:126 [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:087e78db-d16f-448c-bcd5-89c39825663b User:root}
I180829 15:31:59.010424 3192 storage/replica_command.go:298 [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180829 15:31:59.036685 3241 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}
I180829 15:31:59.056829 3167 storage/replica_command.go:298 [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180829 15:31:59.060232 3252 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}
I180829 15:31:59.062121 3262 storage/replica_command.go:298 [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180829 15:31:59.063617 2853 server/server.go:1604 [n1] done ensuring all necessary migrations have run
I180829 15:31:59.063652 2853 server/server.go:1607 [n1] serving sql connections
I180829 15:31:59.068671 3285 sql/event_log.go:126 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:42533} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2118-gc1e0990 StartedAt:1535556718888495642 LocalityAddress:[]} ClusterID:134ebbb7-0f04-47c8-b955-9320356cd647 StartedAt:1535556718888495642 LastUp:1535556718888495642}
I180829 15:31:59.070317 3283 server/server_update.go:67 [n1] no need to upgrade, cluster already at the newest version
I180829 15:31:59.072985 3273 storage/replica_command.go:298 [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180829 15:31:59.077989 3249 storage/replica_command.go:298 [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180829 15:31:59.089558 3334 storage/replica_command.go:298 [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180829 15:31:59.104468 3341 storage/replica_command.go:298 [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180829 15:31:59.117941 3287 storage/replica_command.go:298 [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180829 15:31:59.123115 3394 storage/replica_command.go:298 [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180829 15:31:59.129374 2056 storage/replica_command.go:298 [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180829 15:31:59.136261 2060 storage/replica_command.go:298 [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180829 15:31:59.142523 2064 storage/replica_command.go:298 [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180829 15:31:59.150211 3422 storage/replica_command.go:298 [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180829 15:31:59.157559 3474 storage/replica_command.go:298 [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180829 15:31:59.177053 3324 storage/replica_command.go:298 [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180829 15:31:59.242592 3452 sql/event_log.go:126 [n1,client=127.0.0.1:55370,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:0s User:root}
I180829 15:31:59.246529 3452 sql/event_log.go:126 [n1,client=127.0.0.1:55370,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180829 15:31:59.247657 3455 storage/replica_command.go:298 [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180829 15:31:59.250517 3452 sql/event_log.go:126 [n1,client=127.0.0.1:55370,user=root] Event: "create_table", target: 53, info: {TableName:d.public.foo Statement:CREATE TABLE foo (a INT PRIMARY KEY) User:root}
I180829 15:31:59.256577 3499 storage/replica_command.go:298 [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
--- FAIL: testrace/TestChangefeedTimestamps (3.600s)
------- Stdout: -------
W180829 15:32:31.439633 2841 server/status/runtime.go:310 [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180829 15:32:31.527158 2841 server/server.go:849 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180829 15:32:31.527738 2841 base/addr_validation.go:271 [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180829 15:32:31.527848 2841 base/addr_validation.go:311 [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180829 15:32:31.550111 2841 server/config.go:493 [n?] 1 storage engine initialized
I180829 15:32:31.550227 2841 server/config.go:496 [n?] RocksDB cache size: 128 MiB
I180829 15:32:31.550278 2841 server/config.go:496 [n?] store 0: in-memory, size 0 B
I180829 15:32:31.652778 2841 server/node.go:373 [n?] **** cluster d96ec1d0-7737-4ad2-84ab-584267668e1f has been created
I180829 15:32:31.652984 2841 server/server.go:1411 [n?] **** add additional nodes by specifying --join=127.0.0.1:39027
I180829 15:32:31.653948 2841 gossip/gossip.go:382 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:39027" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2118-gc1e0990" started_at:1535556751653612019
I180829 15:32:31.720413 2841 server/node.go:476 [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}
I180829 15:32:31.720736 2841 storage/stores.go:242 [n1] read 0 node addresses from persistent storage
I180829 15:32:31.721149 2841 server/node.go:697 [n1] connecting to gossip network to verify cluster ID...
I180829 15:32:31.721283 2841 server/node.go:722 [n1] node connected via gossip and verified as part of cluster "d96ec1d0-7737-4ad2-84ab-584267668e1f"
I180829 15:32:31.721743 2841 server/node.go:546 [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180829 15:32:31.722910 2841 server/status/recorder.go:652 [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180829 15:32:31.722994 2841 server/server.go:1802 [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180829 15:32:31.725252 2841 server/server.go:1548 [n1] starting https server at 127.0.0.1:36381 (use: 127.0.0.1:36381)
I180829 15:32:31.725342 2841 server/server.go:1550 [n1] starting grpc/postgres server at 127.0.0.1:39027
I180829 15:32:31.725394 2841 server/server.go:1551 [n1] advertising CockroachDB node at 127.0.0.1:39027
I180829 15:32:31.731083 3111 server/status/recorder.go:652 [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180829 15:32:31.790687 2956 storage/replica_command.go:298 [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180829 15:32:31.920648 3005 storage/replica_command.go:298 [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180829 15:32:31.942424 3096 storage/intent_resolver.go:668 [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=4f74ebe0 key=/Table/SystemConfigSpan/Start rw=true pri=0.01758039 iso=SERIALIZABLE stat=PENDING epo=0 ts=1535556751.797782036,0 orig=1535556751.797782036,0 max=1535556751.797782036,0 wto=false rop=false seq=6
I180829 15:32:31.955294 2919 sql/event_log.go:126 [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180829 15:32:32.173137 3156 storage/replica_command.go:298 [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180829 15:32:32.281816 3189 storage/replica_command.go:298 [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180829 15:32:32.388131 2926 storage/replica_command.go:298 [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180829 15:32:32.443911 2766 sql/event_log.go:126 [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-12 User:root}
I180829 15:32:32.457358 3163 storage/replica_command.go:298 [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180829 15:32:32.529678 3152 storage/replica_command.go:298 [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180829 15:32:32.574121 3147 sql/event_log.go:126 [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180829 15:32:32.660202 3220 storage/replica_command.go:298 [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180829 15:32:32.724203 2825 storage/replica_command.go:298 [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180829 15:32:32.790017 3266 storage/replica_command.go:298 [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180829 15:32:32.848386 3227 sql/event_log.go:126 [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:c6b7287b-2729-4eef-9cd4-11b5c856cedd User:root}
I180829 15:32:32.895308 3239 storage/replica_command.go:298 [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180829 15:32:32.909811 3198 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}
I180829 15:32:32.918947 3216 rpc/nodedialer/nodedialer.go:92 [consistencyChecker,n1,s1,r1/1:/{Min-System/}] connection to n1 established
I180829 15:32:32.952982 3244 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}
I180829 15:32:32.965224 3287 storage/replica_command.go:298 [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180829 15:32:33.023505 2841 server/server.go:1604 [n1] done ensuring all necessary migrations have run
I180829 15:32:33.023631 2841 server/server.go:1607 [n1] serving sql connections
I180829 15:32:33.052809 3305 storage/replica_command.go:298 [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180829 15:32:33.066167 3315 sql/event_log.go:126 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:39027} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2118-gc1e0990 StartedAt:1535556751653612019 LocalityAddress:[]} ClusterID:d96ec1d0-7737-4ad2-84ab-584267668e1f StartedAt:1535556751653612019 LastUp:1535556751653612019}
I180829 15:32:33.075890 3233 server/server_update.go:67 [n1] no need to upgrade, cluster already at the newest version
I180829 15:32:33.111523 3348 storage/replica_command.go:298 [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180829 15:32:33.163114 3337 storage/replica_command.go:298 [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180829 15:32:33.219342 3362 storage/replica_command.go:298 [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180829 15:32:33.295920 3370 storage/replica_command.go:298 [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180829 15:32:33.341224 3430 storage/replica_command.go:298 [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180829 15:32:33.389318 3380 storage/replica_command.go:298 [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180829 15:32:33.497648 3434 storage/replica_command.go:298 [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180829 15:32:33.549840 3467 storage/replica_command.go:298 [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180829 15:32:33.835233 3440 sql/event_log.go:126 [n1,client=127.0.0.1:49704,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:0s User:root}
I180829 15:32:33.879560 3388 storage/replica_command.go:298 [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180829 15:32:33.897716 3440 sql/event_log.go:126 [n1,client=127.0.0.1:49704,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180829 15:32:33.961285 3440 sql/event_log.go:126 [n1,client=127.0.0.1:49704,user=root] Event: "create_table", target: 53, info: {TableName:d.public.foo Statement:CREATE TABLE foo (a INT PRIMARY KEY) User:root}
I180829 15:32:33.969499 3406 storage/replica_command.go:298 [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180829 15:32:34.240108 2841 util/stop/stopper.go:537 quiescing; tasks left:
1 [async] transport racer
I180829 15:32:34.474359 3095 kv/transport_race.go:91 transport race promotion: ran 26 iterations on up to 1040 requestschangefeed_test.go:188: error scanning '&{<nil> 0xc42124b200}': pq: restart transaction: HandledRetryableTxnError: TransactionRetryError: retry txn (RETRY_SERIALIZABLE): "sql txn" id=415c4e7f key=/Table/53/1/1/0 rw=true pri=0.00591776 iso=SERIALIZABLE stat=PENDING epo=0 ts=1535556719.293778058,1 orig=1535556719.286437264,0 max=1535556719.286437264,0 wto=false rop=false seq=3
------- Stdout: -------
W180829 15:31:58.849194 2853 server/status/runtime.go:310 [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180829 15:31:58.863026 2853 server/server.go:849 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180829 15:31:58.863237 2853 base/addr_validation.go:271 [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180829 15:31:58.863257 2853 base/addr_validation.go:311 [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180829 15:31:58.877696 2853 server/config.go:493 [n?] 1 storage engine initialized
I180829 15:31:58.877732 2853 server/config.go:496 [n?] RocksDB cache size: 128 MiB
I180829 15:31:58.877741 2853 server/config.go:496 [n?] store 0: in-memory, size 0 B
I180829 15:31:58.888340 2853 server/node.go:373 [n?] **** cluster 134ebbb7-0f04-47c8-b955-9320356cd647 has been created
I180829 15:31:58.888383 2853 server/server.go:1411 [n?] **** add additional nodes by specifying --join=127.0.0.1:42533
I180829 15:31:58.888574 2853 gossip/gossip.go:382 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:42533" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2118-gc1e0990" started_at:1535556718888495642
I180829 15:31:58.889752 2853 storage/store.go:1540 [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180829 15:31:58.889858 2853 server/node.go:476 [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}
I180829 15:31:58.889912 2853 storage/stores.go:242 [n1] read 0 node addresses from persistent storage
I180829 15:31:58.889993 2853 server/node.go:697 [n1] connecting to gossip network to verify cluster ID...
I180829 15:31:58.903684 2853 server/node.go:722 [n1] node connected via gossip and verified as part of cluster "134ebbb7-0f04-47c8-b955-9320356cd647"
I180829 15:31:58.903734 2853 server/node.go:546 [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180829 15:31:58.904035 2853 server/status/recorder.go:652 [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180829 15:31:58.904076 2853 server/server.go:1802 [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180829 15:31:58.904208 2853 server/server.go:1548 [n1] starting https server at 127.0.0.1:42089 (use: 127.0.0.1:42089)
I180829 15:31:58.904229 2853 server/server.go:1550 [n1] starting grpc/postgres server at 127.0.0.1:42533
I180829 15:31:58.904247 2853 server/server.go:1551 [n1] advertising CockroachDB node at 127.0.0.1:42533
I180829 15:31:58.907896 3145 storage/replica_command.go:298 [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180829 15:31:58.907959 3119 server/status/recorder.go:652 [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180829 15:31:58.925523 2881 sql/event_log.go:126 [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180829 15:31:58.938024 3157 storage/replica_command.go:298 [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180829 15:31:58.953820 3150 storage/replica_command.go:298 [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
W180829 15:31:58.958711 2951 storage/intent_resolver.go:668 [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=e91cd13a key=/Table/SystemConfigSpan/Start rw=true pri=0.01682788 iso=SERIALIZABLE stat=PENDING epo=0 ts=1535556718.941726190,0 orig=1535556718.941726190,0 max=1535556718.941726190,0 wto=false rop=false seq=12
I180829 15:31:58.964108 3171 sql/event_log.go:126 [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-12 User:root}
I180829 15:31:58.972533 3188 storage/replica_command.go:298 [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180829 15:31:58.981827 3177 sql/event_log.go:126 [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180829 15:31:58.983505 2026 storage/replica_command.go:298 [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180829 15:31:58.995316 3220 storage/replica_command.go:298 [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180829 15:31:59.006890 3212 sql/event_log.go:126 [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:087e78db-d16f-448c-bcd5-89c39825663b User:root}
I180829 15:31:59.010424 3192 storage/replica_command.go:298 [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180829 15:31:59.036685 3241 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}
I180829 15:31:59.056829 3167 storage/replica_command.go:298 [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180829 15:31:59.060232 3252 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}
I180829 15:31:59.062121 3262 storage/replica_command.go:298 [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180829 15:31:59.063617 2853 server/server.go:1604 [n1] done ensuring all necessary migrations have run
I180829 15:31:59.063652 2853 server/server.go:1607 [n1] serving sql connections
I180829 15:31:59.068671 3285 sql/event_log.go:126 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:42533} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2118-gc1e0990 StartedAt:1535556718888495642 LocalityAddress:[]} ClusterID:134ebbb7-0f04-47c8-b955-9320356cd647 StartedAt:1535556718888495642 LastUp:1535556718888495642}
I180829 15:31:59.070317 3283 server/server_update.go:67 [n1] no need to upgrade, cluster already at the newest version
I180829 15:31:59.072985 3273 storage/replica_command.go:298 [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180829 15:31:59.077989 3249 storage/replica_command.go:298 [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180829 15:31:59.089558 3334 storage/replica_command.go:298 [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180829 15:31:59.104468 3341 storage/replica_command.go:298 [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180829 15:31:59.117941 3287 storage/replica_command.go:298 [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180829 15:31:59.123115 3394 storage/replica_command.go:298 [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180829 15:31:59.129374 2056 storage/replica_command.go:298 [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180829 15:31:59.136261 2060 storage/replica_command.go:298 [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180829 15:31:59.142523 2064 storage/replica_command.go:298 [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180829 15:31:59.150211 3422 storage/replica_command.go:298 [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180829 15:31:59.157559 3474 storage/replica_command.go:298 [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180829 15:31:59.177053 3324 storage/replica_command.go:298 [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180829 15:31:59.242592 3452 sql/event_log.go:126 [n1,client=127.0.0.1:55370,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:changefeed.experimental_poll_interval Value:0s User:root}
I180829 15:31:59.246529 3452 sql/event_log.go:126 [n1,client=127.0.0.1:55370,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I180829 15:31:59.247657 3455 storage/replica_command.go:298 [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180829 15:31:59.250517 3452 sql/event_log.go:126 [n1,client=127.0.0.1:55370,user=root] Event: "create_table", target: 53, info: {TableName:d.public.foo Statement:CREATE TABLE foo (a INT PRIMARY KEY) User:root}
I180829 15:31:59.256577 3499 storage/replica_command.go:298 [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
Please assign, take a look and update the issue accordingly.