teamcity: failed tests on master: testrace/TestSessionFinishRollsBackTxn #26524
Description
The following tests appear to have failed:
--- FAIL: testrace/TestSessionFinishRollsBackTxn (9.470s)
------- Stdout: -------
W180607 19:17:42.181205 36910 server/status/runtime.go:109 Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180607 19:17:42.263819 36910 server/server.go:784 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180607 19:17:42.307187 36910 server/config.go:539 [n?] 1 storage engine initialized
I180607 19:17:42.307359 36910 server/config.go:542 [n?] RocksDB cache size: 128 MiB
I180607 19:17:42.307412 36910 server/config.go:542 [n?] store 0: in-memory, size 0 B
I180607 19:17:42.381695 36910 server/node.go:376 [n?] **** cluster 0b628926-6d69-4d59-bbc6-407beeb10b92 has been created
I180607 19:17:42.381879 36910 server/server.go:1359 [n?] **** add additional nodes by specifying --join=127.0.0.1:40967
I180607 19:17:42.431141 37235 kv/dist_sender.go:331 [n1] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180607 19:17:42.432715 36910 server/node.go:506 [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=1, writes=0.00, bytesPerReplica={p10=7043.00 p25=7043.00 p50=7043.00 p75=7043.00 p90=7043.00 pMax=7043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180607 19:17:42.433367 36910 server/node.go:354 [n1] node ID 1 initialized
I180607 19:17:42.433888 36910 gossip/gossip.go:333 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:40967" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:6 >
I180607 19:17:42.435452 36910 storage/stores.go:222 [n1] read 0 node addresses from persistent storage
I180607 19:17:42.436123 36910 server/node.go:647 [n1] connecting to gossip network to verify cluster ID...
I180607 19:17:42.436448 36910 server/node.go:672 [n1] node connected via gossip and verified as part of cluster "0b628926-6d69-4d59-bbc6-407beeb10b92"
I180607 19:17:42.438595 36910 server/node.go:440 [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180607 19:17:42.460383 36910 server/server.go:1487 [n1] starting https server at 127.0.0.1:40731
I180607 19:17:42.461282 36910 server/server.go:1488 [n1] starting grpc/postgres server at 127.0.0.1:40967
I180607 19:17:42.461360 36910 server/server.go:1489 [n1] advertising CockroachDB node at 127.0.0.1:40967
W180607 19:17:42.474856 36910 sql/jobs/registry.go:287 [n1] unable to get node liveness: node not in the liveness table
I180607 19:17:42.495680 37016 storage/replica_command.go:863 [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180607 19:17:43.214566 37248 storage/replica_command.go:863 [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180607 19:17:43.233652 37003 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=9ea4d3ef key=/Table/SystemConfigSpan/Start rw=true pri=0.03132033 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399062.564180243,0 orig=1528399062.564180243,0 max=1528399062.564180243,0 wto=false rop=false seq=6
I180607 19:17:43.356938 36993 sql/event_log.go:126 [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180607 19:17:43.487716 37301 storage/replica_command.go:863 [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180607 19:17:43.674267 37333 storage/replica_command.go:863 [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180607 19:17:43.843547 37298 sql/event_log.go:126 [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
W180607 19:17:43.897286 37362 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=a1312383 key=/Local/Range/System/NodeLivenessMax/RangeDescriptor rw=true pri=0.02782750 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399063.674466405,0 orig=1528399063.674466405,0 max=1528399063.674466405,0 wto=false rop=false seq=1
W180607 19:17:43.967767 37292 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=a1312383 key=/Local/Range/System/NodeLivenessMax/RangeDescriptor rw=true pri=0.02782750 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399063.674466405,0 orig=1528399063.674466405,0 max=1528399063.674466405,0 wto=false rop=false seq=1
I180607 19:17:43.997505 37260 storage/replica_command.go:863 [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180607 19:17:44.224897 37289 sql/event_log.go:126 [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180607 19:17:44.268879 37379 storage/replica_command.go:863 [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180607 19:17:44.499932 37343 storage/replica_command.go:863 [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180607 19:17:44.710139 37383 storage/replica_command.go:863 [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180607 19:17:44.759693 37297 sql/event_log.go:126 [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180607 19:17:44.922504 37355 storage/replica_command.go:863 [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
W180607 19:17:45.109910 37407 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=6ec7b6f9 key=/Local/Range/Table/12/RangeDescriptor rw=true pri=0.01796843 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399064.923049581,0 orig=1528399064.923049581,0 max=1528399064.923049581,0 wto=false rop=false seq=1
I180607 19:17:45.145755 37427 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}
I180607 19:17:45.185837 37323 storage/replica_command.go:863 [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180607 19:17:45.311300 37443 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}
I180607 19:17:45.384254 37327 storage/replica_command.go:863 [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180607 19:17:45.452426 36910 server/server.go:1566 [n1] done ensuring all necessary migrations have run
I180607 19:17:45.452702 36910 server/server.go:1569 [n1] serving sql connections
I180607 19:17:45.514965 37275 server/server_update.go:66 [n1] no need to upgrade, cluster already at the newest version
I180607 19:17:45.569904 37392 storage/replica_command.go:863 [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180607 19:17:45.639927 37277 sql/event_log.go:126 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:40967} Attrs: Locality: ServerVersion:2.0-6} ClusterID:0b628926-6d69-4d59-bbc6-407beeb10b92 StartedAt:1528399062436518815 LastUp:1528399062436518815}
I180607 19:17:45.715391 37464 storage/replica_command.go:863 [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180607 19:17:45.872394 37491 storage/replica_command.go:863 [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180607 19:17:45.991094 37507 storage/replica_command.go:863 [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180607 19:17:46.119026 37500 storage/replica_command.go:863 [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180607 19:17:46.305688 37531 storage/replica_command.go:863 [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180607 19:17:46.468736 37510 storage/replica_command.go:863 [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180607 19:17:46.567839 37489 storage/replica_command.go:863 [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180607 19:17:46.727259 37608 storage/replica_command.go:863 [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180607 19:17:46.899374 37599 storage/replica_command.go:863 [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
W180607 19:17:46.997827 37578 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=d41206b9 key=/Local/Range/Table/50/RangeDescriptor rw=true pri=0.01654224 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399066.899576855,0 orig=1528399066.899576855,0 max=1528399066.899576855,0 wto=false rop=false seq=1
I180607 19:17:48.231214 37651 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root,intExec=log-event] statement filter running on: INSERT INTO system.public.eventlog("timestamp", "eventType", "targetID", "reportingID", info) VALUES (now(), $1, $2, $3, $4), with err=<nil>
I180607 19:17:48.237917 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: CREATE DATABASE t, with err=<nil>
I180607 19:17:48.278478 37645 sql/event_log.go:126 [n1,client=127.0.0.1:35282,user=root] Event: "create_database", target: 52, info: {DatabaseName:t Statement:CREATE DATABASE t User:root}
I180607 19:17:48.287477 37623 storage/replica_command.go:863 [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180607 19:17:48.353750 37652 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root,intExec=log-event] statement filter running on: INSERT INTO system.public.eventlog("timestamp", "eventType", "targetID", "reportingID", info) VALUES (now(), $1, $2, $3, $4), with err=<nil>
I180607 19:17:48.354723 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: CREATE TABLE t.public.test (k INT PRIMARY KEY, v TEXT), with err=<nil>
I180607 19:17:48.358798 37548 sql/txn_restart_test.go:344 [split,n1,s1,r22/1:/{Table/51-Max},intExec=log-range-event] statement filter running on: INSERT INTO system.public.rangelog("timestamp", "rangeID", "storeID", "eventType", "otherRangeID", info) VALUES ($1, $2, $3, $4, $5, $6), with err=<nil>
I180607 19:17:48.368789 37645 sql/event_log.go:126 [n1,client=127.0.0.1:35282,user=root] Event: "create_table", target: 53, info: {TableName:t.public.test Statement:CREATE TABLE t.public.test (k INT PRIMARY KEY, v TEXT) User:root}
--- FAIL: testrace/TestSessionFinishRollsBackTxn: TestSessionFinishRollsBackTxn/Open (2.290s)
conn_executor_test.go:232: Looks like the checking tx was unexpectedly blocked. It took 1.981794338s to commit.
------- Stdout: -------
I180607 19:17:48.416520 37631 storage/replica_command.go:863 [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180607 19:17:48.460223 37670 sql/txn_restart_test.go:344 [split,n1,s1,r23/1:/{Table/52-Max},intExec=log-range-event] statement filter running on: INSERT INTO system.public.rangelog("timestamp", "rangeID", "storeID", "eventType", "otherRangeID", info) VALUES ($1, $2, $3, $4, $5, $6), with err=<nil>
I180607 19:17:48.621942 37699 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35286,user=root] statement filter running on: SET TRANSACTION PRIORITY NORMAL, with err=<nil>
I180607 19:17:48.651690 37688 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35286,user=root,intExec=lease-insert] statement filter running on: INSERT INTO system.public.lease("descID", version, "nodeID", expiration) VALUES (53, 1, 1, '2018-06-07 19:21:48.740605+00:00'), with err=<nil>
I180607 19:17:48.680546 37699 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35286,user=root] statement filter running on: INSERT INTO t.public.test(k, v) VALUES (1, 'a'), with err=<nil>
W180607 19:17:48.692746 37699 internal/client/txn.go:557 [n1,client=127.0.0.1:35286,user=root] failure aborting transaction: context canceled; abort caused by: connExecutor closing
I180607 19:17:48.696847 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: SET TRANSACTION PRIORITY LOW, with err=<nil>
I180607 19:17:50.676320 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: SELECT count(1) FROM t.public.test, with err=<nil>
I180607 19:17:50.678211 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: COMMIT TRANSACTION, with err=<nil>
--- FAIL: testrace/TestSessionFinishRollsBackTxn (10.060s)
------- Stdout: -------
W180607 19:17:42.181205 36910 server/status/runtime.go:109 Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180607 19:17:42.263819 36910 server/server.go:784 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180607 19:17:42.307187 36910 server/config.go:539 [n?] 1 storage engine initialized
I180607 19:17:42.307359 36910 server/config.go:542 [n?] RocksDB cache size: 128 MiB
I180607 19:17:42.307412 36910 server/config.go:542 [n?] store 0: in-memory, size 0 B
I180607 19:17:42.381695 36910 server/node.go:376 [n?] **** cluster 0b628926-6d69-4d59-bbc6-407beeb10b92 has been created
I180607 19:17:42.381879 36910 server/server.go:1359 [n?] **** add additional nodes by specifying --join=127.0.0.1:40967
I180607 19:17:42.431141 37235 kv/dist_sender.go:331 [n1] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180607 19:17:42.432715 36910 server/node.go:506 [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=1, writes=0.00, bytesPerReplica={p10=7043.00 p25=7043.00 p50=7043.00 p75=7043.00 p90=7043.00 pMax=7043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180607 19:17:42.433367 36910 server/node.go:354 [n1] node ID 1 initialized
I180607 19:17:42.433888 36910 gossip/gossip.go:333 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:40967" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:6 >
I180607 19:17:42.435452 36910 storage/stores.go:222 [n1] read 0 node addresses from persistent storage
I180607 19:17:42.436123 36910 server/node.go:647 [n1] connecting to gossip network to verify cluster ID...
I180607 19:17:42.436448 36910 server/node.go:672 [n1] node connected via gossip and verified as part of cluster "0b628926-6d69-4d59-bbc6-407beeb10b92"
I180607 19:17:42.438595 36910 server/node.go:440 [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180607 19:17:42.460383 36910 server/server.go:1487 [n1] starting https server at 127.0.0.1:40731
I180607 19:17:42.461282 36910 server/server.go:1488 [n1] starting grpc/postgres server at 127.0.0.1:40967
I180607 19:17:42.461360 36910 server/server.go:1489 [n1] advertising CockroachDB node at 127.0.0.1:40967
W180607 19:17:42.474856 36910 sql/jobs/registry.go:287 [n1] unable to get node liveness: node not in the liveness table
I180607 19:17:42.495680 37016 storage/replica_command.go:863 [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180607 19:17:43.214566 37248 storage/replica_command.go:863 [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180607 19:17:43.233652 37003 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=9ea4d3ef key=/Table/SystemConfigSpan/Start rw=true pri=0.03132033 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399062.564180243,0 orig=1528399062.564180243,0 max=1528399062.564180243,0 wto=false rop=false seq=6
I180607 19:17:43.356938 36993 sql/event_log.go:126 [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180607 19:17:43.487716 37301 storage/replica_command.go:863 [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180607 19:17:43.674267 37333 storage/replica_command.go:863 [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180607 19:17:43.843547 37298 sql/event_log.go:126 [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
W180607 19:17:43.897286 37362 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=a1312383 key=/Local/Range/System/NodeLivenessMax/RangeDescriptor rw=true pri=0.02782750 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399063.674466405,0 orig=1528399063.674466405,0 max=1528399063.674466405,0 wto=false rop=false seq=1
W180607 19:17:43.967767 37292 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=a1312383 key=/Local/Range/System/NodeLivenessMax/RangeDescriptor rw=true pri=0.02782750 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399063.674466405,0 orig=1528399063.674466405,0 max=1528399063.674466405,0 wto=false rop=false seq=1
I180607 19:17:43.997505 37260 storage/replica_command.go:863 [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180607 19:17:44.224897 37289 sql/event_log.go:126 [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180607 19:17:44.268879 37379 storage/replica_command.go:863 [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180607 19:17:44.499932 37343 storage/replica_command.go:863 [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180607 19:17:44.710139 37383 storage/replica_command.go:863 [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180607 19:17:44.759693 37297 sql/event_log.go:126 [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180607 19:17:44.922504 37355 storage/replica_command.go:863 [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
W180607 19:17:45.109910 37407 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=6ec7b6f9 key=/Local/Range/Table/12/RangeDescriptor rw=true pri=0.01796843 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399064.923049581,0 orig=1528399064.923049581,0 max=1528399064.923049581,0 wto=false rop=false seq=1
I180607 19:17:45.145755 37427 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}
I180607 19:17:45.185837 37323 storage/replica_command.go:863 [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180607 19:17:45.311300 37443 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}
I180607 19:17:45.384254 37327 storage/replica_command.go:863 [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180607 19:17:45.452426 36910 server/server.go:1566 [n1] done ensuring all necessary migrations have run
I180607 19:17:45.452702 36910 server/server.go:1569 [n1] serving sql connections
I180607 19:17:45.514965 37275 server/server_update.go:66 [n1] no need to upgrade, cluster already at the newest version
I180607 19:17:45.569904 37392 storage/replica_command.go:863 [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180607 19:17:45.639927 37277 sql/event_log.go:126 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:40967} Attrs: Locality: ServerVersion:2.0-6} ClusterID:0b628926-6d69-4d59-bbc6-407beeb10b92 StartedAt:1528399062436518815 LastUp:1528399062436518815}
I180607 19:17:45.715391 37464 storage/replica_command.go:863 [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180607 19:17:45.872394 37491 storage/replica_command.go:863 [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180607 19:17:45.991094 37507 storage/replica_command.go:863 [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180607 19:17:46.119026 37500 storage/replica_command.go:863 [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180607 19:17:46.305688 37531 storage/replica_command.go:863 [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180607 19:17:46.468736 37510 storage/replica_command.go:863 [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180607 19:17:46.567839 37489 storage/replica_command.go:863 [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180607 19:17:46.727259 37608 storage/replica_command.go:863 [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180607 19:17:46.899374 37599 storage/replica_command.go:863 [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
W180607 19:17:46.997827 37578 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=d41206b9 key=/Local/Range/Table/50/RangeDescriptor rw=true pri=0.01654224 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528399066.899576855,0 orig=1528399066.899576855,0 max=1528399066.899576855,0 wto=false rop=false seq=1
I180607 19:17:48.231214 37651 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root,intExec=log-event] statement filter running on: INSERT INTO system.public.eventlog("timestamp", "eventType", "targetID", "reportingID", info) VALUES (now(), $1, $2, $3, $4), with err=<nil>
I180607 19:17:48.237917 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: CREATE DATABASE t, with err=<nil>
I180607 19:17:48.278478 37645 sql/event_log.go:126 [n1,client=127.0.0.1:35282,user=root] Event: "create_database", target: 52, info: {DatabaseName:t Statement:CREATE DATABASE t User:root}
I180607 19:17:48.287477 37623 storage/replica_command.go:863 [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180607 19:17:48.353750 37652 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root,intExec=log-event] statement filter running on: INSERT INTO system.public.eventlog("timestamp", "eventType", "targetID", "reportingID", info) VALUES (now(), $1, $2, $3, $4), with err=<nil>
I180607 19:17:48.354723 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: CREATE TABLE t.public.test (k INT PRIMARY KEY, v TEXT), with err=<nil>
I180607 19:17:48.358798 37548 sql/txn_restart_test.go:344 [split,n1,s1,r22/1:/{Table/51-Max},intExec=log-range-event] statement filter running on: INSERT INTO system.public.rangelog("timestamp", "rangeID", "storeID", "eventType", "otherRangeID", info) VALUES ($1, $2, $3, $4, $5, $6), with err=<nil>
I180607 19:17:48.368789 37645 sql/event_log.go:126 [n1,client=127.0.0.1:35282,user=root] Event: "create_table", target: 53, info: {TableName:t.public.test Statement:CREATE TABLE t.public.test (k INT PRIMARY KEY, v TEXT) User:root}
------- Stdout: -------
W180607 19:06:27.899060 41976 server/status/runtime.go:109 Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180607 19:06:27.904747 41976 server/server.go:784 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180607 19:06:27.917668 41976 server/config.go:539 [n?] 1 storage engine initialized
I180607 19:06:27.917749 41976 server/config.go:542 [n?] RocksDB cache size: 128 MiB
I180607 19:06:27.917769 41976 server/config.go:542 [n?] store 0: in-memory, size 0 B
I180607 19:06:27.921227 41976 server/node.go:376 [n?] **** cluster 915fcc83-b8c3-4643-b821-3d048080fd05 has been created
I180607 19:06:27.921298 41976 server/server.go:1359 [n?] **** add additional nodes by specifying --join=127.0.0.1:36025
I180607 19:06:27.922060 41976 storage/store.go:1454 [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180607 19:06:27.926220 41976 server/node.go:506 [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=7043.00 p25=7043.00 p50=7043.00 p75=7043.00 p90=7043.00 pMax=7043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180607 19:06:27.926317 41976 server/node.go:354 [n1] node ID 1 initialized
I180607 19:06:27.926428 41976 gossip/gossip.go:333 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:36025" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:6 >
I180607 19:06:27.926722 41976 storage/stores.go:222 [n1] read 0 node addresses from persistent storage
I180607 19:06:27.926886 41976 server/node.go:647 [n1] connecting to gossip network to verify cluster ID...
I180607 19:06:27.928792 41976 server/node.go:672 [n1] node connected via gossip and verified as part of cluster "915fcc83-b8c3-4643-b821-3d048080fd05"
I180607 19:06:27.928863 41976 server/node.go:440 [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180607 19:06:27.929004 41976 server/server.go:1487 [n1] starting https server at 127.0.0.1:45207
I180607 19:06:27.929047 41976 server/server.go:1488 [n1] starting grpc/postgres server at 127.0.0.1:36025
I180607 19:06:27.929072 41976 server/server.go:1489 [n1] advertising CockroachDB node at 127.0.0.1:36025
I180607 19:06:27.964171 43444 storage/replica_command.go:863 [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180607 19:06:27.969221 43688 sql/event_log.go:126 [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180607 19:06:27.974258 43698 storage/replica_command.go:863 [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180607 19:06:28.005909 43714 storage/replica_command.go:863 [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180607 19:06:28.014807 43724 storage/replica_command.go:863 [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180607 19:06:28.024751 43702 sql/event_log.go:126 [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180607 19:06:28.027097 43433 storage/replica_command.go:863 [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
W180607 19:06:28.044285 43713 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=e74cdeda key=/Local/Range/System/tsd/RangeDescriptor rw=true pri=0.02207411 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528398388.031099801,0 orig=1528398388.031099801,0 max=1528398388.031099801,0 wto=false rop=false seq=1
W180607 19:06:28.048250 43455 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=c387736b key=/Table/SystemConfigSpan/Start rw=true pri=0.01466139 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528398388.029111948,0 orig=1528398388.029111948,0 max=1528398388.029111948,0 wto=false rop=false seq=6
I180607 19:06:28.048617 43762 storage/replica_command.go:863 [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180607 19:06:28.054820 43729 sql/event_log.go:126 [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180607 19:06:28.063009 43769 storage/replica_command.go:863 [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180607 19:06:28.078829 43796 storage/replica_command.go:863 [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180607 19:06:28.082723 43758 sql/event_log.go:126 [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180607 19:06:28.089267 43816 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}
I180607 19:06:28.092600 43821 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}
I180607 19:06:28.093792 41976 server/server.go:1566 [n1] done ensuring all necessary migrations have run
I180607 19:06:28.093826 41976 server/server.go:1569 [n1] serving sql connections
I180607 19:06:28.095689 43786 storage/replica_command.go:863 [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180607 19:06:28.096982 43827 sql/event_log.go:126 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:36025} Attrs: Locality: ServerVersion:2.0-6} ClusterID:915fcc83-b8c3-4643-b821-3d048080fd05 StartedAt:1528398387928838861 LastUp:1528398387928838861}
I180607 19:06:28.097070 43777 server/server_update.go:66 [n1] no need to upgrade, cluster already at the newest version
I180607 19:06:28.101095 43504 storage/replica_command.go:863 [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180607 19:06:28.105692 43738 storage/replica_command.go:863 [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180607 19:06:28.160265 43874 storage/replica_command.go:863 [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180607 19:06:28.165303 43867 storage/replica_command.go:863 [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180607 19:06:28.205928 43881 storage/replica_command.go:863 [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180607 19:06:28.213315 43872 storage/replica_command.go:863 [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180607 19:06:28.217877 43922 storage/replica_command.go:863 [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180607 19:06:28.222369 43903 storage/replica_command.go:863 [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180607 19:06:28.231876 43841 storage/replica_command.go:863 [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
W180607 19:06:28.236618 43962 storage/intent_resolver.go:638 [n1,s1] failed to push during intent resolution: failed to push "split" id=9a5f439c key=/Local/Range/Table/21/RangeDescriptor rw=true pri=0.00480856 iso=SERIALIZABLE stat=PENDING epo=0 ts=1528398388.231907008,0 orig=1528398388.231907008,0 max=1528398388.231907008,0 wto=false rop=false seq=1
I180607 19:06:28.237579 43911 storage/replica_command.go:863 [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180607 19:06:28.242546 43971 storage/replica_command.go:863 [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180607 19:06:28.246802 43952 storage/replica_command.go:863 [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180607 19:06:28.290401 44007 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57404,user=root,intExec=log-event] statement filter running on: INSERT INTO system.public.eventlog("timestamp", "eventType", "targetID", "reportingID", info) VALUES (now(), $1, $2, $3, $4), with err=<nil>
I180607 19:06:28.290476 43989 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57404,user=root] statement filter running on: CREATE DATABASE t, with err=<nil>
I180607 19:06:28.291061 43989 sql/event_log.go:126 [n1,client=127.0.0.1:57404,user=root] Event: "create_database", target: 52, info: {DatabaseName:t Statement:CREATE DATABASE t User:root}
I180607 19:06:28.293766 44011 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57404,user=root,intExec=log-event] statement filter running on: INSERT INTO system.public.eventlog("timestamp", "eventType", "targetID", "reportingID", info) VALUES (now(), $1, $2, $3, $4), with err=<nil>
I180607 19:06:28.293826 43989 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57404,user=root] statement filter running on: CREATE TABLE t.public.test (k INT PRIMARY KEY, v TEXT), with err=<nil>
I180607 19:06:28.295354 43928 storage/replica_command.go:863 [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180607 19:06:28.297877 43930 sql/txn_restart_test.go:344 [split,n1,s1,r22/1:/{Table/51-Max},intExec=log-range-event] statement filter running on: INSERT INTO system.public.rangelog("timestamp", "rangeID", "storeID", "eventType", "otherRangeID", info) VALUES ($1, $2, $3, $4, $5, $6), with err=<nil>
I180607 19:06:28.302834 43989 sql/event_log.go:126 [n1,client=127.0.0.1:57404,user=root] Event: "create_table", target: 53, info: {TableName:t.public.test Statement:CREATE TABLE t.public.test (k INT PRIMARY KEY, v TEXT) User:root}
I180607 19:06:28.303308 43694 storage/replica_command.go:863 [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180607 19:06:28.307175 44015 sql/txn_restart_test.go:344 [split,n1,s1,r23/1:/{Table/52-Max},intExec=log-range-event] statement filter running on: INSERT INTO system.public.rangelog("timestamp", "rangeID", "storeID", "eventType", "otherRangeID", info) VALUES ($1, $2, $3, $4, $5, $6), with err=<nil>
--- FAIL: testrace/TestSessionFinishRollsBackTxn: TestSessionFinishRollsBackTxn/Open (2.340s)
conn_executor_test.go:232: Looks like the checking tx was unexpectedly blocked. It took 1.981794338s to commit.
------- Stdout: -------
I180607 19:17:48.416520 37631 storage/replica_command.go:863 [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180607 19:17:48.460223 37670 sql/txn_restart_test.go:344 [split,n1,s1,r23/1:/{Table/52-Max},intExec=log-range-event] statement filter running on: INSERT INTO system.public.rangelog("timestamp", "rangeID", "storeID", "eventType", "otherRangeID", info) VALUES ($1, $2, $3, $4, $5, $6), with err=<nil>
I180607 19:17:48.621942 37699 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35286,user=root] statement filter running on: SET TRANSACTION PRIORITY NORMAL, with err=<nil>
I180607 19:17:48.651690 37688 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35286,user=root,intExec=lease-insert] statement filter running on: INSERT INTO system.public.lease("descID", version, "nodeID", expiration) VALUES (53, 1, 1, '2018-06-07 19:21:48.740605+00:00'), with err=<nil>
I180607 19:17:48.680546 37699 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35286,user=root] statement filter running on: INSERT INTO t.public.test(k, v) VALUES (1, 'a'), with err=<nil>
W180607 19:17:48.692746 37699 internal/client/txn.go:557 [n1,client=127.0.0.1:35286,user=root] failure aborting transaction: context canceled; abort caused by: connExecutor closing
I180607 19:17:48.696847 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: SET TRANSACTION PRIORITY LOW, with err=<nil>
I180607 19:17:50.676320 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: SELECT count(1) FROM t.public.test, with err=<nil>
I180607 19:17:50.678211 37645 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:35282,user=root] statement filter running on: COMMIT TRANSACTION, with err=<nil>
------- Stdout: -------
I180607 19:06:28.332195 44026 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57406,user=root] statement filter running on: SET TRANSACTION PRIORITY NORMAL, with err=<nil>
I180607 19:06:28.334752 44029 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57406,user=root,intExec=lease-insert] statement filter running on: INSERT INTO system.public.lease("descID", version, "nodeID", expiration) VALUES (53, 1, 1, '2018-06-07 19:10:59.302634+00:00'), with err=<nil>
I180607 19:06:28.335879 44026 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57406,user=root] statement filter running on: INSERT INTO t.public.test(k, v) VALUES (1, 'a'), with err=<nil>
I180607 19:06:28.336330 43989 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57404,user=root] statement filter running on: SET TRANSACTION PRIORITY LOW, with err=<nil>
W180607 19:06:28.336765 44026 internal/client/txn.go:557 [n1,client=127.0.0.1:57406,user=root] failure aborting transaction: HandledRetryableTxnError: TransactionAbortedError: txn aborted "sql txn" id=ad20e9a0 key=/Table/53/1/1/0 rw=true pri=0.06104521 iso=SERIALIZABLE stat=ABORTED epo=0 ts=1528398388.331879762,0 orig=1528398388.331879762,0 max=1528398388.831879762,0 wto=false rop=false seq=2; abort caused by: connExecutor closing
I180607 19:06:28.337135 43989 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57404,user=root] statement filter running on: SELECT count(1) FROM t.public.test, with err=<nil>
I180607 19:06:28.356715 43989 sql/txn_restart_test.go:344 [n1,client=127.0.0.1:57404,user=root] statement filter running on: COMMIT TRANSACTION, with err=<nil>
Please assign, take a look and update the issue accordingly.