LG-13132 Adds property to SP redirect initiated event

[kevinsmaster5]

🎫 Ticket

Link to the relevant ticket:
LG-13132

🛠 Summary of changes

Creates a session variable when visiting Log in page. This differs from the session[:session_started_at] value because it gets revised upon returning to the Log in page. The latter exists to service other features like determining session expiration for example.
A duration between most recent visit to the Log in page and execution of SP redirect is calculated and passed along to AnalyticsEvents.

The purpose is to create an accurate account of the time it takes a user directly from signing in to conclusion at the SP. It will support a new Cloudwatch log dashboard widget.

📜 Testing Plan

Provide a checklist of steps to confirm the changes.

• In the local terminal run make watch_events
• Using either OIDC or SAML Sinatra log into the local instance, authenticate and proceed to the SP
• Check the log for presence of a sign_in_duration_in_seconds property that has a value that you expect
• Notice that if you leave the sign in page and come back to it before signing in the time differs from session_duration

I forgot my password which caused a 10 second delay recoreded in session_duration.

[zachmargolis]

1. if the session[:sign_in_page_visited_at] gets cleared or wiped, this will be zero because it's .now. What if we left it nil when is no session[:sign_in_page_visited_at] so that we can tell the difference between missing data and zero?

2. .to_i.round(2) is redundant, because integers can't be rounded. Is the goal to have 2 decimals of floating point precision?

[kevinsmaster5]

1. That's a good point. It might also be helpful to get an idea of how often someone is bouncing to a different browser so instead of the data showing a huge spike it will have some nil values to query against. 🤔

2. I didn't realize converting to integer already truncates https://dev.to/dawncronin/number-conversions-in-ruby-1ned#:~:text=Ruby%20has%20a%20built%20in,will%20round%20to%20two%20decimals. "the to_i conversion truncates the number,"

[zachmargolis]

this is defined outside of the concern aka it's making a method name at global scope, I don't think that']s what we want

[kevinsmaster5]

Definitely not! Good catch.

[zachmargolis]

another fun helper:

Suggested change

	session[:sign_in_page_visited_at] = (Time.zone.now - 2.minutes).to_s
	session[:sign_in_page_visited_at] = 2.minutes.ago.to_s

[zachmargolis]

I'm worried about clock skew contributing to flakey specs here, we probably want to freeze time with a specific time and specifically specify 120 seconds ago for the time

[kevinsmaster5]

Would that mean wrapping the expect() blocks like this?

diff --git a/spec/controllers/openid_connect/authorization_controller_spec.rb b/spec/controllers/openid_connect/authorization_controller_spec.rb
index 7b1ca74e73..fdc40c393d 100644
--- a/spec/controllers/openid_connect/authorization_controller_spec.rb
+++ b/spec/controllers/openid_connect/authorization_controller_spec.rb
@@ -142,15 +142,17 @@ RSpec.describe OpenidConnect::AuthorizationController, allowed_extra_analytics:
               user_sp_authorized: true,
               code_digest: kind_of(String),
             )
-            expect(@analytics).to have_logged_event(
-              'SP redirect initiated',
-              ial: 1,
-              billed_ial: 1,
-              sign_in_duration_seconds: 60,
-              sign_in_flow:,
-              acr_values: 'http://idmanagement.gov/ns/assurance/ial/1',
-              vtr: nil,
-            )
+            freeze_time do
+              expect(@analytics).to have_logged_event(
+                'SP redirect initiated',
+                ial: 1,
+                billed_ial: 1,
+                sign_in_duration_seconds: 60,
+                sign_in_flow:,
+                acr_values: 'http://idmanagement.gov/ns/assurance/ial/1',
+                vtr: nil,
+              )

Unrelated but I arbitrarily changed to 60 seconds trying something different.
session[:sign_in_page_visited_at] = 1.minute.ago.to_s

[zachmargolis]

freeze_time usually goes in an around or a before block

[aduth]

Can we add a spec/controllers/concerns/sign_in_duration_concern_spec.rb with test coverage?

[zachmargolis]

to make the time easier to track, I would consider using a let block to freeze a specific time

so like

let(:now) { Time.zone.now)

around do |ex|
  freeze_time(now) { ex.run }
end

...

it 'tracks events' do
  travel_to now + 15.seconds
  ...

[kevinsmaster5]

I see. I have added that as a let block and updated those tracked events. Thanks!

[aduth]

Non-blocking: I feel like it'd be nice to have a little bit of sub-second precision here, since I'd expect the typical value to be somewhat low where precision matters, especially if this is always rounding down. Alternatively we could seconds.round.

[kevinsmaster5]

I see. I have it goint .to_f now that seems to be more towards precision. What do you think?

[aduth]

Yeah I think that's better.

That also brings it a lot closer into alignment with the value for session_duration as well, which is nice.

[kevinsmaster5]

@aduth is that the correct way to get this in compliance?
This bubbled up when I rebased
https://gitlab.login.gov/lg/identity-idp/-/jobs/1197662

[aduth]

I think this might be an issue on main, possibly from someone else's changes.

[aduth]

I created a pull request at #10617 which fixes this in isolation, but tl;dr is yes this is the correct way to fix the issue, though I wouldn't expect you'd need it in your pull request. If your pull request is ready to go, feel free to merge those changes, but otherwise we can handle it in #10617 and rebase your branch with the fix on main.