From e4062dc005bd78c47a41c021d85c80bb607e7b65 Mon Sep 17 00:00:00 2001
From: "kirby@puppetlabs.com" <mk.kirby@gmail.com>
Date: Fri, 8 May 2020 14:39:25 -0700
Subject: [PATCH] Remove unreasonable ttl of 0 concept for a ready vm

---
 lib/vmpooler.rb                |  2 +-
 lib/vmpooler/api/v1.rb         |  4 ++
 lib/vmpooler/pool_manager.rb   | 41 +++++++++---------
 spec/unit/pool_manager_spec.rb | 79 +++++++++++++++++-----------------
 4 files changed, 65 insertions(+), 61 deletions(-)

diff --git a/lib/vmpooler.rb b/lib/vmpooler.rb
index e5932d6..28aa323 100644
--- a/lib/vmpooler.rb
+++ b/lib/vmpooler.rb
@@ -64,7 +64,7 @@ module Vmpooler
     parsed_config[:config]['vm_checktime'] = string_to_int(ENV['VM_CHECKTIME']) || parsed_config[:config]['vm_checktime'] || 1
     parsed_config[:config]['vm_lifetime'] = string_to_int(ENV['VM_LIFETIME']) || parsed_config[:config]['vm_lifetime'] || 24
     parsed_config[:config]['ready_ttl'] = string_to_int(ENV['READY_TTL']) || parsed_config[:config]['ready_ttl'] || 5
-    parsed_config[:config]['ondemand_request_ttl'] = string_to_int(ENV['ONDEMAND_REQUEST_TTL']) || parsed_config[:config]['ready_ttl'] || 5
+    parsed_config[:config]['ondemand_request_ttl'] = string_to_int(ENV['ONDEMAND_REQUEST_TTL']) || parsed_config[:config]['ondemand_request_ttl'] || 5
     parsed_config[:config]['prefix'] = ENV['PREFIX'] || parsed_config[:config]['prefix'] || ''
 
     parsed_config[:config]['logfile'] = ENV['LOGFILE'] if ENV['LOGFILE']
diff --git a/lib/vmpooler/api/v1.rb b/lib/vmpooler/api/v1.rb
index 348debc..188a5aa 100644
--- a/lib/vmpooler/api/v1.rb
+++ b/lib/vmpooler/api/v1.rb
@@ -934,6 +934,10 @@ module Vmpooler
           result[pool_alias] = { 'hostname': instances }
         end
         status 200
+      elsif request_hash['status'] == 'failed'
+        result['ready'] = false
+        result['message'] = "The request failed to provision instances within the configured ondemand_request_ttl '#{config['ondemand_request_ttl']}'"
+        status 200
       else
         platform_parts = request_hash['requested'].split(',')
         platform_parts.each do |platform|
diff --git a/lib/vmpooler/pool_manager.rb b/lib/vmpooler/pool_manager.rb
index 5a0e762..f92409c 100644
--- a/lib/vmpooler/pool_manager.rb
+++ b/lib/vmpooler/pool_manager.rb
@@ -111,7 +111,6 @@ module Vmpooler
 
     def fail_pending_vm(vm, pool, timeout, redis, exists = true)
       clone_stamp = redis.hget("vmpooler__vm__#{vm}", 'clone')
-      return true unless clone_stamp
 
       time_since_clone = (Time.now - Time.parse(clone_stamp)) / 60
       if time_since_clone > timeout
@@ -139,16 +138,16 @@ module Vmpooler
       finish = format('%<time>.2f', time: Time.now - Time.parse(clone_time))
 
       if request_id
-        vm_hash = redis.hgetall("vmpooler__vm__#{vm}")
-        if vm_hash['status'] == 'failed'
+        if redis.hget("vmpooler__odrequest__#{request_id}", 'status') == 'failed'
           move_vm_queue(pool, vm, 'pending', 'completed', redis, "moved to completed queue. '#{request_id}' could not be filled in time")
           return nil
         end
