Merge branch 'master' into 14873-api-rails5-upgrade
[arvados.git] / 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