Address PR review feedback

- Rename RootJobMixin -> RecursiveDeleteRootJobMixin (it is delete-specific)
- Move defer-while-in-flight and raise-if-failed into the mixin; keep
  sub_jobs_in_flight? side-effect-free
- Log sub-resource failures via rescue (log_immediate_failures /
  log_recursive_delete_failure) instead of looping over sub_resource_errors
- Merge the two SubResourceError/StandardError rescue blocks in
  ServiceInstanceDelete#delete
- raise_if_sub_jobs_failed short-circuits with any? instead of building errors
- Memoize @service_instance per pass (cleared in ensure); use resource_guid
  consistently in both recursive-delete jobs
- Add ServiceInstance#route_bindings association and use it
- SubResourceError#any_in_progress? uses any? (drop in_progress_operations)
- Enqueuer exposes current_root_job_guid overridden by GenericEnqueuer
- apps_controller: build the job from the locked resource for symmetry
- logging_context: align save/restore variable naming
- migration: use elsif in the down block
- Restore DeleteAppErrorTranslatorJob spec; assert FOR UPDATE via
  have_queried_db_times

Author: johha

app/actions/v3/service_instance_delete.rb

@@ -52,12 +52,10 @@ def delete
         end
 
         result
-      rescue SubResourceError => e
-        raise if !@fail_if_in_progress && e.any_in_progress? # re-raise SubResourceError so that root job continues to run
-
-        update_last_operation_with_failure(e.message) unless service_instance.operation_in_progress?
-        raise e
       rescue StandardError => e
+        # In-progress sub-resource deletions aren't failures: re-raise so the root job re-enqueues and waits.
+        raise if e.is_a?(SubResourceError) && e.any_in_progress?
+
         update_last_operation_with_failure(e.message) unless service_instance.operation_in_progress?
         raise e
       end
@@ -150,7 +148,7 @@ def destroy
       end
 
       def remove_associations
-        errors = delete_bindings(RouteBinding.where(service_instance:), user_audit_info: service_event_repository.user_audit_info)
+        errors = delete_bindings(service_instance.route_bindings, user_audit_info: service_event_repository.user_audit_info)
         errors += delete_bindings(service_instance.service_bindings, user_audit_info: service_event_repository.user_audit_info)
         errors += delete_bindings(service_instance.service_keys, user_audit_info: service_event_repository.user_audit_info)
         errors + unshare_all_spaces

app/controllers/v3/apps_controller.rb

@@ -161,7 +161,9 @@ def destroy
         resource_model: AppModel,
         resource_guid: app.guid,
         operation: 'app.delete'
-      ) { VCAP::CloudController::V3::RecursiveDeleteAppJob.new(app.guid, user_audit_info) }
+      ) do |locked_app|
+        VCAP::CloudController::V3::RecursiveDeleteAppJob.new(locked_app.guid, user_audit_info)
+      end
 
       app_not_found! unless job
     else

app/errors/sub_resource_error.rb

@@ -20,12 +20,8 @@ def failures
       @errors.reject { |e| e.is_a?(AsyncOperationInProgress) }
     end
 
-    def in_progress_operations
-      @errors.select { |e| e.is_a?(AsyncOperationInProgress) }
-    end
-
     def any_in_progress?
-      in_progress_operations.any?
+      @errors.any? { |e| e.is_a?(AsyncOperationInProgress) }
     end
 
     def message

app/jobs/enqueuer.rb

@@ -9,8 +9,6 @@
 module VCAP::CloudController
   module Jobs
     class Enqueuer
-      attr_accessor :root_job_guid
-
       def initialize(opts={})
         @opts = opts
         @timeout_calculator = JobTimeoutCalculator.new(VCAP::CloudController::Config.config)
@@ -23,7 +21,7 @@ def enqueue(job, run_at: nil, priority_increment: nil)
       end
 
       def enqueue_pollable(job, existing_guid: nil, run_at: nil, priority_increment: nil, preserve_priority: false)
-        wrapped_job = PollableJobWrapper.new(job, existing_guid:, root_job_guid:)
+        wrapped_job = PollableJobWrapper.new(job, existing_guid: existing_guid, root_job_guid: current_root_job_guid)
 
         wrapped_job = yield wrapped_job if block_given?
 
@@ -49,6 +47,11 @@ def self.unwrap_job(job)
 
       private
 
+      # Base enqueuer has no root-job context; GenericEnqueuer overrides this while a root job is active.
+      def current_root_job_guid
+        nil
+      end
+
       def enqueue_job(job, run_at: nil, priority_increment: nil, preserve_priority: false)
         @opts['guid'] = SecureRandom.uuid
         request_id = ::VCAP::Request.current_id

app/jobs/generic_enqueuer.rb

@@ -17,11 +17,17 @@ def self.reset!
       end
 
       def activate_root_context(root_job_guid:)
-        self.root_job_guid = root_job_guid
+        @root_job_guid = root_job_guid
       end
 
       def deactivate_root_context