+        pool_alias = redis.hget("vmpooler__vm__#{vm}", 'pool_alias')
 
         redis.pipelined do
           redis.hset("vmpooler__active__#{pool}", vm, Time.now)
           redis.hset("vmpooler__vm__#{vm}", 'checkout', Time.now)
-          redis.sadd("vmpooler__#{request_id}__#{vm_hash['pool_alias']}__#{pool}", vm)
+          redis.sadd("vmpooler__#{request_id}__#{pool_alias}__#{pool}", vm)
         end
         puts redis.smembers("vmpooler__#{request_id}__#{pool['alias']}__#{pool}")
         move_vm_queue(pool, vm, 'pending', 'running', redis)
@@ -197,24 +196,23 @@ module Vmpooler
       mutex.synchronize do
         @redis.with_metrics do |redis|
           check_stamp = redis.hget('vmpooler__vm__' + vm, 'check')
-          break if check_stamp && (((Time.now - Time.parse(check_stamp)) / 60) <= $config[:config]['vm_checktime'])
+          last_checked_too_soon = ((Time.now - Time.parse(check_stamp)).to_i < $config[:config]['vm_checktime'] * 60) if check_stamp
+          break if check_stamp && last_checked_too_soon
 
           redis.hset('vmpooler__vm__' + vm, 'check', Time.now)
           # Check if the hosts TTL has expired
-          if ttl > 0
-            # if 'boottime' is nil, set bootime to beginning of unix epoch, forces TTL to be assumed expired
-            boottime = redis.hget("vmpooler__vm__#{vm}", 'ready')
-            if boottime
-              boottime = Time.parse(boottime)
-            else
-              boottime = Time.at(0)
-            end
-            if ((Time.now - boottime) / 60).to_s[/^\d+\.\d{1}/].to_f > ttl
-              redis.smove('vmpooler__ready__' + pool_name, 'vmpooler__completed__' + pool_name, vm)
+          # if 'boottime' is nil, set bootime to beginning of unix epoch, forces TTL to be assumed expired
+          boottime = redis.hget("vmpooler__vm__#{vm}", 'ready')
+          if boottime
+            boottime = Time.parse(boottime)
+          else
+            boottime = Time.at(0)
+          end
+          if (Time.now - boottime).to_i > ttl * 60
+            redis.smove('vmpooler__ready__' + pool_name, 'vmpooler__completed__' + pool_name, vm)
 
-              $logger.log('d', "[!] [#{pool_name}] '#{vm}' reached end of TTL after #{ttl} minutes, removed from 'ready' queue")
-              return nil
-            end
+            $logger.log('d', "[!] [#{pool_name}] '#{vm}' reached end of TTL after #{ttl} minutes, removed from 'ready' queue")
+            return nil
           end
 
           break if mismatched_hostname?(vm, pool_name, provider, redis)
@@ -1154,13 +1152,13 @@ module Vmpooler
       end
     end
 
-    def check_ready_pool_vms(pool_name, provider, pool_check_response, inventory, pool_ttl = 0)
+    def check_ready_pool_vms(pool_name, provider, pool_check_response, inventory, pool_ttl)
       @redis.with_metrics do |redis|
         redis.smembers("vmpooler__ready__#{pool_name}").each do |vm|
           if inventory[vm]
             begin
               pool_check_response[:checked_ready_vms] += 1
-              check_ready_vm(vm, pool_name, pool_ttl || 0, provider)
+              check_ready_vm(vm, pool_name, pool_ttl, provider)
             rescue StandardError => e
               $logger.log('d', "[!] [#{pool_name}] _check_pool failed with an error while evaluating ready VMs: #{e}")
             end
@@ -1495,7 +1493,8 @@ module Vmpooler
     def request_expired?(request_id, score, redis)
       delta = Time.now.to_i - score.to_i
       ondemand_request_ttl = $config[:config]['ondemand_request_ttl']
-      return false unless (delta / 60) > ondemand_request_ttl
+      return false unless delta > ondemand_request_ttl * 60
+
       $logger.log('s', "Ondemand request for '#{request_id}' failed to provision all instances within the configured ttl '#{ondemand_request_ttl}'")
       expiration_ttl = $config[:redis]['data_ttl'].to_i * 60 * 60
       redis.pipelined do
