Add provisioining event tracing

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

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,23 +276,23 @@
     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
 
     it 'takes no action if VM is within timeout' do
       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
 
     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)