LG-14253 Track time to complete proofing workflow (#11179)

We want to start tracking how long it takes people to complete identity proofing. Part of that is understanding how long it takes people to go from the start of the process to the enter password step where their profile is created. At this point we want to know:

1. How long did it take the person to complete the workflow
2. What steps remain before person finishes proofing (i.e. verify-by-mail, in-person-proofing, or fraud review)

The enter password submit events already logs enough information to determine the second. This commit starts tracking the duration of the proofing session by adding a timestamp at the welcome step and logging the elapsed seconds since on the enter password events.

app/controllers/idv/enter_password_controller.rb

@@ -51,6 +51,7 @@ def create
         gpo_verification_pending: idv_session.profile.gpo_verification_pending?,
         in_person_verification_pending: idv_session.profile.in_person_verification_pending?,
         deactivation_reason: idv_session.profile.deactivation_reason,
+        proofing_workflow_time_in_seconds: idv_session.proofing_workflow_time_in_seconds,
         **ab_test_analytics_buckets,
       )
       Funnel::DocAuth::RegisterStep.new(current_user.id, current_sp&.issuer).
@@ -62,6 +63,7 @@ def create
         gpo_verification_pending: idv_session.profile.gpo_verification_pending?,
         in_person_verification_pending: idv_session.profile.in_person_verification_pending?,
         deactivation_reason: idv_session.profile.deactivation_reason,
+        proofing_workflow_time_in_seconds: idv_session.proofing_workflow_time_in_seconds,
         **ab_test_analytics_buckets,
       )
 

app/controllers/idv/welcome_controller.rb

@@ -9,6 +9,7 @@ class WelcomeController < ApplicationController
     before_action :confirm_not_rate_limited
 
     def show
+      idv_session.proofing_started_at ||= Time.zone.now.iso8601
       analytics.idv_doc_auth_welcome_visited(**analytics_arguments)
 
       Funnel::DocAuth::RegisterStep.new(current_user.id, sp_session[:issuer]).

app/services/analytics_events.rb

@@ -1861,6 +1861,7 @@ def idv_doc_auth_welcome_visited(step:, analytics_id:, skip_hybrid_handoff: nil,
   # @param [String, nil] deactivation_reason Reason user's profile was deactivated, if any.
   # @param [String,nil] active_profile_idv_level ID verification level of user's active profile.
   # @param [String,nil] pending_profile_idv_level ID verification level of user's pending profile.
+  # @param [Integer,nil] proofing_workflow_time_in_seconds The time since starting proofing
   # @identity.idp.previous_event_name  IdV: review info visited
   def idv_enter_password_submitted(
     success:,
@@ -1874,6 +1875,7 @@ def idv_enter_password_submitted(
     proofing_components: nil,
     active_profile_idv_level: nil,
     pending_profile_idv_level: nil,
+    proofing_workflow_time_in_seconds: nil,
     **extra
   )
     track_event(
@@ -1889,6 +1891,7 @@ def idv_enter_password_submitted(
       proofing_components:,
       active_profile_idv_level:,
       pending_profile_idv_level:,
+      proofing_workflow_time_in_seconds:,
       **extra,
     )
   end
@@ -1949,6 +1952,7 @@ def idv_enter_password_visited(
   # @param [String,nil] active_profile_idv_level ID verification level of user's active profile.
   # @param [String,nil] pending_profile_idv_level ID verification level of user's pending profile.
   # @param [Array,nil] profile_history Array of user's profiles (oldest to newest).
+  # @param [Integer,nil] proofing_workflow_time_in_seconds The time since starting proofing
   # @see Reporting::IdentityVerificationReport#query This event is used by the identity verification
   #       report. Changes here should be reflected there.
   # Tracks the last step of IDV, indicates the user successfully proofed
@@ -1965,6 +1969,7 @@ def idv_final(
     active_profile_idv_level: nil,
     pending_profile_idv_level: nil,
     profile_history: nil,
+    proofing_workflow_time_in_seconds: nil,
     **extra
   )
     track_event(
@@ -1981,6 +1986,7 @@ def idv_final(
       active_profile_idv_level:,
       pending_profile_idv_level:,
       profile_history:,
+      proofing_workflow_time_in_seconds:,
       **extra,
     )
   end

app/services/idv/session.rb

@@ -22,6 +22,7 @@ class Session
       phone_for_mobile_flow
       previous_phone_step_params
       profile_id
+      proofing_started_at
       redo_document_capture
       resolution_successful
       selfie_check_performed
@@ -205,6 +206,10 @@ def add_failed_phone_step_number(phone)
       failed_phone_step_numbers << phone_e164 if !failed_phone_step_numbers.include?(phone_e164)
     end
 
+    def proofing_workflow_time_in_seconds
+      Time.zone.now - Time.zone.parse(proofing_started_at) if proofing_started_at.present?
+    end
+
     def pii_from_user_in_flow_session
       user_session.dig('idv/in_person', :pii_from_user)
     end

spec/controllers/idv/enter_password_controller_spec.rb

@@ -27,6 +27,7 @@
     allow(IdentityConfig.store).to receive(:usps_mock_fallback).and_return(false)
     allow(subject).to receive(:ab_test_analytics_buckets).and_return(ab_test_args)
     subject.idv_session.welcome_visited = true
+    subject.idv_session.proofing_started_at = 5.minutes.ago.iso8601
     subject.idv_session.idv_consent_given = true
     subject.idv_session.flow_path = 'standard'
     subject.idv_session.pii_from_doc = Pii::StateId.new(**Idp::Constants::MOCK_IDV_APPLICANT)
@@ -283,7 +284,7 @@ def show
       end
     end
 
-    it 'redirects to personal key path' do
+    it 'redirects to personal key path', :freeze_time do
       put :create, params: { user: { password: ControllerHelper::VALID_PASSWORD } }
 
       expect(@analytics).to have_logged_event(
@@ -294,6 +295,7 @@ def show
           fraud_rejection: false,
           gpo_verification_pending: false,
           in_person_verification_pending: false,
+          proofing_workflow_time_in_seconds: 5.minutes.to_i,
           **ab_test_args,
         ),
       )

spec/controllers/idv/welcome_controller_spec.rb

@@ -64,15 +64,30 @@
       )
     end
 
+    it 'sets the proofing started timestamp', :freeze_time do
+      get :show
+
+      expect(subject.idv_session.proofing_started_at).to eq(Time.zone.now.iso8601)
+    end
+
     context 'welcome already visited' do
-      it 'does not redirect to agreement' do
+      before do
         subject.idv_session.welcome_visited = true
+        subject.idv_session.proofing_started_at = 5.minutes.ago.iso8601
+      end
 
+      it 'does not redirect to agreement' do
         get :show
 
         expect(response).to render_template('idv/welcome/show')
       end
 
+      it 'does not overwrite the proofing started timestamp' do
+        get :show
+
+        expect(subject.idv_session.proofing_started_at).to eq(5.minutes.ago.iso8601)
+      end
+
       context 'and verify info already completed' do
         before do
           subject.idv_session.flow_path = 'standard'

spec/features/idv/analytics_spec.rb

@@ -226,12 +226,12 @@
         proofing_components: lexis_nexis_address_proofing_components,
       },
       :idv_enter_password_submitted => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false, proofing_workflow_time_in_seconds: 0.0,
         active_profile_idv_level: 'legacy_unsupervised',
         proofing_components: lexis_nexis_address_proofing_components
       },
       'IdV: final resolution' => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false, proofing_workflow_time_in_seconds: 0.0,
         active_profile_idv_level: 'legacy_unsupervised',
         profile_history: match_array(kind_of(Idv::ProfileLogging)),
         proofing_components: lexis_nexis_address_proofing_components
@@ -341,12 +341,12 @@
         proofing_components: lexis_nexis_address_proofing_components,
       },
       :idv_enter_password_submitted => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false, proofing_workflow_time_in_seconds: 0.0,
         active_profile_idv_level: 'legacy_unsupervised',
         proofing_components: lexis_nexis_address_proofing_components
       },
       'IdV: final resolution' => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false, proofing_workflow_time_in_seconds: 0.0,
         active_profile_idv_level: 'legacy_unsupervised',
         profile_history: match_array(kind_of(Idv::ProfileLogging)),
         proofing_components: lexis_nexis_address_proofing_components
