Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

teamcity: failed tests on master: test/TestLeaseRenewedPeriodically, testrace/TestLeaseRenewedPeriodically #28771

Closed
cockroach-teamcity opened this issue Aug 17, 2018 · 0 comments · Fixed by #28954
Closed

teamcity: failed tests on master: test/TestLeaseRenewedPeriodically, testrace/TestLeaseRenewedPeriodically #28771

cockroach-teamcity opened this issue Aug 17, 2018 · 0 comments · Fixed by #28954
Assignees
@vivekmenezes
Labels
A-schema-changes C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
2.1

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#844735:

--- FAIL: testrace/TestLeaseRenewedPeriodically (7.580s)
lease_test.go:1653: expected no leases to be releases, released 1
------- Stdout: -------
W180817 18:09:43.695467 82501 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180817 18:09:43.785091 82501 server/server.go:829  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180817 18:09:43.785843 82501 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180817 18:09:43.785950 82501 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180817 18:09:43.819143 82501 server/config.go:496  [n?] 1 storage engine initialized
I180817 18:09:43.819443 82501 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180817 18:09:43.819613 82501 server/config.go:499  [n?] store 0: in-memory, size 0 B
I180817 18:09:43.977843 82501 server/node.go:373  [n?] **** cluster 6070414a-1520-4518-b42c-356d27115403 has been created
I180817 18:09:43.978062 82501 server/server.go:1400  [n?] **** add additional nodes by specifying --join=127.0.0.1:46071
I180817 18:09:43.979439 82501 gossip/gossip.go:383  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46071" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1723-gea7e255" started_at:1534529383978950419 
I180817 18:09:44.034427 82501 storage/store.go:1506  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180817 18:09:44.072606 82501 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}
I180817 18:09:44.073317 82501 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180817 18:09:44.073850 82501 server/node.go:697  [n1] connecting to gossip network to verify cluster ID...
I180817 18:09:44.085157 82501 server/node.go:722  [n1] node connected via gossip and verified as part of cluster "6070414a-1520-4518-b42c-356d27115403"
I180817 18:09:44.085836 82501 server/node.go:546  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180817 18:09:44.087329 82501 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180817 18:09:44.087401 82501 server/server.go:1806  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180817 18:09:44.094678 82427 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180817 18:09:44.113611 82501 server/server.go:1537  [n1] starting https server at 127.0.0.1:45209 (use: 127.0.0.1:45209)
I180817 18:09:44.113897 82501 server/server.go:1539  [n1] starting grpc/postgres server at 127.0.0.1:46071
I180817 18:09:44.113955 82501 server/server.go:1540  [n1] advertising CockroachDB node at 127.0.0.1:46071
W180817 18:09:44.114293 82501 jobs/registry.go:308  [n1] unable to get node liveness: node not in the liveness table
I180817 18:09:44.177813 82692 storage/replica_command.go:282  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180817 18:09:44.641810 82760 storage/replica_command.go:282  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180817 18:09:44.650008 82758 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=7610301e key=/Table/SystemConfigSpan/Start rw=true pri=0.03807819 iso=SERIALIZABLE stat=PENDING epo=0 ts=1534529384.186222198,0 orig=1534529384.186222198,0 max=1534529384.186222198,0 wto=false rop=false seq=6
I180817 18:09:44.788179 82430 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180817 18:09:44.865870 82761 storage/replica_command.go:282  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180817 18:09:45.072122 82765 storage/replica_command.go:282  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180817 18:09:45.317039 82494 rpc/nodedialer/nodedialer.go:92  [consistencyChecker,n1,s1,r1/1:/{Min-System/}] connection to n1 established
I180817 18:09:45.518902 82769 storage/replica_command.go:282  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180817 18:09:45.703189 82732 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180817 18:09:45.747344 82751 storage/replica_command.go:282  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180817 18:09:46.014000 82814 storage/replica_command.go:282  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180817 18:09:46.085860 82818 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180817 18:09:46.233286 82783 storage/replica_command.go:282  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180817 18:09:46.370624 82856 storage/replica_command.go:282  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180817 18:09:46.546052 82831 storage/replica_command.go:282  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180817 18:09:46.730245 82886 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}
I180817 18:09:46.852438 82863 storage/replica_command.go:282  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180817 18:09:47.048920 82896 storage/replica_command.go:282  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180817 18:09:47.140410 82903 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}
I180817 18:09:47.330281 82950 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}
I180817 18:09:47.334512 82934 storage/replica_command.go:282  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180817 18:09:47.557959 82501 server/server.go:1593  [n1] done ensuring all necessary migrations have run
I180817 18:09:47.558215 82501 server/server.go:1596  [n1] serving sql connections
I180817 18:09:47.619307 83007 storage/replica_command.go:282  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180817 18:09:47.757583 83046 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46071} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1723-gea7e255 StartedAt:1534529383978950419 LocalityAddress:[]} ClusterID:6070414a-1520-4518-b42c-356d27115403 StartedAt:1534529383978950419 LastUp:1534529383978950419}
I180817 18:09:47.800810 83044 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180817 18:09:47.850911 83107 storage/replica_command.go:282  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180817 18:09:48.133858 83122 storage/replica_command.go:282  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180817 18:09:48.483801 83071 storage/replica_command.go:282  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180817 18:09:48.647322 83175 storage/replica_command.go:282  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180817 18:09:48.822134 83203 storage/replica_command.go:282  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180817 18:09:49.025959 83236 storage/replica_command.go:282  [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180817 18:09:49.154904 83195 storage/replica_command.go:282  [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180817 18:09:50.026580 83216 sql/event_log.go:126  [n1,client=127.0.0.1:57832,user=root] Event: "create_database", target: 52, info: {DatabaseName:t Statement:CREATE DATABASE t User:root}
I180817 18:09:50.043959 83331 storage/replica_command.go:282  [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180817 18:09:50.355896 83319 storage/replica_command.go:282  [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180817 18:09:50.397045 83216 sql/event_log.go:126  [n1,client=127.0.0.1:57832,user=root] Event: "create_table", target: 53, info: {TableName:t.public.test1 Statement:CREATE TABLE t.public.test1 (k CHAR PRIMARY KEY, v CHAR) User:root}
I180817 18:09:50.662281 83216 sql/event_log.go:126  [n1,client=127.0.0.1:57832,user=root] Event: "create_table", target: 54, info: {TableName:t.public.test2 Statement:CREATE TABLE t.public.test2 () User:root}
I180817 18:09:50.747014 83401 storage/replica_command.go:282  [split,n1,s1,r24/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r25]
I180817 18:09:51.051471 82501 util/stop/stopper.go:537  quiescing; tasks left:
2      node.Node: batch
2      [async] kv.TxnCoordSender: heartbeat loop
1      refresh table:54 lease
1      refresh table:53 lease
1      refresh table:23 lease
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
I180817 18:09:51.054996 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      refresh table:53 lease
1      refresh table:23 lease
1      node.Node: batch
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
W180817 18:09:51.057082 83345 internal/client/txn.go:514  failure aborting transaction: node unavailable; try another peer; abort caused by: kv/txn_interceptor_heartbeat.go:374: node already quiescing
I180817 18:09:51.057599 83376 sql/lease.go:1743  refreshing table: 23 lease failed: kv/txn_interceptor_heartbeat.go:374: node already quiescing
I180817 18:09:51.058069 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      refresh table:53 lease
1      node.Node: batch
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
I180817 18:09:51.058556 82540 sql/lease.go:1746  didnt refresh table: 23 lease: node unavailable; try another peer
I180817 18:09:51.059491 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      refresh table:53 lease
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
W180817 18:09:51.060704 83432 sql/lease.go:1022  error: node unavailable; try another peer, not releasing lease: &{'5' '\x01' {{%!q(uint64=957919000) %!q(int64=63670126190) %!q(*time.Location=<nil>)}}}
I180817 18:09:51.061114 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
I180817 18:09:51.061388 83400 sql/lease.go:1746  didnt refresh table: 53 lease: node unavailable; try another peer
I180817 18:09:51.061653 83400 sql/lease.go:1746  didnt refresh table: 54 lease: node unavailable; try another peer
W180817 18:09:51.062169 83375 sql/lease.go:257  error releasing lease &{'\x17' '\x01' {{%!q(uint64=848816000) %!q(int64=63670126190) %!q(*time.Location=<nil>)}}}: lease-release: node unavailable; try another peer
I180817 18:09:51.062592 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
I180817 18:09:51.089334 82745 kv/transport_race.go:67  transport race promotion: ran 28 iterations on up to 1892 requests
--- FAIL: test/TestLeaseRenewedPeriodically (8.210s)

------- Stdout: -------
W180817 17:52:59.841256 85152 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180817 17:52:59.852187 85152 server/server.go:829  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180817 17:52:59.852336 85152 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180817 17:52:59.852363 85152 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180817 17:52:59.854775 85152 server/config.go:496  [n?] 1 storage engine initialized
I180817 17:52:59.854799 85152 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180817 17:52:59.854808 85152 server/config.go:499  [n?] store 0: in-memory, size 0 B
I180817 17:52:59.858963 85152 server/node.go:373  [n?] **** cluster 69c5697a-54ac-43ba-9f9d-6ddad77d3b44 has been created
I180817 17:52:59.858986 85152 server/server.go:1400  [n?] **** add additional nodes by specifying --join=127.0.0.1:42477
I180817 17:52:59.859104 85152 gossip/gossip.go:383  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:42477" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1723-gea7e255" started_at:1534528379859048706 
I180817 17:52:59.859812 85152 storage/store.go:1506  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180817 17:52:59.859869 85152 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}
I180817 17:52:59.859903 85152 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180817 17:52:59.859953 85152 server/node.go:697  [n1] connecting to gossip network to verify cluster ID...
I180817 17:52:59.861165 85152 server/node.go:722  [n1] node connected via gossip and verified as part of cluster "69c5697a-54ac-43ba-9f9d-6ddad77d3b44"
I180817 17:52:59.861238 85152 server/node.go:546  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180817 17:52:59.861510 85152 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180817 17:52:59.861559 85152 server/server.go:1806  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180817 17:52:59.861642 85152 server/server.go:1537  [n1] starting https server at 127.0.0.1:45375 (use: 127.0.0.1:45375)
I180817 17:52:59.861672 85152 server/server.go:1539  [n1] starting grpc/postgres server at 127.0.0.1:42477
I180817 17:52:59.861693 85152 server/server.go:1540  [n1] advertising CockroachDB node at 127.0.0.1:42477
I180817 17:52:59.863677 85306 storage/replica_command.go:282  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180817 17:52:59.878479 85259 storage/replica_command.go:282  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180817 17:52:59.880858 85536 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180817 17:52:59.929338 85245 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180817 17:52:59.934165 85586 storage/replica_command.go:282  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180817 17:52:59.940706 85593 storage/replica_command.go:282  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
W180817 17:52:59.961718 85602 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "split" id=f627283a key=/Local/Range/System/NodeLivenessMax/RangeDescriptor rw=true pri=0.00707833 iso=SERIALIZABLE stat=PENDING epo=0 ts=1534528379.940732133,0 orig=1534528379.940732133,0 max=1534528379.940732133,0 wto=false rop=false seq=1
I180817 17:52:59.966144 85288 storage/replica_command.go:282  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180817 17:52:59.981111 85620 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180817 17:53:00.008882 85295 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180817 17:53:00.011464 85311 storage/replica_command.go:282  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180817 17:53:00.047186 85624 storage/replica_command.go:282  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180817 17:53:00.060151 85562 storage/replica_command.go:282  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180817 17:53:00.065211 85682 storage/replica_command.go:282  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180817 17:53:00.067878 85650 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}
I180817 17:53:00.070779 85614 storage/replica_command.go:282  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180817 17:53:00.077729 85679 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}
I180817 17:53:00.080460 85709 storage/replica_command.go:282  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180817 17:53:00.081973 85705 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}
I180817 17:53:00.110392 85727 storage/replica_command.go:282  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180817 17:53:00.112686 85152 server/server.go:1593  [n1] done ensuring all necessary migrations have run
I180817 17:53:00.112721 85152 server/server.go:1596  [n1] serving sql connections
I180817 17:53:00.117489 85760 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:42477} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1723-gea7e255 StartedAt:1534528379859048706 LocalityAddress:[]} ClusterID:69c5697a-54ac-43ba-9f9d-6ddad77d3b44 StartedAt:1534528379859048706 LastUp:1534528379859048706}
I180817 17:53:00.123262 85812 storage/replica_command.go:282  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180817 17:53:00.125366 85758 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180817 17:53:00.137669 85801 storage/replica_command.go:282  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180817 17:53:00.144813 85660 storage/replica_command.go:282  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180817 17:53:00.178016 85775 storage/replica_command.go:282  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180817 17:53:00.183366 85881 storage/replica_command.go:282  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180817 17:53:00.188867 85854 storage/replica_command.go:282  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180817 17:53:00.193639 85869 storage/replica_command.go:282  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180817 17:53:00.200110 85823 storage/replica_command.go:282  [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180817 17:53:00.205775 85900 storage/replica_command.go:282  [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180817 17:53:00.292296 85982 storage/replica_command.go:282  [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180817 17:53:00.296720 85930 sql/event_log.go:126  [n1,client=127.0.0.1:52356,user=root] Event: "create_database", target: 52, info: {DatabaseName:t Statement:CREATE DATABASE t User:root}
I180817 17:53:00.306774 85930 sql/event_log.go:126  [n1,client=127.0.0.1:52356,user=root] Event: "create_table", target: 53, info: {TableName:t.public.test1 Statement:CREATE TABLE t.public.test1 (k CHAR PRIMARY KEY, v CHAR) User:root}
I180817 17:53:00.311757 86026 storage/replica_command.go:282  [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180817 17:53:00.312348 85930 sql/event_log.go:126  [n1,client=127.0.0.1:52356,user=root] Event: "create_table", target: 54, info: {TableName:t.public.test2 Statement:CREATE TABLE t.public.test2 () User:root}
I180817 17:53:00.331525 86053 storage/replica_command.go:282  [split,n1,s1,r24/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r25]lease_test.go:1653: expected no leases to be releases, released 1
------- Stdout: -------
W180817 18:09:43.695467 82501 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180817 18:09:43.785091 82501 server/server.go:829  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180817 18:09:43.785843 82501 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180817 18:09:43.785950 82501 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180817 18:09:43.819143 82501 server/config.go:496  [n?] 1 storage engine initialized
I180817 18:09:43.819443 82501 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180817 18:09:43.819613 82501 server/config.go:499  [n?] store 0: in-memory, size 0 B
I180817 18:09:43.977843 82501 server/node.go:373  [n?] **** cluster 6070414a-1520-4518-b42c-356d27115403 has been created
I180817 18:09:43.978062 82501 server/server.go:1400  [n?] **** add additional nodes by specifying --join=127.0.0.1:46071
I180817 18:09:43.979439 82501 gossip/gossip.go:383  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46071" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1723-gea7e255" started_at:1534529383978950419 
I180817 18:09:44.034427 82501 storage/store.go:1506  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180817 18:09:44.072606 82501 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}
I180817 18:09:44.073317 82501 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180817 18:09:44.073850 82501 server/node.go:697  [n1] connecting to gossip network to verify cluster ID...
I180817 18:09:44.085157 82501 server/node.go:722  [n1] node connected via gossip and verified as part of cluster "6070414a-1520-4518-b42c-356d27115403"
I180817 18:09:44.085836 82501 server/node.go:546  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180817 18:09:44.087329 82501 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180817 18:09:44.087401 82501 server/server.go:1806  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180817 18:09:44.094678 82427 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180817 18:09:44.113611 82501 server/server.go:1537  [n1] starting https server at 127.0.0.1:45209 (use: 127.0.0.1:45209)
I180817 18:09:44.113897 82501 server/server.go:1539  [n1] starting grpc/postgres server at 127.0.0.1:46071
I180817 18:09:44.113955 82501 server/server.go:1540  [n1] advertising CockroachDB node at 127.0.0.1:46071
W180817 18:09:44.114293 82501 jobs/registry.go:308  [n1] unable to get node liveness: node not in the liveness table
I180817 18:09:44.177813 82692 storage/replica_command.go:282  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180817 18:09:44.641810 82760 storage/replica_command.go:282  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180817 18:09:44.650008 82758 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=7610301e key=/Table/SystemConfigSpan/Start rw=true pri=0.03807819 iso=SERIALIZABLE stat=PENDING epo=0 ts=1534529384.186222198,0 orig=1534529384.186222198,0 max=1534529384.186222198,0 wto=false rop=false seq=6
I180817 18:09:44.788179 82430 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180817 18:09:44.865870 82761 storage/replica_command.go:282  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180817 18:09:45.072122 82765 storage/replica_command.go:282  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180817 18:09:45.317039 82494 rpc/nodedialer/nodedialer.go:92  [consistencyChecker,n1,s1,r1/1:/{Min-System/}] connection to n1 established
I180817 18:09:45.518902 82769 storage/replica_command.go:282  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180817 18:09:45.703189 82732 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180817 18:09:45.747344 82751 storage/replica_command.go:282  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180817 18:09:46.014000 82814 storage/replica_command.go:282  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180817 18:09:46.085860 82818 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180817 18:09:46.233286 82783 storage/replica_command.go:282  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180817 18:09:46.370624 82856 storage/replica_command.go:282  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180817 18:09:46.546052 82831 storage/replica_command.go:282  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180817 18:09:46.730245 82886 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}
I180817 18:09:46.852438 82863 storage/replica_command.go:282  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180817 18:09:47.048920 82896 storage/replica_command.go:282  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180817 18:09:47.140410 82903 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}
I180817 18:09:47.330281 82950 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}
I180817 18:09:47.334512 82934 storage/replica_command.go:282  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180817 18:09:47.557959 82501 server/server.go:1593  [n1] done ensuring all necessary migrations have run
I180817 18:09:47.558215 82501 server/server.go:1596  [n1] serving sql connections
I180817 18:09:47.619307 83007 storage/replica_command.go:282  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180817 18:09:47.757583 83046 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46071} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1723-gea7e255 StartedAt:1534529383978950419 LocalityAddress:[]} ClusterID:6070414a-1520-4518-b42c-356d27115403 StartedAt:1534529383978950419 LastUp:1534529383978950419}
I180817 18:09:47.800810 83044 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180817 18:09:47.850911 83107 storage/replica_command.go:282  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180817 18:09:48.133858 83122 storage/replica_command.go:282  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180817 18:09:48.483801 83071 storage/replica_command.go:282  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180817 18:09:48.647322 83175 storage/replica_command.go:282  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180817 18:09:48.822134 83203 storage/replica_command.go:282  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180817 18:09:49.025959 83236 storage/replica_command.go:282  [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180817 18:09:49.154904 83195 storage/replica_command.go:282  [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180817 18:09:50.026580 83216 sql/event_log.go:126  [n1,client=127.0.0.1:57832,user=root] Event: "create_database", target: 52, info: {DatabaseName:t Statement:CREATE DATABASE t User:root}
I180817 18:09:50.043959 83331 storage/replica_command.go:282  [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180817 18:09:50.355896 83319 storage/replica_command.go:282  [split,n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53 [r24]
I180817 18:09:50.397045 83216 sql/event_log.go:126  [n1,client=127.0.0.1:57832,user=root] Event: "create_table", target: 53, info: {TableName:t.public.test1 Statement:CREATE TABLE t.public.test1 (k CHAR PRIMARY KEY, v CHAR) User:root}
I180817 18:09:50.662281 83216 sql/event_log.go:126  [n1,client=127.0.0.1:57832,user=root] Event: "create_table", target: 54, info: {TableName:t.public.test2 Statement:CREATE TABLE t.public.test2 () User:root}
I180817 18:09:50.747014 83401 storage/replica_command.go:282  [split,n1,s1,r24/1:/{Table/53-Max}] initiating a split of this range at key /Table/54 [r25]
I180817 18:09:51.051471 82501 util/stop/stopper.go:537  quiescing; tasks left:
2      node.Node: batch
2      [async] kv.TxnCoordSender: heartbeat loop
1      refresh table:54 lease
1      refresh table:53 lease
1      refresh table:23 lease
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
I180817 18:09:51.054996 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      refresh table:53 lease
1      refresh table:23 lease
1      node.Node: batch
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
W180817 18:09:51.057082 83345 internal/client/txn.go:514  failure aborting transaction: node unavailable; try another peer; abort caused by: kv/txn_interceptor_heartbeat.go:374: node already quiescing
I180817 18:09:51.057599 83376 sql/lease.go:1743  refreshing table: 23 lease failed: kv/txn_interceptor_heartbeat.go:374: node already quiescing
I180817 18:09:51.058069 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      refresh table:53 lease
1      node.Node: batch
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
I180817 18:09:51.058556 82540 sql/lease.go:1746  didnt refresh table: 23 lease: node unavailable; try another peer
I180817 18:09:51.059491 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      refresh table:53 lease
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
W180817 18:09:51.060704 83432 sql/lease.go:1022  error: node unavailable; try another peer, not releasing lease: &{'5' '\x01' {{%!q(uint64=957919000) %!q(int64=63670126190) %!q(*time.Location=<nil>)}}}
I180817 18:09:51.061114 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
1      [async] sql.tableState: releasing descriptor lease
I180817 18:09:51.061388 83400 sql/lease.go:1746  didnt refresh table: 53 lease: node unavailable; try another peer
I180817 18:09:51.061653 83400 sql/lease.go:1746  didnt refresh table: 54 lease: node unavailable; try another peer
W180817 18:09:51.062169 83375 sql/lease.go:257  error releasing lease &{'\x17' '\x01' {{%!q(uint64=848816000) %!q(int64=63670126190) %!q(*time.Location=<nil>)}}}: lease-release: node unavailable; try another peer
I180817 18:09:51.062592 82501 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] transport racer
I180817 18:09:51.089334 82745 kv/transport_race.go:67  transport race promotion: ran 28 iterations on up to 1892 requests

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone Aug 17, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Aug 17, 2018
@tbg tbg added the A-sql-execution Relating to SQL execution. label Aug 21, 2018
@vivekmenezes vivekmenezes added A-schema-changes and removed A-sql-execution Relating to SQL execution. labels Aug 21, 2018
vivekmenezes added a commit to vivekmenezes/cockroach that referenced this issue Aug 22, 2018
@vivekmenezes
sql: fix flaky TestLeaseRenewedPeriodically
26c1c3f 
I changed GossipUpdateEvent as well which is strictly not needed
but there is a chance without it there will continue to be
some flakiness.

This fix essentially moves the check for release counts
further up before lease acquisition. This fixes a race
where after lease acquisition the periodic timer would
fire, acquire/release some leases.

fixes cockroachdb#28771

Release note: None
@vivekmenezes vivekmenezes mentioned this issue Aug 22, 2018
Merged
craig bot pushed a commit that referenced this issue Aug 22, 2018
@vivekmenezes
Merge #28954
ddbb082 
28954: sql: fix flaky TestLeaseRenewedPeriodically r=vivekmenezes a=vivekmenezes

I changed GossipUpdateEvent as well which is strictly not needed
but there is a chance without it there will continue to be
some flakiness.

This fix essentially moves the check for release counts
further up before lease acquisition. This fixes a race
where after lease acquisition the periodic timer would
fire, acquire/release some leases.

fixes #28771

Release note: None

Co-authored-by: Vivek Menezes <[email protected]>
@craig craig bot closed this as completed in #28954 Aug 22, 2018
@vivekmenezes vivekmenezes mentioned this issue Aug 22, 2018
Merged
vivekmenezes added a commit to vivekmenezes/cockroach that referenced this issue Aug 31, 2018
@vivekmenezes
sql: fix flaky TestLeaseRenewedPeriodically
e91f931 
I changed GossipUpdateEvent as well which is strictly not needed
but there is a chance without it there will continue to be
some flakiness.

This fix essentially moves the check for release counts
further up before lease acquisition. This fixes a race
where after lease acquisition the periodic timer would
fire, acquire/release some leases.

fixes cockroachdb#28771

Release note: None
craig bot pushed a commit that referenced this issue Aug 31, 2018
@vivekmenezes
Merge #28965
a4147fa 
28965: backport-2.1: sql: fix flaky TestLeaseRenewedPeriodically r=vivekmenezes a=vivekmenezes

Backport 1/1 commits from #28954.

/cc @cockroachdb/release

---

I changed GossipUpdateEvent as well which is strictly not needed
but there is a chance without it there will continue to be
some flakiness.

This fix essentially moves the check for release counts
further up before lease acquisition. This fixes a race
where after lease acquisition the periodic timer would
fire, acquire/release some leases.

fixes #28771

Release note: None


Co-authored-by: Vivek Menezes <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@vivekmenezes vivekmenezes

Labels
A-schema-changes C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
2.1
Development

Successfully merging a pull request may close this issue.

sql: fix flaky TestLeaseRenewedPeriodically vivekmenezes/cockroach
3 participants
@tbg @vivekmenezes @cockroach-teamcity