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