LG-14380 Add profile_age_in_seconds to out-of-band verification eve…

…nts (#11186)

We are working to better measure the time it takes users to complete identity proofing. In #11179 we began logging how long it takes people to complete the identity proofing workflow.

This proofing workflow time only tells a part of the story. Many users have to complete out-of-band events to finish identity proofing. We need to know how long these workflows take to complete to fully understand how long identity proofing takes.

When a user finishes the proofing workflow we create a `Profile` record. This profile represents the proofing attempt and is in a “pending” state until the user completes those events. By logging the age of the pending profile we can determine how long it has been since the user finished the proofing workflow and thus how long they have been in a pending state.

This commit opts to log the age of the profile in seconds. This will simplify the creation of the Cloudwatch dashboard to represent this information since CloudWatch does not have good tooling for dealing with timestamps.

There are 3 out-of-band processes that can be required to complete proofing:

1. Verify-by-mail code entry
2. In-person proofing results
3. Fraud review pass

These are represented by the following events:

1.  `IdV: enter verify by mail code submitted`
2. `GetUspsProofingResultsJob: Enrollment status updated`
3. `Fraud: Profile review passed`

This commit adds a `profile_age_in_seconds` property to all of these events. To measure this a `profile_age_in_seconds` method was also added to the `Profile` model.

The `profile_age_in_seconds` property was also added to the `Fraud: Profile review rejected` events to maintain existing symmetry between arguments there.

app/forms/gpo_verify_form.rb

@@ -41,6 +41,7 @@ def submit(is_enhanced_ipp)
       success: result,
       errors: errors,
       extra: {
+        profile_age_in_seconds: pending_profile&.profile_age_in_seconds,
         enqueued_at: gpo_confirmation_code&.code_sent_at,
         which_letter: which_letter,
         letter_count: letter_count,

app/jobs/get_usps_proofing_results_job.rb

@@ -623,6 +623,7 @@ def log_enrollment_updated_analytics(enrollment:, enrollment_passed:, enrollment
       reason: reason,
       job_name: self.class.name,
       tmx_status: enrollment.profile&.tmx_status,
+      profile_age_in_seconds: enrollment.profile&.profile_age_in_seconds,
       enhanced_ipp: enrollment.enhanced_ipp?,
     )
   end

app/models/profile.rb

@@ -302,6 +302,10 @@ def self.build_compound_pii(pii)
     values.join(':')
   end
 
+  def profile_age_in_seconds
+    (Time.zone.now - created_at).round
+  end
+
   private
 
   def confirm_that_profile_can_be_activated!

app/services/analytics_events.rb

@@ -675,12 +675,14 @@ def forget_all_browsers_visited
   # @param [Hash] errors Errors resulting from form validation
   # @param [String] exception
   # @param [String] profile_fraud_review_pending_at
+  # @param [Integer] profile_age_in_seconds How many seconds have passed since profile created
   # The user was passed by manual fraud review
   def fraud_review_passed(
     success:,
     errors:,
     exception:,
     profile_fraud_review_pending_at:,
+    profile_age_in_seconds:,
     **extra
   )
     track_event(
@@ -689,6 +691,7 @@ def fraud_review_passed(
       errors: errors,
       exception: exception,
       profile_fraud_review_pending_at: profile_fraud_review_pending_at,
+      profile_age_in_seconds: profile_age_in_seconds,
       **extra,
     )
   end
@@ -697,12 +700,14 @@ def fraud_review_passed(
   # @param [Hash] errors Errors resulting from form validation
   # @param [String] exception
   # @param [String] profile_fraud_review_pending_at
+  # @param [Integer] profile_age_in_seconds How many seconds have passed since profile created
   # The user was rejected by manual fraud review
   def fraud_review_rejected(
     success:,
     errors:,
     exception:,
     profile_fraud_review_pending_at:,
+    profile_age_in_seconds:,
     **extra
   )
     track_event(
@@ -711,6 +716,7 @@ def fraud_review_rejected(
       errors: errors,
       exception: exception,
       profile_fraud_review_pending_at: profile_fraud_review_pending_at,
+      profile_age_in_seconds: profile_age_in_seconds,
       **extra,
     )
   end
@@ -2943,13 +2949,17 @@ def idv_in_person_usps_proofing_results_job_enrollment_incomplete(
   # @param [Boolean] fraud_suspected
   # @param [Boolean] passed did this enrollment pass or fail?
   # @param [String] reason why did this enrollment pass or fail?
+  # @param [String] tmx_status the tmx_status of the enrollment profile profile
+  # @param [Integer] profile_age_in_seconds How many seconds have passed since profile created
   def idv_in_person_usps_proofing_results_job_enrollment_updated(
     enrollment_code:,
     enrollment_id:,
     minutes_since_established:,
     fraud_suspected:,
     passed:,
     reason:,
+    tmx_status:,
+    profile_age_in_seconds:,
     **extra
   )
     track_event(
@@ -2960,6 +2970,8 @@ def idv_in_person_usps_proofing_results_job_enrollment_updated(
       fraud_suspected: fraud_suspected,
       passed: passed,
       reason: reason,
+      tmx_status: tmx_status,
+      profile_age_in_seconds: profile_age_in_seconds,
       **extra,
     )
   end
@@ -4306,6 +4318,7 @@ def idv_usps_auth_token_refresh_job_started(**extra)
   # @param [DateTime] enqueued_at When was this letter enqueued
   # @param [Integer] which_letter Sorted by enqueue time, which letter had this code
   # @param [Integer] letter_count How many letters did the user enqueue for this profile
+  # @param [Integer] profile_age_in_seconds How many seconds have passed since profile created
   # @param [Integer] submit_attempts Number of attempts to enter a correct code
   #                  (previously called "attempts")
   # @param [Boolean] pending_in_person_enrollment
@@ -4319,6 +4332,7 @@ def idv_verify_by_mail_enter_code_submitted(
     enqueued_at:,
     which_letter:,
     letter_count:,
+    profile_age_in_seconds:,
     submit_attempts:,
     pending_in_person_enrollment:,
     fraud_check_failed:,
@@ -4333,6 +4347,7 @@ def idv_verify_by_mail_enter_code_submitted(
       enqueued_at:,
       which_letter:,
       letter_count:,
+      profile_age_in_seconds:,
       submit_attempts:,
       pending_in_person_enrollment:,
       fraud_check_failed:,

lib/action_account.rb

@@ -187,6 +187,7 @@ def run(args:, config:)
         elsif FraudReviewChecker.new(user).fraud_review_eligible?
           profile = user.fraud_review_pending_profile
           profile_fraud_review_pending_at = profile.fraud_review_pending_at
+          profile_age_in_seconds = profile.profile_age_in_seconds
           profile.reject_for_fraud(notify_user: true)
           success = true
 
@@ -216,6 +217,7 @@ def run(args:, config:)
           errors: analytics_error_hash,
           exception: nil,
           profile_fraud_review_pending_at: profile_fraud_review_pending_at,
+          profile_age_in_seconds: profile_age_in_seconds,
         )
       end
 
@@ -236,6 +238,7 @@ def run(args:, config:)
           errors: { message: log_text[:missing_uuid] },
           exception: nil,
           profile_fraud_review_pending_at: nil,
+          profile_age_in_seconds: nil,
         )
       end
 
@@ -278,6 +281,7 @@ def run(args:, config:)
         elsif FraudReviewChecker.new(user).fraud_review_eligible?
           profile = user.fraud_review_pending_profile
           profile_fraud_review_pending_at = profile.fraud_review_pending_at
+          profile_age_in_seconds = profile.profile_age_in_seconds
           profile.activate_after_passing_review
           success = true
 
@@ -316,6 +320,7 @@ def run(args:, config:)
           errors: analytics_error_hash,
           exception: nil,
           profile_fraud_review_pending_at: profile_fraud_review_pending_at,
+          profile_age_in_seconds: profile_age_in_seconds,
         )
       end
 
@@ -336,6 +341,7 @@ def run(args:, config:)
           errors: { message: log_text[:missing_uuid] },
           exception: nil,
           profile_fraud_review_pending_at: nil,
+          profile_age_in_seconds: nil,
         )
       end
 

spec/controllers/idv/by_mail/enter_code_controller_spec.rb

@@ -201,6 +201,7 @@
           pending_in_person_enrollment: false,
           fraud_check_failed: false,
           enqueued_at: pending_profile.gpo_confirmation_codes.last.code_sent_at,
+          profile_age_in_seconds: instance_of(Integer),
           which_letter: 1,
           letter_count: 1,
           submit_attempts: 1,
@@ -243,6 +244,7 @@
             pending_in_person_enrollment: true,
             fraud_check_failed: false,
             enqueued_at: pending_profile.gpo_confirmation_codes.last.code_sent_at,
+            profile_age_in_seconds: instance_of(Integer),
             which_letter: 1,
             letter_count: 1,
             submit_attempts: 1,
@@ -271,6 +273,7 @@
               pending_in_person_enrollment: false,
               fraud_check_failed: true,
               enqueued_at: pending_profile.gpo_confirmation_codes.last.code_sent_at,
+              profile_age_in_seconds: instance_of(Integer),
               which_letter: 1,
               letter_count: 1,
               submit_attempts: 1,
@@ -299,6 +302,7 @@
               pending_in_person_enrollment: false,
               fraud_check_failed: true,
               enqueued_at: user.pending_profile.gpo_confirmation_codes.last.code_sent_at,
+              profile_age_in_seconds: instance_of(Integer),
               which_letter: 1,
               letter_count: 1,
               submit_attempts: 1,
@@ -332,6 +336,7 @@
               pending_in_person_enrollment: false,
               fraud_check_failed: true,
               enqueued_at: user.pending_profile.gpo_confirmation_codes.last.code_sent_at,
+              profile_age_in_seconds: instance_of(Integer),
               which_letter: 1,
               letter_count: 1,
               submit_attempts: 1,
@@ -361,6 +366,7 @@
           fraud_check_failed: false,
           letter_count: 1,
           submit_attempts: 1,
+          profile_age_in_seconds: instance_of(Integer),
           error_details: { otp: { confirmation_code_incorrect: true } },
         )
         expect(response).to render_template(:index)
@@ -394,6 +400,7 @@
             fraud_check_failed: false,
             letter_count: 1,
             submit_attempts: 1,
+            profile_age_in_seconds: instance_of(Integer),
             error_details: { otp: { confirmation_code_incorrect: true } },
           }
           post(:create, params: { gpo_verify_form: { otp: bad_otp } })

spec/jobs/get_usps_proofing_results_job_spec.rb

@@ -46,6 +46,7 @@
             status: response['status'],
             job_name: 'GetUspsProofingResultsJob',
             tmx_status: :threatmetrix_pass,
+            profile_age_in_seconds: instance_of(Integer),
             enhanced_ipp: enhanced_ipp_enrollment,
           }.compact,
         ),

spec/lib/action_account_spec.rb

@@ -169,6 +169,7 @@
           'Fraud: Profile review rejected',
           success: true,
           profile_fraud_review_pending_at: profile_fraud_review_pending_at,
+          profile_age_in_seconds: instance_of(Integer),
         )
         expect(analytics).to have_logged_event(
           'Fraud: Profile review rejected',
@@ -223,6 +224,7 @@
           'Fraud: Profile review passed',
           success: true,
           profile_fraud_review_pending_at: profile_fraud_review_pending_at,
+          profile_age_in_seconds: instance_of(Integer),
         )
         expect(analytics).to have_logged_event(
           'Fraud: Profile review passed',

spec/models/profile_spec.rb

@@ -1098,6 +1098,14 @@
     end
   end
 
+  describe '#profile_age_in_seconds' do
+    it 'logs the time since the created_at timestamp', :freeze_time do
+      profile = create(:profile, created_at: 5.minutes.ago)
+
+      expect(profile.profile_age_in_seconds).to eq(5.minutes.to_i)
+    end
+  end
+
   describe 'query class methods' do
     describe '.active' do
       it 'returns only active Profiles' do