{"action":"created","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/10602","repository_url":"https://api.github.com/repos/cockroachdb/cockroach","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/10602/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/10602/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/10602/events","html_url":"https://github.com/cockroachdb/cockroach/issues/10602","id":188564626,"number":10602,"title":"stability: entire delta cluster stuck, not serving any SQL traffic","user":{"login":"a-robinson","id":7085343,"avatar_url":"https://avatars.githubusercontent.com/u/7085343?v=3","gravatar_id":"","url":"https://api.github.com/users/a-robinson","html_url":"https://github.com/a-robinson","followers_url":"https://api.github.com/users/a-robinson/followers","following_url":"https://api.github.com/users/a-robinson/following{/other_user}","gists_url":"https://api.github.com/users/a-robinson/gists{/gist_id}","starred_url":"https://api.github.com/users/a-robinson/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/a-robinson/subscriptions","organizations_url":"https://api.github.com/users/a-robinson/orgs","repos_url":"https://api.github.com/users/a-robinson/repos","events_url":"https://api.github.com/users/a-robinson/events{/privacy}","received_events_url":"https://api.github.com/users/a-robinson/received_events","type":"User","site_admin":false},"labels":[{"id":371606733,"url":"https://api.github.com/repos/cockroachdb/cockroach/labels/stability","name":"stability","color":"b60205","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":12,"created_at":"2016-11-10T17:05:57Z","updated_at":"2016-11-10T21:12:47Z","closed_at":null,"body":"Delta has been failing to serve requests for most of the last 19 hours, having only 3 good hours from 8-11 UTC this morning.\r\n\r\nThe logs are full of \"context deadline exceeded\" errors.\r\n\r\nThere are a ton (> 1000) of repeated logs like this in a row, all for the same range/replica, spammed such that each is came less than a hundred microseconds after the last:\r\n```\r\nW161110 16:39:04.701610 506 storage/gc_queue.go:218  [n10,gc,s19,r5444/7:/Table/55/1/871{86020…-91657…}] unable to resolve intents of committed txn on gc: context deadline exceeded\r\n```\r\n\r\nThose are followed by a ton of errors about an inability to push a transaction, with the context being the same range/replica. These are spammed even faster, coming 10s of microseconds apart:\r\n```\r\nW161110 16:39:04.727940 4935162 storage/gc_queue.go:628  [n10,gc,s19,r5444/7:/Table/55/1/871{86020…-91657…}] push of txn id=cf175f6e key=/Table/55/1/2699716940960131706/\"bd72518a-c1ae-4f98-a1d3-8c40d4f6fe43\"/7751851/0 rw=false pri=0.00868472 iso=SERIALIZABLE stat=PENDING epo=0 ts=1478513462.086455407,0 orig=0.000000000,0 max=0.000000000,0 wto=false rop=false failed: context deadline exceeded\r\n```\r\n\r\nIn the one case I looked at most closely, there was another different error mixed in the middle every couple hundred lines:\r\n```\r\nW161110 16:39:04.791403 4935416 storage/gc_queue.go:628  [n10,gc,s19,r5444/7:/Table/55/1/871{86020…-91657…}] push of txn \"sql/executor.go:546 sql txn implicit\" id=be657d16 key=/Table/55/1/8718809091224052977/\"8a16506f-3592-4c78-a50d-b1b83f015480\"/6148471/0 rw=true pri=0.01430796 iso=SERIALIZABLE stat=PENDING epo=0 ts=1478241838.382343181,0 orig=1478241838.382343181,0 max=1478241838.456109681,0 wto=false rop=false failed: context deadline exceeded\r\n```\r\n\r\nOnce that stops, there are a bunch of \"transferring raft leadership\" messages about different ranges before the pattern starts over again for a different range/replica.\r\n\r\nI'll check out a profile of the node next."},"comment":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/comments/259808927","html_url":"https://github.com/cockroachdb/cockroach/issues/10602#issuecomment-259808927","issue_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/10602","id":259808927,"user":{"login":"a-robinson","id":7085343,"avatar_url":"https://avatars.githubusercontent.com/u/7085343?v=3","gravatar_id":"","url":"https://api.github.com/users/a-robinson","html_url":"https://github.com/a-robinson","followers_url":"https://api.github.com/users/a-robinson/followers","following_url":"https://api.github.com/users/a-robinson/following{/other_user}","gists_url":"https://api.github.com/users/a-robinson/gists{/gist_id}","starred_url":"https://api.github.com/users/a-robinson/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/a-robinson/subscriptions","organizations_url":"https://api.github.com/users/a-robinson/orgs","repos_url":"https://api.github.com/users/a-robinson/repos","events_url":"https://api.github.com/users/a-robinson/events{/privacy}","received_events_url":"https://api.github.com/users/a-robinson/received_events","type":"User","site_admin":false},"created_at":"2016-11-10T21:12:47Z","updated_at":"2016-11-10T21:12:47Z","body":"There are some problems with inconsistent data in the cluster. There are a bunch of consistency check errors, like:\r\n\r\n```\r\nlogs/cockroach.stderr.13:E161110 14:05:13.568640 4201911 storage/stores_server.go:86  consistency check failed on range ID 3186: expected checksum c86b786f961e7df72b6f4f8408fefeab5141623cff902ecc46f4593b9d32b423262e23b31abc6b0ab24b49d832ec5a39d4a47e227da133d016051e7dba77927a, got 3293e8a81d782aeda88b37275fb361f3511389534f921cb10da1e1c7a4744308c975b3a849178a0e964770515faf86e351f9c3cb8eddf5d7d85e2094f8655948\r\nlogs/cockroach.stderr.13:E161110 14:06:00.186700 4201652 storage/replica_command.go:1870  [n10,replica consistency checker,s20,r3885/2:/Table/55/1/809{36830…-42445…}] could not CollectChecksum from replica {5 9 10}: rpc error: code = 4 desc = context deadline exceeded\r\nlogs/cockroach.stderr.13:E161110 14:07:10.187396 4206949 storage/replica_command.go:1870  [n10,replica consistency checker,s20,r17182/2:/Table/55/1/3316{1057…-6647…}] could not CollectChecksum from replica {5 9 5}: rpc error: code = 4 desc = context deadline exceeded\r\nlogs/cockroach.stderr.13:E161110 14:07:10.733325 4211455 storage/replica_command.go:1887  [n10,replica consistency checker,s19,r5064/9:/Table/55/1/8962{1500…-7178…}]\r\nlogs/cockroach.stderr.13:E161110 14:07:10.733458 4211456 storage/replica_command.go:1907  [n10,replica consistency checker,s19,r5064/9:/Table/55/1/8962{1500…-7178…}] consistency check failed with 1 inconsistent replicas; fetching details\r\nlogs/cockroach.stderr.13:E161110 14:07:10.733587 4211456 storage/replica_command.go:1913  [n10,replica consistency checker,s19,r5064/9:/Table/55/1/8962{1500…-7178…}] could not rerun consistency check: context canceled\r\n```\r\n\r\nAnd the replicas with consistency errors appear to be correlated with the context deadline exceeded errors. We don't know how the data became inconsistent, but we did find a bug with the consistency checking code in the process. Once we find a consistency check issue, we try collecting the details asynchronously with a context that get's getting cancelled shortly after kicking off the async task. We'll fix that issue and see if we can get a diff of what the inconsistency is."}}
{"actor":{"display_login":"a-robinson"}}