diff --git a/spec/unit/pool_manager_spec.rb b/spec/unit/pool_manager_spec.rb
index b7d6cc3..a960ce3 100644
--- a/spec/unit/pool_manager_spec.rb
+++ b/spec/unit/pool_manager_spec.rb
@@ -164,6 +164,7 @@ EOT
     before(:each) do
       redis_connection_pool.with do |redis|
         create_pending_vm(pool,vm,redis)
+        config[:config]['vm_checktime'] = 15
       end
     end
 
@@ -338,7 +339,7 @@ EOT
       context 'when the request has been marked as failed' do
         before(:each) do
           redis_connection_pool.with do |redis|
-            redis.hset("vmpooler__vm__#{vm}", 'status', 'failed')
+            redis.hset("vmpooler__odrequest__#{request_id}", 'status', 'failed')
           end
         end
 
@@ -360,7 +361,7 @@ EOT
   end
 
   describe '#check_ready_vm' do
-    let(:ttl) { 0 }
+    let(:ttl) { 5 }
     let(:poolconfig) { config[:pools][0] }
 
     before do
@@ -376,7 +377,7 @@ EOT
   end
 
   describe '#_check_ready_vm' do
-    let(:ttl) { 0 }
+    let(:ttl) { 5 }
     let(:host) { {} }
     let(:config) { YAML.load(<<-EOT
 ---
@@ -417,8 +418,6 @@ EOT
     end
 
     context 'a VM that has never been checked' do
-      let(:last_check_date) { Time.now - 901 }
-
       it 'should set the current check timestamp' do
         redis_connection_pool.with do |redis|
           expect(redis.hget("vmpooler__vm__#{vm}", 'check')).to be_nil
@@ -445,10 +444,6 @@ EOT
       end
 
       context 'and is ready' do
-        before(:each) do
-          expect(provider).to receive(:vm_ready?).with(pool, vm).and_return(true)
-        end
-
         it 'should only set the next check interval' do
           subject._check_ready_vm(vm, pool, ttl, provider)
         end
@@ -456,9 +451,8 @@ EOT
 
       context 'has correct name and is not ready' do
         before(:each) do
-          expect(provider).to receive(:vm_ready?).with(pool, vm).and_return(false)
           redis_connection_pool.with do |redis|
-            redis.hset("vmpooler__vm__#{vm}", 'ready', Time.now - 901)
+            redis.hset("vmpooler__vm__#{vm}", 'ready', Time.now - 200)
             redis.sadd("vmpooler__ready__#{pool}", vm)
           end
         end
@@ -501,36 +495,19 @@ EOT
 
         context 'with a hostname mismatch' do
           let(:different_hostname) { 'different_name' }
+          let(:longer_ttl) { 20 }
           before(:each) do
-            expect(provider).to receive(:get_vm).with(pool,vm).and_return(host)
             host['hostname'] = different_hostname
             redis_connection_pool.with do |redis|
-              redis.sadd("vmpooler__ready__#{pool}", vm)
+              expect(subject).to receive(:mismatched_hostname?).with(vm, pool, provider, redis).and_return(true)
+              redis.hset("vmpooler__vm__#{vm}", 'ready', Time.now - 300)
             end
           end
 
-          it 'should move the VM to the completed queue' do
-            redis_connection_pool.with do |redis|
-              expect(redis).to receive(:smove).with("vmpooler__ready__#{pool}", "vmpooler__completed__#{pool}", vm)
-            end
+          it 'should not run vm_still_ready?' do
+            expect(subject).to_not receive(:vm_still_ready?)
 
-            subject._check_ready_vm(vm, pool, ttl, provider)
-          end
-
-          it 'should move the VM to the completed queue in Redis' do
-            redis_connection_pool.with do |redis|
-              expect(redis.sismember("vmpooler__ready__#{pool}", vm)).to be(true)
-              expect(redis.sismember("vmpooler__completed__#{pool}", vm)).to be(false)
-              subject._check_ready_vm(vm, pool, ttl, provider)
-              expect(redis.sismember("vmpooler__ready__#{pool}", vm)).to be(false)
-              expect(redis.sismember("vmpooler__completed__#{pool}", vm)).to be(true)
-            end
-          end
-
-          it 'should log messages about being misnamed' do
-            expect(logger).to receive(:log).with('d', "[!] [#{pool}] '#{vm}' has mismatched hostname #{different_hostname}, removed from 'ready' queue")
-
-            subject._check_ready_vm(vm, pool, ttl, provider)
+            subject._check_ready_vm(vm, pool, longer_ttl, provider)
           end
         end
       end
@@ -3743,6 +3720,7 @@ EOT
 
   describe '#check_ready_pool_vms' do
     let(:provider) { double('provider') }
+    let(:pool_ttl) { 5 }
     let(:pool_check_response) {
       {:checked_ready_vms => 0}
     }
@@ -3761,7 +3739,7 @@ EOT
       it 'should not call check_ready_vm' do
         expect(subject).to receive(:check_ready_vm).exactly(0).times
 
-        subject.check_ready_pool_vms(pool, provider, pool_check_response, inventory)
+        subject.check_ready_pool_vms(pool, provider, pool_check_response, inventory, pool_ttl)
       end
 
       it 'should move the VM to completed queue' do
@@ -3769,7 +3747,7 @@ EOT
           expect(subject).to receive(:move_vm_queue).with(pool,vm,'ready','completed',redis,String).and_call_original
         end
 
-        subject.check_ready_pool_vms(pool, provider, pool_check_response, inventory)
+        subject.check_ready_pool_vms(pool, provider, pool_check_response, inventory, pool_ttl)
       end
     end
 
@@ -3787,7 +3765,7 @@ EOT
       end
 
       it 'should return the number of checked ready VMs' do
-        subject.check_ready_pool_vms(pool, provider, pool_check_response, inventory)
+        subject.check_ready_pool_vms(pool, provider, pool_check_response, inventory, pool_ttl)
 
         expect(pool_check_response[:checked_ready_vms]).to be(1)
       end
@@ -3806,9 +3784,9 @@ EOT
       end
 
       it 'should use a pool TTL of zero if none set' do
-        expect(subject).to receive(:check_ready_vm).with(vm,pool,0,provider)
+        expect(subject).to receive(:check_ready_vm).with(vm,pool,pool_ttl,provider)
 
-        subject.check_ready_pool_vms(pool, provider, pool_check_response, inventory)
+        subject.check_ready_pool_vms(pool, provider, pool_check_response, inventory, pool_ttl)
       end
     end
   end
@@ -4921,8 +4899,10 @@ EOT
 
   describe '#request_expired?' do
     let(:ondemand_request_ttl) { 5 }
+    let(:expiration_ttl) { 10 }
     before(:each) do
       config[:config]['ondemand_request_ttl'] = ondemand_request_ttl
+      config[:redis]['data_ttl'] = expiration_ttl
     end
 
     context 'with a request that has taken too long to be filled' do
@@ -4947,6 +4927,27 @@ EOT
           subject.request_expired?(request_id, expired_time, redis)
         end
       end
+
+      it 'removes the request from processing requests' do
+        redis_connection_pool.with do |redis|
+          expect(redis).to receive(:zrem).with('vmpooler__provisioning__processing', request_id)
+          subject.request_expired?(request_id, expired_time, redis)
+        end
+      end
+
+      it 'sets the status as failed on the request hash' do
+        redis_connection_pool.with do |redis|
+          expect(redis).to receive(:hset).with("vmpooler__odrequest__#{request_id}", 'status', 'failed')
+          subject.request_expired?(request_id, expired_time, redis)
+        end
+      end
+
+      it 'marks the request hash for expiration' do
+        redis_connection_pool.with do |redis|
+          expect(redis).to receive(:expire).with("vmpooler__odrequest__#{request_id}", expiration_ttl * 60 * 60)
+          subject.request_expired?(request_id, expired_time, redis)
+        end
+      end
     end
 
     context 'with a request that has been made within the ttl' do