cloudfoundry / cloudfoundry/cloud_controller_ng

Concurrency: DELETE /v3/route/:guid and DELETE /v3/service_route_bindings/:guid can cause 500 - unknown error

Open
#3,735 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Ruby
Stars
207
Forks
373
Avg merge
2d 12h
Merged PRs (30d)
56

Description

Issue

A route delete request led to an unknown error 500 response.

Context

This was caused by trying to delete the service binding from the DB, but the service binding was already gone. A concurrently running request to delete the service route binding (DELETE /v3/service_route_bindings) deleted the resource first.

Here the error message from the logs:
"message":"Request failed: 500: {\"error_code\"=>\"UnknownError\", \"description\"=>\"An unknown error occurred.\", \"code\"=>10001, \"test_mode_info\"=>{\"description\"=>\"Attempt to delete object did not result in a single row modification (Rows Deleted: 0, SQL: DELETE FROM \\\"route_bindings\\\" WHERE (\\\"id\\\" = 745543))\", \"error_code\"=>\"CF-NoExistingObject\", \"backtrace\"=>[\"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1674:in _delete'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1208:in delete'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1715:in _destroy_delete'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1704:in block in _destroy'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1047:in around_destroy'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1701:in _destroy'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1220:in block (2 levels) in destroy'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/transactions.rb:235:in block in transaction'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/connection_pool/threaded.rb:88:in hold'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/connecting.rb:293:in synchronize'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/transactions.rb:197:in transaction'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1954:in checked_transaction'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1220:in block in destroy'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1940:in checked_save_failure'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1220:in destroy'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/actions/services/service_key_delete.rb:29:in delete_service_binding'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/actions/services/service_key_delete.rb:9:in block in delete'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/dataset/actions.rb:162:in block in each'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:651:in block (2 levels) in fetch_rows'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:651:in yield_hash_rows'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:651:in block in fetch_rows'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:161:in execute'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:532:in _execute'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:348:in block (2 levels) in execute'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:555:in check_database_errors'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:348:in block in execute'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/connection_pool/threaded.rb:88:in hold'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/connecting.rb:293:in synchronize'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:348:in execute'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/dataset/actions.rb:1189:in execute'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/adapters/postgres.rb:651:in fetch_rows'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/dataset/actions.rb:162:in each'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel_pg-1.17.1/lib/sequel_pg/sequel_pg.rb:83:in each'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/actions/services/service_key_delete.rb:8:in each_with_object'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/actions/services/service_key_delete.rb:8:in delete'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/models/runtime/route.rb:248:in destroy_route_bindings'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/models/runtime/route.rb:212:in before_destroy'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1703:in block in _destroy'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1047:in around_destroy'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/models/runtime/route.rb:254:in around_destroy'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1701:in _destroy'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1220:in block (2 levels) in destroy'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/transactions.rb:235:in block in transaction'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/connection_pool/threaded.rb:88:in hold'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/connecting.rb:293:in synchronize'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/transactions.rb:197:in transaction'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1954:in checked_transaction'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1220:in block in destroy'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1940:in checked_save_failure'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/model/base.rb:1220:in destroy'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/actions/route_delete.rb:10:in block (2 levels) in delete'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/transactions.rb:264:in _transaction'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/transactions.rb:239:in block in transaction'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/connection_pool/threaded.rb:88:in hold'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/connecting.rb:293:in synchronize'", "/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/gem_home/ruby/3.2.0/gems/sequel-5.77.0/lib/sequel/database/transactions.rb:197:in transaction'\", \"/var/vcap/data/packages/cloud_controller_ng/45d435008ea60f85e1594223ed03a635d74d9055/cloud_controller_ng/app/actions/route_delete.rb:9:in block in delete'
`
 

Steps to Reproduce

This can be reproduced with the following commands:

cf create-app test-app
cf create-route customer-app-domain1.com --hostname test-app
cf create-service async-service async-plan test-instance
# service must have `"requires": ["route_forwarding"],` in the catalog's service entry
cf bind-route-service customer-app-domain1.com --hostname test-app test-instance
# before running the next command the worker process should be in debug mode and a breakpoint should be set in app/actions/services/service_key_delete.rb line 29 `service_binding.destroy`
cf delete-route customer-app-domain1.com --hostname test-app
# while the previous command stops at the breakpoint run the following
cf urs customer-app-domain1.com --hostname test-app
# after this command finished, let the worker continue on the first request, which will fail with above error

Expected result

The route delete request continues even if the service binding is gone already.
Or locks prevent that two jobs try to delete the binding at the same time and the route delete job fails with ServiceBindingOperation in progress.

Current result

The route delete request fails with Attempt to delete object did not result in a single row modification.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with app/actions/route_delete.rb, app/models/runtime/route.rb, and app/actions/services/service_key_delete.rb, especially service_key_delete.rb line 29 where service_binding.destroy is called. Reproduce the concurrent DELETE requests using the commands in the issue and the suggested breakpoint. Done means the concurrent deletion no longer produces the reported 500 response.

Written by the indexing model from the issue text.

Assessment

Tech stack
ruby
Domain
api, backend, databases
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.