-        self.root_job_guid = nil
+        @root_job_guid = nil
+      end
+
+      private
+
+      def current_root_job_guid
+        @root_job_guid
       end
     end
   end

app/jobs/logging_context_job.rb

@@ -89,11 +89,11 @@ def with_request_id_set
       def with_root_job_guid_set
         return yield if @root_job_guid.nil?
 
-        previous = ::VCAP::Request.current_root_job_guid
+        current_root_job_guid = ::VCAP::Request.current_root_job_guid
         ::VCAP::Request.current_root_job_guid = @root_job_guid
         yield
       ensure
-        ::VCAP::Request.current_root_job_guid = previous unless @root_job_guid.nil?
+        ::VCAP::Request.current_root_job_guid = current_root_job_guid unless @root_job_guid.nil?
       end
     end
   end

app/jobs/mixins/root_job_mixin.rb …ixins/recursive_delete_root_job_mixin.rbapp/jobs/mixins/root_job_mixin.rb renamed to app/jobs/mixins/recursive_delete_root_job_mixin.rb app/jobs/mixins/root_job_mixin.rb renamed to app/jobs/mixins/recursive_delete_root_job_mixin.rb

@@ -4,7 +4,7 @@
 
 module VCAP::CloudController
   module Jobs
-    module RootJobMixin
+    module RecursiveDeleteRootJobMixin
       # Buffer added on top of the sub-jobs' next run_at so the root wakes just after them, never before.
       ROOT_JOB_BUFFER_SECONDS = 5
 
@@ -16,12 +16,26 @@ def root_job_guid
 
       def perform_with_root_job_handling
         activate_root_job_context
+
+        if sub_jobs_in_flight?
+          add_in_progress_warning(root_job)
+          logger.info("#{display_name} #{resource_guid} (job #{root_job_guid}) waiting on in-progress sub-resource deletions")
+          return
+        end
+
+        raise_if_sub_jobs_failed
+
         yield
       rescue SubResourceError => e
-        return if e.any_in_progress?
+        if e.any_in_progress?
+          log_immediate_failures(e.failures) # log failures that surfaced this run; async ones still polling defer us and are retried on the next run
+          return
+        end
 
-        raise compound_error_for(e.failures)
-      rescue CloudController::Errors::ApiError, CloudController::Errors::CompoundError
+        raise log_recursive_delete_failure(compound_error_for(e.failures)) # sync error occurred & no async job pending -> log and fail
+      rescue CloudController::Errors::CompoundError => e
+        raise log_recursive_delete_failure(e) # async sub job failed -> log and fail
+      rescue CloudController::Errors::ApiError
         raise
       rescue StandardError => e
         raise CloudController::Errors::ApiError.new_from_details('UnableToPerform', 'delete', e.message)
@@ -76,18 +90,32 @@ def seconds_until_slowest_sub_job
       end
 
       def sub_jobs_in_flight?
-        return false if active_sub_jobs.empty?
-
-        add_in_progress_warning(root_job)
-        true
+        active_sub_jobs.any?
       end
 
       def raise_if_sub_jobs_failed
-        return if sub_job_errors.empty?
+        return unless sub_jobs.any? { |s| s.state == PollableJobModel::FAILED_STATE }
 
         raise CloudController::Errors::CompoundError.new(all_failure_errors)
       end
 
+      # Logs failures that surfaced during this run (a binding's unbind failed immediately rather than going
+      # async-in-progress). Makes them visible to operators even though the run defers on the async ones,
+      # which are retried on the next run.
+      def log_immediate_failures(failures)
+        failures.each do |error|
+          logger.warn("#{display_name} #{resource_guid} (job #{root_job_guid}) sub-resource deletion failed: #{error.message}")
+        end
+      end
+
+      # Logs each underlying failure and returns the error so callers can `raise log_recursive_delete_failure(error)`.
+      def log_recursive_delete_failure(error)
+        error.underlying_errors.each do |underlying|
+          logger.warn("#{display_name} #{resource_guid} (job #{root_job_guid}) sub-resource deletion failed: #{underlying.message}")
+        end
+        error
+      end
+
       def add_in_progress_warning(job)
         return if job.warnings_dataset.any?
 

app/jobs/v3/recursive_delete_app_job.rb

@@ -1,32 +1,24 @@
 require 'jobs/reoccurring_job'
-require 'jobs/mixins/root_job_mixin'
+require 'jobs/mixins/recursive_delete_root_job_mixin'
 require 'actions/app_delete'
 require 'actions/app_stop'
 
 module VCAP::CloudController
   module V3
     class RecursiveDeleteAppJob < Jobs::ReoccurringJob
-      include Jobs::RootJobMixin
+      include Jobs::RecursiveDeleteRootJobMixin
 
-      attr_reader :app_guid
+      attr_reader :resource_guid
 
-      def initialize(app_guid, user_audit_info)
+      def initialize(resource_guid, user_audit_info)
         super()
