{"action":"created","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/8526","repository_url":"https://api.github.com/repos/cockroachdb/cockroach","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/8526/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/8526/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/8526/events","html_url":"https://github.com/cockroachdb/cockroach/issues/8526","id":171045045,"number":8526,"title":"stress: failed test in cockroach/storage/storage.test: TestStoreMetrics","user":{"login":"cockroach-teamcity","id":20559710,"avatar_url":"https://avatars.githubusercontent.com/u/20559710?v=3","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":[{"url":"https://api.github.com/repos/cockroachdb/cockroach/labels/Robot","name":"Robot","color":"5319e7"},{"url":"https://api.github.com/repos/cockroachdb/cockroach/labels/test-failure","name":"test-failure","color":"e11d21"}],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":{"url":"https://api.github.com/repos/cockroachdb/cockroach/milestones/5","html_url":"https://github.com/cockroachdb/cockroach/milestones/Q3","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/milestones/5/labels","id":1875804,"number":5,"title":"Q3","description":"","creator":{"login":"petermattis","id":6201335,"avatar_url":"https://avatars.githubusercontent.com/u/6201335?v=3","gravatar_id":"","url":"https://api.github.com/users/petermattis","html_url":"https://github.com/petermattis","followers_url":"https://api.github.com/users/petermattis/followers","following_url":"https://api.github.com/users/petermattis/following{/other_user}","gists_url":"https://api.github.com/users/petermattis/gists{/gist_id}","starred_url":"https://api.github.com/users/petermattis/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/petermattis/subscriptions","organizations_url":"https://api.github.com/users/petermattis/orgs","repos_url":"https://api.github.com/users/petermattis/repos","events_url":"https://api.github.com/users/petermattis/events{/privacy}","received_events_url":"https://api.github.com/users/petermattis/received_events","type":"User","site_admin":false},"open_issues":135,"closed_issues":136,"state":"open","created_at":"2016-07-11T13:25:51Z","updated_at":"2016-08-14T18:45:18Z","due_on":"2016-10-01T04:00:00Z","closed_at":null},"comments":1,"created_at":"2016-08-14T06:34:18Z","updated_at":"2016-08-14T18:45:18Z","closed_at":"2016-08-14T18:45:18Z","body":"Binary: cockroach/static-tests.tar.gz sha: https://github.com/cockroachdb/cockroach/commits/b44ebfb6d0911c8d6e9c6d8fc1099d592791a894\n\nStress build found a failed test:\n\n```\n=== RUN   TestStoreMetrics\nI160814 04:47:14.456048 storage/engine/rocksdb.go:354  opening in memory rocksdb instance\nW160814 04:47:14.456756 gossip/gossip.go:1017  not connected to cluster; use --join to specify a connected node\nI160814 04:47:14.458453 storage/store.go:2525  store=1:1: system config not yet available\nI160814 04:47:14.459163 storage/replica_trigger.go:308  store=1:1 range=1 [/Min-/Max): new range lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 900ms following replica {0 0 0} 1970-01-01 00:00:00 +0000 UTC 0s [physicalTime=1970-01-01 00:00:00 +0000 UTC]\nI160814 04:47:14.459542 storage/engine/rocksdb.go:354  opening in memory rocksdb instance\nW160814 04:47:14.460351 gossip/gossip.go:1017  not connected to cluster; use --join to specify a connected node\nI160814 04:47:14.461517 storage/store.go:2525  store=2:2: system config not yet available\nI160814 04:47:14.461539 gossip/client.go:75  node 2: starting client to 127.0.0.1:35096\nI160814 04:47:14.461668 storage/engine/rocksdb.go:354  opening in memory rocksdb instance\nI160814 04:47:14.461933 gossip/server.go:185  node 1: received gossip from node 2\nI160814 04:47:14.461968 gossip/server.go:283  node 1: replying to 2 \nI160814 04:47:14.462041 gossip/server.go:185  node 1: received gossip from node 2\nI160814 04:47:14.462095 gossip/server.go:283  node 1: replying to 2 \nI160814 04:47:14.462231 gossip/server.go:185  node 1: received gossip from node 2\nI160814 04:47:14.462255 gossip/server.go:283  node 1: replying to 2 \nI160814 04:47:14.462305 gossip/server.go:185  node 1: received gossip from node 2\nI160814 04:47:14.462321 gossip/server.go:283  node 1: replying to 2 \nW160814 04:47:14.462438 gossip/gossip.go:1017  not connected to cluster; use --join to specify a connected node\nI160814 04:47:14.463211 storage/store.go:2525  store=3:3: system config not yet available\nI160814 04:47:14.463343 gossip/client.go:75  node 3: starting client to 127.0.0.1:35096\nI160814 04:47:14.463633 gossip/server.go:185  node 1: received gossip from node 3\nI160814 04:47:14.463660 gossip/server.go:283  node 1: replying to 3 \nI160814 04:47:14.463737 gossip/server.go:185  node 1: received gossip from node 3\nI160814 04:47:14.463765 gossip/server.go:283  node 1: replying to 3 \nI160814 04:47:14.463916 gossip/server.go:185  node 1: received gossip from node 3\nI160814 04:47:14.463941 gossip/server.go:283  node 1: replying to 3 \nI160814 04:47:14.464013 gossip/server.go:185  node 1: received gossip from node 3\nI160814 04:47:14.464037 gossip/server.go:283  node 1: replying to 3 \nI160814 04:47:14.465398 storage/replica_command.go:2216  store=1:1 range=1 [/Min-/Max): initiating a split of this range at key \"m\"\nE160814 04:47:14.467367 storage/queue.go:508  [replicate] (purgatory) on store=1:1 range=1 [/Min-\"m\"): 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\nE160814 04:47:14.467534 storage/queue.go:508  [replicate] (purgatory) on store=1:1 range=2 [\"m\"-/Max): 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\nI160814 04:47:14.472228 storage/replica_raftstorage.go:474  generated snapshot for range 2 at index 10 in 110.62µs. encoded size=2407, 23 KV pairs, 0 log entries\nI160814 04:47:14.472476 storage/replica_command.go:3059  store=1:1 range=2 [\"m\"-/Max): change replicas of 2: read existing descriptor range_id:2 start_key:\"m\" end_key:\"\\377\\377\" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 \nI160814 04:47:14.472874 storage/replica_raftstorage.go:600  store=2:2 range=2 [/Min-/Min): with replicaID [?], applying preemptive snapshot for range 2 at index 10 (encoded size=2407, 23 KV pairs, 0 log entries)\nI160814 04:47:14.473136 storage/replica.go:2144  store=1:1 range=1 [/Min-\"m\"): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>\nI160814 04:47:14.473627 storage/replica.go:2144  store=1:1 range=2 [\"m\"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/\"m\"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/\"m\"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>\nI160814 04:47:14.473901 storage/replica.go:1520  store=1:1 range=2 [\"m\"-/Max): proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2} for range 2: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]\nI160814 04:47:14.474091 storage/replica.go:2144  store=1:1 range=2 [\"m\"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/\"m\"/RangeDescriptor,/Min), pErr=<nil>\nI160814 04:47:14.474699 storage/replica_raftstorage.go:474  generated snapshot for range 2 at index 13 in 121.74µs. encoded size=3231, 25 KV pairs, 3 log entries\nW160814 04:47:14.474835 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/\"m\"/\"rdsc\\x00\" must be greater than start /Local/Range/\"m\"/RangeDescriptor\nI160814 04:47:14.474904 storage/replica_raftstorage.go:603  store=2:2 range=2 [\"m\"-/Max): with replicaID [?], applied preemptive snapshot for range 2 in 2.000445ms\nI160814 04:47:14.474964 storage/replica_command.go:3059  store=1:1 range=2 [\"m\"-/Max): change replicas of 2: read existing descriptor range_id:2 start_key:\"m\" end_key:\"\\377\\377\" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 \nI160814 04:47:14.475276 storage/replica.go:2144  store=1:1 range=1 [/Min-\"m\"): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>\nI160814 04:47:14.475399 storage/replica_raftstorage.go:600  store=3:3 range=2 [/Min-/Min): with replicaID [?], applying preemptive snapshot for range 2 at index 13 (encoded size=3231, 25 KV pairs, 3 log entries)\nI160814 04:47:14.475667 storage/replica_raftstorage.go:603  store=3:3 range=2 [\"m\"-/Max): with replicaID [?], applied preemptive snapshot for range 2 in 242.983µs\nI160814 04:47:14.477021 storage/replica.go:2144  store=2:2 range=2 [\"m\"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/\"m\"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/\"m\"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>\nI160814 04:47:14.477215 storage/replica.go:2144  store=2:2 range=2 [\"m\"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/\"m\"/RangeDescriptor,/Min), pErr=<nil>\nI160814 04:47:14.477338 storage/replica.go:2144  store=1:1 range=2 [\"m\"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/\"m\"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/\"m\"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>\nI160814 04:47:14.477632 storage/replica.go:2144  store=2:2 range=2 [\"m\"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/\"m\"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/\"m\"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>\nI160814 04:47:14.477701 storage/replica.go:1520  store=1:1 range=2 [\"m\"-/Max): proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:3} for range 2: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3}]\nI160814 04:47:14.478431 storage/replica.go:2144  store=1:1 range=2 [\"m\"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/\"m\"/RangeDescriptor,/Min), pErr=<nil>\nI160814 04:47:14.478707 storage/replica.go:2144  store=2:2 range=2 [\"m\"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/\"m\"/RangeDescriptor,/Min), pErr=<nil>\nI160814 04:47:14.478813 stopper.go:408  quiesceing; tasks left:\n1      storage/intent_resolver.go:346\nW160814 04:47:14.478905 storage/intent_resolver.go:325  store=1:1 range=2 [\"m\"-/Max): failed to resolve intents: failed to send RPC: sending to all 1 replicas failed; last error: failed to send RPC: store is stopped\nI160814 04:47:14.882525 storage/replica_raftstorage.go:474  generated snapshot for range 2 at index 15 in 157.451µs. encoded size=4094, 27 KV pairs, 5 log entries\nI160814 04:47:14.883220 storage/replica_raftstorage.go:600  store=3:3 range=2 [/Min-/Min): with replicaID 3, applying Raft snapshot for range 2 at index 15 (encoded size=4094, 27 KV pairs, 5 log entries)\nI160814 04:47:14.883571 storage/replica_raftstorage.go:603  store=3:3 range=2 [\"m\"-/Max): with replicaID 3, applied Raft snapshot for range 2 in 317.36µs\nI160814 04:47:14.883606 storage/replica_trigger.go:308  store=2:2 range=2 [\"m\"-/Max): new range lease replica {2 2 2} 1970-01-01 00:00:00.9 +0000 UTC 1.8s following replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 900ms [physicalTime=1970-01-01 00:00:01.8 +0000 UTC]\nI160814 04:47:14.884006 gossip/server.go:185  node 1: received gossip from node 2\nI160814 04:47:14.884073 gossip/server.go:283  node 1: replying to 2 \nE160814 04:47:14.885809 storage/client_test.go:863  engine 0: missing key \"z\"\nE160814 04:47:14.885846 storage/client_test.go:863  engine 2: missing key \"z\"\nE160814 04:47:14.885950 storage/client_test.go:863  engine 0: missing key \"z\"\nE160814 04:47:14.885987 storage/client_test.go:863  engine 2: missing key \"z\"\nI160814 04:47:14.886112 stopper.go:408  quiesceing; tasks left:\n1      storage/intent_resolver.go:306\nI160814 04:47:14.886133 stopper.go:408  quiesceing; tasks left:\n1      storage/client_test.go:425\nW160814 04:47:14.886438 storage/replica.go:410  store=2:2 range=2 [\"m\"-/Max): outgoing raft transport stream to {3 3 3} closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:3 StoreID:3 ReplicaID:3}: no store registered for {NodeID:2 StoreID:2 ReplicaID:2}\nW160814 04:47:14.886466 storage/intent_resolver.go:299  store=1:1 range=1 [/Min-\"m\"): failed to resolve intents: node unavailable; try another peer\nW160814 04:47:14.886662 storage/replica.go:410  store=1:1 range=2 [\"m\"-/Max): outgoing raft transport stream to {2 2 2} closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no store registered for {NodeID:1 StoreID:1 ReplicaID:1}\nI160814 04:47:14.886977 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:39006->127.0.0.1:57106: use of closed network connection\nI160814 04:47:14.886991 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:32884->127.0.0.1:49928: use of closed network connection\n--- FAIL: TestStoreMetrics (0.43s)\n\tclient_metrics_test.go:94: cluster_id:<00000000-0000-0000-0000-000000000000> node_id:1 store_id:1 : expected intent count to be zero, was 1\n```\n\nRun Details:\n\n```\n0 runs so far, 0 failures, over 5s\n0 runs so far, 0 failures, over 10s\n0 runs so far, 0 failures, over 15s\n0 runs so far, 0 failures, over 20s\n0 runs so far, 0 failures, over 25s\n0 runs so far, 0 failures, over 30s\n0 runs so far, 0 failures, over 35s\n15 runs so far, 0 failures, over 40s\n15 runs so far, 0 failures, over 45s\n16 runs so far, 0 failures, over 50s\n16 runs so far, 0 failures, over 55s\n16 runs so far, 0 failures, over 1m0s\n16 runs so far, 0 failures, over 1m5s\n16 runs so far, 0 failures, over 1m10s\n17 runs so far, 0 failures, over 1m15s\n19 runs completed, 1 failures, over 1m16s\nFAIL\n```\nPlease assign, take a look and update the issue accordingly."},"comment":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/comments/239689364","html_url":"https://github.com/cockroachdb/cockroach/issues/8526#issuecomment-239689364","issue_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/8526","id":239689364,"user":{"login":"tamird","id":1535036,"avatar_url":"https://avatars.githubusercontent.com/u/1535036?v=3","gravatar_id":"","url":"https://api.github.com/users/tamird","html_url":"https://github.com/tamird","followers_url":"https://api.github.com/users/tamird/followers","following_url":"https://api.github.com/users/tamird/following{/other_user}","gists_url":"https://api.github.com/users/tamird/gists{/gist_id}","starred_url":"https://api.github.com/users/tamird/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tamird/subscriptions","organizations_url":"https://api.github.com/users/tamird/orgs","repos_url":"https://api.github.com/users/tamird/repos","events_url":"https://api.github.com/users/tamird/events{/privacy}","received_events_url":"https://api.github.com/users/tamird/received_events","type":"User","site_admin":false},"created_at":"2016-08-14T18:45:17Z","updated_at":"2016-08-14T18:45:17Z","body":"#8437."}}
{"actor":{"display_login":"tamird"}}