Skip to content

Commit b19c596

Browse files
authored
Recover stuck service operations after transient DB failures (#5011)
1 parent f566623 commit b19c596

10 files changed

Lines changed: 457 additions & 2 deletions

File tree

Lines changed: 117 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,117 @@
1+
module VCAP::CloudController
2+
module Jobs
3+
module Runtime
4+
class ServiceOperationsCreateInProgressCleanup < VCAP::CloudController::Jobs::CCJob
5+
BATCH_SIZE = 10
6+
7+
def perform
8+
logger.info("Cleaning up service 'create' operations stuck in 'in progress'")
9+
cleanup_operations(ServiceInstanceOperation, ServiceInstance, :service_instance_id, 'service_instance.create', :cleanup_failed_provision)
10+
cleanup_operations(ServiceBindingOperation, ServiceBinding, :service_binding_id, 'service_bindings.create', :cleanup_failed_bind)
11+
cleanup_operations(ServiceKeyOperation, ServiceKey, :service_key_id, 'service_keys.create', :cleanup_failed_key)
12+
end
13+
14+
def max_attempts
15+
1
16+
end
17+
18+
private
19+
20+
def cleanup_operations(operation_model, instance_model, foreign_key, jobs_operation, orphan_mitigator_method)
21+
# The explanation below uses service_instance_operations as the concrete example;
22+
# the same logic applies to service_binding_operations and service_key_operations
23+
# when invoked with their respective arguments.
24+
#
25+
# Find stuck service instance 'in progress' operations where the broker is still working
26+
# but CC's polling job has permanently failed due to a transient error (e.g. brief db connection flip).
27+
# Join path: service_instance_operations → service_instances → jobs → delayed_jobs.
28+
#
29+
# Filters:
30+
# - service_instance_operations.state='in progress': the broker has not yet reported a final state
31+
# (succeeded or failed) that CC could successfully persist; if CC had received and saved a final
32+
# state from the broker, this column would already be 'succeeded' or 'failed' — not 'in progress'
33+
# - service_instance_operations.type='create': scope to create operations only
34+
# - service_instance_operations.created_at > CURRENT_TIMESTAMP - max_duration: operations beyond the max async polling window
35+
# are intentionally excluded — the broker has given up on them too, so they are out of scope for this cleanup
36+
# - jobs.state IN (POLLING, FAILED): the pollable job has not reached COMPLETE (a successful job
37+
# would already be done and is out of scope); POLLING covers the case where the failure hook
38+
# itself couldn't write FAILED due to the DB flip
39+
# - jobs.operation='service_instance.create': prevents matching update/delete jobs for the same
40+
# service instance that happen to share the same resource_guid
41+
# - delayed_jobs.failed_at IS NOT NULL: the delayed job permanently failed (exhausted max_attempts);
42+
# jobs still alive or locked have failed_at=NULL and must not be touched
43+
operation_table = operation_model.table_name
44+
instance_table = instance_model.table_name
45+
46+
stuck = operation_model.
47+
join(instance_table, id: Sequel[operation_table][foreign_key]).
48+
join(:jobs, resource_guid: Sequel[instance_table][:guid]).
49+
join(:delayed_jobs, guid: Sequel[:jobs][:delayed_job_guid]).
50+
where(Sequel[operation_table][:state] => 'in progress').
51+
where(Sequel[operation_table][:type] => 'create').
52+
where(Sequel.lit("#{operation_table}.created_at > CURRENT_TIMESTAMP - INTERVAL '?' SECOND", default_maximum_duration_seconds.to_i)).
53+
where(Sequel[:jobs][:state] => [PollableJobModel::POLLING_STATE, PollableJobModel::FAILED_STATE]).
54+
where(Sequel[:jobs][:operation] => jobs_operation).
55+
exclude(Sequel[:delayed_jobs][:failed_at] => nil).
56+
select(
57+
Sequel[:jobs][:guid].as(:pollable_guid),
58+
Sequel[operation_table][:id].as(:op_id),
59+
Sequel[operation_table][foreign_key].as(:resource_id)
60+
).
61+
order(Sequel[operation_table][:created_at]).
62+
limit(BATCH_SIZE)
63+
64+
stuck.each do |row|
65+
mitigate_orphan(operation_model, instance_model, orphan_mitigator_method,
66+
row[:op_id], row[:resource_id], row[:pollable_guid])
67+
end
68+
end
69+
70+
def mitigate_orphan(operation_model, instance_model, orphan_mitigator_method, op_id, resource_id, pollable_guid)
71+
# Mark the stuck create operation as failed, mark its pollable job as failed,
72+
# and trigger broker-side orphan deprovisioning to clean up any resource the
73+
# broker may have created.
74+
operation_model.db.transaction do
75+
operation = operation_model.where(id: op_id, state: 'in progress').for_update.skip_locked.first
76+
return unless operation
77+
78+
instance = instance_model.first(id: resource_id)
79+
return unless instance
80+
81+
instance_type = instance_model.to_s.split('::').last
82+
83+
logger.info(
84+
"#{instance_type} #{instance.guid} create operation is stuck in 'in progress'. " \
85+
"Setting operation's state to 'failed' and pollable job's state to 'FAILED'.",
86+
instance_type: instance_type,
87+
instance_guid: instance.guid,
88+
operation_id: op_id,
89+
pollable_job_guid: pollable_guid
90+
)
91+
92+
operation.update(state: 'failed',
93+
description: "Operation was stuck in 'in progress' state. Set to 'failed' by cleanup job; orphan mitigation triggered.")
94+
PollableJobModel.where(guid: pollable_guid).update(state: PollableJobModel::FAILED_STATE)
95+
orphan_mitigator.send(orphan_mitigator_method, instance)
96+
end
97+
end
98+
99+
def orphan_mitigator
100+
@orphan_mitigator ||= VCAP::Services::ServiceBrokers::V2::OrphanMitigator.new
101+
end
102+
103+
def default_maximum_duration_seconds
104+
Config.config.get(:broker_client_max_async_poll_duration_minutes).minutes
105+
end
106+
107+
def logger
108+
@logger ||= Steno.logger('cc.background.service-operations-create-in-progress-cleanup')
109+
end
110+
111+
def job_name_in_configuration
112+
:service_operations_create_in_progress_cleanup
113+
end
114+
end
115+
end
116+
end
117+
end

config/cloud_controller.yml

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,9 @@ pollable_jobs:
5555
service_operations_initial_cleanup:
5656
frequency_in_seconds: 300
5757

58+
service_operations_create_in_progress_cleanup:
59+
frequency_in_seconds: 3600 #1h
60+
5861
completed_tasks:
5962
cutoff_age_in_days: 31
6063

@@ -369,7 +372,6 @@ diego_sync:
369372
pending_droplets:
370373
frequency_in_seconds: 300
371374
expiration_in_seconds: 42
372-
373375
pending_builds:
374376
expiration_in_seconds: 42
375377
frequency_in_seconds: 300
Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
Sequel.migration do
2+
no_transaction # required for concurrently option on postgres
3+
4+
up do
5+
if database_type == :postgres
6+
VCAP::Migration.with_concurrent_timeout(self) do
7+
add_index :jobs, %i[operation state],
8+
name: :jobs_operation_state_index,
9+
where: "state IN ('POLLING', 'FAILED')",
10+
if_not_exists: true,
11+
concurrently: true
12+
end
13+
elsif database_type == :mysql
14+
alter_table(:jobs) do
15+
# rubocop:disable Sequel/ConcurrentIndex -- MySQL does not support concurrent index operations
16+
add_index %i[operation state], name: :jobs_operation_state_index unless @db.indexes(:jobs).key?(:jobs_operation_state_index)
17+
# rubocop:enable Sequel/ConcurrentIndex
18+
end
19+
end
20+
end
21+
22+
down do
23+
if database_type == :postgres
24+
VCAP::Migration.with_concurrent_timeout(self) do
25+
drop_index :jobs, %i[operation state],
26+
name: :jobs_operation_state_index,
27+
if_exists: true,
28+
concurrently: true
29+
end
30+
elsif database_type == :mysql
31+
alter_table(:jobs) do
32+
# rubocop:disable Sequel/ConcurrentIndex
33+
drop_index %i[operation state], name: :jobs_operation_state_index if @db.indexes(:jobs).key?(:jobs_operation_state_index)
34+
# rubocop:enable Sequel/ConcurrentIndex
35+
end
36+
end
37+
end
38+
end

lib/cloud_controller/clock/scheduler.rb

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,8 @@ class Scheduler
2424
{ name: 'pending_droplets', class: Jobs::Runtime::PendingDropletCleanup },
2525
{ name: 'pending_builds', class: Jobs::Runtime::PendingBuildCleanup },
2626
{ name: 'failed_jobs', class: Jobs::Runtime::FailedJobsCleanup },
27-
{ name: 'service_operations_initial_cleanup', class: Jobs::Runtime::ServiceOperationsInitialCleanup }
27+
{ name: 'service_operations_initial_cleanup', class: Jobs::Runtime::ServiceOperationsInitialCleanup },
28+
{ name: 'service_operations_create_in_progress_cleanup', class: Jobs::Runtime::ServiceOperationsCreateInProgressCleanup }
2829
].freeze
2930

