Concurrency: DELETE /v3/route/:guid and DELETE /v3/service_route_bindings/:guid can cause 500 - unknown error
svkrieger opened this issue · 0 comments
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.