Fix for specific time scheduled crawls skipping if too many crawlers (#597)

* Bump 8.16 version (#595)

* New diffs

* Make tests run for now until we better understand the tests around sync_triggered? and custom_sync_triggered?

* Added additional tests in crawler_scheduler_spec.rb + wrapped Time.now() calls in Timecop.freeze() + fixed minor typo in :monthly_interval cron schedule

* Added a new test to ensure debug logs are presented when a schedule is skipped + added an expect() to an existing test to check if debug logs are presented there as well + revised debug log wording to include the poll_interval value

* Added regex to expect() for debug messages to ensure we are getting the correct messages + moved those expect() lines out of the before(:each) blocks and into it blocks

---------

Co-authored-by: Chenhui Wang <[email protected]>

Author: mattnowzari

Gemfile

@@ -39,7 +39,7 @@ group :test do
   gem 'ruby-debug-ide'
   gem 'pry-remote'
   gem 'pry-nav'
-  gem 'debase', '0.2.5.beta2'
+  gem 'debase', '0.2.8'
   gem 'timecop'
   gem 'simplecov', require: false
   gem 'simplecov-material'

Gemfile.lock

@@ -20,9 +20,9 @@ GEM
       dry-validation (~> 1.0, >= 1.0.0)
     crack (0.4.5)
       rexml
-    debase (0.2.5.beta2)
-      debase-ruby_core_source (>= 0.10.12)
-    debase-ruby_core_source (0.10.14)
+    debase (0.2.8)
+      debase-ruby_core_source (>= 3.3.6)
+    debase-ruby_core_source (3.3.6)
     deep_merge (1.2.2)
     diff-lcs (1.5.0)
     docile (1.4.0)
@@ -94,7 +94,6 @@ GEM
     faraday-retry (1.0.3)
     faraday_middleware (1.0.0)
       faraday (~> 1.0)
-    ffi (1.15.5-java)
     forwardable (1.3.2)
     fugit (1.11.1)
       et-orbi (~> 1, >= 1.2.11)
@@ -122,10 +121,6 @@ GEM
     pry (0.14.1)
       coderay (~> 1.1)
       method_source (~> 1.0)
-    pry (0.14.1-java)
-      coderay (~> 1.1)
-      method_source (~> 1.0)
-      spoon (~> 0.0)
     pry-nav (1.0.0)
       pry (>= 0.9.10, < 0.15)
     pry-remote (0.1.8)
@@ -186,8 +181,6 @@ GEM
       simplecov (>= 0.16.0)
     simplecov_json_formatter (0.1.4)
     slop (3.6.0)
-    spoon (0.0.6)
-      ffi
     timecop (0.9.4)
     tzinfo (2.0.6)
       concurrent-ruby (~> 1.0)
@@ -215,7 +208,7 @@ DEPENDENCIES
   bundler (= 2.3.15)
   concurrent-ruby (~> 1.1.9)
   config (~> 4.0.0)
-  debase (= 0.2.5.beta2)
+  debase (= 0.2.8)
   dry-configurable (= 0.13.0)
   dry-container (= 0.9.0)
   dry-core (= 0.7.1)

lib/connectors/crawler/scheduler.rb

@@ -24,14 +24,15 @@ def connector_settings
 
       def when_triggered
         loop do
+          time_at_poll_start = Time.now # grab the time right before we iterate over all connectors
           connector_settings.each do |cs|
             # crawler only supports :sync
-            if sync_triggered?(cs)
+            if sync_triggered?(cs, time_at_poll_start)
               yield cs, :sync, nil
               next
             end
 
-            schedule_key = custom_schedule_triggered(cs)
+            schedule_key = custom_schedule_triggered(cs, time_at_poll_start)
             yield cs, :sync, schedule_key if schedule_key
           end
         rescue *Utility::AUTHORIZATION_ERRORS => e
@@ -53,10 +54,10 @@ def connector_registered?(service_type)
       end
 
       # custom scheduling has no ordering, so the first-found schedule is returned
-      def custom_schedule_triggered(cs)
+      def custom_schedule_triggered(cs, time_at_poll_start)
         cs.custom_scheduling_settings.each do |key, custom_scheduling|
           identifier = "#{cs.formatted} - #{custom_scheduling[:name]}"
-          if schedule_triggered?(custom_scheduling, identifier)
+          if schedule_triggered?(custom_scheduling, identifier, time_at_poll_start)
             return key
           end
         end

lib/core/scheduler.rb

@@ -62,7 +62,7 @@ def shutdown
 
     private
 
-    def sync_triggered?(connector_settings)
+    def sync_triggered?(connector_settings, time_at_poll_start = Time.now)
       unless connector_settings.valid_index_name?
         Utility::Logger.warn("The index name of #{connector_settings.formatted} is invalid.")
         return false
@@ -80,7 +80,7 @@ def sync_triggered?(connector_settings)
         return true
       end
 
-      schedule_triggered?(connector_settings.full_sync_scheduling, connector_settings.formatted)
+      schedule_triggered?(connector_settings.full_sync_scheduling, connector_settings.formatted, time_at_poll_start)
     end
 
     def heartbeat_triggered?(connector_settings)
@@ -149,7 +149,7 @@ def connector_registered?(service_type)
       end
     end
 
-    def schedule_triggered?(scheduling_settings, identifier)
+    def schedule_triggered?(scheduling_settings, identifier, time_at_poll_start = Time.now)
       # Don't sync if sync is explicitly disabled
       unless scheduling_settings.present? && scheduling_settings[:enabled] == true
         Utility::Logger.debug("#{identifier.capitalize} scheduling is disabled.")
@@ -179,12 +179,15 @@ def schedule_triggered?(scheduling_settings, identifier)
         return false
       end
 
-      next_trigger_time = cron_parser.next_time(Time.now)
-
+      next_trigger_time = cron_parser.next_time(time_at_poll_start)
       # Sync if next trigger happens before the next poll
-      if next_trigger_time <= Time.now + @poll_interval
+      poll_window = time_at_poll_start + @poll_interval
+      if next_trigger_time <= poll_window
         Utility::Logger.info("#{identifier.capitalize} sync is triggered by cron schedule #{current_schedule}.")
         return true
+      else
+        # log that a sync was not triggered, share the next trigger time and when poll interval was meant to end
+        Utility::Logger.debug("Sync for #{identifier.capitalize} not triggered as #{next_trigger_time} occurs after the poll window #{poll_window}. Poll window began at #{time_at_poll_start}, poll interval is #{@poll_interval} seconds.")
       end
 
       false

spec/connectors/crawler/crawler_scheduler_spec.rb

@@ -1,5 +1,6 @@
 require 'core/connector_settings'
 require 'connectors/crawler/scheduler'
+require 'timecop'
 
 describe Connectors::Crawler::Scheduler do
   subject { described_class.new(poll_interval, heartbeat_interval) }
@@ -67,7 +68,7 @@
       let(:weekly_enabled) { false }
       let(:weekly_interval) { '0 0 * * 1 ?' }
       let(:monthly_enabled) { false }
-      let(:monthly_interval) { '0 0 * 1 * ?' }
+      let(:monthly_interval) { '0 0 1 * * ?' }
       let(:custom_scheduling_settings) do
         {
           :weekly_key => {
@@ -88,14 +89,15 @@
       let(:weekly_next_trigger_time) { 1.day.from_now }
       let(:monthly_next_trigger_time) { 1.day.from_now }
 
+      let(:time_at_poll_start) { Timecop.freeze(Time.now) }
+
       let(:cron_parser) { instance_double(Fugit::Cron) }
 
       before(:each) do
         allow(Core::ConnectorSettings).to receive(:fetch_crawler_connectors).and_return(connector_settings)
 
-        allow(subject).to receive(:sync_triggered?).with(connector_settings).and_call_original
-        allow(subject).to receive(:custom_sync_triggered?).with(connector_settings).and_call_original
-
+        allow(subject).to receive(:sync_triggered?).with(connector_settings, time_at_poll_start).and_call_original
+        allow(subject).to receive(:custom_sync_triggered?).with(connector_settings, time_at_poll_start).and_call_original
         allow(connector_settings).to receive(:connector_status_allows_sync?).and_return(true)
         allow(connector_settings).to receive(:sync_now?).and_return(sync_now)
         allow(connector_settings).to receive(:full_sync_scheduling).and_return(full_sync_scheduling)
@@ -109,13 +111,17 @@
         allow(Fugit::Cron).to receive(:parse).and_return(cron_parser)
       end
 
+      after(:each) do
+        Timecop.return
+      end
+
       context 'when none are enabled' do
         it_behaves_like 'does not trigger', :sync
       end
 
       context 'when one custom scheduling is enabled and ready to sync' do
         let(:monthly_enabled) { true }
-        let(:monthly_next_trigger_time) { Time.now + poll_interval - 10 }
+        let(:monthly_next_trigger_time) { time_at_poll_start + poll_interval - 10 }
 
         before(:each) do
           allow(Utility::Cron).to receive(:quartz_to_crontab).with(monthly_interval)
@@ -125,12 +131,12 @@
         it_behaves_like 'triggers', :monthly_key
       end
 
-      context 'when all custom schedulings are enabled and ready to sync' do
+      context 'when all custom scheduling is enabled and ready to sync' do
         let(:weekly_enabled) { true }
         let(:monthly_enabled) { true }
 
-        let(:weekly_next_trigger_time) { Time.now + poll_interval - 10 }
-        let(:monthly_next_trigger_time) { Time.now + poll_interval - 10 }
+        let(:weekly_next_trigger_time) { time_at_poll_start + poll_interval - 10 }
+        let(:monthly_next_trigger_time) { time_at_poll_start + poll_interval - 10 }
 
         before(:each) do
           allow(cron_parser).to receive(:next_time).and_return(weekly_next_trigger_time, monthly_next_trigger_time)
@@ -145,9 +151,9 @@
         let(:weekly_enabled) { true }
         let(:monthly_enabled) { true }
 
-        let(:next_trigger_time) { Time.now + poll_interval - 10 }
-        let(:weekly_next_trigger_time) { Time.now + poll_interval - 10 }
-        let(:monthly_next_trigger_time) { Time.now + poll_interval - 10 }
+        let(:next_trigger_time) { time_at_poll_start + poll_interval - 10 }
+        let(:weekly_next_trigger_time) { time_at_poll_start + poll_interval - 10 }
+        let(:monthly_next_trigger_time) { time_at_poll_start + poll_interval - 10 }
 
         before(:each) do
           allow(cron_parser).to receive(:next_time).and_return(next_trigger_time, weekly_next_trigger_time, monthly_next_trigger_time)
@@ -156,6 +162,77 @@
         # it will return the base scheduling
         it_behaves_like 'triggers', nil
       end
+
+      context 'when base and custom scheduling are enabled and are scheduled after the poll interval' do
+        let(:sync_enabled) { true }
+        let(:weekly_enabled) { true }
+        let(:monthly_enabled) { true }
+
+        let(:next_trigger_time) { time_at_poll_start + poll_interval + 10 }
+        let(:weekly_next_trigger_time) { time_at_poll_start + poll_interval + 10 }
+        let(:monthly_next_trigger_time) { time_at_poll_start + poll_interval + 10 }
+
+        before(:each) do
+          allow(cron_parser).to receive(:next_time).with(time_at_poll_start).and_return(next_trigger_time, weekly_next_trigger_time, monthly_next_trigger_time)
+        end
+
+        # functionally the same as shared test 'does not trigger' but with an extra expect() to check for debug messages
+        it 'does not yield task' do
+          # expect three debug messages because three schedules are not being triggered
+          expect(Utility::Logger).to receive(:debug).exactly(3).times.with(match(/^Sync for (\w+.*)|( - \w+) not triggered as .*/))
+          expect { |b| subject.when_triggered(&b) }.to_not yield_control
+        end
+      end
+
+      context 'when base and custom scheduling are enabled, but one is scheduled after the poll interval' do
+        let(:sync_enabled) { true }
+        let(:weekly_enabled) { true }
+
+        let(:next_trigger_time) { time_at_poll_start + poll_interval + 10 }
+        let(:weekly_next_trigger_time) { time_at_poll_start + poll_interval - 10 }
+
+        before(:each) do
+          allow(cron_parser).to receive(:next_time).with(time_at_poll_start).and_return(next_trigger_time, weekly_next_trigger_time)
+        end
+
+        # functionally the same as shared test 'triggers', but with an extra expect() to check for a debug message
+        it 'yields :sync task with an optional scheduling_key value' do
+          expect(Utility::Logger).to receive(:debug).exactly(1).times.with(match(/^Sync for (\w+.*)|( - \w+) not triggered as .*/))
+          expect { |b| subject.when_triggered(&b) }.to yield_with_args(connector_settings, :sync, :weekly_key)
+        end
+      end
+
+      context 'when base and custom scheduling are enabled and require sync and are scheduled at the start of the poll interval' do
+        let(:sync_enabled) { true }
+        let(:weekly_enabled) { true }
+        let(:monthly_enabled) { true }
+
+        let(:next_trigger_time) { time_at_poll_start }
+        let(:weekly_next_trigger_time) { time_at_poll_start }
+        let(:monthly_next_trigger_time) { time_at_poll_start }
+
+        before(:each) do
+          allow(cron_parser).to receive(:next_time).with(time_at_poll_start).and_return(next_trigger_time, weekly_next_trigger_time, monthly_next_trigger_time)
+        end
+
+        it_behaves_like 'triggers', nil
+      end
+
+      context 'when base and custom scheduling are enabled and require sync and are scheduled at end of the poll interval' do
+        let(:sync_enabled) { true }
+        let(:weekly_enabled) { true }
+        let(:monthly_enabled) { true }
+
+        let(:next_trigger_time) { time_at_poll_start + poll_interval }
+        let(:weekly_next_trigger_time) { time_at_poll_start + poll_interval }
+        let(:monthly_next_trigger_time) { time_at_poll_start + poll_interval }
+
+        before(:each) do
+          allow(cron_parser).to receive(:next_time).with(time_at_poll_start).and_return(next_trigger_time, weekly_next_trigger_time, monthly_next_trigger_time)
+        end
+
+        it_behaves_like 'triggers', nil
+      end
     end
   end
 end