From 8503c026e63af2f396e82194e4ba24f1b49c1482 Mon Sep 17 00:00:00 2001 From: Lucas Di Pentima Date: Fri, 18 Sep 2020 17:18:57 -0300 Subject: [PATCH] 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 --- services/api/test/fixtures/logs.yml | 5 +++++ services/api/test/unit/log_test.rb | 35 +++++++++++++++-------------- 2 files changed, 23 insertions(+), 17 deletions(-) diff --git a/services/api/test/fixtures/logs.yml b/services/api/test/fixtures/logs.yml index b1b77c5190..25f1efff62 100644 --- 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 58f0cddb70..131f8b4b12 100644 --- 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 -- 2.30.2