-        @app_guid = app_guid
+        @resource_guid = resource_guid
         @user_audit_info = user_audit_info
       end
 
       def perform
         perform_with_root_job_handling do
-          if sub_jobs_in_flight?
-            logger.info("app delete #{app_guid} (job #{root_job_guid}) waiting on in-progress service binding deletions")
-            return
-          end
-
-          log_failed_bindings
-          raise_if_sub_jobs_failed
-
-          app = AppModel.first(guid: app_guid)
+          app = AppModel.first(guid: resource_guid)
           return finish unless app
 
           AppStop.stop(app: app, user_audit_info: @user_audit_info, delete_triggered: true) if app.desired_state != ProcessModel::STOPPED
@@ -37,10 +29,6 @@ def perform
 
       def handle_timeout; end
 
-      def resource_guid
-        app_guid
-      end
-
       def resource_type
         'app'
       end
@@ -57,19 +45,13 @@ def max_attempts
 
       attr_reader :user_audit_info
 
-      def log_failed_bindings
-        sub_resource_errors.each do |guid, error|
-          logger.warn("app delete #{app_guid} (job #{root_job_guid}): service binding #{guid} deletion failed: #{error.message}")
-        end
-      end
-
       def in_progress_warning_detail
         'Deletion of the app is still in progress: one or more service bindings are still being deleted. ' \
           'It will complete once those operations finish.'
       end
 
       def sub_resource_errors
-        app = AppModel.first(guid: app_guid)
+        app = AppModel.first(guid: resource_guid)
         return [] unless app
 
         app.service_bindings.select(&:delete_failed?).map do |binding|

app/jobs/v3/recursive_delete_service_instance_job.rb

@@ -1,30 +1,22 @@
 require 'jobs/reoccurring_job'
-require 'jobs/mixins/root_job_mixin'
+require 'jobs/mixins/recursive_delete_root_job_mixin'
 require 'actions/v3/service_instance_delete'
 
 module VCAP::CloudController
   module V3
     class RecursiveDeleteServiceInstanceJob < VCAP::CloudController::Jobs::ReoccurringJob
-      include Jobs::RootJobMixin
+      include Jobs::RecursiveDeleteRootJobMixin
 
       attr_reader :resource_guid
 
-      def initialize(guid, user_audit_info)
+      def initialize(resource_guid, user_audit_info)
         super()
-        @resource_guid = guid
+        @resource_guid = resource_guid
         @user_audit_info = user_audit_info
       end
 
       def perform
         perform_with_root_job_handling do
-          if sub_jobs_in_flight?
-            logger.info("service instance delete #{resource_guid} (job #{root_job_guid}) waiting on in-progress binding deletions")
-            return
-          end
-
-          log_failed_children
-          raise_if_sub_jobs_failed
-
           return finish unless service_instance
 
           self.maximum_duration_seconds = service_instance.service_plan.try(:maximum_polling_duration)
@@ -39,6 +31,8 @@ def perform
 
           self.polling_interval_seconds = result[:retry_after].to_i if result[:retry_after]
         end
+      ensure
+        @service_instance = nil # drop the per-pass cache so it is not serialised into the reoccurring-job reschedule
       end
 
       def handle_timeout
@@ -71,7 +65,7 @@ def in_progress_warning_detail
       end
 
       def service_instance
-        ManagedServiceInstance.first(guid: resource_guid)
+        @service_instance ||= ManagedServiceInstance.first(guid: resource_guid)
       end
 
       def delete_in_progress?
@@ -83,17 +77,11 @@ def action
         ServiceInstanceDelete.new(service_instance, Repositories::ServiceEventRepository.new(user_audit_info), fail_if_in_progress: false)
       end
 
-      def log_failed_children
-        sub_resource_errors.each do |guid, error|
-          logger.warn("service instance delete #{resource_guid} (job #{root_job_guid}): binding #{guid} deletion failed: #{error.message}")
-        end
-      end
-
       def sub_resource_errors
         si = service_instance
         return [] unless si
 
-        children = si.service_bindings + si.service_keys + RouteBinding.where(service_instance: si).all
+        children = si.service_bindings + si.service_keys + si.route_bindings
         children.select(&:delete_failed?).map do |child|
           identity = "#{child.class.name.demodulize.underscore} #{child.guid}"
           [child.guid, CloudController::Errors::ApiError.new_from_details('UnprocessableEntity', "#{identity}: #{child.last_operation.description}")]

app/models/services/service_instance.rb

@@ -30,6 +30,7 @@ class InvalidServiceBinding < StandardError; end
 
     one_to_many :service_bindings, before_add: :validate_service_binding, key: :service_instance_guid, primary_key: :guid
     one_to_many :service_keys
+    one_to_many :route_bindings
 
     one_to_many :labels, class: 'VCAP::CloudController::ServiceInstanceLabelModel', key: :resource_guid, primary_key: :guid
     one_to_many :annotations, class: 'VCAP::CloudController::ServiceInstanceAnnotationModel', key: :resource_guid, primary_key: :guid