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 "token isn't included in ApiClientAuthorization logs" do
 232     set_user_from_auth :admin_trustedclient
 233     auth = ApiClientAuthorization.new
 234     auth.user = users(:spectator)
 235     auth.api_client = api_clients(:untrusted)
 236     auth.save!
 237     assert_logged_with_clean_properties(auth, :create, 'api_token')
 238     auth.expires_at = Time.now
 239     auth.save!
 240     assert_logged_with_clean_properties(auth, :update, 'api_token')
 241     auth.destroy
 242     assert_logged_with_clean_properties(auth, :delete, 'api_token')
 243   end
 244
 245   test "use ownership and permission links to determine which logs a user can see" do
 246     known_logs = [:noop,
 247                   :admin_changes_repository2,
 248                   :admin_changes_specimen,
 249                   :system_adds_foo_file,
 250                   :system_adds_baz,
 251                   :log_owned_by_active,
 252                   :crunchstat_for_running_job]
 253
 254     c = Log.readable_by(users(:admin)).order("id asc").each.to_a
 255     assert_log_result c, known_logs, known_logs
 256
 257     c = Log.readable_by(users(:active)).order("id asc").each.to_a
 258     assert_log_result c, known_logs, [:admin_changes_repository2, # owned by active
 259                                       :system_adds_foo_file,      # readable via link
 260                                       :system_adds_baz,           # readable via 'all users' group
 261                                       :log_owned_by_active,       # log owned by active
 262                                       :crunchstat_for_running_job] # log & job owned by active
 263
 264     c = Log.readable_by(users(:spectator)).order("id asc").each.to_a
 265     assert_log_result c, known_logs, [:noop,                   # object_uuid is spectator
 266                                       :admin_changes_specimen, # object_uuid is a specimen owned by spectator
 267                                       :system_adds_baz] # readable via 'all users' group
 268   end
 269
 270   def assert_log_result result, known_logs, expected_logs
 271     # All of expected_logs must appear in result. Additional logs can
 272     # appear too, but only if they are _not_ listed in known_logs
 273     # (i.e., we do not make any assertions about logs not mentioned in
 274     # either "known" or "expected".)
 275     result_ids = result.collect(&:id)
 276     expected_logs.each do |want|
 277       assert_includes result_ids, logs(want).id
 278     end
 279     (known_logs - expected_logs).each do |notwant|
 280       refute_includes result_ids, logs(notwant).id
 281     end
 282   end
 283
 284   test "non-empty configuration.unlogged_attributes" do
 285     Rails.configuration.unlogged_attributes = ["manifest_text"]
 286     txt = ". acbd18db4cc2f85cedef654fccc4a4d8+3 0:3:foo\n"
 287
 288     act_as_system_user do
 289       coll = Collection.create(manifest_text: txt)
 290       assert_logged_with_clean_properties(coll, :create, 'manifest_text')
 291       coll.name = "testing"
 292       coll.save!
 293       assert_logged_with_clean_properties(coll, :update, 'manifest_text')
 294       coll.destroy
 295       assert_logged_with_clean_properties(coll, :delete, 'manifest_text')
 296     end
 297   end
 298
 299   test "empty configuration.unlogged_attributes" do
 300     Rails.configuration.unlogged_attributes = []
 301     txt = ". acbd18db4cc2f85cedef654fccc4a4d8+3 0:3:foo\n"
 302
 303     act_as_system_user do
 304       coll = Collection.create(manifest_text: txt)
 305       assert_logged(coll, :create) do |props|
 306         assert_equal(txt, props['new_attributes']['manifest_text'])
 307       end
 308       coll.update_attributes!(name: "testing")
 309       assert_logged(coll, :update) do |props|
 310         assert_equal(txt, props['old_attributes']['manifest_text'])
 311         assert_equal(txt, props['new_attributes']['manifest_text'])
 312       end
 313       coll.destroy
 314       assert_logged(coll, :delete) do |props|
 315         assert_equal(txt, props['old_attributes']['manifest_text'])
 316       end
 317     end
 318   end
 319
 320   def assert_no_logs_deleted
 321     logs_before = Log.unscoped.all.count
 322     yield
 323     assert_equal logs_before, Log.unscoped.all.count
 324   end
 325
 326   def remaining_audit_logs
 327     Log.unscoped.where('event_type in (?)', %w(create update destroy delete))
 328   end
 329
 330   # Default settings should not delete anything -- some sites rely on
 331   # the original "keep everything forever" behavior.
 332   test 'retain old audit logs with default settings' do
 333     assert_no_logs_deleted do
 334       AuditLogs.delete_old(
 335         max_age: Rails.configuration.max_audit_log_age,
 336         max_batch: Rails.configuration.max_audit_log_delete_batch)
 337     end
 338   end
 339
 340   # Batch size 0 should retain all logs -- even if max_age is very
 341   # short, and even if the default settings (and associated test) have
 342   # changed.
 343   test 'retain old audit logs with max_audit_log_delete_batch=0' do
 344     assert_no_logs_deleted do
 345       AuditLogs.delete_old(max_age: 1, max_batch: 0)
 346     end
 347   end
 348
 349   # We recommend a more conservative age of 5 minutes for production,
 350   # but 3 minutes suits our test data better (and is test-worthy in
 351   # that it's expected to work correctly in production).
 352   test 'delete old audit logs with production settings' do
 353     initial_log_count = Log.unscoped.all.count
 354     AuditLogs.delete_old(max_age: 180, max_batch: 100000)
 355     assert_operator remaining_audit_logs.count, :<, initial_log_count
 356   end
 357
 358   test 'delete all audit logs in multiple batches' do
 359     AuditLogs.delete_old(max_age: 0.00001, max_batch: 2)
 360     assert_equal [], remaining_audit_logs.collect(&:uuid)
 361   end
 362
 363   test 'delete old audit logs in thread' do
 364     begin
 365       Rails.configuration.max_audit_log_age = 20
 366       Rails.configuration.max_audit_log_delete_batch = 100000
 367       Rails.cache.delete 'AuditLogs'
 368       initial_log_count = Log.unscoped.all.count + 1
 369       act_as_system_user do
 370         Log.create!()
 371         initial_log_count += 1
 372       end
 373       deadline = Time.now + 10
 374       while remaining_audit_logs.count == initial_log_count
 375         if Time.now > deadline
 376           raise "timed out"
 377         end
 378         sleep 0.1
 379       end
 380       assert_operator remaining_audit_logs.count, :<, initial_log_count
 381     ensure
 382       # The test framework rolls back our transactions, but that
 383       # doesn't undo the deletes we did from separate threads.
 384       ActiveRecord::Base.connection.exec_query 'ROLLBACK'
 385       Thread.new do
 386         begin
 387           dc = DatabaseController.new
 388           dc.define_singleton_method :render do |*args| end
 389           dc.reset
 390         ensure
 391           ActiveRecord::Base.connection.close
 392         end
 393       end.join
 394     end
 395   end
 396 end