{"action":"created","issue":{"url":"https://api.github.com/repos/cloudfoundry/cloud_controller_ng/issues/1104","repository_url":"https://api.github.com/repos/cloudfoundry/cloud_controller_ng","labels_url":"https://api.github.com/repos/cloudfoundry/cloud_controller_ng/issues/1104/labels{/name}","comments_url":"https://api.github.com/repos/cloudfoundry/cloud_controller_ng/issues/1104/comments","events_url":"https://api.github.com/repos/cloudfoundry/cloud_controller_ng/issues/1104/events","html_url":"https://github.com/cloudfoundry/cloud_controller_ng/issues/1104","id":302228235,"number":1104,"title":"api_worker priority exceeds beyond integer limit","user":{"login":"suhlig","id":80507,"avatar_url":"https://avatars1.githubusercontent.com/u/80507?v=4","gravatar_id":"","url":"https://api.github.com/users/suhlig","html_url":"https://github.com/suhlig","followers_url":"https://api.github.com/users/suhlig/followers","following_url":"https://api.github.com/users/suhlig/following{/other_user}","gists_url":"https://api.github.com/users/suhlig/gists{/gist_id}","starred_url":"https://api.github.com/users/suhlig/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/suhlig/subscriptions","organizations_url":"https://api.github.com/users/suhlig/orgs","repos_url":"https://api.github.com/users/suhlig/repos","events_url":"https://api.github.com/users/suhlig/events{/privacy}","received_events_url":"https://api.github.com/users/suhlig/received_events","type":"User","site_admin":false},"labels":[{"id":240264792,"url":"https://api.github.com/repos/cloudfoundry/cloud_controller_ng/labels/unscheduled","name":"unscheduled","color":"D9D9D9","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":2,"created_at":"2018-03-05T09:36:22Z","updated_at":"2018-04-25T20:56:30Z","closed_at":null,"author_association":"MEMBER","body":"## Issue\r\n\r\nFailed jobs de-prioritise beyond the integer limit of the underlying PostgreSQL DB\r\n\r\n## Context\r\n\r\nWe had a few VCAP::CloudController::Jobs::Services::DeleteOrphanedInstance that failed multiple times. It looks as if the [de-prioritization that happens after each failure](https://github.com/cloudfoundry/cloud_controller_ng/blob/master/app/jobs/logging_context_job.rb#L48-L54) does not check whether it reached the limit of the underlying database column (a PostgreSQL integer in our case):\r\n\r\n```\r\nPG::NumericValueOutOfRange: ERROR:  integer out of range: \r\n  UPDATE \"delayed_jobs\" SET ... \"priority\" = 2147483648, \"handler\" = '\r\n    --- \r\n    !ruby/object:VCAP::CloudController::Jobs::LoggingContextJob\r\n    handler: !ruby/object:VCAP::CloudController::Jobs::TimeoutJob\r\n    handler: !ruby/object:VCAP::CloudController::Jobs::Services::DeleteOrphanedInstance\r\n    name: service-instance-deprovision\r\n    ...\r\n    \"last_error\" = 'Service instance : Service broker error: {\r\n      \"description\"=>\"Error deprovisioning instance bacdc304-9137-43a2-9dc9-4daefe3b0e0d\"\r\n    }\r\n    /var/vcap/data/packages/cloud_controller_ng/.../cloud_controller_ng/lib/services/service_brokers/v2/client.rb:186:in `rescue in deprovision'\r\n    ...\r\n  '\r\n```\r\n\r\nThis happened with cf-release v270.\r\n\r\n## Steps to Reproduce\r\n\r\nAttempt to delete a service-binding managed by a broker that is not available for a long time\r\n\r\n## Expected result\r\n\r\nA permanently failed job, or maybe just an upper bound of the priority\r\n\r\n## Current result\r\n\r\n`PG::NumericValueOutOfRange: ERROR:  integer out of range`\r\n"},"comment":{"url":"https://api.github.com/repos/cloudfoundry/cloud_controller_ng/issues/comments/384431317","html_url":"https://github.com/cloudfoundry/cloud_controller_ng/issues/1104#issuecomment-384431317","issue_url":"https://api.github.com/repos/cloudfoundry/cloud_controller_ng/issues/1104","id":384431317,"user":{"login":"jenspinney","id":3200507,"avatar_url":"https://avatars0.githubusercontent.com/u/3200507?v=4","gravatar_id":"","url":"https://api.github.com/users/jenspinney","html_url":"https://github.com/jenspinney","followers_url":"https://api.github.com/users/jenspinney/followers","following_url":"https://api.github.com/users/jenspinney/following{/other_user}","gists_url":"https://api.github.com/users/jenspinney/gists{/gist_id}","starred_url":"https://api.github.com/users/jenspinney/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jenspinney/subscriptions","organizations_url":"https://api.github.com/users/jenspinney/orgs","repos_url":"https://api.github.com/users/jenspinney/repos","events_url":"https://api.github.com/users/jenspinney/events{/privacy}","received_events_url":"https://api.github.com/users/jenspinney/received_events","type":"User","site_admin":false},"created_at":"2018-04-25T20:56:30Z","updated_at":"2018-04-25T20:56:30Z","author_association":"MEMBER","body":"@suhlig Sorry for the delay getting back to you. I’ve spent a couple days investigating this, and I haven’t been able to figure out how this could happen.\r\n\r\nThe priority of the job does get doubled on each failure, and we should be defensive about not letting that grow indefinitely, but the DeleteOrphanedInstance job has a `max_attempts` value of 11, so the priority of that job should be getting capped at 2^(11-1) (1024). After it hits 11 attempts, the job should simply fail. I'm really curious about why this isn't happening for your system. If do see this issue again and are able to grep the worker logs, I'd really like to see what attempt number you're getting up to. Or do you still have access to an environment where this happens? If so, would you be able to download the cloud_controller_worker logs for the cc-worker vms and run the following grep on the combined log file?\r\n\r\n`grep \"Job VCAP::CloudController::Jobs::Services::DeleteOrphanedInstance (id=.*) (queue=cc-generic) FAILED (.* prior attempts) with VCAP::Services::ServiceBrokers::V2\" <your_combined_log_file>`\r\n\r\nOf course we could just fix this by capping the priority at some reasonable value, but I feel somewhat uncomfortable doing that before actually understanding the scenario where this is possible (maybe whatever is causing `max_attempts` to be ignored is a larger problem we need to look at).\r\n\r\nYou’re using cf-release v270, which corresponds to cloud_controller_ng SHA d2dbae2838ec0aa8d8b26e8918d4036405177716 and it seems like nothing relevant has changed in this area since that commit.\r\n\r\nFor reference, here are the steps I took:\r\n\r\n1. Deployed and registered a service broker to a CF hosted on a bosh-lite. (I’m using cf-deployment 1.27).\r\n1. Modified the service broker to return status code 500 to all requests.\r\n1. Attempted to provision a new service instance via the CF CLI. This initiates orphan mitigation, kicking off the same DeleteOrphanedInstance job you're getting problems from. The DeleteOrphanedInstance job will fail every time it runs because of the 500s, causing the job to continue retrying.\r\n1. After 11 attempts (approx 34 hours) in my environment (bosh-lite with mysql) the job is marked as failed and stops retrying. The max value priority gets to is 1024.\r\n1. I redeployed and replaced mysql with postgres and repeated the steps above and got the same result.\r\n\r\nThe only code modification I made was adjusting `reschedule_at` in the job so that I didn’t have to wait the full 34 hours. \r\n\r\nIf you’re able to grep those logs and see how many attempts are being made, or if you have any ideas of things we should be looking at, I’m very interested. At this point, I’m not able to repro the problem."}}
{"actor":{"display_login":"jenspinney"}}