Merge pull request #611 from puppetlabs/POD-10

(POD-10) Log reason for failed VM checks.

lib/vmpooler/api/helpers.rb

@@ -551,18 +551,6 @@ module Vmpooler
           end
         end
       end
-
-      def vm_ready?(vm_name, domain = nil)
-        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
-          begin
-            open_socket(vm_name, domain)
-          rescue StandardError => _e
-            return false
-          end
-
-          true
-        end
-      end
     end
   end
 end

lib/vmpooler/pool_manager.rb

@@ -103,7 +103,7 @@ module Vmpooler
       mutex.synchronize do
         @redis.with_metrics do |redis|
           request_id = redis.hget("vmpooler__vm__#{vm}", 'request_id')
-          if provider.vm_ready?(pool, vm)
+          if provider.vm_ready?(pool, vm, redis)
             move_pending_vm_to_ready(vm, pool, redis, request_id)
           else
             fail_pending_vm(vm, pool, timeout, redis)
@@ -130,6 +130,7 @@ module Vmpooler
         if exists
           request_id = redis.hget("vmpooler__vm__#{vm}", 'request_id')
           pool_alias = redis.hget("vmpooler__vm__#{vm}", 'pool_alias') if request_id
+          open_socket_error = redis.hget("vmpooler__vm__#{vm}", 'open_socket_error')
           redis.smove("vmpooler__pending__#{pool}", "vmpooler__completed__#{pool}", vm)
           if request_id
             ondemandrequest_hash = redis.hgetall("vmpooler__odrequest__#{request_id}")
@@ -139,7 +140,7 @@ module Vmpooler
             end
           end
           $metrics.increment("errors.markedasfailed.#{pool}")
-          $logger.log('d', "[!] [#{pool}] '#{vm}' marked as 'failed' after #{timeout} minutes")
+          $logger.log('d', "[!] [#{pool}] '#{vm}' marked as 'failed' after #{timeout} minutes with error: #{open_socket_error}")
         else
           remove_nonexistent_vm(vm, pool, redis)
         end
@@ -197,11 +198,12 @@ module Vmpooler
 
     def vm_still_ready?(pool_name, vm_name, provider, redis)
       # Check if the VM is still ready/available
-      return true if provider.vm_ready?(pool_name, vm_name)
+      return true if provider.vm_ready?(pool_name, vm_name, redis)
 
       raise("VM #{vm_name} is not ready")
     rescue StandardError
-      move_vm_queue(pool_name, vm_name, 'ready', 'completed', redis, "is unreachable, removed from 'ready' queue")
+      open_socket_error = redis.hget("vmpooler__vm__#{vm_name}", 'open_socket_error')
+      move_vm_queue(pool_name, vm_name, 'ready', 'completed', redis, "removed from 'ready' queue. vm unreachable with error: #{open_socket_error}")
     end
 
     def check_ready_vm(vm, pool_name, ttl, provider)
@@ -318,7 +320,7 @@ module Vmpooler
               redis.hset("vmpooler__vm__#{vm}", 'user_tagged', 'true') if success
             end
 
-            throw :stop_checking if provider.vm_ready?(pool, vm)
+            throw :stop_checking if provider.vm_ready?(pool, vm, redis)
 
             throw :stop_checking if provider.get_vm(pool, vm)
 

spec/unit/pool_manager_spec.rb

@@ -203,8 +203,8 @@ EOT
     context 'host is in pool' do
 
       it 'calls move_pending_vm_to_ready if host is ready' do
-        expect(provider).to receive(:vm_ready?).with(pool,vm).and_return(true)
         redis_connection_pool.with do |redis|
+          expect(provider).to receive(:vm_ready?).with(pool, vm, redis).and_return(true)
           expect(subject).to receive(:move_pending_vm_to_ready).with(vm, pool, redis, nil)
         end
 
@@ -212,8 +212,8 @@ EOT
       end
 
       it 'calls fail_pending_vm if host is not ready' do
-        expect(provider).to receive(:vm_ready?).with(pool,vm).and_return(false)
         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, redis)
         end
 
@@ -298,7 +298,7 @@ EOT
     it 'logs message 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(logger).to receive(:log).with('d', "[!] [#{pool}] '#{vm}' marked as 'failed' after #{timeout} minutes")
+        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, redis, exists: true)).to eq(true)
       end
     end
@@ -628,7 +628,7 @@ EOT
         end
 
         it 'should log messages about being unreachable' do
-          expect(logger).to receive(:log).with('d', "[!] [#{pool}] '#{vm}' is unreachable, removed from 'ready' queue")
+          expect(logger).to receive(:log).with('d', "[!] [#{pool}] '#{vm}' removed from 'ready' queue. vm unreachable with error: ")
 
           subject._check_ready_vm(vm, pool, ttl, provider)
         end