@@ -442,11 +442,11 @@
         proofing_components: gpo_letter_proofing_components
       },
       :idv_enter_password_submitted => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: true, in_person_verification_pending: false,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: true, in_person_verification_pending: false, proofing_workflow_time_in_seconds: 0.0,
         proofing_components: gpo_letter_proofing_components
       },
       'IdV: final resolution' => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: true, in_person_verification_pending: false,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: true, in_person_verification_pending: false, proofing_workflow_time_in_seconds: 0.0,
         # NOTE: pending_profile_idv_level should be set here, a nil value is cached for current_user.pending_profile.
         profile_history: match_array(kind_of(Idv::ProfileLogging)),
         proofing_components: gpo_letter_proofing_components
@@ -558,11 +558,11 @@
         proofing_components: { document_check: 'usps', source_check: 'aamva', resolution_check: 'lexis_nexis', threatmetrix: threatmetrix, threatmetrix_review_status: 'pass', address_check: 'lexis_nexis_address' },
       },
       :idv_enter_password_submitted => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: true,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: true, proofing_workflow_time_in_seconds: 0.0,
         proofing_components: { document_check: 'usps', source_check: 'aamva', resolution_check: 'lexis_nexis', threatmetrix: threatmetrix, threatmetrix_review_status: 'pass', address_check: 'lexis_nexis_address' }
       },
       'IdV: final resolution' => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: true,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: true, proofing_workflow_time_in_seconds: 0.0,
         # NOTE: pending_profile_idv_level should be set here, a nil value is cached for current_user.pending_profile.
         profile_history: match_array(kind_of(Idv::ProfileLogging)),
         proofing_components: { document_check: 'usps', source_check: 'aamva', resolution_check: 'lexis_nexis', threatmetrix: threatmetrix, threatmetrix_review_status: 'pass', address_check: 'lexis_nexis_address' }
@@ -680,12 +680,12 @@
         proofing_components: lexis_nexis_address_proofing_components,
       },
       :idv_enter_password_submitted => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false, proofing_workflow_time_in_seconds: 0.0,
         active_profile_idv_level: 'unsupervised_with_selfie',
         proofing_components: lexis_nexis_address_proofing_components
       },
       'IdV: final resolution' => {
-        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false,
+        success: true, fraud_review_pending: false, fraud_rejection: false, gpo_verification_pending: false, in_person_verification_pending: false, proofing_workflow_time_in_seconds: 0.0,
         active_profile_idv_level: 'unsupervised_with_selfie',
         profile_history: match_array(kind_of(Idv::ProfileLogging)),
         proofing_components: lexis_nexis_address_proofing_components