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