16791: Fixes audit log cleaning tests.

Log fixtures lacking the created_at field set in the past in combination
with incorrect testing made us believe the LogTest was working ok.
Specifically, LogTest#test_delete_old_audit_logs_in_thread was not doing
the waiting for the log entries to be eliminated, so there was a race
between the AuditLogs thread cleaning the records and the test teardown doing
the rollback producing the intermittent failure of
use_ownership_and_permission_links_to_determine_which_logs_a_user_can_see.

Arvados-DCO-1.1-Signed-off-by: Lucas Di Pentima <lucas@di-pentima.com.ar>

diff --git a/services/api/test/fixtures/logs.yml b/services/api/test/fixtures/logs.yml
index b1b77c5190ca020f467d3c2c3aab9cf80e54fb28..25f1efff62c8f71246749a3b3c189d297eb7ed82 100644 (file)
--- a/services/api/test/fixtures/logs.yml
+++ b/services/api/test/fixtures/logs.yml
@@ -9,6 +9,7 @@ noop: # nothing happened ...to the 'spectator' user
   object_uuid: zzzzz-tpzed-l1s2piq4t4mps8r
   object_owner_uuid: zzzzz-tpzed-000000000000000
   event_at: <%= 1.minute.ago.to_s(:db) %>
+  created_at: <%= 1.minute.ago.to_s(:db) %>
 
 admin_changes_repository2: # admin changes repository2, which is owned by active user
   id: 2
@@ -16,6 +17,7 @@ admin_changes_repository2: # admin changes repository2, which is owned by active
   owner_uuid: zzzzz-tpzed-d9tiejq69daie8f # admin user
   object_uuid: zzzzz-2x53u-382brsig8rp3667 # repository foo
   object_owner_uuid: zzzzz-tpzed-xurymjxw79nv3jz # active user
+  created_at: <%= 2.minute.ago.to_s(:db) %>
   event_at: <%= 2.minute.ago.to_s(:db) %>
   event_type: update
 
@@ -25,6 +27,7 @@ admin_changes_specimen: # admin changes specimen owned_by_spectator
   owner_uuid: zzzzz-tpzed-d9tiejq69daie8f # admin user
   object_uuid: zzzzz-2x53u-3b0xxwzlbzxq5yr # specimen owned_by_spectator
   object_owner_uuid: zzzzz-tpzed-l1s2piq4t4mps8r # spectator user
+  created_at: <%= 3.minute.ago.to_s(:db) %>
   event_at: <%= 3.minute.ago.to_s(:db) %>
   event_type: update
 
@@ -34,6 +37,7 @@ system_adds_foo_file: # foo collection added, readable by active through link
   owner_uuid: zzzzz-tpzed-000000000000000 # system user
   object_uuid: zzzzz-4zz18-znfnqtbbv4spc3w # foo file
   object_owner_uuid: zzzzz-tpzed-000000000000000 # system user
+  created_at: <%= 4.minute.ago.to_s(:db) %>
   event_at: <%= 4.minute.ago.to_s(:db) %>
   event_type: create
 
@@ -43,6 +47,7 @@ system_adds_baz: # baz collection added, readable by active and spectator throug
   owner_uuid: zzzzz-tpzed-000000000000000 # system user
   object_uuid: zzzzz-4zz18-y9vne9npefyxh8g # baz file
   object_owner_uuid: zzzzz-tpzed-000000000000000 # system user
+  created_at: <%= 5.minute.ago.to_s(:db) %>
   event_at: <%= 5.minute.ago.to_s(:db) %>
   event_type: create
 

diff --git a/services/api/test/unit/log_test.rb b/services/api/test/unit/log_test.rb
index 58f0cddb709064ad2f8af9df6c20aa20f0c77d6a..131f8b4b12194ec48bf4174721fe5294a6148118 100644 (file)
--- a/services/api/test/unit/log_test.rb
+++ b/services/api/test/unit/log_test.rb
@@ -319,6 +319,7 @@ class LogTest < ActiveSupport::TestCase
 
   def assert_no_logs_deleted
     logs_before = Log.unscoped.all.count
+    assert logs_before > 0
     yield
     assert_equal logs_before, Log.unscoped.all.count
   end
@@ -350,34 +351,34 @@ class LogTest < ActiveSupport::TestCase
   # but 3 minutes suits our test data better (and is test-worthy in
   # that it's expected to work correctly in production).
   test 'delete old audit logs with production settings' do
-    initial_log_count = Log.unscoped.all.count
+    initial_log_count = remaining_audit_logs.count
+    assert initial_log_count > 0
     AuditLogs.delete_old(max_age: 180, max_batch: 100000)
     assert_operator remaining_audit_logs.count, :<, initial_log_count
   end
 
   test 'delete all audit logs in multiple batches' do
+    assert remaining_audit_logs.count > 2
     AuditLogs.delete_old(max_age: 0.00001, max_batch: 2)
     assert_equal [], remaining_audit_logs.collect(&:uuid)
   end
 
   test 'delete old audit logs in thread' do
-    begin
-      Rails.configuration.AuditLogs.MaxAge = 20
-      Rails.configuration.AuditLogs.MaxDeleteBatch = 100000
-      Rails.cache.delete 'AuditLogs'
-      initial_log_count = Log.unscoped.all.count + 1
-      act_as_system_user do
-        Log.create!()
-        initial_log_count += 1
-      end
-      deadline = Time.now + 10
-      while remaining_audit_logs.count == initial_log_count
-        if Time.now > deadline
-          raise "timed out"
-        end
-        sleep 0.1
+    Rails.configuration.AuditLogs.MaxAge = 20
+    Rails.configuration.AuditLogs.MaxDeleteBatch = 100000
+    Rails.cache.delete 'AuditLogs'
+    initial_audit_log_count = remaining_audit_logs.count
+    assert initial_audit_log_count > 0
+    act_as_system_user do
+      Log.create!()
+    end
+    deadline = Time.now + 1
+    while remaining_audit_logs.count == initial_audit_log_count
+      if Time.now > deadline
+        raise "timed out"
       end
-      assert_operator remaining_audit_logs.count, :<, initial_log_count
+      sleep 0.1
     end
+    assert_operator remaining_audit_logs.count, :<, initial_audit_log_count
   end
 end