3031
def initialize(config)

lib/cloud_controller/config_schemas/clock_schema.rb

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,9 @@ class ClockSchema < VCAP::Config
3434
completed_tasks: {
3535
cutoff_age_in_days: Integer
3636
},
37+
service_operations_create_in_progress_cleanup: {
38+
frequency_in_seconds: Integer
39+
},
3740
default_health_check_timeout: Integer,
3841

3942
uaa: {

lib/cloud_controller/jobs.rb

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525
require 'jobs/runtime/expired_blob_cleanup'
2626
require 'jobs/runtime/expired_orphaned_blob_cleanup'
2727
require 'jobs/runtime/expired_resource_cleanup'
28+
require 'jobs/runtime/service_operations_create_in_progress_cleanup'
2829
require 'jobs/runtime/failed_jobs_cleanup'
2930
require 'jobs/runtime/service_operations_initial_cleanup'
3031
require 'jobs/runtime/legacy_jobs'

lib/tasks/jobs.rake

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -49,6 +49,7 @@ namespace :jobs do
4949
'audit_events',
5050
'failed_jobs',
5151
'service_operations_initial_cleanup',
52+
'service_operations_create_in_progress_cleanup',
5253
'service_usage_events',
5354
'completed_tasks',
5455
'expired_blob_cleanup',
Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,37 @@
1+
require 'spec_helper'
2+
require 'migrations/helpers/migration_shared_context'
3+
4+
RSpec.describe 'migration to add operation_state_index on jobs table', isolation: :truncation, type: :migration do
5+
include_context 'migration' do
6+
let(:migration_filename) { '20260505071445_add_jobs_operation_state_index.rb' }
7+
end
8+
9+
def operation_state_index_present?
10+
if db.database_type == :postgres
11+
db.fetch("SELECT 1 FROM pg_indexes WHERE tablename = 'jobs' AND indexname = 'jobs_operation_state_index'").any?
12+
else
13+
db.indexes(:jobs).key?(:jobs_operation_state_index)
14+
end
15+
end
16+
17+
describe 'jobs table' do
18+
it 'adds index and handles idempotency gracefully' do
19+
# Test up migration
20+
expect(operation_state_index_present?).to be_falsey
21+
expect { Sequel::Migrator.run(db, migrations_path, target: current_migration_index, allow_missing_migration_files: true) }.not_to raise_error
22+
expect(operation_state_index_present?).to be_truthy
23+
24+
# Test up migration idempotency
25+
expect { Sequel::Migrator.run(db, migrations_path, target: current_migration_index, allow_missing_migration_files: true) }.not_to raise_error
26+
expect(operation_state_index_present?).to be_truthy
27+
28+
# Test down migration
29+
expect { Sequel::Migrator.run(db, migrations_path, target: current_migration_index - 1, allow_missing_migration_files: true) }.not_to raise_error
30+
expect(operation_state_index_present?).to be_falsey
31+
32+
# Test down migration idempotency
33+
expect { Sequel::Migrator.run(db, migrations_path, target: current_migration_index - 1, allow_missing_migration_files: true) }.not_to raise_error
34+
expect(operation_state_index_present?).to be_falsey
35+
end
36+
end
37+
end

0 commit comments

Comments
 (0)