7399: added test for partial line segment throttling.

diff --git a/services/api/lib/crunch_dispatch.rb b/services/api/lib/crunch_dispatch.rb
index cbdd04e61c453b9b9012774e93ea4a86fc75afb5..1017895b25218cea5927fd568851be8047554ffb 100644 (file)
--- a/services/api/lib/crunch_dispatch.rb
+++ b/services/api/lib/crunch_dispatch.rb
@@ -429,7 +429,7 @@ class CrunchDispatch
         log_throttle_bytes_so_far: 0,
         log_throttle_lines_so_far: 0,
         log_throttle_bytes_skipped: 0,
-        log_throttle_partial_line_last_at: 0,
+        log_throttle_partial_line_last_at: Time.new(0),
         log_throttle_first_partial_line: true,
       }
       i.close
@@ -447,10 +447,11 @@ class CrunchDispatch
     if running_job[:log_throttle_is_open]
       partial_line = false
       skip_counts = false
-      if line.start_with?('[...]') and line.end_with?('[...]')
+      line_splits = line.split('stderr ')
+      if line_splits[1].andand.start_with?('[...]') and line_splits[1].end_with?('[...]')
         partial_line = true
-        if Time.now > j[:log_throttle_partial_line_last_at] + Rails.configuration.crunch_log_partial_line_throttle_period
-          j[:log_throttle_partial_line_last_at] = Time.now
+        if Time.now > running_job[:log_throttle_partial_line_last_at] + Rails.configuration.crunch_log_partial_line_throttle_period
+          running_job[:log_throttle_partial_line_last_at] = Time.now
         else
           skip_counts = true
         end
@@ -480,8 +481,8 @@ class CrunchDispatch
         message = "Exceeded rate #{Rails.configuration.crunch_log_throttle_lines} lines per #{Rails.configuration.crunch_log_throttle_period} seconds (crunch_log_throttle_lines), logging will be silenced for the next #{remaining_time.round} seconds."
         running_job[:log_throttle_is_open] = false
 
-      elsif partial_line and j[:log_throttle_first_partial_line]
-        j[:log_throttle_first_partial_line] = false
+      elsif partial_line and running_job[:log_throttle_first_partial_line]
+        running_job[:log_throttle_first_partial_line] = false
         message = "Rate-limiting partial segments of long lines to one every #{Rails.configuration.crunch_log_partial_line_throttle_period} seconds."
       end
     end
@@ -497,6 +498,8 @@ class CrunchDispatch
       message += " A complete log is still being written to Keep, and will be available when the job finishes.\n"
       line.replace message
       true
+    elsif partial_line
+      false
     else
       running_job[:log_throttle_is_open]
     end
@@ -521,7 +524,7 @@ class CrunchDispatch
         j[:log_throttle_lines_so_far] = 0
         j[:log_throttle_bytes_skipped] = 0
         j[:log_throttle_is_open] = true
-        j[:log_throttle_partial_line_last_at] = 0
+        j[:log_throttle_partial_line_last_at] = Time.new(0)
         j[:log_throttle_first_partial_line] = true
       end
 

diff --git a/services/api/test/unit/crunch_dispatch_test.rb b/services/api/test/unit/crunch_dispatch_test.rb
index 09f4af6373fa03a2f4bdb79e332ea7b38130ff0a..04b06d747e724a3594ca7c4ba356a01dbb417bdc 100644 (file)
--- a/services/api/test/unit/crunch_dispatch_test.rb
+++ b/services/api/test/unit/crunch_dispatch_test.rb
@@ -116,4 +116,63 @@ class CrunchDispatchTest < ActiveSupport::TestCase
       return f.flock(File::LOCK_EX|File::LOCK_NB)
     end
   end
+
+  test 'rate limit of partial line segments' do
+    act_as_system_user do
+      Rails.configuration.crunch_log_partial_line_throttle_period = 1
+
+      job = {}
+      job[:bytes_logged] = 0
+      job[:log_throttle_bytes_so_far] = 0
+      job[:log_throttle_lines_so_far] = 0
+      job[:log_throttle_bytes_skipped] = 0
+      job[:log_throttle_is_open] = true
+      job[:log_throttle_partial_line_last_at] = Time.new(0)
+      job[:log_throttle_first_partial_line] = true
+
+      dispatch = CrunchDispatch.new
+
+      line = "first log line"
+      limit = dispatch.rate_limit(job, line)
+      assert_equal true, limit
+      assert_equal "first log line", line
+      assert_equal 1, job[:log_throttle_lines_so_far]
+
+      # first partial line segment is skipped and counted towards skipped lines
+      now = Time.now
+      line = "#{Time.now} stderr [...] this is first partial line segment [...]"
+      limit = dispatch.rate_limit(job, line)
+      assert_equal true, limit
+      assert_includes line, "Rate-limiting partial segments of long lines", line
+      assert_equal 2, job[:log_throttle_lines_so_far]
+
+      # next partial line segment within throttle interval is skipped but not counted towards skipped lines
+      line = "#{Time.now} stderr [...] second partial line segment within the interval [...]"
+      limit = dispatch.rate_limit(job, line)
+      assert_equal false, limit
+      assert_equal 2, job[:log_throttle_lines_so_far]
+
+      # next partial line after interval is counted towards skipped lines
+      sleep(1)
+      line = "#{Time.now} stderr [...] third partial line segment after the interval [...]"
+      limit = dispatch.rate_limit(job, line)
+      assert_equal false, limit
+      assert_equal 3, job[:log_throttle_lines_so_far]
+
+      now = Time.now
+      # this is not a valid line segment
+      line = "#{now} stderr [...] does not end with [...] and is not a partial segment"
+      limit = dispatch.rate_limit(job, line)
+      assert_equal true, limit
+      assert_equal "#{now} stderr [...] does not end with [...] and is not a partial segment", line
+      assert_equal 4, job[:log_throttle_lines_so_far]
+
+      # this also is not a valid line segment
+      line = "#{now} stderr does not start correctly but ends with [...]"
+      limit = dispatch.rate_limit(job, line)
+      assert_equal true, limit
+      assert_equal "#{now} stderr does not start correctly but ends with [...]", line
+      assert_equal 5, job[:log_throttle_lines_so_far]
+    end
+  end
 end