search

cloudfoundry / cloud_controller_ng

Cloud Foundry Cloud Controller
Apache License 2.0
191 stars 357 forks source link

Asynchronously created instances become stuck in "create in progress" when creation is cancelled but broker does not support cancelling #1919

Closed ionphractal closed 3 years ago

ionphractal commented 3 years ago

Issue

When using an asynchronous service broker which does not support cancellation of operations, a service instance becomes stuck in "create in progress" when the service instance is deleted before the creation succeeded.

Context

At some point CC started to support the cancellation of create operations: https://github.com/cloudfoundry/cloud_controller_ng/commit/ff4ee3dbc85a755e762fc8d5ec03f0caef1c64ca

The openservicebroker specification states that the broker can return 422 Unprocessable Entity "if the Service Instance is being processed by some other operation and therefore cannot be deleted at this time". (https://github.com/openservicebrokerapi/servicebroker/blob/master/spec.md#deprovisioning)

There may be some service brokers that can handle cancellation of creation but this cannot be ensured. So the Cloud Controller should handle these situations by disallowing the deprovisioning and allowing the provisioning to finish.

Steps to Reproduce

Requirements:

Steps:

  1. create a service instance asynchronously cf create-service async-service plan test
  2. delete the service while in "create in progress" cf delete-service test

Expected result

The delete command should fail and the service should become "create succeeded" at some point.

Current result

The CC returns Server error, status code: 409, error code: 60016, message: An operation for service instance test is in progress. and it logs a CF-AsyncServiceInstanceOperationInProgress backtrace in the log (see below).

However, the service instance is stuck in "create in progress" forever because the broker_provided_operation column is emptied.

{
  "description": "An operation for service instance test is in progress.",
  "error_code": "CF-AsyncServiceInstanceOperationInProgress",
  "code": 60016,
  "test_mode_info": {
    "description": "An operation for service instance test is in progress.",
    "error_code": "CF-AsyncServiceInstanceOperationInProgress",
    "backtrace": [
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/lib/services/service_brokers/v2/client.rb:248:in `rescue in deprovision'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/lib/services/service_brokers/v2/client.rb:223:in `deprovision'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/app/actions/services/service_instance_delete.rb:85:in `delete_one'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/app/actions/services/service_instance_delete.rb:19:in `block in delete'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/dataset/actions.rb:150:in `block in each'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:614:in `block (2 levels) in fetch_rows'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:800:in `yield_hash_rows'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:614:in `block in fetch_rows'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:146:in `execute'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:500:in `_execute'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:318:in `block (2 levels) in execute'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:522:in `check_database_errors'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:318:in `block in execute'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/database/connecting.rb:270:in `synchronize'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:318:in `execute'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/dataset/actions.rb:1089:in `execute'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/adapters/postgres.rb:614:in `fetch_rows'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sequel-5.35.0/lib/sequel/dataset/actions.rb:150:in `each'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/app/actions/services/service_instance_delete.rb:14:in `each_with_object'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/app/actions/services/service_instance_delete.rb:14:in `delete'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/app/jobs/delete_action_job.rb:21:in `perform'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/app/controllers/services/lifecycle/service_instance_deprovisioner.rb:19:in `deprovision_service_instance'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/app/controllers/services/service_instances_controller.rb:187:in `delete'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/app/controllers/base/base_controller.rb:84:in `dispatch'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/lib/cloud_controller/rest_controller/routes.rb:16:in `block in define_route'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1635:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1635:in `block in compile!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:987:in `block (3 levels) in route!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1006:in `route_eval'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:987:in `block (2 levels) in route!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1035:in `block in process_route'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1033:in `catch'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1033:in `process_route'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:985:in `block in route!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:984:in `each'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:984:in `route!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1098:in `block in dispatch!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1072:in `block in invoke'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1072:in `catch'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1072:in `invoke'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1095:in `dispatch!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:919:in `block in call!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1072:in `block in invoke'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1072:in `catch'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1072:in `invoke'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:919:in `call!'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:908:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-protection-2.0.8.1/lib/rack/protection/xss_header.rb:18:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-protection-2.0.8.1/lib/rack/protection/path_traversal.rb:16:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-protection-2.0.8.1/lib/rack/protection/json_csrf.rb:26:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-protection-2.0.8.1/lib/rack/protection/base.rb:50:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-protection-2.0.8.1/lib/rack/protection/base.rb:50:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-protection-2.0.8.1/lib/rack/protection/frame_options.rb:31:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-2.2.3/lib/rack/null_logger.rb:11:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:194:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/sinatra-2.0.8.1/lib/sinatra/base.rb:1951:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/middleware/request_logs.rb:38:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/middleware/security_context_setter.rb:19:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/middleware/vcap_request_id.rb:15:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/middleware/cors.rb:49:in `call_app'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/middleware/cors.rb:14:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/cloud_controller_ng/middleware/request_metrics.rb:12:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/rack-2.2.3/lib/rack/builder.rb:244:in `call'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/thin-1.7.2/lib/thin/connection.rb:86:in `block in pre_process'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/thin-1.7.2/lib/thin/connection.rb:84:in `catch'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/thin-1.7.2/lib/thin/connection.rb:84:in `pre_process'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/thin-1.7.2/lib/thin/connection.rb:50:in `block in process'",
      "/var/vcap/data/packages/cloud_controller_ng/7b4ebd12b4e9dabe36d9147a0492fa6fa6729ae1/gem_home/ruby/2.5.0/gems/eventmachine-1.0.9.1/lib/eventmachine.rb:1067:in `block in spawn_threadpool'"
    ]
  }
}

I've tried to delete the instance at the broker directly while being created and it returns 422 as expected.

Possible Fix

From the CC code it looks like the this line https://github.com/cloudfoundry/cloud_controller_ng/blob/569b0ba2035819668528613494eb470cef4aec1f/app/actions/services/service_instance_delete.rb#L86 calls the broker and throws an exception due to the 422 returned https://github.com/cloudfoundry/cloud_controller_ng/blob/569b0ba2035819668528613494eb470cef4aec1f/lib/services/service_brokers/v2/client.rb#L248

So after that there seems nothing to delete the operations.

I suspect the DeleterLock https://github.com/cloudfoundry/cloud_controller_ng/blob/569b0ba2035819668528613494eb470cef4aec1f/app/actions/services/service_instance_delete.rb#L81-L82

to just save a new empty operations record in the table because it destroys it first https://github.com/cloudfoundry/cloud_controller_ng/blob/569b0ba2035819668528613494eb470cef4aec1f/app/actions/services/locks/deleter_lock.rb#L15-L22

https://github.com/cloudfoundry/cloud_controller_ng/blob/569b0ba2035819668528613494eb470cef4aec1f/app/models/services/managed_service_instance.rb#L148-L153

But I don't have enough insight in the internals to propose anything here.

cf-gitbot commented 3 years ago

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/175378670

The labels on this github issue will be updated when the story is started.

kirederik commented 3 years ago

Hi @ionphractal ,

Thanks for bringing this up to our attention and for the analysis of the code.

We have encountered this issue in the past but decide to fix it only on v3. There are plans to release a CF CLI version that uses the v3 endpoints on the create and delete commands soon 🤞🏽

I'll close this issue for now on the basis that's fixed on v3. Feel free to reopen it if you'd like to push for a fix on v2 or if there's something here that I have missed.

Thanks!