[DPC-4370] Add onboarding time logs (#2320)

## 🎫 Ticket

https://jira.cms.gov/browse/DPC-4370

## 🛠 Changes

Supports DPC-4370 by adding to Splunk logs.

## ℹ️ Context

<!-- Why were these changes made? Add background context suitable for a
non-technical audience. -->

<!-- If any of the following security implications apply, this PR must
not be merged without Stephen Walter's approval. Explain in this section
and add @SJWalter11 as a reviewer.
  - Adds a new software dependency or dependencies.
  - Modifies or invalidates one or more of our security controls.
  - Stores or transmits data that was not stored or transmitted before.
- Requires additional review of security implications for other reasons.
-->

## 🧪 Validation

<!-- How were the changes verified? Did you fully test the acceptance
criteria in the ticket? Provide reproducible testing instructions and
screenshots if applicable. -->

.gitignore

@@ -43,6 +43,8 @@ ops/config/decrypted/*
 !ops/config/decrypted/README.md
 .mvn/
 
+/tmp/cache/*
+/tmp/local_secret.txt
 /tmp/letter_opener/admin/*
 /tmp/letter_opener/web/*
 

dpc-portal/app/controllers/credential_delegate_invitations_controller.rb

@@ -20,7 +20,8 @@ def create
     if @cd_invitation.save
       Rails.logger.info(['Credential Delegate invited',
                          { actionContext: LoggingConstants::ActionContext::Registration,
-                           actionType: LoggingConstants::ActionType::CdInvited }])
+                           actionType: LoggingConstants::ActionType::CdInvited,
+                           invitation: @cd_invitation.id }])
       InvitationMailer.with(invitation: @cd_invitation).invite_cd.deliver_later
       if Rails.env.local?
         logger.info("Invitation URL: #{accept_organization_invitation_url(@organization, @cd_invitation)}")

dpc-portal/app/controllers/invitations_controller.rb

@@ -15,6 +15,7 @@ class InvitationsController < ApplicationController
   before_action :block_test_utilities, only: %i[set_idp_token]
 
   def show
+    log_invitation_flow_start
     render(Page::Invitations::StartComponent.new(@organization, @invitation))
   end
 
@@ -47,7 +48,8 @@ def confirm_cd
     session["invitation_status_#{@invitation.id}"] = 'verification_complete'
     Rails.logger.info(['Approved access authorization occurred for the Credential Delegate',
                        { actionContext: LoggingConstants::ActionContext::Registration,
-                         actionType: LoggingConstants::ActionType::CdConfirmed }])
+                         actionType: LoggingConstants::ActionType::CdConfirmed,
+                         invitation: @invitation.id }])
     render(Page::Invitations::AcceptInvitationComponent.new(@organization, @invitation, @given_name, @family_name))
   end
 
@@ -63,15 +65,17 @@ def register
     sign_in(:user, @user)
     Rails.logger.info(['User logged in',
                        { actionContext: LoggingConstants::ActionContext::Registration,
-                         actionType: LoggingConstants::ActionType::UserLoggedIn }])
+                         actionType: LoggingConstants::ActionType::UserLoggedIn,
+                         invitation: @invitation.id }])
     render(Page::Invitations::SuccessComponent.new(@organization, @invitation, @given_name, @family_name))
   end
 
   def login
     login_session
     Rails.logger.info(['User began login flow',
                        { actionContext: LoggingConstants::ActionContext::Registration,
-                         actionType: LoggingConstants::ActionType::BeginLogin }])
+                         actionType: LoggingConstants::ActionType::BeginLogin,
+                         invitation: @invitation.id }])
     url = URI::HTTPS.build(host: IDP_HOST,
                            path: '/openid_connect/authorize',
                            query: { acr_values: 'http://idmanagement.gov/ns/assurance/ial/2',
@@ -178,15 +182,17 @@ def create_cd_org_link
     CdOrgLink.create!(user:, provider_organization: @organization, invitation: @invitation)
     Rails.logger.info(['Credential Delegate linked to organization',
                        { actionContext: LoggingConstants::ActionContext::Registration,
-                         actionType: LoggingConstants::ActionType::CdLinkedToOrg }])
+                         actionType: LoggingConstants::ActionType::CdLinkedToOrg,
+                         invitation: @invitation.id }])
     @invitation.accept!
   end
 
   def create_ao_org_link
     AoOrgLink.create!(user:, provider_organization: @organization, invitation: @invitation)
     Rails.logger.info(['Authorized Official linked to organization',
                        { actionContext: LoggingConstants::ActionContext::Registration,
-                         actionType: LoggingConstants::ActionType::AoLinkedToOrg }])
+                         actionType: LoggingConstants::ActionType::AoLinkedToOrg,
+                         invitation: @invitation.id }])
     @invitation.accept!
     @user.update(verification_status: 'approved')
     @organization.update(verification_status: 'approved')
@@ -231,11 +237,13 @@ def validate_invitation
     if @invitation.credential_delegate?
       Rails.logger.info(['Credential Delegate Invitation expired',
                          { actionContext: LoggingConstants::ActionContext::Registration,
-                           actionType: LoggingConstants::ActionType::CdInvitationExpired }])
+                           actionType: LoggingConstants::ActionType::CdInvitationExpired,
+                           invitation: @invitation.id }])
     elsif @invitation.authorized_official?
       Rails.logger.info(['Authorized Official Invitation expired',
                          { actionContext: LoggingConstants::ActionContext::Registration,
-                           actionType: LoggingConstants::ActionType::AoInvitationExpired }])
+                           actionType: LoggingConstants::ActionType::AoInvitationExpired,
+                           invitation: @invitation.id }])
     end
     render(Page::Invitations::BadInvitationComponent.new(@invitation, @invitation.unacceptable_reason),
            status: :forbidden)
@@ -263,10 +271,25 @@ def block_test_utilities
     render plain: :forbidden, status: :forbidden unless Rails.env.test?
   end
 
+  def log_invitation_flow_start
+    if @invitation.credential_delegate?
+      Rails.logger.info(['Credential Delegate invitation flow started,',
+                         { actionContext: LoggingConstants::ActionContext::Registration,
+                           actionType: LoggingConstants::ActionType::CdInvitationFlowStarted,
+                           invitation: @invitation.id }])
+    elsif @invitation.authorized_official?
+      Rails.logger.info(['Authorized Official invitation flow started,',
+                         { actionContext: LoggingConstants::ActionContext::Registration,
+                           actionType: LoggingConstants::ActionType::AoInvitationFlowStarted,
+                           invitation: @invitation.id }])
+    end
+  end
+
   def log_ao_verification_error(error, service_unavailable)
     if service_unavailable
       logger.error(['CPI API Gateway unavailable',
-                    { actionContext: LoggingConstants::ActionContext::Registration, error: error.message }])
+                    { actionContext: LoggingConstants::ActionContext::Registration, error: error.message,
+                      invitation: @invitation.id }])
     else
       logger.info(['AO Check Fail',
                    { actionContext: LoggingConstants::ActionContext::Registration,
@@ -280,11 +303,13 @@ def log_create_user
     if @invitation.credential_delegate?
       Rails.logger.info(['Credential Delegate user created,',
                          { actionContext: LoggingConstants::ActionContext::Registration,
-                           actionType: LoggingConstants::ActionType::CdCreated }])
+                           actionType: LoggingConstants::ActionType::CdCreated,
+                           invitation: @invitation.id }])
     elsif @invitation.authorized_official?
       Rails.logger.info(['Authorized Official user created,',
                          { actionContext: LoggingConstants::ActionContext::Registration,
-                           actionType: LoggingConstants::ActionType::AoCreated }])
+                           actionType: LoggingConstants::ActionType::AoCreated,
+                           invitation: @invitation.id }])
     end
   end
 

dpc-portal/app/services/ao_invitation_service.rb

@@ -14,7 +14,8 @@ def create_invitation(given_name, family_name, ao_email, org_npi)
 
     Rails.logger.info(['Authorized Official invited',
                        { actionContext: LoggingConstants::ActionContext::Registration,
-                         actionType: LoggingConstants::ActionType::AoInvited }])
+                         actionType: LoggingConstants::ActionType::AoInvited,
+                         invitation: invitation.id }])
 
     InvitationMailer.with(invitation:, given_name:, family_name:).invite_ao.deliver_now
 

dpc-portal/config/initializers/logging.rb

@@ -11,6 +11,8 @@ module ActionContext
   end
 
   module ActionType
+    AoInvitationFlowStarted = 'AoInvitationFlowStarted'
+    CdInvitationFlowStarted = 'CdInvitationFlowStarted'
     AoInvited = 'AoInvited'
     CdInvited = 'CdInvited'
     AoInvitationExpired = 'AoInvitationExpired'

dpc-portal/spec/requests/credential_delegate_invitations_spec.rb

@@ -150,10 +150,22 @@
       end
 
       it 'logs on success' do
+        invitation_id = 123
+        invitation = instance_double(Invitation)
+        expect(invitation).to receive(:id).and_return(invitation_id)
+        expect(invitation).to receive(:save).and_return(true)
+        expect(Invitation).to receive(:new).and_return(invitation)
+
+        mailer = double(InvitationMailer)
+        expect(InvitationMailer).to receive(:with).with(invitation:).and_return(mailer)
+        expect(mailer).to receive(:invite_cd).and_return(mailer)
+        expect(mailer).to receive(:deliver_later)
+
         allow(Rails.logger).to receive(:info)
         expect(Rails.logger).to receive(:info).with(['Credential Delegate invited',
                                                      { actionContext: LoggingConstants::ActionContext::Registration,
-                                                       actionType: LoggingConstants::ActionType::CdInvited }])
+                                                       actionType: LoggingConstants::ActionType::CdInvited,
+                                                       invitation: invitation_id }])
         post "/organizations/#{api_id}/credential_delegate_invitations", params: successful_parameters
       end
 

dpc-portal/spec/requests/invitations_spec.rb

@@ -49,14 +49,16 @@
           expect(Rails.logger).to receive(:info).with(
             ['Credential Delegate Invitation expired',
              { actionContext: LoggingConstants::ActionContext::Registration,
-               actionType: LoggingConstants::ActionType::CdInvitationExpired }]
+               actionType: LoggingConstants::ActionType::CdInvitationExpired,
+               invitation: invitation.id }]
           )
         elsif invitation.authorized_official?
           allow(Rails.logger).to receive(:info)
           expect(Rails.logger).to receive(:info).with(
             ['Authorized Official Invitation expired',
              { actionContext: LoggingConstants::ActionContext::Registration,
-               actionType: LoggingConstants::ActionType::AoInvitationExpired }]
+               actionType: LoggingConstants::ActionType::AoInvitationExpired,
+               invitation: invitation.id }]
           )
         end
         send(method, "/organizations/#{org.id}/invitations/#{invitation.id}/#{path_suffix}")
@@ -126,7 +128,8 @@
         allow(Rails.logger).to receive(:info)
         expect(Rails.logger).to receive(:info).with(['User began login flow',
                                                      { actionContext: LoggingConstants::ActionContext::Registration,
-                                                       actionType: LoggingConstants::ActionType::BeginLogin }])
+                                                       actionType: LoggingConstants::ActionType::BeginLogin,
+                                                       invitation: invitation.id }])
         org_id = invitation.provider_organization.id
         post "/organizations/#{org_id}/invitations/#{invitation.id}/login"
       end
@@ -462,7 +465,8 @@
             approved_access_log_message = [
               'Approved access authorization occurred for the Credential Delegate',
               { actionContext: LoggingConstants::ActionContext::Registration,
-                actionType: LoggingConstants::ActionType::CdConfirmed }
+                actionType: LoggingConstants::ActionType::CdConfirmed,
+                invitation: cd_invite.id }
             ]
             expect(Rails.logger).to receive(:info).with(approved_access_log_message)
             get "/organizations/#{org.id}/invitations/#{cd_invite.id}/confirm_cd"
@@ -562,11 +566,13 @@
           if invitation.authorized_official?
             expect(Rails.logger).to receive(:info).with(['Authorized Official linked to organization',
                                                          { actionContext: LoggingConstants::ActionContext::Registration,
-                                                           actionType: LoggingConstants::ActionType::AoLinkedToOrg }])
+                                                           actionType: LoggingConstants::ActionType::AoLinkedToOrg,
+                                                           invitation: invitation.id }])
           else
             expect(Rails.logger).to receive(:info).with(['Credential Delegate linked to organization',
                                                          { actionContext: LoggingConstants::ActionContext::Registration,
-                                                           actionType: LoggingConstants::ActionType::CdLinkedToOrg }])
+                                                           actionType: LoggingConstants::ActionType::CdLinkedToOrg,
+                                                           invitation: invitation.id }])
           end
           post "/organizations/#{org.id}/invitations/#{invitation.id}/register"
         end
@@ -575,7 +581,8 @@
           allow(Rails.logger).to receive(:info)
           expect(Rails.logger).to receive(:info).with(['User logged in',
                                                        { actionContext: LoggingConstants::ActionContext::Registration,
-                                                         actionType: LoggingConstants::ActionType::UserLoggedIn }])
+                                                         actionType: LoggingConstants::ActionType::UserLoggedIn,
+                                                         invitation: invitation.id }])
           post "/organizations/#{org.id}/invitations/#{invitation.id}/register"
         end
 
@@ -593,11 +600,13 @@
           if invitation.authorized_official?
             expect(Rails.logger).to receive(:info).with(['Authorized Official user created,',
                                                          { actionContext: LoggingConstants::ActionContext::Registration,
-                                                           actionType: LoggingConstants::ActionType::AoCreated }])
+                                                           actionType: LoggingConstants::ActionType::AoCreated,
+                                                           invitation: invitation.id }])
           else
             expect(Rails.logger).to receive(:info).with(['Credential Delegate user created,',
                                                          { actionContext: LoggingConstants::ActionContext::Registration,
-                                                           actionType: LoggingConstants::ActionType::CdCreated }])
+                                                           actionType: LoggingConstants::ActionType::CdCreated,
+                                                           invitation: invitation.id }])
           end
           post "/organizations/#{org.id}/invitations/#{invitation.id}/register"
         end

dpc-portal/spec/services/ao_invitation_service_spec.rb

@@ -48,7 +48,7 @@
       end.to change { ProviderOrganization.count }.by 0
     end
 
-    it 'creates org wich PECOS name' do
+    it 'creates org with PECOS name' do
       service.create_invitation(*params, organization_npi)
       organization = ProviderOrganization.find_by(npi: organization_npi)
       expect(organization.name).to eq "Organization #{organization_npi}"
@@ -76,10 +76,25 @@
     end
 
     it 'logs on success' do
+      organization = instance_double(ProviderOrganization)
+      expect(ProviderOrganization).to receive(:find_or_create_by).with(npi: organization_npi).and_return(organization)
+
+      invitation_id = 123
+      invitation = instance_double(Invitation)
+      expect(invitation).to receive(:id).and_return(invitation_id)
+      expect(Invitation).to receive(:create).and_return(invitation)
+
+      mailer = double(InvitationMailer)
+      expect(InvitationMailer).to receive(:with).with(invitation:, given_name: params[0], family_name: params[1])
+                                                .and_return(mailer)
+      expect(mailer).to receive(:invite_ao).and_return(mailer)
+      expect(mailer).to receive(:deliver_now)
+
       allow(Rails.logger).to receive(:info)
       expect(Rails.logger).to receive(:info).with(['Authorized Official invited',
                                                    { actionContext: LoggingConstants::ActionContext::Registration,
-                                                     actionType: LoggingConstants::ActionType::AoInvited }])
+                                                     actionType: LoggingConstants::ActionType::AoInvited,
+                                                     invitation: invitation_id }])
       service.create_invitation(*params, organization_npi)
     end
   end