{"action":"opened","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/20258","repository_url":"https://api.github.com/repos/cockroachdb/cockroach","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/20258/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/20258/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/20258/events","html_url":"https://github.com/cockroachdb/cockroach/issues/20258","id":276744916,"number":20258,"title":"sql/jobs: TestRegistryResumeExpiredLease failed under stress","user":{"login":"cockroach-teamcity","id":20559710,"avatar_url":"https://avatars0.githubusercontent.com/u/20559710?v=4","gravatar_id":"","url":"https://api.github.com/users/cockroach-teamcity","html_url":"https://github.com/cockroach-teamcity","followers_url":"https://api.github.com/users/cockroach-teamcity/followers","following_url":"https://api.github.com/users/cockroach-teamcity/following{/other_user}","gists_url":"https://api.github.com/users/cockroach-teamcity/gists{/gist_id}","starred_url":"https://api.github.com/users/cockroach-teamcity/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cockroach-teamcity/subscriptions","organizations_url":"https://api.github.com/users/cockroach-teamcity/orgs","repos_url":"https://api.github.com/users/cockroach-teamcity/repos","events_url":"https://api.github.com/users/cockroach-teamcity/events{/privacy}","received_events_url":"https://api.github.com/users/cockroach-teamcity/received_events","type":"User","site_admin":false},"labels":[{"id":335217860,"url":"https://api.github.com/repos/cockroachdb/cockroach/labels/Robot","name":"Robot","color":"5319e7","default":false},{"id":191587409,"url":"https://api.github.com/repos/cockroachdb/cockroach/labels/test-failure","name":"test-failure","color":"e11d21","default":false}],"state":"open","locked":false,"assignee":{"login":"benesch","id":882976,"avatar_url":"https://avatars1.githubusercontent.com/u/882976?v=4","gravatar_id":"","url":"https://api.github.com/users/benesch","html_url":"https://github.com/benesch","followers_url":"https://api.github.com/users/benesch/followers","following_url":"https://api.github.com/users/benesch/following{/other_user}","gists_url":"https://api.github.com/users/benesch/gists{/gist_id}","starred_url":"https://api.github.com/users/benesch/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/benesch/subscriptions","organizations_url":"https://api.github.com/users/benesch/orgs","repos_url":"https://api.github.com/users/benesch/repos","events_url":"https://api.github.com/users/benesch/events{/privacy}","received_events_url":"https://api.github.com/users/benesch/received_events","type":"User","site_admin":false},"assignees":[{"login":"benesch","id":882976,"avatar_url":"https://avatars1.githubusercontent.com/u/882976?v=4","gravatar_id":"","url":"https://api.github.com/users/benesch","html_url":"https://github.com/benesch","followers_url":"https://api.github.com/users/benesch/followers","following_url":"https://api.github.com/users/benesch/following{/other_user}","gists_url":"https://api.github.com/users/benesch/gists{/gist_id}","starred_url":"https://api.github.com/users/benesch/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/benesch/subscriptions","organizations_url":"https://api.github.com/users/benesch/orgs","repos_url":"https://api.github.com/users/benesch/repos","events_url":"https://api.github.com/users/benesch/events{/privacy}","received_events_url":"https://api.github.com/users/benesch/received_events","type":"User","site_admin":false}],"milestone":null,"comments":0,"created_at":"2017-11-25T11:40:43Z","updated_at":"2017-11-25T11:40:43Z","closed_at":null,"author_association":"MEMBER","body":"SHA: https://github.com/cockroachdb/cockroach/commits/0cd176ae8a552ed9284a159092279dd43d41afad\n\nParameters:\n```\nTAGS=\nGOFLAGS=-race\n```\n\nStress build found a failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=419465&tab=buildLog\n\n```\nW171125 11:40:38.040517 1539 server/status/runtime.go:109  Could not parse build timestamp: parsing time \"\" as \"2006/01/02 15:04:05\": cannot parse \"\" as \"2006\"\nI171125 11:40:38.062316 1539 server/config.go:512  [n?] 1 storage engine initialized\nI171125 11:40:38.062378 1539 server/config.go:515  [n?] RocksDB cache size: 128 MiB\nI171125 11:40:38.062419 1539 server/config.go:515  [n?] store 0: in-memory, size 0 B\nI171125 11:40:38.151811 1539 server/node.go:347  [n?] **** cluster c23e3449-30db-442e-a314-07799aa4ad65 has been created\nI171125 11:40:38.151911 1539 server/server.go:907  [n?] **** add additional nodes by specifying --join=127.0.0.1:55254\nI171125 11:40:38.153198 1539 vendor/google.golang.org/grpc/resolver_conn_wrapper.go:64  dialing to target with scheme: \"\"\nI171125 11:40:38.153258 1539 vendor/google.golang.org/grpc/resolver_conn_wrapper.go:70  could not get resolver for scheme: \"\"\nI171125 11:40:38.163011 1539 storage/store.go:1204  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available\nI171125 11:40:38.163273 1539 server/node.go:472  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=3.2 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=3298.00 p25=3298.00 p50=3298.00 p75=3298.00 p90=3298.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00}\nI171125 11:40:38.163441 1539 server/node.go:329  [n1] node ID 1 initialized\nI171125 11:40:38.163650 1539 gossip/gossip.go:331  [n1] NodeDescriptor set to node_id:1 address:<network_field:\"tcp\" address_field:\"127.0.0.1:55254\" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:4 > \nI171125 11:40:38.165011 1539 storage/stores.go:332  [n1] read 0 node addresses from persistent storage\nI171125 11:40:38.165339 1539 server/node.go:617  [n1] connecting to gossip network to verify cluster ID...\nI171125 11:40:38.165433 1539 server/node.go:642  [n1] node connected via gossip and verified as part of cluster \"c23e3449-30db-442e-a314-07799aa4ad65\"\nI171125 11:40:38.165735 1539 server/node.go:414  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []\nI171125 11:40:38.166352 1539 sql/distsql_physical_planner.go:125  [n1] creating DistSQLPlanner with address {tcp 127.0.0.1:55254}\nI171125 11:40:38.172922 1577 vendor/google.golang.org/grpc/resolver_conn_wrapper.go:64  dialing to target with scheme: \"\"\nI171125 11:40:38.172989 1577 vendor/google.golang.org/grpc/resolver_conn_wrapper.go:70  could not get resolver for scheme: \"\"\nI171125 11:40:38.176409 1813 storage/replica_command.go:1395  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/\"\" [r2]\nI171125 11:40:38.239510 1813 storage/replica_command.go:1395  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]\nI171125 11:40:38.277612 1539 server/server.go:1119  [n1] starting https server at 127.0.0.1:46515\nI171125 11:40:38.277694 1539 server/server.go:1120  [n1] starting grpc/postgres server at 127.0.0.1:55254\nI171125 11:40:38.277748 1539 server/server.go:1121  [n1] advertising CockroachDB node at 127.0.0.1:55254\nW171125 11:40:38.277901 1539 sql/jobs/registry.go:167  [n1] unable to get node liveness: node not in the liveness table\nI171125 11:40:38.318406 1813 storage/replica_command.go:1395  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]\nW171125 11:40:38.513723 1725 storage/intent_resolver.go:350  [n1,s1,r4/1:/{System/NodeL…-Max}]: failed to push during intent resolution: failed to push \"sql txn implicit\" id=32517be7 key=/Table/SystemConfigSpan/Start rw=true pri=0.01298226 iso=SERIALIZABLE stat=PENDING epo=0 ts=1511610038.323414835,0 orig=1511610038.323414835,0 max=1511610038.323414835,0 wto=false rop=false seq=7\nI171125 11:40:38.518281 1813 storage/replica_command.go:1395  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]\nI171125 11:40:38.572516 1539 sql/event_log.go:113  [n1] Event: \"alter_table\", target: 12, info: {TableName:eventlog Statement:ALTER TABLE system.eventlog ALTER COLUMN \"uniqueID\" SET DEFAULT uuid_v4() User:node MutationID:0 CascadeDroppedViews:[]}\nI171125 11:40:38.611555 1813 storage/replica_command.go:1395  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/\"tse\" [r6]\nI171125 11:40:38.726676 1813 storage/replica_command.go:1395  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]\nI171125 11:40:38.727461 1539 sql/lease.go:348  [n1] publish: descID=12 (eventlog) version=2 mtime=2017-11-25 11:40:38.641189429 +0000 UTC\nI171125 11:40:38.861659 1813 storage/replica_command.go:1395  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]\nI171125 11:40:38.908415 1813 storage/replica_command.go:1395  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]\nI171125 11:40:39.024434 1813 storage/replica_command.go:1395  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]\nI171125 11:40:39.046443 1539 sql/event_log.go:113  [n1] Event: \"set_cluster_setting\", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}\nI171125 11:40:39.143944 1813 storage/replica_command.go:1395  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]\nI171125 11:40:39.177372 1813 storage/replica_command.go:1395  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]\nI171125 11:40:39.244397 1813 storage/replica_command.go:1395  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]\nW171125 11:40:39.279720 1886 storage/intent_resolver.go:350  [n1,s1,r1/1:/{Min-System/}]: failed to push during intent resolution: failed to push \"split\" id=12d5dc44 key=/Local/Range/Table/15/RangeDescriptor rw=true pri=0.05986593 iso=SERIALIZABLE stat=PENDING epo=0 ts=1511610039.244460065,0 orig=1511610039.244460065,0 max=1511610039.244460065,0 wto=false rop=false seq=3\nI171125 11:40:39.288594 1813 storage/replica_command.go:1395  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]\nI171125 11:40:39.301926 1539 sql/event_log.go:113  [n1] Event: \"set_cluster_setting\", target: 0, info: {SettingName:version Value:$1 User:node}\nI171125 11:40:39.380722 1539 sql/event_log.go:113  [n1] Event: \"set_cluster_setting\", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}\nW171125 11:40:39.395724 1921 storage/intent_resolver.go:350  [n1,s1,r1/1:/{Min-System/}]: failed to push during intent resolution: failed to push \"split\" id=a5b73085 key=/Local/Range/Table/16/RangeDescriptor rw=true pri=0.03159838 iso=SERIALIZABLE stat=PENDING epo=0 ts=1511610039.288689194,0 orig=1511610039.288689194,0 max=1511610039.288689194,0 wto=false rop=false seq=4\nI171125 11:40:39.485127 1813 storage/replica_command.go:1395  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]\nI171125 11:40:39.505283 1539 server/server.go:1179  [n1] done ensuring all necessary migrations have run\nI171125 11:40:39.505367 1539 server/server.go:1182  [n1] serving sql connections\nI171125 11:40:39.538516 2034 sql/event_log.go:113  [n1] Event: \"node_join\", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:55254} Attrs: Locality: ServerVersion:1.1-4} ClusterID:c23e3449-30db-442e-a314-07799aa4ad65 StartedAt:1511610038165465460 LastUp:1511610038165465460}\nI171125 11:40:39.575364 1813 storage/replica_command.go:1395  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]\nI171125 11:40:39.648678 1813 storage/replica_command.go:1395  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]\nW171125 11:40:39.959419 2107 storage/engine/mvcc.go:1900  [n1,s1,r12/1:/Table/1{5-6}] unable to find value for /Table/15/2/\"pending\"/2017-11-25T11:40:39.866963Z/299957091952525313/0 @ 1511610039.896382333,1\n==================\nWARNING: DATA RACE\nWrite at 0x000003872980 by goroutine 235:\n  github.com/cockroachdb/cockroach/pkg/sql/jobs_test.TestRegistryResumeExpiredLease()\n      /go/src/github.com/cockroachdb/cockroach/pkg/sql/jobs/registry.go:200 +0xff7\n  github.com/cockroachdb/cockroach/pkg/sql/jobs_test.TestRegistryResumeExpiredLease()\n      /go/src/github.com/cockroachdb/cockroach/pkg/sql/jobs/registry_external_test.go:116 +0xb6a\n  github.com/cockroachdb/cockroach/pkg/sql/jobs_test.TestRegistryResumeExpiredLease()\n      /go/src/github.com/cockroachdb/cockroach/pkg/sql/jobs/registry_external_test.go:113 +0xa9b\n  testing.tRunner()\n      /usr/local/go/src/testing/testing.go:746 +0x16c\n\nPrevious read at 0x000003872980 by goroutine 117:\n  github.com/cockroachdb/cockroach/pkg/sql/jobs.(*Registry).maybeAdoptJob()\n      /go/src/github.com/cockroachdb/cockroach/pkg/sql/jobs/registry.go:283 +0x802\n  github.com/cockroachdb/cockroach/pkg/sql/jobs.(*Registry).Start.func2()\n      /go/src/github.com/cockroachdb/cockroach/pkg/sql/jobs/registry.go:153 +0x1a3\n  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1()\n      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0x160\n\nGoroutine 235 (running) created at:\n  testing.(*T).Run()\n      /usr/local/go/src/testing/testing.go:789 +0x568\n  testing.runTests.func1()\n      /usr/local/go/src/testing/testing.go:1004 +0xa7\n  testing.tRunner()\n      /usr/local/go/src/testing/testing.go:746 +0x16c\n  testing.runTests()\n      /usr/local/go/src/testing/testing.go:1002 +0x521\n  testing.(*M).Run()\n      /usr/local/go/src/testing/testing.go:921 +0x206\n  github.com/cockroachdb/cockroach/pkg/sql/jobs_test.TestMain()\n      /go/src/github.com/cockroachdb/cockroach/pkg/sql/jobs/main_test.go:33 +0x15d\n  main.main()\n      github.com/cockroachdb/cockroach/pkg/sql/jobs/_test/_testmain.go:56 +0x1cd\n\nGoroutine 117 (running) created at:\n  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker()\n      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:189 +0xba\n  github.com/cockroachdb/cockroach/pkg/sql/jobs.(*Registry).Start()\n      /go/src/github.com/cockroachdb/cockroach/pkg/sql/jobs/registry.go:149 +0x2fa\n  github.com/cockroachdb/cockroach/pkg/sql/jobs_test.TestRegistryResumeExpiredLease()\n      /go/src/github.com/cockroachdb/cockroach/pkg/sql/jobs/registry_external_test.go:87 +0x69c\n  testing.tRunner()\n      /usr/local/go/src/testing/testing.go:746 +0x16c\n==================\nI171125 11:40:40.152380 2058 sql/jobs/registry.go:304  job 299957091856416769: resuming\nI171125 11:40:40.212383 2059 sql/jobs/registry.go:304  job 299957092225089537: resuming\nI171125 11:40:40.212975 1539 util/stop/stopper.go:474  quiescing; tasks left:\n1      node.Node: batch\n1      [async] transport racer\nI171125 11:40:40.213060 1579 kv/transport_race.go:68  transport race promotion: ran 35 iterations on up to 774 requests\nW171125 11:40:40.213696 1627 vendor/google.golang.org/grpc/transport/log.go:36  transport: http2Server.HandleStreams failed to read frame: io: read/write on closed pipe\nW171125 11:40:40.214664 1581 vendor/google.golang.org/grpc/clientconn.go:934  grpc: addrConn.resetTransport failed to create client transport: connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:55254: operation was canceled\"; Reconnecting to {127.0.0.1:55254 0  <nil>}\nW171125 11:40:40.214777 1581 vendor/google.golang.org/grpc/clientconn.go:1028  grpc: addrConn.transportMonitor exits due to: context canceled\nW171125 11:40:40.215119 1628 vendor/google.golang.org/grpc/clientconn.go:1028  grpc: addrConn.transportMonitor exits due to: connection error: desc = \"transport: authentication handshake failed: context canceled\"\nI171125 11:40:40.213243 1539 util/stop/stopper.go:474  quiescing; tasks left:\n1      node.Node: batch\nE171125 11:40:40.215638 2104 sql/jobs/registry.go:154  error while adopting jobs: node unavailable; try another peer\n\ttesting.go:699: race detected during execution of test\n```"}}
{"actor":{"display_login":"cockroach-teamcity"}}