services/api/test/unit/log_test.rb

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