Move event log recording in UpdateUser service into callbacks on User model #2623

floehopper · 2024-01-04T16:14:13Z

The new Current class inherits from ActiveSupport::CurrentAttributes which means that its singleton attribute accessors are "thread-isolated". This means that we can set Current.user & Current.user_ip in a new before_action in ApplicationController and then make use of them in model code without needing access to a controller.

I've used this change to simplify calls to EventLog methods and move a bunch of functionality in UserUpdate#call into model callbacks. I think we could take this further, but I wanted to get these changes merged now that I'm reasonably confident this is a sensible approach.

Further work

Currently not all calls to EventLog.record_event require the initiating user or the user's IP address. This means that currently we have to pass initiator: true and/or ip_address: true options. I strongly suspect the reason why some calls don't require the initiating user or the user's IP address is because it was awkward/impossible to obtain them at the callsite. However, now that they are available from the Current model, it would simplify the code a lot if we just always recorded them. And I can't see why this would be a bad idea.
There is other functionality in UserUpdate#call (e.g. sending of email notifications) that could me moved to callbacks on the User model. This would simplify UserUpdate#call and ultimately make it redundant. And I think it would make the code a lot more resilient, because developers wouldn't need to keep remembering to use UserUpdate whenever they need to make a change to a user. There are already places where this has been missed. Also UserUpdate is the only "service" in the app, so it's a bit of an outlier and it would be good to make the code more idiomatic.
Similarly there are probably calls to EventLog.record_event or sending of email notifications in controllers which could move into callbacks on other models.

chrislo

This looks great 👍

test/services/user_update_test.rb

floehopper · 2024-01-08T16:23:26Z

@chrisroos Has identified some possible flaws in this which need investigating before this is merged:

What happens when current_user (provided by Devise) changes in the middle of a request, e.g. signing in, signing out, etc. Maybe there are some Devise hooks we could use to keep Current.user up-to-date...?
What happens when a non-web process (e.g.Sidekiq worker, Rake task, Rails console, etc) triggers an event without setting Current.user? This might explain why some of the events don't require an initiator.

floehopper · 2024-01-09T15:49:26Z

What happens when current_user (provided by Devise) changes in the middle of a request, e.g. signing in, signing out, etc. Maybe there are some Devise hooks we could use to keep Current.user up-to-date...?

I think we might be able to use Warden::Hooks#after_set_user to cope with this...?

cc @chrisroos

The `Current` class inherits from `ActiveSupport::CurrentAttributes` [1] which means that its singleton attribute accessors are "thread-isolated". This means that we can set them in a new `before_action` in `ApplicationController` and then make use of them in model code without needing access to a controller. I'm hoping to use this to simplify calls to `EventLog` methods and ultimately move a bunch of functionality in `UserUpdate#call` into model callbacks. [1]: https://api.rubyonrails.org/v7.0.8/classes/ActiveSupport/CurrentAttributes.html

floehopper · 2024-02-20T15:58:27Z

@chrisroos

What happens when current_user (provided by Devise) changes in the middle of a request, e.g. signing in, signing out, etc. Maybe there are some Devise hooks we could use to keep Current.user up-to-date...?

I've attempted to address this in 32ad5d5. Let me know what you think.

chrisroos · 2024-02-21T11:08:55Z

test/lib/data_hygiene/bulk_organisation_updater_test.rb

@@ -7,7 +7,9 @@ def process(csv_file)
    file.close

    begin
-      DataHygiene::BulkOrganisationUpdater.call(file.path, logger: Rails.logger)
+      with_current(user: create(:admin_user)) do
+        DataHygiene::BulkOrganisationUpdater.call(file.path, logger: Rails.logger)


