services/api/test/unit/log_test.rb

   1 # Copyright (C) The Arvados Authors. All rights reserved.
   2 #
   3 # SPDX-License-Identifier: AGPL-3.0
   4
   5 require 'test_helper'
   6 require 'audit_logs'
   7
   8 class LogTest < ActiveSupport::TestCase
   9   include CurrentApiClient
  10
  11   EVENT_TEST_METHODS = {
  12     :create => [:created_at, :assert_nil, :assert_not_nil],
  13     :update => [:modified_at, :assert_not_nil, :assert_not_nil],
  14     :delete => [nil, :assert_not_nil, :assert_nil],
  15   }
  16
  17   setup do
  18     @start_time = Time.now
  19     @log_count = 1
  20   end
  21
  22   def assert_properties(test_method, event, props, *keys)
  23     verb = (test_method == :assert_nil) ? 'have nil' : 'define'
  24     keys.each do |prop_name|
  25       assert_includes(props, prop_name, "log properties missing #{prop_name}")
  26       self.send(test_method, props[prop_name],
  27                 "#{event.to_s} log should #{verb} #{prop_name}")
  28     end
  29   end
  30
  31   def get_logs_about(thing)
  32     Log.where(object_uuid: thing.uuid).order("created_at ASC").all
  33   end
  34
  35   def clear_logs_about(thing)
  36     Log.where(object_uuid: thing.uuid).delete_all
  37   end
  38
  39   def assert_logged(thing, event_type)
  40     logs = get_logs_about(thing)
  41     assert_equal(@log_count, logs.size, "log count mismatch")
  42     @log_count += 1
  43     log = logs.last
  44     props = log.properties
  45     assert_equal(current_user.andand.uuid, log.owner_uuid,
  46                  "log is not owned by current user")
  47     assert_equal(current_user.andand.uuid, log.modified_by_user_uuid,
  48                  "log is not 'modified by' current user")
  49     assert_equal(thing.uuid, log.object_uuid, "log UUID mismatch")
  50     assert_equal(event_type.to_s, log.event_type, "log event type mismatch")
  51     time_method, old_props_test, new_props_test = EVENT_TEST_METHODS[event_type]
  52     if time_method.nil? or (timestamp = thing.send(time_method)).nil?
  53       assert(log.event_at >= @start_time, "log timestamp too old")
  54     else
  55       assert_in_delta(timestamp, log.event_at, 1, "log timestamp mismatch")
  56     end
  57     assert_properties(old_props_test, event_type, props,
  58                       'old_etag', 'old_attributes')
  59     assert_properties(new_props_test, event_type, props,
  60                       'new_etag', 'new_attributes')
  61     ['old_attributes', 'new_attributes'].each do |logattr|
  62       next if !props[logattr]
  63       assert_match /"created_at":"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{9}Z"/, Oj.dump(props, mode: :compat)
  64     end
  65     yield props if block_given?
  66   end
  67
  68   def assert_logged_with_clean_properties(obj, event_type, excluded_attr)
  69     assert_logged(obj, event_type) do |props|
  70       ['old_attributes', 'new_attributes'].map do |logattr|
  71         attributes = props[logattr]
  72         next if attributes.nil?
  73         refute_includes(attributes, excluded_attr,
  74                         "log #{logattr} includes #{excluded_attr}")
  75       end
  76       yield props if block_given?
  77     end
  78   end
  79
  80   test "creating a user makes a log" do
  81     set_user_from_auth :admin_trustedclient
  82     u = User.new(first_name: "Log", last_name: "Test")
  83     u.save!
  84     assert_logged(u, :create) do |props|
  85       assert_equal(u.etag, props['new_etag'], "new user etag mismatch")
  86       assert_equal(u.first_name, props['new_attributes']['first_name'],
  87                    "new user first name mismatch")
  88       assert_equal(u.last_name, props['new_attributes']['last_name'],
  89                    "new user first name mismatch")
  90     end
  91   end
  92
  93   test "updating a virtual machine makes a log" do
  94     set_user_from_auth :admin_trustedclient
  95     vm = virtual_machines(:testvm)
  96     orig_etag = vm.etag
  97     vm.hostname = 'testvm.testshell'
  98     vm.save!
  99     assert_logged(vm, :update) do |props|
 100       assert_equal(orig_etag, props['old_etag'], "updated VM old etag mismatch")
 101       assert_equal(vm.etag, props['new_etag'], "updated VM new etag mismatch")
 102       assert_equal('testvm.shell', props['old_attributes']['hostname'],
 103                    "updated VM old name mismatch")
 104       assert_equal('testvm.testshell', props['new_attributes']['hostname'],
 105                    "updated VM new name mismatch")
 106     end
 107   end
 108
 109   test "old_attributes preserves values deep inside a hash" do
 110     set_user_from_auth :active
 111     it = collections(:collection_owned_by_active)
 112     clear_logs_about it
 113     it.properties = {'foo' => {'bar' => ['baz', 'qux', {'quux' => 'bleat'}]}}
 114     it.save!
 115     assert_logged it, :update
 116     it.properties['foo']['bar'][2]['quux'] = 'blert'
 117     it.save!
 118     assert_logged it, :update do |props|
 119       assert_equal 'bleat', props['old_attributes']['properties']['foo']['bar'][2]['quux']
 120       assert_equal 'blert', props['new_attributes']['properties']['foo']['bar'][2]['quux']
 121     end
 122   end
 123
 124   test "destroying an authorization makes a log" do
 125     set_user_from_auth :admin_trustedclient
 126     auth = api_client_authorizations(:spectator)
 127     orig_etag = auth.etag
 128     orig_attrs = auth.attributes
 129     orig_attrs.delete 'api_token'
 130     auth.destroy
 131     assert_logged(auth, :delete) do |props|
 132       assert_equal(orig_etag, props['old_etag'], "destroyed auth etag mismatch")
 133       assert_equal(orig_attrs, props['old_attributes'],
 134                    "destroyed auth attributes mismatch")
 135     end
 136   end
 137
 138   test "updating a group twice makes two logs" do
 139     set_user_from_auth :admin_trustedclient
 140     group = groups(:empty_lonely_group)
 141     name1 = group.name
 142     name2 = "#{name1} under test"
 143     group.name = name2
 144     group.save!
 145     assert_logged(group, :update) do |props|
 146       assert_equal(name1, props['old_attributes']['name'],
 147                    "group start name mismatch")
 148       assert_equal(name2, props['new_attributes']['name'],
 149                    "group updated name mismatch")
 150     end
 151     group.name = name1
 152     group.save!
 153     assert_logged(group, :update) do |props|
 154       assert_equal(name2, props['old_attributes']['name'],
 155                    "group pre-revert name mismatch")
 156       assert_equal(name1, props['new_attributes']['name'],
 157                    "group final name mismatch")
 158     end
 159   end
 160
 161   test "making a log doesn't get logged" do
 162     set_user_from_auth :active_trustedclient
 163     log = Log.new
 164     log.save!
 165     assert_equal(0, get_logs_about(log).size, "made a Log about a Log")
 166   end
 167
 168   test "non-admins can't modify or delete logs" do
 169     set_user_from_auth :active_trustedclient
 170     log = Log.new(summary: "immutable log test")
 171     assert_nothing_raised { log.save! }
 172     log.summary = "log mutation test should fail"
 173     assert_raise(ArvadosModel::PermissionDeniedError) { log.save! }
 174     assert_raise(ArvadosModel::PermissionDeniedError) { log.destroy }
 175   end
 176
 177   test "admins can modify and delete logs" do
 178     set_user_from_auth :admin_trustedclient
 179     log = Log.new(summary: "admin log mutation test")
 180     assert_nothing_raised { log.save! }
 181     log.summary = "admin mutated log test"
 182     assert_nothing_raised { log.save! }
 183     assert_nothing_raised { log.destroy }
 184   end
 185
 186   test "failure saving log causes failure saving object" do
 187     Log.class_eval do
 188       alias_method :_orig_validations, :perform_validations
 189       def perform_validations(options)
 190         false
 191       end
 192     end
 193     begin
 194       set_user_from_auth :active_trustedclient
 195       user = users(:active)
 196       user.first_name = 'Test'
 197       assert_raise(ActiveRecord::RecordInvalid) { user.save! }
 198     ensure
 199       Log.class_eval do
 200         alias_method :perform_validations, :_orig_validations
 201       end
 202     end
 203   end
 204
 205   test "don't log changes only to ApiClientAuthorization.last_used_*" do
 206     set_user_from_auth :admin_trustedclient
 207     auth = api_client_authorizations(:spectator)
 208     start_log_count = get_logs_about(auth).size
 209     auth.last_used_at = Time.now
 210     auth.last_used_by_ip_address = '::1'
 211     auth.save!
 212     assert_equal(start_log_count, get_logs_about(auth).size,
 213                  "log count changed after 'using' ApiClientAuthorization")
 214     auth.created_by_ip_address = '::1'
 215     auth.save!
 216     assert_logged(auth, :update)
 217   end
 218
 219   test "don't log changes only to Collection.preserve_version" do
 220     set_user_from_auth :admin_trustedclient
 221     col = collections(:collection_owned_by_active)
 222     clear_logs_about col
 223     start_log_count = get_logs_about(col).size
 224     assert_equal false, col.preserve_version
 225     col.preserve_version = true
 226     col.save!
 227     assert_equal(start_log_count, get_logs_about(col).size,
 228                  "log count changed after updating Collection.preserve_version")
 229     col.name = 'updated by admin'
 230     col.save!
 231     assert_logged(col, :update)
 232   end
 233
 234   test "token isn't included in ApiClientAuthorization logs" do
 235     set_user_from_auth :admin_trustedclient
 236     auth = ApiClientAuthorization.new
 237     auth.user = users(:spectator)
 238     auth.save!
 239     assert_logged_with_clean_properties(auth, :create, 'api_token')
 240     auth.expires_at = Time.now
 241     auth.save!
 242     assert_logged_with_clean_properties(auth, :update, 'api_token')
 243     auth.destroy
 244     assert_logged_with_clean_properties(auth, :delete, 'api_token')
 245   end
 246
 247   test "use ownership and permission links to determine which logs a user can see" do
 248     known_logs = [:noop,
 249                   :admin_changes_collection_owned_by_active,
 250                   :admin_changes_collection_owned_by_foo,
 251                   :system_adds_foo_file,
 252                   :system_adds_baz,
 253                   :log_owned_by_active,
 254                   :crunchstat_for_running_container]
 255
 256     c = Log.readable_by(users(:admin)).order("id asc").each.to_a
 257     assert_log_result c, known_logs, known_logs
 258
 259     c = Log.readable_by(users(:active)).order("id asc").each.to_a
 260     assert_log_result c, known_logs, [:admin_changes_collection_owned_by_active,
 261                                       :system_adds_foo_file,             # readable via link
 262                                       :system_adds_baz,                  # readable via 'all users' group
 263                                       :log_owned_by_active,              # log owned by active
 264                                       :crunchstat_for_running_container] # log & job owned by active
 265
 266     c = Log.readable_by(users(:spectator)).order("id asc").each.to_a
 267     assert_log_result c, known_logs, [:noop,                             # object_uuid is spectator
 268                                       :system_adds_baz]                  # readable via 'all users' group
 269
 270     c = Log.readable_by(users(:user_foo_in_sharing_group)).order("id asc").each.to_a
 271     assert_log_result c, known_logs, [:admin_changes_collection_owned_by_foo] # collection's parent is readable via role group
 272   end
 273
 274   def assert_log_result result, known_logs, expected_logs
 275     # All of expected_logs must appear in result. Additional logs can
 276     # appear too, but only if they are _not_ listed in known_logs
 277     # (i.e., we do not make any assertions about logs not mentioned in
 278     # either "known" or "expected".)
 279     result_ids = result.collect(&:id)
 280     expected_logs.each do |want|
 281       assert_includes result_ids, logs(want).id
 282     end
 283     (known_logs - expected_logs).each do |notwant|
 284       refute_includes result_ids, logs(notwant).id
 285     end
 286   end
 287
 288   test "non-empty configuration.unlogged_attributes" do
 289     Rails.configuration.AuditLogs.UnloggedAttributes = ConfigLoader.to_OrderedOptions({"manifest_text"=>{}})
 290     txt = ". acbd18db4cc2f85cedef654fccc4a4d8+3 0:3:foo\n"
 291
 292     act_as_system_user do
 293       coll = Collection.create(manifest_text: txt)
 294       assert_logged_with_clean_properties(coll, :create, 'manifest_text')
 295       coll.name = "testing"
 296       coll.save!
 297       assert_logged_with_clean_properties(coll, :update, 'manifest_text')
 298       coll.destroy
 299       assert_logged_with_clean_properties(coll, :delete, 'manifest_text')
 300     end
 301   end
 302
 303   test "empty configuration.unlogged_attributes" do
 304     Rails.configuration.AuditLogs.UnloggedAttributes = ConfigLoader.to_OrderedOptions({})
 305     txt = ". acbd18db4cc2f85cedef654fccc4a4d8+3 0:3:foo\n"
 306
 307     act_as_system_user do
 308       coll = Collection.create(manifest_text: txt)
 309       assert_logged(coll, :create) do |props|
 310         assert_equal(txt, props['new_attributes']['manifest_text'])
 311       end
 312       coll.update!(name: "testing")
 313       assert_logged(coll, :update) do |props|
 314         assert_equal(txt, props['old_attributes']['manifest_text'])
 315         assert_equal(txt, props['new_attributes']['manifest_text'])
 316       end
 317       coll.destroy
 318       assert_logged(coll, :delete) do |props|
 319         assert_equal(txt, props['old_attributes']['manifest_text'])
 320       end
 321     end
 322   end
 323
 324   def assert_no_logs_deleted
 325     logs_before = Log.unscoped.all.count
 326     assert logs_before > 0
 327     yield
 328     assert_equal logs_before, Log.unscoped.all.count
 329   end
 330
 331   def remaining_audit_logs
 332     Log.unscoped.where('event_type in (?)', %w(create update destroy delete))
 333   end
 334
 335   # Default settings should not delete anything -- some sites rely on
 336   # the original "keep everything forever" behavior.
 337   test 'retain old audit logs with default settings' do
 338     assert_no_logs_deleted do
 339       AuditLogs.delete_old(
 340         max_age: Rails.configuration.AuditLogs.MaxAge,
 341         max_batch: Rails.configuration.AuditLogs.MaxDeleteBatch)
 342     end
 343   end
 344
 345   # Batch size 0 should retain all logs -- even if max_age is very
 346   # short, and even if the default settings (and associated test) have
 347   # changed.
 348   test 'retain old audit logs with max_audit_log_delete_batch=0' do
 349     assert_no_logs_deleted do
 350       AuditLogs.delete_old(max_age: 1, max_batch: 0)
 351     end
 352   end
 353
 354   # We recommend a more conservative age of 5 minutes for production,
 355   # but 3 minutes suits our test data better (and is test-worthy in
 356   # that it's expected to work correctly in production).
 357   test 'delete old audit logs with production settings' do
 358     initial_log_count = remaining_audit_logs.count
 359     assert initial_log_count > 0
 360     AuditLogs.delete_old(max_age: 180, max_batch: 100000)
 361     assert_operator remaining_audit_logs.count, :<, initial_log_count
 362   end
 363
 364   test 'delete all audit logs in multiple batches' do
 365     assert remaining_audit_logs.count > 2
 366     AuditLogs.delete_old(max_age: 0.00001, max_batch: 2)
 367     assert_equal [], remaining_audit_logs.collect(&:uuid)
 368   end
 369
 370   test 'delete old audit logs in thread' do
 371     Rails.configuration.AuditLogs.MaxAge = 20
 372     Rails.configuration.AuditLogs.MaxDeleteBatch = 100000
 373     Rails.cache.delete 'AuditLogs'
 374     initial_audit_log_count = remaining_audit_logs.count
 375     assert initial_audit_log_count > 0
 376     act_as_system_user do
 377       Log.create!()
 378     end
 379     deadline = Time.now + 10
 380     while remaining_audit_logs.count == initial_audit_log_count
 381       if Time.now > deadline
 382         raise "timed out"
 383       end
 384       sleep 0.1
 385     end
 386     assert_operator remaining_audit_logs.count, :<, initial_audit_log_count
 387   end
 388 end