Only check hostname for mismatch after time since ready has past

Configure hostname checking so it is not checked until a VM has been
ready for greater than one minute. Without this change hostname checking
will often fail because the configured value has not propogated to the
VM on some platforms before this check is run.

lib/vmpooler/pool_manager.rb

@@ -87,6 +87,7 @@ module Vmpooler
 
       $redis.smove('vmpooler__pending__' + pool, 'vmpooler__ready__' + pool, vm)
       $redis.hset('vmpooler__boot__' + Date.today.to_s, pool + ':' + vm, finish) # maybe remove as this is never used by vmpooler itself?
+      $redis.hset("vmpooler__vm__#{vm}", 'ready', Time.now)
 
       # last boot time is displayed in API, and used by alarming script
       $redis.hset('vmpooler__lastboot', pool, Time.now)
@@ -145,6 +146,16 @@ module Vmpooler
       check_hostname = $config[:config]['check_ready_vm_hostname_for_mismatch'] if check_hostname.nil?
       return if check_hostname == false
 
+      # Wait one minute before checking a VM for hostname mismatch
+      # When checking as soon as the VM passes the ready test the instance
+      # often doesn't report its hostname yet causing the VM to be removed immediately
+      vm_ready_time = $redis.hget("vmpooler__vm__#{vm}", 'ready')
+      if vm_ready_time
+        wait_before_checking = 60
+        time_since_ready = (Time.now - Time.parse(vm_ready_time)).to_i
+        return unless time_since_ready > wait_before_checking
+      end
+
       # Check if the hostname has magically changed from underneath Pooler
       vm_hash = provider.get_vm(pool['name'], vm)
       hostname = vm_hash['hostname']
@@ -152,7 +163,7 @@ module Vmpooler
       return if hostname.empty?
       return if hostname == vm
       $redis.smove('vmpooler__ready__' + pool['name'], 'vmpooler__completed__' + pool['name'], vm)
-      $logger.log('d', "[!] [#{pool['name']}] '#{vm}' has mismatched hostname, removed from 'ready' queue")
+      $logger.log('d', "[!] [#{pool['name']}] '#{vm}' has mismatched hostname #{hostname}, removed from 'ready' queue")
       return true
     end
 

spec/unit/pool_manager_spec.rb

@@ -197,7 +197,7 @@ EOT
         redis.hset("vmpooler__vm__#{vm}", 'clone',Time.now.to_s)
         expect(metrics).to receive(:timing).with(/time_to_ready_state\./,/0/)
 
-        subject.move_pending_vm_to_ready(vm, pool, host)
+        subject.move_pending_vm_to_ready(vm, pool)
       end
 
 
@@ -329,13 +329,22 @@ EOT
       end
 
       context 'with hostname mismatch checking enabled' do
+
+        context 'when less than 60 seconds since a VM moved to ready' do
           before(:each) do
-          expect(provider).to receive(:get_vm).with(pool,vm).and_return(host)
+            redis.hset("vmpooler__vm__#{vm}", 'ready', Time.now)
+          end
+
+          it 'should return nil' do
+            expect(subject._check_ready_vm(vm, poolconfig, ttl, provider)).to be_nil
+          end
         end
 
         context 'with a hostname mismatch' do
+          let(:different_hostname) { 'different_name' }
           before(:each) do
-            host['hostname'] = 'different_name'
+            expect(provider).to receive(:get_vm).with(pool,vm).and_return(host)
+            host['hostname'] = different_hostname
           end
 
           it 'should move the VM to the completed queue' do
@@ -353,7 +362,7 @@ EOT
           end
 
           it 'should log messages about being misnamed' do
-            expect(logger).to receive(:log).with('d', "[!] [#{pool}] '#{vm}' has mismatched hostname, removed from 'ready' queue")
+            expect(logger).to receive(:log).with('d', "[!] [#{pool}] '#{vm}' has mismatched hostname #{different_hostname}, removed from 'ready' queue")
 
             subject._check_ready_vm(vm, poolconfig, ttl, provider)
           end