Does this imply that we need to set Current.user in the data_hygiene:bulk_update_organisation Rake task too? I think it does otherwise the behaviour of EventLog.record_email_change will be slightly different after this change (it'll record an EMAIL_CHANGED event instead of an EMAIL_CHANGE_INITIATED event).

Good catch. Although the original implementation seems a bit weird. I wonder if it would be clearer to have two methods on EventLog: one for recording an EMAIL_CHANGED event and one for recording an EMAIL_CHANGE_INITIATED event...? What do you think...?

Separately, I've been experimenting with setting Current.user to a sensible value for rake tasks, use of the rails console, and for background jobs. I wonder if this might be a better way to solve this problem (because Current.user would then always be set.

chrisroos · 2024-02-21T12:39:33Z

test/services/user_update_test.rb

@@ -7,6 +7,7 @@ class UserUpdateTest < ActionView::TestCase
  setup do
    @current_user = create(:superadmin_user)
    @affected_user = create(:user)
+    @affected_user.name = "different-name"


Is this necessary to get past the return if previous_changes.none? clause?

Yes, I think that's probably correct. Do you think I should do something to make that clearer?

chrisroos · 2024-02-21T12:42:12Z

app/models/user.rb

@@ -463,4 +464,11 @@ def strip_whitespace_from_name
  def update_password_changed
    self.password_changed_at = Time.current if (new_record? || encrypted_password_changed?) && !password_changed_at_changed?
  end
+
+  def record_update


Did you consider adding unit tests for this method? Or is the behaviour (particularly the guard clauses) tested elsewhere?

I think at this point I was relying on the unit test(s) in UserUpdateTest. However, it might well make sense to move those to UserTest in this commit (or possibly a subsequent commit).

chrisroos · 2024-02-21T12:42:48Z

app/models/user.rb

@@ -471,4 +472,11 @@ def record_update

    EventLog.record_event(self, EventLog::ACCOUNT_UPDATED, initiator: true, ip_address: true)
  end
+
+  def record_role_change


As with User#record_update, I wonder whether it's worth adding unit tests for this method?

Agreed 👍

chrisroos · 2024-02-21T12:46:21Z

app/models/user.rb

+
+  def record_organisation_change
+    return if Current.user.blank?
+    return unless organisation_id_previously_changed?


Out of interest, what's the difference between #organisation_id_previously_changed? and #organisation_id_changed??

Out of interest, what's the difference between #organisation_id_previously_changed? and #organisation_id_changed??

From what I remember, the former includes changes that have been persisted but the latter does not. Since User#record_orgnisation_change is being called in an after_update callback, we need the version which includes changes that have been persisted. I'm afraid I can't remember why I used an after_update callback rather than a before_update callback!

Following up on this, it looks as if I may have followed the precedent set by UserUpdate#call which seems to persist the changes first and only then record the various events.

chrisroos · 2024-02-21T12:49:29Z

app/models/user.rb

+
+    organisations = organisation_id_previous_change.map do |organisation_id|
+      Organisation.find_by(id: organisation_id)&.name || Organisation::NONE
+    end


I found this slightly confusing as I had to look up that #organisation_id_previous_change returned an array of the from and to values, and also that the variable is named organisations but it holds an array of organisation names.

I agree that this could be made clearer 👍

chrisroos · 2024-02-21T12:52:37Z

app/models/user.rb

+
+  def record_2sv_mandated
+    return if Current.user.blank?
+    return unless require_2sv && require_2sv_previously_changed?


I know that you've copied this from the previous implementation in UserUpdate#record_2sv_mandated but I do wonder whether this should be using User#require_2sv? instead of #require_2sv.

Confusingly, it looks as if User#require_2sv? is not simply a reflection of the value in the users.require_2sv column, but rather it includes some other logic involving an organisation setting and any exemption. So I don't think we should use User#require_2sv? here.

Having said all that, it feels as if we should change the name of User#require_2sv? or the underlying column to make things more idiomatic and less surprising.

I think this makes the tests more robust. Also it'll make some upcoming changes easier.

Unfortunately a bunch of the tests were relying on the `initiator` defaulting to the user being updated, so for the moment I've replicated that in the new implementation of `EventLog.record_email_change`. However, I plan to remove that in a subsequent commit.

Now that we're using `Current.user` to obtain the `initiator`, there's no need for the default - `Current.user` should always be set. This means we have to explicitly set `Current.user` in some tests to avoid validation errors due to `EventLog#initiator_id` being missing.

Previously I found it confusing that the `previous_organisation` & `new_organisation` arguments were actually the names of the organisations rather than the organisations themselves. Renaming them to `previous_organisation_name` & `new_organisation_name` respectively makes things less confusing.

The `ip_address` option for this method is optional and not all callsites were setting it. This means we only record the current user's IP address in some cases. To this end I've repurposed the `ip_address` option to be a boolean value indicating whether or not we want to record the user's IP address.

The `initiator` option for this method is optional and not all callsites were setting it. This means we only record the initiating user in some cases. To this end I've repurposed the `initiator` option to be a boolean value indicating whether or not we want to record the initiating user.

This is now called *automatically* via an `after_update` callback which means it's called more reliably and more frequently than `UserUpdate#record_update` was called. The `ActiveModel::Dirty#previous_changes` guard condition avoids recording events when none of the user's attributes have changed which would be pretty pointless. The `Current.user` guard condition is necessary, because `LogEvent::ACCOUNT_UPDATED` has `require_initiator` set to true and so would trigger a validation error if `Current.user` was not set. I've had to add a few stubs for extra `LogEvent::ACCOUNT_UPDATED` event log records which reflect a slight change in behaviour. However, I don't think these extra even log records are necessarily a bad thing! The advantage of recording the event in a callback like this is that we don't need to remember to use `UserUpdate#call` to make any changes to a user. This in turn means that we will now be recording events when an API user's attributes are updated. which we weren't previously because the `ApiUsersController` wasn't calling `UserUpdate#call`.

This is now called *automatically* via an `after_update` callback which means it's called more reliably than `UserUpdate#record_role_change` was called. I've changed the implementation very slightly to make use of other magic methods provided by `ActiveModel::Dirty#previous_changes`. I don't believe any of these changes will have changed the behaviour. The `Current.user` guard condition is necessary, because `LogEvent::ROLE_CHANGED` has `require_initiator` set to true and so would trigger a validation error if `Current.user` was not set. The advantage of recording the event in a callback like this is that we don't need to remember to use `UserUpdate#call` to make any changes to a user and we may now catch some places where a user's role was being updated but no event was being recorded.

This is now called *automatically* via an `after_update` callback which means it's called more reliably than `UserUpdate#record_organisation_change` was called. I've changed the implementation very slightly to make use of other magic methods provided by `ActiveModel::Dirty#previous_changes`. I don't believe any of these changes will have changed the behaviour. The `Current.user` guard condition is necessary, because `LogEvent::ORGANISATION_CHANGED` has `require_initiator` set to true and so would trigger a validation error if `Current.user` was not set. The advantage of recording the event in a callback like this is that we don't need to remember to use `UserUpdate#call` to make any changes to a user and we may now catch some places where a user's organisation was being updated but no event was being recorded.

This is now called *automatically* via an `after_update` callback which means it's called more reliably than `UserUpdate#record_2sv_exemption_removed` was called. I've changed the implementation very slightly to make use of other magic methods provided by `ActiveModel::Dirty#previous_changes`. I don't believe any of these changes will have changed the behaviour. The `Current.user` guard condition is necessary, because `LogEvent::TWO_STEP_EXEMPTION_REMOVED` has `require_initiator` set to true and so would trigger a validation error if `Current.user` was not set. The advantage of recording the event in a callback like this is that we don't need to remember to use `UserUpdate#call` to make any changes to a user and we may now catch some places where a user's 2SV was being removed but no event was being recorded.

This is now called *automatically* via an `after_update` callback which means it's called more reliably than `UserUpdate#record_2sv_mandated` was called. I've changed the implementation very slightly to make use of other magic methods provided by `ActiveModel::Dirty#previous_changes`. I don't believe any of these changes will have changed the behaviour. The `Current.user` guard condition is necessary, because `LogEvent::TWO_STEP_MANDATED` has `require_initiator` set to true and so would trigger a validation error if `Current.user` was not set. The advantage of recording the event in a callback like this is that we don't need to remember to use `UserUpdate#call` to make any changes to a user and we may now catch some places where 2SV was being mandated for a user but no event was being recorded.

Previously, if a user was signed in or out in the *middle* of an action, the value of `Current.user` was not updated. This makes use of `Warden::Manager.after_set_user` [1] and `Warden::Manager.before_logout` [2] hooks to update `Current.user`. I'm using `Devise::Controllers::SignInOut#sign_in` [3] & `Devise::Controllers::SignInOut#sign_out` within the tests, because I believe that's what you're supposed to use when using `Devise` and indeed it looks like that's what we're using in e.g. `ConfirmationsController`, `Devise::TwoStepVerificationController` & `Devise::TwoStepVerificationSessionController`. I've added the `Warden::Manager` hooks within `Devise::Hooks::SetCurrentUser` and required it from the top of `app/controllers/application_controller.rb` to be consistent what we're already doing with `Devise::Hooks::TwoStepVerification`, although it seems a bit odd/non-idiomatic to execute some code via a call to `require`. Also it strikes me as slightly odd that the hooks are in a top-level `Devise` module despite being associated with `Warden`, although I suppose `Warden` is only there because it's a dependency of `Devise`. [1]: https://www.rubydoc.info/gems/warden/1.2.9/Warden/Hooks#after_set_user-instance_method [2]: https://www.rubydoc.info/gems/warden/1.2.9/Warden/Hooks#before_logout-instance_method [3]: https://www.rubydoc.info/github/plataformatec/devise/Devise%2FControllers%2FSignInOut:sign_in [4]: https://www.rubydoc.info/github/plataformatec/devise/Devise%2FControllers%2FSignInOut:sign_out

I'm planning to create a bunch of "reference" users like this and it seems clearer to make them class methods on `ApiUser`.

TODO: * Ensure that `Current.user` is being set in the same thread that the job's `#perform` method is called in. * Add tests

TODO: * Add tests

floehopper · 2024-02-21T17:39:31Z

@chrisroos

What happens when a non-web process (e.g.Sidekiq worker, Rake task, Rails console, etc) triggers an event without setting Current.user? This might explain why some of the events don't require an initiator.

I'm assuming that most/all of the calls to EventLog methods from non-web processes were not previously specifying a current user to record against the event. However, given that I'm a bit uncertain about this and in any case it might be nice to have separate users for these scenarios, I've spiked on setting Current.user for all background jobs, any Rails console, and relevant Rake tasks in the following commits:

floehopper · 2024-02-21T17:43:56Z

While I still think this is a sensible idea, having discussed the PR with @chrisroos today, I've decided that I'm not going to have enough time before I finish this week to get this into a state where the risk of causing a problem is sufficiently low to justify the benefits of the change, especially given that a bunch of the stuff mentioned in the "Further work" section of the PR description would also need to be done to really see all the benefits. So I'm going to close the PR and hope that someone has the time to come back to it at some point the in the future! 😅

cc @chrislo @JonathanHallam @jkempster34

floehopper mentioned this pull request Jan 4, 2024

Move UpdateUser methods into after_update callbacks on User #2582

Closed

floehopper force-pushed the move-event-log-recording-in-update-user-service-into-callbacks-on-user-model branch from f0eb17a to 76c4a55 Compare January 4, 2024 16:31

floehopper marked this pull request as ready for review January 4, 2024 16:59

floehopper requested review from chrisroos and chrislo January 4, 2024 16:59

chrislo approved these changes Jan 8, 2024

View reviewed changes

test/services/user_update_test.rb Outdated Show resolved Hide resolved

chrislo mentioned this pull request Jan 23, 2024

Refactor build user update params #2657

Merged

floehopper force-pushed the move-event-log-recording-in-update-user-service-into-callbacks-on-user-model branch from 76c4a55 to 53b540e Compare February 20, 2024 12:27

chrisroos reviewed Feb 21, 2024

View reviewed changes

floehopper force-pushed the move-event-log-recording-in-update-user-service-into-callbacks-on-user-model branch from 32ad5d5 to 7439bb7 Compare February 21, 2024 16:58

floehopper added 16 commits February 21, 2024 17:19

Simplify UserUpdate#initialize using methods on Current

d6b6648

Make with_current method available in all tests

19af8bc

Query db vs use return value in EventLog.record_email_change tests

9bb9b7a

I think this makes the tests more robust. Also it'll make some upcoming changes easier.

Simplify EventLog.record_role_change using methods on Current

1ec6bb4

Add test coverage for EventLog.record_organisation_change

7ac20a3

Simplify EventLog.record_organisation_change using methods on Current

c1b3865

Simplify EventLog.record_account_invitation using methods on Current

1a7e487

Use Current.user in User#reset_2sv!

a364d73

floehopper added 3 commits February 21, 2024 17:20

floehopper force-pushed the move-event-log-recording-in-update-user-service-into-callbacks-on-user-model branch from 7439bb7 to 9114bdb Compare February 21, 2024 17:20

floehopper added 4 commits February 21, 2024 17:23

Extract ApiUser#for_sso_push method

5506f4f

I'm planning to create a bunch of "reference" users like this and it seems clearer to make them class methods on `ApiUser`.

WIP: Set Current.user for all background jobs

4217150

TODO: * Ensure that `Current.user` is being set in the same thread that the job's `#perform` method is called in. * Add tests

WIP: Set Current.user in a Rails console

63db798

TODO: * Add tests

WIP: Set Current.user in application Rake tasks

c5cf7b3

TODO: * Add tests

floehopper closed this Feb 21, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Move event log recording in UpdateUser service into callbacks on User model #2623

Move event log recording in UpdateUser service into callbacks on User model #2623

floehopper commented Jan 4, 2024 •

edited

Loading

chrislo left a comment

floehopper commented Jan 8, 2024

floehopper commented Jan 9, 2024 •

edited

Loading

floehopper commented Feb 20, 2024

chrisroos Feb 21, 2024

floehopper Feb 21, 2024

chrisroos Feb 21, 2024 •

edited

Loading

floehopper Feb 21, 2024 •

edited

Loading

chrisroos Feb 21, 2024

floehopper Feb 21, 2024

chrisroos Feb 21, 2024

floehopper Feb 21, 2024

chrisroos Feb 21, 2024

floehopper Feb 21, 2024

floehopper Feb 21, 2024

chrisroos Feb 21, 2024

floehopper Feb 21, 2024

chrisroos Feb 21, 2024

floehopper Feb 21, 2024

floehopper commented Feb 21, 2024

floehopper commented Feb 21, 2024

Move event log recording in UpdateUser service into callbacks on User model #2623

Move event log recording in UpdateUser service into callbacks on User model #2623

Conversation

floehopper commented Jan 4, 2024 • edited Loading

Further work

chrislo left a comment

Choose a reason for hiding this comment

floehopper commented Jan 8, 2024

floehopper commented Jan 9, 2024 • edited Loading

floehopper commented Feb 20, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

chrisroos Feb 21, 2024 • edited Loading

Choose a reason for hiding this comment

floehopper Feb 21, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

floehopper commented Feb 21, 2024

floehopper commented Feb 21, 2024

floehopper commented Jan 4, 2024 •

edited

Loading

floehopper commented Jan 9, 2024 •

edited

Loading

chrisroos Feb 21, 2024 •

edited

Loading

floehopper Feb 21, 2024 •

edited

Loading