From 03ea03f90a8c9b4e642726f2f1d217e7771ceaac Mon Sep 17 00:00:00 2001 From: Dimitri Tischenko Date: Tue, 19 Sep 2023 12:23:00 +0100 Subject: [PATCH 1/3] Add provisioining event tracing --- lib/vmpooler/pool_manager.rb | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/lib/vmpooler/pool_manager.rb b/lib/vmpooler/pool_manager.rb index 4f00347..6da5d28 100644 --- a/lib/vmpooler/pool_manager.rb +++ b/lib/vmpooler/pool_manager.rb @@ -89,7 +89,7 @@ module Vmpooler rescue StandardError => e $logger.log('s', "[!] [#{pool}] '#{vm}' #{timeout} #{provider} errored while checking a pending vm : #{e}") @redis.with_metrics do |redis| - fail_pending_vm(vm, pool, timeout, timeout_notification, redis) + fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider) end raise end @@ -106,7 +106,7 @@ module Vmpooler if provider.vm_ready?(pool, vm, redis) move_pending_vm_to_ready(vm, pool, redis, request_id) else - fail_pending_vm(vm, pool, timeout, timeout_notification, redis) + fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider) end end end @@ -122,7 +122,7 @@ module Vmpooler $logger.log('d', "[!] [#{pool}] '#{vm}' no longer exists. Removing from pending.") end - def fail_pending_vm(vm, pool, timeout, timeout_notification, redis, exists: true) + def fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true) clone_stamp = redis.hget("vmpooler__vm__#{vm}", 'clone') time_since_clone = (Time.now - Time.parse(clone_stamp)) / 60 @@ -150,12 +150,23 @@ module Vmpooler "[!] [#{pool}] '#{vm}' This error is wholly unexpected" end $logger.log('d', nonexist_warning) + # if vm provisioning failed, we want to see the trace + trace = get_provisioning_trace(vm, pool, provider) + $logger.log('d', "vm provisioning trace: #{trace}") if trace true rescue StandardError => e $logger.log('d', "Fail pending VM failed with an error: #{e}") false end + def get_provisioning_trace(vm, pool, provider) + # only call get_provisioning_trace if the provider supports it + return nil unless provider.respond_to?(:get_provisioning_trace) + trace = provider.get_provisioning_trace(vm, pool) + return nil if trace.nil? + trace + end + def handle_timed_out_vm(vm, pool, redis) request_id = redis.hget("vmpooler__vm__#{vm}", 'request_id') pool_alias = redis.hget("vmpooler__vm__#{vm}", 'pool_alias') if request_id @@ -1287,7 +1298,7 @@ module Vmpooler $logger.log('d', "[!] [#{pool_name}] _check_pool failed with an error while evaluating pending VMs: #{e}") end else - fail_pending_vm(vm, pool_name, pool_timeout, pool_timeout_notification, redis, exists: false) + fail_pending_vm(vm, pool_name, pool_timeout, pool_timeout_notification, redis, provider, exists: false) end end end From 3ac0a255576155a4851152d40930d759f600a6e7 Mon Sep 17 00:00:00 2001 From: Dimitri Tischenko Date: Tue, 19 Sep 2023 12:46:35 +0100 Subject: [PATCH 2/3] fix rubocop and spec issues --- lib/vmpooler/pool_manager.rb | 2 ++ spec/unit/pool_manager_spec.rb | 20 ++++++++++---------- 2 files changed, 12 insertions(+), 10 deletions(-) diff --git a/lib/vmpooler/pool_manager.rb b/lib/vmpooler/pool_manager.rb index 6da5d28..ef2fccb 100644 --- a/lib/vmpooler/pool_manager.rb +++ b/lib/vmpooler/pool_manager.rb @@ -162,8 +162,10 @@ module Vmpooler def get_provisioning_trace(vm, pool, provider) # only call get_provisioning_trace if the provider supports it return nil unless provider.respond_to?(:get_provisioning_trace) + trace = provider.get_provisioning_trace(vm, pool) return nil if trace.nil? + trace end diff --git a/spec/unit/pool_manager_spec.rb b/spec/unit/pool_manager_spec.rb index 3ca075e..85e5013 100644 --- a/spec/unit/pool_manager_spec.rb +++ b/spec/unit/pool_manager_spec.rb @@ -215,7 +215,7 @@ EOT it 'calls fail_pending_vm if host is not ready' do redis_connection_pool.with do |redis| expect(provider).to receive(:vm_ready?).with(pool, vm, redis).and_return(false) - expect(subject).to receive(:fail_pending_vm).with(vm, pool, timeout, timeout_notification, redis) + expect(subject).to receive(:fail_pending_vm).with(vm, pool, timeout, timeout_notification, redis, provider) end subject._check_pending_vm(vm, pool, timeout, timeout_notification, provider) @@ -276,7 +276,7 @@ EOT it 'takes no action if VM is not cloning' do redis_connection_pool.with do |redis| expect(logger).to_not receive(:log) - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider)).to eq(true) end end @@ -284,7 +284,7 @@ EOT redis_connection_pool.with do |redis| redis.hset("vmpooler__vm__#{vm}", 'clone',Time.now.to_s) expect(logger).to_not receive(:log) - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider)).to eq(true) expect(redis.sismember("vmpooler__pending__#{pool}", vm)).to be(true) end end @@ -292,7 +292,7 @@ EOT it 'moves VM to completed queue if VM has exceeded timeout and exists' do redis_connection_pool.with do |redis| redis.hset("vmpooler__vm__#{vm}", 'clone',Date.new(2001,1,1).to_s) - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, exists: true)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true)).to eq(true) expect(redis.sismember("vmpooler__pending__#{pool}", vm)).to be(false) expect(redis.sismember("vmpooler__completed__#{pool}", vm)).to be(true) end @@ -302,7 +302,7 @@ EOT redis_connection_pool.with do |redis| redis.hset("vmpooler__vm__#{vm}", 'clone',Date.new(2001,1,1).to_s) expect(logger).to receive(:log).with('d', "[!] [#{pool}] '#{vm}' marked as 'failed' after #{timeout} minutes with error: ") - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, exists: true)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true)).to eq(true) end end @@ -311,14 +311,14 @@ EOT redis.hset("vmpooler__vm__#{vm}", 'clone',Date.new(2001,1,1).to_s) expect(logger).to_not receive(:log) expect(subject).to receive(:remove_nonexistent_vm).with(vm, pool, redis) - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, exists: false)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: false)).to eq(true) end end it 'swallows error if an error is raised' do redis_connection_pool.with do |redis| redis.hset("vmpooler__vm__#{vm}", 'clone','iamnotparsable_asdate') - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, exists: true)).to eq(false) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true)).to eq(false) end end @@ -327,7 +327,7 @@ EOT redis.hset("vmpooler__vm__#{vm}", 'clone','iamnotparsable_asdate') expect(logger).to receive(:log).with('d', String) - subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, exists: true) + subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true) end end @@ -338,7 +338,7 @@ EOT redis.hset("vmpooler__vm__#{vm}", 'clone',(Time.now - 900).to_s) redis.hset("vmpooler__vm__#{vm}", 'pool_alias', pool) redis.hset("vmpooler__vm__#{vm}", 'request_id', request_id) - subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, exists: true) + subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true) expect(redis.zrange('vmpooler__odcreate__task', 0, -1)).to eq(["#{pool}:#{pool}:1:#{request_id}"]) end end @@ -4140,7 +4140,7 @@ EOT it 'should call fail_pending_vm' do redis_connection_pool.with do |redis| - expect(subject).to receive(:fail_pending_vm).with(vm, pool, Integer, Integer, redis, exists: false) + expect(subject).to receive(:fail_pending_vm).with(vm, pool, Integer, Integer, redis, provider, exists: false) end subject.check_pending_pool_vms(pool, provider, pool_check_response, inventory, timeout, timeout_notification) From 45461bdd449338498fe2bca0415b3a7b9663ebfc Mon Sep 17 00:00:00 2001 From: Dimitri Tischenko Date: Tue, 19 Sep 2023 13:20:50 +0100 Subject: [PATCH 3/3] remove references to provider --- spec/unit/pool_manager_spec.rb | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/spec/unit/pool_manager_spec.rb b/spec/unit/pool_manager_spec.rb index 85e5013..9afc0c4 100644 --- a/spec/unit/pool_manager_spec.rb +++ b/spec/unit/pool_manager_spec.rb @@ -276,7 +276,7 @@ EOT it 'takes no action if VM is not cloning' do redis_connection_pool.with do |redis| expect(logger).to_not receive(:log) - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, nil)).to eq(true) end end @@ -284,7 +284,7 @@ EOT redis_connection_pool.with do |redis| redis.hset("vmpooler__vm__#{vm}", 'clone',Time.now.to_s) expect(logger).to_not receive(:log) - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, nil)).to eq(true) expect(redis.sismember("vmpooler__pending__#{pool}", vm)).to be(true) end end @@ -292,7 +292,7 @@ EOT it 'moves VM to completed queue if VM has exceeded timeout and exists' do redis_connection_pool.with do |redis| redis.hset("vmpooler__vm__#{vm}", 'clone',Date.new(2001,1,1).to_s) - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, nil, exists: true)).to eq(true) expect(redis.sismember("vmpooler__pending__#{pool}", vm)).to be(false) expect(redis.sismember("vmpooler__completed__#{pool}", vm)).to be(true) end @@ -302,7 +302,7 @@ EOT redis_connection_pool.with do |redis| redis.hset("vmpooler__vm__#{vm}", 'clone',Date.new(2001,1,1).to_s) expect(logger).to receive(:log).with('d', "[!] [#{pool}] '#{vm}' marked as 'failed' after #{timeout} minutes with error: ") - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, nil, exists: true)).to eq(true) end end @@ -311,14 +311,14 @@ EOT redis.hset("vmpooler__vm__#{vm}", 'clone',Date.new(2001,1,1).to_s) expect(logger).to_not receive(:log) expect(subject).to receive(:remove_nonexistent_vm).with(vm, pool, redis) - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: false)).to eq(true) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, nil, exists: false)).to eq(true) end end it 'swallows error if an error is raised' do redis_connection_pool.with do |redis| redis.hset("vmpooler__vm__#{vm}", 'clone','iamnotparsable_asdate') - expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true)).to eq(false) + expect(subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, nil, exists: true)).to eq(false) end end @@ -327,7 +327,7 @@ EOT redis.hset("vmpooler__vm__#{vm}", 'clone','iamnotparsable_asdate') expect(logger).to receive(:log).with('d', String) - subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true) + subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, nil, exists: true) end end @@ -338,7 +338,7 @@ EOT redis.hset("vmpooler__vm__#{vm}", 'clone',(Time.now - 900).to_s) redis.hset("vmpooler__vm__#{vm}", 'pool_alias', pool) redis.hset("vmpooler__vm__#{vm}", 'request_id', request_id) - subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, provider, exists: true) + subject.fail_pending_vm(vm, pool, timeout, timeout_notification, redis, nil, exists: true) expect(redis.zrange('vmpooler__odcreate__task', 0, -1)).to eq(["#{pool}:#{pool}:1:#{request_id}"]) end end