diff --git a/lib/vmpooler/pool_manager.rb b/lib/vmpooler/pool_manager.rb index 4f003472..ef2fccb2 100644 --- a/lib/vmpooler/pool_manager.rb +++ b/lib/vmpooler/pool_manager.rb @@ -89,7 +89,7 @@ def check_pending_vm(vm, pool, timeout, timeout_notification, provider) 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 @@ def _check_pending_vm(vm, pool, timeout, timeout_notification, provider) 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 @@ def remove_nonexistent_vm(vm, pool, redis) $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,25 @@ def fail_pending_vm(vm, pool, timeout, timeout_notification, redis, exists: true "[!] [#{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 +1300,7 @@ def check_pending_pool_vms(pool_name, provider, pool_check_response, inventory, $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 diff --git a/spec/unit/pool_manager_spec.rb b/spec/unit/pool_manager_spec.rb index 3ca075e2..9afc0c4f 100644 --- a/spec/unit/pool_manager_spec.rb +++ b/spec/unit/pool_manager_spec.rb @@ -215,7 +215,7 @@ 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 @@ 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, nil)).to eq(true) end end @@ -284,7 +284,7 @@ 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, nil)).to eq(true) expect(redis.sismember("vmpooler__pending__#{pool}", vm)).to be(true) end end @@ -292,7 +292,7 @@ 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, 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 @@ 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, nil, exists: true)).to eq(true) end end @@ -311,14 +311,14 @@ 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, 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, 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 @@ 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, nil, exists: true) end end @@ -338,7 +338,7 @@ 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, nil, exists: true) expect(redis.zrange('vmpooler__odcreate__task', 0, -1)).to eq(["#{pool}:#{pool}:1:#{request_id}"]) end end @@ -4140,7 +4140,7 @@ 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)