{"action":"created","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/3704","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/3704/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/3704/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/3704/events","html_url":"https://github.com/cockroachdb/cockroach/issues/3704","id":125634155,"number":3704,"title":"go test ./sql/... -v -run TestSchemaChangeLease too slow","user":{"login":"vivekmenezes","id":11774212,"avatar_url":"https://avatars.githubusercontent.com/u/11774212?v=3","gravatar_id":"","url":"https://api.github.com/users/vivekmenezes","html_url":"https://github.com/vivekmenezes","followers_url":"https://api.github.com/users/vivekmenezes/followers","following_url":"https://api.github.com/users/vivekmenezes/following{/other_user}","gists_url":"https://api.github.com/users/vivekmenezes/gists{/gist_id}","starred_url":"https://api.github.com/users/vivekmenezes/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/vivekmenezes/subscriptions","organizations_url":"https://api.github.com/users/vivekmenezes/orgs","repos_url":"https://api.github.com/users/vivekmenezes/repos","events_url":"https://api.github.com/users/vivekmenezes/events{/privacy}","received_events_url":"https://api.github.com/users/vivekmenezes/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":{"login":"vivekmenezes","id":11774212,"avatar_url":"https://avatars.githubusercontent.com/u/11774212?v=3","gravatar_id":"","url":"https://api.github.com/users/vivekmenezes","html_url":"https://github.com/vivekmenezes","followers_url":"https://api.github.com/users/vivekmenezes/followers","following_url":"https://api.github.com/users/vivekmenezes/following{/other_user}","gists_url":"https://api.github.com/users/vivekmenezes/gists{/gist_id}","starred_url":"https://api.github.com/users/vivekmenezes/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/vivekmenezes/subscriptions","organizations_url":"https://api.github.com/users/vivekmenezes/orgs","repos_url":"https://api.github.com/users/vivekmenezes/repos","events_url":"https://api.github.com/users/vivekmenezes/events{/privacy}","received_events_url":"https://api.github.com/users/vivekmenezes/received_events","type":"User","site_admin":false},"milestone":null,"comments":2,"created_at":"2016-01-08T15:38:44Z","updated_at":"2016-01-08T20:58:10Z","closed_at":null,"body":"```shell\r\n$ go test ./sql/... -v -run TestSchemaChangeLease\r\n=== RUN   TestSchemaChangeLease\r\nI0108 10:37:05.718302 78874 storage/replica_command.go:1198  range 1: new leader lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC +1452267426.718s\r\nI0108 10:37:05.719386 78874 server/node.go:293  initialized store store=1:1 ([]=): {Capacity:249821663232 Available:210179567616 RangeCount:0}\r\nI0108 10:37:05.719404 78874 server/node.go:220  node ID 1 initialized\r\nI0108 10:37:05.719521 78874 gossip/gossip.go:193  setting node descriptor node_id:1 address:<network_field:\"tcp\" address_field:\"127.0.0.1:59146\" > attrs:<> \r\nI0108 10:37:05.719543 78874 server/node.go:383  connecting to gossip network to verify cluster ID...\r\nI0108 10:37:05.719603 78874 server/node.go:400  node connected via gossip and verified as part of cluster \"cluster-1\"\r\nI0108 10:37:05.719645 78874 server/node.go:258  Started node with [[]=] engine(s) and attributes []\r\nI0108 10:37:05.719694 78874 server/server.go:250  starting https server at 127.0.0.1:59146\r\nI0108 10:37:05.719854 78874 storage/split_queue.go:97  splitting range=1 [/Min-/Max) at keys [/Table/501/0 /Table/502/0]\r\nI0108 10:37:05.720004 78874 sql/pgwire/server.go:76  starting postgres server at 127.0.0.1:59147\r\nI0108 10:37:05.733716 78874 storage/replica_command.go:1275  initiating a split of range=1 [/Min-/Max) at key /Table/501\r\nI0108 10:37:05.738700 78874 storage/replica_command.go:1198  range 2: new leader lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC +1452267426.769s\r\nI0108 10:37:05.738761 78874 storage/replica_command.go:1275  initiating a split of range=2 [/Table/501-/Max) at key /Table/502\r\nI0108 10:37:05.806741 78874 storage/replica_command.go:1198  range 3: new leader lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC +1452267426.807s\r\nI0108 10:37:05.806850 78874 storage/split_queue.go:97  splitting range=3 [/Table/502-/Max) at keys [/Table/1000/0]\r\nI0108 10:37:05.807931 78874 storage/replica_command.go:1275  initiating a split of range=3 [/Table/502-/Max) at key /Table/1000\r\nI0108 10:37:05.813755 78874 storage/replica_command.go:1198  range 4: new leader lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC +1452267426.814s\r\nI0108 10:37:05.813846 78874 storage/split_queue.go:97  splitting range=4 [/Table/1000-/Max) at keys [/Table/1001/0]\r\nI0108 10:37:05.814912 78874 storage/replica_command.go:1275  initiating a split of range=4 [/Table/1000-/Max) at key /Table/1001\r\nI0108 10:37:05.819248 78874 stopper.go:264  draining; tasks left:\r\n2      kv/txn_coord_sender.go:754\r\n1      storage/queue.go:335\r\n1      server/node.go:487\r\nI0108 10:37:05.819268 78874 stopper.go:264  draining; tasks left:\r\n1      storage/queue.go:335\r\n1      server/node.go:487\r\n1      kv/txn_coord_sender.go:754\r\nE0108 10:37:05.819667 78874 client/txn.go:308  failure aborting transaction: failed to send RPC: too many errors encountered (1 of 1 total): server/node.go:488: node 1 stopped; abort caused by: failed to send RPC: too many errors encountered (1 of 1 total): server/node.go:488: node 1 stopped\r\nI0108 10:37:05.819725 78874 stopper.go:264  draining; tasks left:\r\n1      storage/queue.go:335\r\n1      kv/txn_coord_sender.go:754\r\nE0108 10:37:05.819832 78874 storage/queue.go:123  [split] range=4 [/Table/1000-/Max): error: storage/split_queue.go:100: unable to split range=4 [/Table/1000-/Max) at key \"/Table/1001/0\": storage/replica_command.go:1321: split at key /Table/1001 failed: failed to send RPC: too many errors encountered (1 of 1 total): server/node.go:488: node 1 stopped\r\nI0108 10:37:05.819857 78874 stopper.go:264  draining; tasks left:\r\n1      kv/txn_coord_sender.go:754\r\nW0108 10:37:10.818074 78874 kv/txn_coord_sender.go:621  heartbeat to \"storage/replica_command.go:1277 (*Replica).AdminSplit\" id=10bb7b6f key=/Local/Range/RangeDescriptor/\"\\xf9\\x03\\xe9\" rw=true pri=76.81699580 iso=SERIALIZABLE stat=PENDING epo=0 ts=1452267425.814937638,0 orig=1452267425.814937638,0 max=1452267425.864937638,0 failed: failed to send RPC: too many errors encountered (1 of 1 total): server/node.go:488: node 1 stopped\r\nW0108 10:37:15.817787 78874 kv/txn_coord_sender.go:621  heartbeat to \"storage/replica_command.go:1277 (*Replica).AdminSplit\" id=10bb7b6f key=/Local/Range/RangeDescriptor/\"\\xf9\\x03\\xe9\" rw=true pri=76.81699580 iso=SERIALIZABLE stat=PENDING epo=0 ts=1452267425.814937638,0 orig=1452267425.814937638,0 max=1452267425.864937638,0 failed: failed to send RPC: too many errors encountered (1 of 1 total): server/node.go:488: node 1 stopped\r\n--- PASS: TestSchemaChangeLease (15.10s)\r\nPASS\r\nok  \tgithub.com/cockroachdb/cockroach/sql\t15.130s\r\nPASS\r\nok  \tgithub.com/cockroachdb/cockroach/sql/driver\t0.022s\r\nPASS\r\nok  \tgithub.com/cockroachdb/cockroach/sql/parser\t0.011s\r\ntesting: warning: no tests to run\r\nPASS\r\nok  \tgithub.com/cockroachdb/cockroach/sql/pgwire\t0.018s\r\nPASS\r\nok  \tgithub.com/cockroachdb/cockroach/sql/privilege\t0.017s\r\n```"},"comment":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/comments/170122016","html_url":"https://github.com/cockroachdb/cockroach/issues/3704#issuecomment-170122016","issue_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/3704","id":170122016,"user":{"login":"vivekmenezes","id":11774212,"avatar_url":"https://avatars.githubusercontent.com/u/11774212?v=3","gravatar_id":"","url":"https://api.github.com/users/vivekmenezes","html_url":"https://github.com/vivekmenezes","followers_url":"https://api.github.com/users/vivekmenezes/followers","following_url":"https://api.github.com/users/vivekmenezes/following{/other_user}","gists_url":"https://api.github.com/users/vivekmenezes/gists{/gist_id}","starred_url":"https://api.github.com/users/vivekmenezes/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/vivekmenezes/subscriptions","organizations_url":"https://api.github.com/users/vivekmenezes/orgs","repos_url":"https://api.github.com/users/vivekmenezes/repos","events_url":"https://api.github.com/users/vivekmenezes/events{/privacy}","received_events_url":"https://api.github.com/users/vivekmenezes/received_events","type":"User","site_admin":false},"created_at":"2016-01-08T20:58:10Z","updated_at":"2016-01-08T20:58:10Z","body":"The txn coordinator heatbeatLoop mechanism is taking a long time to shutdown resulting in the delay. If I add a 100ms delay at the end of the two tests: TestDatabaseDescriptor, TestSchemaChangeLease, the problem goes away. I tried supplying a stopper to the heartbeat mechanism with no luck. I'm trying to understand this code a bit better so that I can come up with a deterministic solution.\r\n"}}