diff --git a/bin/summarize-user-events b/bin/summarize-user-events new file mode 100755 index 00000000000..0650f35c840 --- /dev/null +++ b/bin/summarize-user-events @@ -0,0 +1,286 @@ +#!/usr/bin/env ruby +# frozen_string_literal: true + +Dir.chdir(__dir__) { require 'bundler/setup' } + +require 'active_support' +require 'active_support/core_ext/integer/time' +require 'active_support/core_ext/object/blank' +require 'active_support/time' +require 'aws-sdk-cloudwatchlogs' +require 'concurrent-ruby' +require 'optparse' + +$LOAD_PATH.unshift(File.expand_path(File.join(__dir__, '../lib'))) +require 'reporting/cloudwatch_client' +require 'reporting/cloudwatch_query_quoting' + +# Require all *_matcher.rb files in lib/event_summarizer +Dir[File.expand_path( + File.join(__dir__, '../lib/event_summarizer', '**', '*_matcher.rb'), +)].sort.each do |f| + require f +end + +class SummarizeUserEvents + attr_reader :file_name, :uuid, :from_date, :stderr, :stdout, :to_date, :zone + + NICE_DATE_AND_TIME_FORMAT = '%B %d, %Y at %I:%M %p %Z' + TIME_ONLY_FORMAT = '%I:%M %p' + + def initialize( + file_name: nil, + user_uuid: nil, + start_time: nil, + end_time: nil, + zone: 'UTC', + stdout: STDOUT, + stderr: STDERR + ) + @file_name = file_name + @zone = zone + @uuid = user_uuid + @from_date = parse_time(start_time) || 1.week.ago + @to_date = parse_time(end_time) || ( + start_time.present? ? + from_date + 1.week : + ActiveSupport::TimeZone[zone].now + ) + @stdout = stdout + @stderr = stderr + end + + def parse_time(time_str) + return nil if time_str.nil? + + parsed = ActiveSupport::TimeZone['UTC'].parse(time_str) + parsed = parsed.in_time_zone(zone) if zone && parsed + + parsed + end + + def matchers + @matchers ||= [ + EventSummarizer::ExampleMatcher.new, + EventSummarizer::AccountDeletionMatcher.new, + EventSummarizer::IdvMatcher.new, + ] + end + + def self.parse_command_line_options(argv) + options = { + zone: 'America/New_York' + } + basename = File.basename($0) + + # rubocop:disable Metrics/LineLength + optparse = OptionParser.new do |opts| + opts.banner = <<~EOM + + Summarize user events in a human-readable format + + Cloudwatch logs can be read from a file as newline-delimited JSON (ndjson), + or fetched directly via aws-vault. + + Usage: #{basename} [OPTIONS] + + Examples: + #{basename} -f events.ndjson + aws-vault exec prod-power -- #{basename} -u 1234-5678-90ab-cdef -s 2024-12-09T10:00:00 -e 2024-12-09T14:30:00 -z America/New_York + + EOM + + opts.on('-f', '--file_name FILE_NAME', 'filename from which to read the events') do |val| + options[:file_name] = val + end + + opts.on('-h', '--help', 'Display this message') do + warn opts + exit + end + + opts.on('-u', '--user-uuid USER_UUID', 'UUID of the protagonist of the story') do |val| + options[:user_uuid] = val + end + + opts.on('-s', '--start-time START_TIME', 'Time of the start of the query period (e.g. 2024-12-09T10:00:00Z), default: 1 week ago') do |val| + options[:start_time] = val + end + + opts.on('-e', '--end-time END_TIME', 'Time of the end of the query period (e.g. 2024-12-09T14:30:00Z), default: 1 week from start') do |val| + options[:end_time] = val + end + + opts.on('-z', '--timezone TIMEZONE', 'Timezone to use (e.g. America/New_York), default: UTC') do |val| + options[:zone] = val + end + end + # rubocop:enable Metrics/LineLength + + optparse.parse!(argv) + + options + end + + + def run + in_correct_time_zone do + find_cloudwatch_events do |event| + # Time.zone is thread-local, and CloudwatchClient may use multiple + # threads to make requests. So we have to make double-sure we're + # in the right Timezone. + in_correct_time_zone do + normalize_event!(event) + + matchers.each do |matcher| + matcher.handle_cloudwatch_event(event) + end + end + end + + overall_results = [] + + matchers.each do |matcher| + results_for_matcher = matcher.finish + overall_results.append(*results_for_matcher) + end + + stdout.puts format_results(overall_results) + end + end + + def format_results(results) + # Each Hash in results should have _at least_ a :title key defined + + results. + sort_by { |r| r[:timestamp] || r[:started_at] || Time.zone.at(0) }. + map do |r| + timestamp = r[:timestamp] || r[:started_at] + + heading = r[:title] + + if timestamp + heading = "#{heading} (#{format_time(timestamp)})" + end + + prev_timestamp = timestamp + + list_items = r[:attributes] + &.sort_by { |attr| attr[:timestamp] || Time.zone.at(0) } + &.map do |attr| + text = attr[:description] + + formatted_timestamp = format_time(attr[:timestamp], prev_timestamp) + prev_timestamp = attr[:timestamp] + + text = "(#{formatted_timestamp}) #{text}" if formatted_timestamp + + "* #{text}" + end + + [ + "## #{heading}", + *list_items, + '', + ] + end.join("\n") + end + + def format_time(timestamp, prev_timestamp = nil) + return if timestamp.blank? + + timestamp = timestamp.in_time_zone(zone) + prev_timestamp = prev_timestamp&.in_time_zone(zone) + + same_date = timestamp.to_date == prev_timestamp&.to_date + + if same_date + timestamp.strftime(TIME_ONLY_FORMAT) + else + timestamp.strftime(NICE_DATE_AND_TIME_FORMAT) + end + end + + def query + format(<<~QUERY) + fields + name + , properties.event_properties.success as success + , @message + , @timestamp + | filter properties.user_id = '#{uuid}' + | sort @timestamp asc + | limit 10000 + QUERY + end + + def cloudwatch_client + @cloudwatch_client ||= Reporting::CloudwatchClient.new( + num_threads: 5, + ensure_complete_logs: true, + log_group_name: 'prod_/srv/idp/shared/log/events.log', + ) + end + + def find_cloudwatch_events(&block) + unless file_name.nil? + warn 'Reading Cloudwatch events as newline-delimited JSON (ndjson) file' + file_source(&block) + else + cloudwatch_source(&block) + end + end + + def file_source(&block) + events = [] + + File.read(file_name).each_line do |line| + next if line.blank? + events << JSON.parse(line) + end + + events.sort_by! { |e| e['@timestamp'] } + + events.each do |e| + block.call(e) + end + end + + def cloudwatch_source(&block) + cloudwatch_client.fetch( + query: query, + from: from_date, + to: to_date, + &block + ) + end + + def in_correct_time_zone + old_time_zone = Time.zone + Time.zone = zone + yield + ensure + Time.zone = old_time_zone + end + + def normalize_event!(event) + if event['@timestamp'].is_a?(String) + event['@timestamp'] = ActiveSupport::TimeZone['UTC'].parse(event['@timestamp']) + end + + if event['@message'].is_a?(String) + event['@message'] = JSON.parse(event['@message']) + end + + event['name'] ||= event['@message']['name'] + end +end + +def main + options = SummarizeUserEvents.parse_command_line_options(ARGV) + SummarizeUserEvents.new(**options).run +end + +if $PROGRAM_NAME == __FILE__ + main +end diff --git a/lib/event_summarizer/account_deletion_matcher.rb b/lib/event_summarizer/account_deletion_matcher.rb new file mode 100644 index 00000000000..ec21f689cce --- /dev/null +++ b/lib/event_summarizer/account_deletion_matcher.rb @@ -0,0 +1,74 @@ +# frozen_string_literal: true + +module EventSummarizer + class AccountDeletionMatcher + ACCOUNT_DELETION_STARTED_EVENT = 'Account Reset: request' + ACCOUNT_DELETION_SUBMITTED_EVENT = 'Account Reset: delete' + ACCOUNT_DELETION_CANCELED_EVENT = 'Account Reset: cancel' + + EVENT_PROPERTIES = ['@message', 'properties', 'event_properties'].freeze + + attr_accessor :account_deletion_events, :event_summaries + + def initialize + @account_deletion_events = Array.new + @event_summaries = Array.new + account_deletion_events + end + + def handle_cloudwatch_event(event) + case event['name'] + when ACCOUNT_DELETION_STARTED_EVENT + process_account_reset_request(event) + when ACCOUNT_DELETION_SUBMITTED_EVENT + process_account_reset_delete(event) + when ACCOUNT_DELETION_CANCELED_EVENT + process_account_reset_cancel(event) + end + end + + def finish + event_summaries + end + + private + + def process_account_reset_request(event) + event_message = { + title: 'Account deletion Request', + attributes: [ + { type: :account_deletion_request, + description: "On #{event["@timestamp"]} user initiated account deletion" }, + ], + } + event_summaries.push(event_message) + end + + def process_account_reset_cancel(event) + event_message = { + title: 'Account deletion cancelled', + attributes: [ + { type: :account_deletion_cancelled, + description: "On #{event["@timestamp"]} user canceled account deletion" }, + ], + } + event_summaries.push(event_message) + end + + def process_account_reset_delete(event) + message = event['@message'] + age = message['properties']['event_properties']['account_age_in_days'] + date = event['@timestamp'] + event_message = { + title: 'Account deleted', + attributes: [ + { + type: :account_deleted, + description: "On #{date} user deleted their account which was #{age} days old", + }, + ], + } + event_summaries.push(event_message) + end + end +end diff --git a/lib/event_summarizer/example_matcher.rb b/lib/event_summarizer/example_matcher.rb new file mode 100644 index 00000000000..b7807ec47f0 --- /dev/null +++ b/lib/event_summarizer/example_matcher.rb @@ -0,0 +1,28 @@ +# frozen_string_literal: true + +module EventSummarizer + class ExampleMatcher + attr_reader :event_count + + def initialize + @event_count = 0 + end + + def handle_cloudwatch_event(_event) + @event_count += 1 + end + + def finish + [ + { + title: 'Processed some events', + attributes: [ + { type: :event_count, description: "Processed #{event_count} event(s)" }, + ], + }.tap do + @event_count = 0 + end, + ] + end + end +end diff --git a/lib/event_summarizer/idv_matcher.rb b/lib/event_summarizer/idv_matcher.rb new file mode 100644 index 00000000000..fdade426166 --- /dev/null +++ b/lib/event_summarizer/idv_matcher.rb @@ -0,0 +1,538 @@ +# frozen_string_literal: true + +require 'active_support' +require 'active_support/time' + +require 'event_summarizer/vendor_result_evaluators/aamva' +require 'event_summarizer/vendor_result_evaluators/instant_verify' +require 'event_summarizer/vendor_result_evaluators/true_id' + +module EventSummarizer + class IdvMatcher + IDV_WELCOME_SUBMITTED_EVENT = 'IdV: doc auth welcome submitted' + IDV_GPO_CODE_SUBMITTED_EVENT = 'IdV: enter verify by mail code submitted' + IDV_FINAL_RESOLUTION_EVENT = 'IdV: final resolution' + IDV_IMAGE_UPLOAD_VENDOR_SUBMITTED_EVENT = 'IdV: doc auth image upload vendor submitted' + IDV_VERIFY_PROOFING_RESULTS_EVENT = 'IdV: doc auth verify proofing results' + IPP_ENROLLMENT_STATUS_UPDATED_EVENT = 'GetUspsProofingResultsJob: Enrollment status updated' + PROFILE_ENCRYPTION_INVALID_EVENT = 'Profile Encryption: Invalid' + RATE_LIMIT_REACHED_EVENT = 'Rate Limit Reached' + + EVENT_PROPERTIES = ['@message', 'properties', 'event_properties'].freeze + + VENDORS = { + 'TrueID' => { + id: :trueid, + name: 'True ID', + evaluator_module: EventSummarizer::VendorResultEvaluators::TrueId, + }, + 'lexisnexis:instant_verify' => { + id: :instant_verify, + name: 'Instant Verify', + evaluator_module: EventSummarizer::VendorResultEvaluators::InstantVerify, + }, + 'aamva:state_id' => { + id: :aamva, + name: 'AAMVA', + evaluator_module: EventSummarizer::VendorResultEvaluators::Aamva, + }, + }.freeze + + UNKNOWN_VENDOR = { + id: :unknown, + name: 'Unknown vendor', + }.freeze + + IdvAttempt = Data.define( + :started_at, + :significant_events, + ) do + def initialize(started_at:, significant_events: []) + super(started_at:, significant_events:) + end + + def flagged_for_fraud? + self.significant_events.any? { |e| e.type == :flagged_for_fraud } + end + + def gpo? + self.significant_events.any? { |e| e.type == :start_gpo } + end + + def gpo_pending? + gpo? && !self.significant_events.any? { |e| e.type == :gpo_code_success } + end + + def ipp? + self.significant_events.any? { |e| e.type == :start_ipp } + end + + def ipp_pending? + ipp? && !self.significant_events.any? { |e| e.type == :ipp_enrollment_complete } + end + + def successful? + self.significant_events.any? do |e| + e.type == :verified + end + end + + def workflow_complete? + gpo? || ipp? || flagged_for_fraud? || successful? + end + end.freeze + + SignificantIdvEvent = Data.define( + :timestamp, + :type, + :description, + ).freeze + + attr_reader :current_idv_attempt + attr_reader :idv_attempts + attr_reader :idv_abandoned_event + + def initialize + @idv_attempts = [] + @current_idv_attempt = nil + end + + # @return {Hash,nil} + def handle_cloudwatch_event(event) + case event['name'] + when IDV_WELCOME_SUBMITTED_EVENT + start_new_idv_attempt(event:) + + when IDV_FINAL_RESOLUTION_EVENT + + for_current_idv_attempt(event:) do + handle_final_resolution_event(event:) + end + + when IDV_GPO_CODE_SUBMITTED_EVENT + for_current_idv_attempt(event:) do + handle_gpo_code_submission(event:) + end + + when IPP_ENROLLMENT_STATUS_UPDATED_EVENT + for_current_idv_attempt(event:) do + handle_ipp_enrollment_status_update(event:) + end + + when IDV_IMAGE_UPLOAD_VENDOR_SUBMITTED_EVENT + for_current_idv_attempt(event:) do + handle_image_upload_vendor_submitted(event:) + end + + when IDV_VERIFY_PROOFING_RESULTS_EVENT + for_current_idv_attempt(event:) do + handle_verify_proofing_results_event(event:) + end + + when PROFILE_ENCRYPTION_INVALID_EVENT + for_current_idv_attempt(event:) do + handle_profile_encryption_error(event:) + end + + when RATE_LIMIT_REACHED_EVENT + handle_rate_limit_reached(event:) + + else + if ENV['LOG_UNHANDLED_EVENTS'] + warn "#{event['@timestamp']} #{event['name']}" + end + end + + check_for_idv_abandonment(event) + end + + def finish + finish_current_idv_attempt + + self.idv_attempts.map { |a| summarize_idv_attempt(a) }.tap do + idv_attempts.clear + end + end + + private + + def add_significant_event( + timestamp:, + type:, + description: + ) + current_idv_attempt.significant_events << SignificantIdvEvent.new( + timestamp:, + type:, + description:, + ) + end + + def check_for_idv_abandonment(event) + return if current_idv_attempt.nil? + + looks_like_idv = /^idv/i.match(event['name']) + return if !looks_like_idv + + if idv_abandoned_event.nil? + @idv_abandoned_event = event + return + end + + is_a_little_bit_newer = event['@timestamp'] - idv_abandoned_event['@timestamp'] < 1.hour + + if is_a_little_bit_newer + @idv_abandoned_event = event + end + end + + def for_current_idv_attempt(event:, &block) + if !current_idv_attempt + warn <<~WARNING + Encountered #{event['name']} without seeing a '#{IDV_WELCOME_SUBMITTED_EVENT}' event first. + This could indicate you need to include earlier events in your request. + WARNING + return + end + + block.call(event) + end + + def finish_current_idv_attempt + if !current_idv_attempt.nil? + looks_like_abandonment = + !current_idv_attempt.workflow_complete? && + !idv_abandoned_event.nil? && + idv_abandoned_event['@timestamp'] < 1.hour.ago + + if looks_like_abandonment + add_significant_event( + type: :idv_abandoned, + timestamp: idv_abandoned_event['@timestamp'], + description: 'User abandoned identity verification', + ) + end + end + + idv_attempts << current_idv_attempt if current_idv_attempt + @current_idv_attempt = nil + @idv_abandoned_event = nil + end + + # @return {Hash,nil} + def handle_final_resolution_event(event:) + timestamp = event['@timestamp'] + + gpo_pending = !!event.dig( + *EVENT_PROPERTIES, + 'gpo_verification_pending', + ) + + if gpo_pending + add_significant_event( + type: :start_gpo, + timestamp:, + description: 'User requested a letter to verify by mail', + ) + end + + ipp_pending = !!event.dig( + *EVENT_PROPERTIES, + 'in_person_verification_pending', + ) + + if ipp_pending + add_significant_event( + type: :start_ipp, + timestamp:, + descirption: 'User entered the in-person proofing flow', + ) + end + + fraud_review_pending = !!event.dig( + *EVENT_PROPERTIES, + 'fraud_review_pending', + ) + + if fraud_review_pending + add_significant_event( + type: :flagged_for_fraud, + timestamp:, + description: 'User was flagged for fraud', + ) + end + + pending = + gpo_pending || + ipp_pending || + fraud_review_pending + + if !pending + add_significant_event( + type: :verified, + timestamp:, + description: 'User completed identity verification (remote unsupervised flow)', + ) + + finish_current_idv_attempt + end + end + + def handle_gpo_code_submission(event:) + timestamp = event['@timestamp'] + success = event.dig(*EVENT_PROPERTIES, 'success') + + if !success + add_significant_event( + type: :gpo_code_failure, + timestamp:, + description: 'The user entered an invalid GPO code', + ) + return + end + + # User successfully entered GPO code. If fraud review is not pending, + # then they are fully verified + fraud_review_pending = !!event.dig( + *EVENT_PROPERTIES, + 'fraud_check_failed', + ) + + fully_verified = !fraud_review_pending + + add_significant_event( + type: :gpo_code_success, + timestamp:, + description:, + ) + + if fully_verified + add_significant_event( + type: :verified, + timestamp:, + description: 'User completed identity verification', + ) + + finish_current_idv_attempt + end + end + + def handle_ipp_enrollment_status_update(event:) + timestamp = event['@timestamp'] + passed = event.dig(*EVENT_PROPERTIES, 'passed') + tmx_status = event.dig(*EVENT_PROPERTIES, 'tmx_status') + + return if !passed + + add_significant_event( + type: :ipp_enrollment_complete, + timestamp:, + description: 'User visited the post office and completed IPP enrollment', + ) + + verified = tmx_status != 'review' && tmx_status != 'reject' + + if verified + current_idv_attempt.event << SignificantIdvEvent.new( + type: :verified, + timestamp:, + description: 'User is fully verified', + ) + end + end + + def handle_profile_encryption_error(event:) + caveats = [ + # TODO these need to check if GPO/IPP were still pending at time of the event + current_idv_attempt.gpo? ? 'The user will not be able to enter a GPO code' : nil, + current_idv_attempt.ipp? ? 'the user will not be able to verify in-person' : nil, + ].compact + + add_significant_event( + type: :password_reset, + timestamp: event['@timestamp'], + description: [ + 'The user reset their password and did not provide their personal key.', + caveats.length > 0 ? + "The user will not be able to #{caveats.join(' or ')}" : + nil, + ].compact.join(' '), + ) + end + + def handle_rate_limit_reached(event:) + limiters = { + 'idv_doc_auth' => 'Doc Auth', + } + + limiter_type = event.dig(*EVENT_PROPERTIES, 'limiter_type') + + limit_name = limiters[limiter_type] + + return if limit_name.blank? + + timestamp = event['@timestamp'] + + for_current_idv_attempt(event:) do + add_significant_event( + type: :rate_limited, + timestamp:, + description: "Rate limited for #{limit_name}", + ) + end + end + + def handle_image_upload_vendor_submitted(event:) + timestamp = event['@timestamp'] + success = event.dig(*EVENT_PROPERTIES, 'success') + doc_type = event.dig(*EVENT_PROPERTIES, 'DocClassName') + + if success + prior_failures = current_idv_attempt.significant_events.count do |e| + e.type == :failed_document_capture + end + attempts = prior_failures > 0 ? "after #{prior_failures} tries" : 'on the first attempt' + + add_significant_event( + timestamp:, + type: :passed_document_capture, + description: "User successfully verified their #{doc_type.downcase} #{attempts}", + ) + return + end + + prev_count = current_idv_attempt.significant_events.count + + alerts = event.dig(*EVENT_PROPERTIES, 'processed_alerts') + alerts['success'] = false + alerts['vendor_name'] = event.dig(*EVENT_PROPERTIES, 'vendor') + + add_events_for_failed_vendor_result( + alerts, + timestamp:, + ) + + any_events_added = current_idv_attempt.significant_events.count > prev_count + + if !any_events_added + add_significant_event( + timestamp:, + type: :failed_document_capture, + description: "User failed to verify their #{doc_type.downcase} (check logs for reason)", + ) + end + end + + def handle_verify_proofing_results_event(event:) + timestamp = event['@timestamp'] + success = event.dig(*EVENT_PROPERTIES, 'success') + + if success + # We only really care about passing identity resolution if the + # user previously failed in this attempt + + prior_failures = current_idv_attempt.significant_events.count do |e| + e.type == :failed_identity_resolution + end + + if prior_failures > 0 + # TODO: What changed that made them be able to pass? + + add_significant_event( + timestamp:, + type: :passed_identity_resolution, + description: "User passed identity resolution after #{prior_failures + 1} tries", + ) + end + + return + end + + # Failing identity resolution is where it gets interesting + + prev_count = current_idv_attempt.significant_events.count + + add_events_for_failed_vendor_result( + event.dig( + *EVENT_PROPERTIES, 'proofing_results', 'context', 'stages', 'resolution' + ), + timestamp:, + ) + + add_events_for_failed_vendor_result( + event.dig( + *EVENT_PROPERTIES, 'proofing_results', 'context', 'stages', 'residential_address' + ), + timestamp:, + ) + + add_events_for_failed_vendor_result( + event.dig( + *EVENT_PROPERTIES, 'proofing_results', 'context', 'stages', 'state_id' + ), + timestamp:, + ) + + any_events_added = current_idv_attempt.significant_events.count > prev_count + + if !any_events_added + add_significant_event( + timestamp:, + type: :failed_identity_resolution, + description: 'User failed identity resolution (check logs for reason)', + ) + end + end + + def add_events_for_failed_vendor_result(result, timestamp:) + return if result['success'] + + vendor = VENDORS[result['vendor_name']] || UNKNOWN_VENDOR + evaluator = vendor[:evaluator_module] + + if !evaluator.present? + add_significant_event( + type: :"#{vendor[:id]}_request_failed", + timestamp:, + description: "Request to #{vendor[:name]} failed.", + ) + return + end + + evaluation = evaluator.evaluate_result(result) + add_significant_event(**evaluation, timestamp:) if evaluation + end + + # @return {IdvAttempt,nil} The previous IdvAttempt (if any) + def start_new_idv_attempt(event:) + finish_current_idv_attempt if current_idv_attempt + + @current_idv_attempt = IdvAttempt.new( + started_at: event['@timestamp'], + ) + end + + def summarize_idv_attempt(attempt) + type = :idv + title = 'Identity verification started' + attributes = attempt.significant_events.map do |e| + { + type: e.type, + timestamp: e.timestamp, + description: e.description, + } + end + + if attempt.successful? + title = 'Identity verified' + end + + { + started_at: attempt.started_at, + title:, + type:, + attributes:, + } + end + end +end diff --git a/lib/event_summarizer/vendor_result_evaluators/aamva.rb b/lib/event_summarizer/vendor_result_evaluators/aamva.rb new file mode 100644 index 00000000000..1929b8acd9f --- /dev/null +++ b/lib/event_summarizer/vendor_result_evaluators/aamva.rb @@ -0,0 +1,129 @@ +# frozen_string_literal: true + +module EventSummarizer + module VendorResultEvaluators + module Aamva + ID_TYPES = { + 'state_id_card' => 'non-driving ID card', + 'drivers_license' => "drivers' license", + }.freeze + + # TODO: Load these from the AAMVA proofer or put them somewhere common + + REQUIRED_VERIFICATION_ATTRIBUTES = %i[ + state_id_number + dob + last_name + first_name + ].freeze + + REQUIRED_IF_PRESENT_ATTRIBUTES = [:state_id_expiration].freeze + + # @param result {Hash} The result structure logged to Cloudwatch + # @return [Hash] A Hash with a type, timestamp, and description key. + def self.evaluate_result(result) + if result['success'] + return { + type: :aamva_success, + description: 'AAMVA call succeeded', + } + end + + if result['timed_out'] + return { + type: :aamva_timed_out, + description: 'AAMVA request timed out.', + } + end + + if result['mva_exception'] + state = result['state_id_jurisdiction'] + return { + type: :aamva_mva_exception, + # rubocop:disable Layout/LineLength + description: "AAMVA request failed because the MVA in #{state} failed to return a response.", + # rubocop:enable Layout/LineLength + } + end + + if result['exception'] + + description = 'AAMVA request resulted in an exception' + + m = /ExceptionText: (.+?),/.match(result['exception']) + if m.present? + description = "#{description} (#{m[1]})" + end + + return { + type: :aamva_exception, + description:, + } + end + + # The API call failed because of actual errors in the user's data. + # Try to come up with an explanation + + explanation = explain_errors(result) || 'Check logs for more info.' + + return { + type: :aamva_error, + description: "AAMVA request failed. #{explanation}", + } + end + + def self.explain_errors(result) + # The values in the errors object are arrays + attributes = {} + result['errors'].each do |key, values| + attributes[key] = values.first + end + + id_type = ID_TYPES[result['state_id_type']] || 'id card' + state = result['state_id_jurisdiction'] + + if mva_says_invalid_id_number?(attributes) + # rubocop:disable Layout/LineLength + return "The ID # from the user's #{id_type} was invalid according to the state of #{state}" + # rubocop:enable Layout/LineLength + end + + failed_attributes = relevant_failed_attributes(attributes) + + if !failed_attributes.empty? + plural = failed_attributes.length == 1 ? '' : 's' + + # rubocop:disable Layout/LineLength + "#{failed_attributes.length} attribute#{plural} failed to validate: #{failed_attributes.join(', ')}" + # rubocop:enable Layout/LineLength + end + end + + def self.mva_says_invalid_id_number?(attributes) + # When all attributes are marked "MISSING", except ID number, + # which is marked "UNVERIFIED", that indicates the MVA could not + # find the ID number to compare PII + + missing_count = attributes.count do |_attr, status| + status == 'MISSING' + end + + attributes['state_id_number'] == 'UNVERIFIED' && missing_count == attributes.count - 1 + end + + def self.relevant_failed_attributes(attributes) + failed_attributes = Set.new + + REQUIRED_VERIFICATION_ATTRIBUTES.each do |attr| + failed_attributes << attr if attributes[attr] != 'VERIFIED' + end + + REQUIRED_IF_PRESENT_ATTRIBUTES.each do |attr| + failed_attributes << attr if attributes[attr].present? && attributes[attr] != 'VERIFIED' + end + + failed_attributes + end + end + end +end diff --git a/lib/event_summarizer/vendor_result_evaluators/instant_verify.rb b/lib/event_summarizer/vendor_result_evaluators/instant_verify.rb new file mode 100644 index 00000000000..e8d7941ee0e --- /dev/null +++ b/lib/event_summarizer/vendor_result_evaluators/instant_verify.rb @@ -0,0 +1,79 @@ +# frozen_string_literal: true + +require 'active_support/core_ext/string/inflections' + +module EventSummarizer + module VendorResultEvaluators + module InstantVerify + # @param result {Hash} The result structure logged to Cloudwatch + # @return [Hash] A Hash with a type and description keys. + def self.evaluate_result(result) + if result['success'] + { + type: :instant_verify_success, + description: 'Instant Verify call succeeded', + } + elsif result['timed_out'] + { + type: :instant_verify_timed_out, + description: 'Instant Verify request timed out.', + } + elsif result['exception'] + { + type: :instant_verify_exception, + description: 'Instant Verify request resulted in an exception', + } + else + # The API call failed because of actual errors in the user's data. + # Try to come up with an explanation + + explanation = explain_errors(result) || 'Check logs for more info.' + + { + type: :instant_verify_error, + description: "Instant Verify request failed. #{explanation}", + } + end + end + + # Attempts to render a legible explanation of what went wrong in a + # LexisNexis Instant Verify request. + # @param result {Hash} The result structure logged to Cloudwatch + # @return {String} + def self.explain_errors(result) + # (The structure of the 'errors' key for Instant Verify is kind of weird) + + failed_items = [] + + result.dig('errors', 'InstantVerify')&.each do |iv_instance| + next if iv_instance['ProductStatus'] != 'fail' + iv_instance['Items'].each do |item| + if item['ItemStatus'] == 'fail' + failed_items << item + end + end + end + + if failed_items.empty? + return 'Check the full logs for more info.' + end + + checks = failed_items.map do |item| + name = item['ItemName'] + reason = item['ItemReason'] + reason_code = reason ? reason['Code'] : nil + + if reason_code + # TODO: Translate these reason codes to plain language + # TODO: Add suggestions for how the user could remedy + "#{name} (#{reason_code})" + else + name + end + end + + "#{checks.length} #{'check'.pluralize(checks.length)} failed: #{checks.join(", ")}" + end + end + end +end diff --git a/lib/event_summarizer/vendor_result_evaluators/true_id.rb b/lib/event_summarizer/vendor_result_evaluators/true_id.rb new file mode 100644 index 00000000000..f7b59694974 --- /dev/null +++ b/lib/event_summarizer/vendor_result_evaluators/true_id.rb @@ -0,0 +1,29 @@ +# frozen_string_literal: true + +module EventSummarizer + module VendorResultEvaluators + module TrueId + # @param result {Hash} The array of processed_alerts.failed logged to Cloudwatch + # @return [Hash] A Hash with a type and description keys. + def self.evaluate_result(result) + alerts = [] + result['failed'].each do |alert| + if alert['result'] == 'Failed' + alerts << { + type: :"trueid_#{alert['name'].parameterize(separator: '_')}", + description: alert['disposition'], + } + end + end + + if alerts.present? + alerts.uniq! { |a| a[:description] } + return { + type: :trueid_failures, + description: "TrueID request failed. #{alerts.map { |a| a[:description] }.join(' ')}", + } + end + end + end + end +end diff --git a/spec/bin/summarize-user-events_spec.rb b/spec/bin/summarize-user-events_spec.rb new file mode 100644 index 00000000000..9923123c849 --- /dev/null +++ b/spec/bin/summarize-user-events_spec.rb @@ -0,0 +1,187 @@ +require 'rails_helper' +load Rails.root.join('bin/summarize-user-events') + +RSpec.describe SummarizeUserEvents do + let(:user_uuid) { nil } + let(:start_time) { nil } + let(:end_time) { nil } + let(:zone) { 'America/New_York' } + let(:stdout) { StringIO.new } + let(:stderr) { StringIO.new } + + subject(:instance) do + described_class.new( + file_name: nil, + user_uuid:, + start_time:, + end_time:, + zone:, + stdout:, + stderr:, + ) + end + + describe '#normalize_event!' do + let(:event) do + { + 'name' => 'test event', + '@timestamp' => '2024-12-31 21:21:47.374', + '@message' => { + '@timestamp' => '2024-12-31 21:21:47.374', + 'name' => 'test event', + }, + } + end + + subject(:normalized_event) do + event.dup.tap do |event| + instance.normalize_event!(event) + end + end + + context 'when @message is a string' do + let(:event) do + super().tap do |event| + event['@message'] = JSON.generate(event['@message']) + end + end + it 'parses @message as JSON' do + expect(event['@message']).to be_a(String) + expect(normalized_event['@message']).to eql( + '@timestamp' => '2024-12-31 21:21:47.374', + 'name' => 'test event', + ) + end + end + + context 'when @timestamp is a string' do + it 'parses it in UTC' do + expected = Time.zone.parse('2024-12-31 21:21:47.374 UTC') + Time.use_zone('America/Los_Angeles') do + expect(normalized_event['@timestamp']).to eql(expected) + end + end + end + end + + describe '#parse_command_line_options' do + let(:argv) do + [] + end + + subject(:parsed) do + described_class.parse_command_line_options(argv) + end + + it 'parses default options' do + expect(parsed).to eql( + { zone: 'America/New_York' }, + ) + end + + context '-z' do + let(:argv) { ['-z', 'America/Los_Angeles'] } + + it 'parses zone' do + expect(parsed).to eql( + { + zone: 'America/Los_Angeles', + }, + ) + end + end + end + + describe '#parse_time' do + let(:input) { nil } + + subject(:actual) do + instance.parse_time(input) + end + + context 'with valid UTC timestamp' do + let(:input) do + '2025-01-07T19:56:03Z' + end + it 'parses it as UTC, then converts to configured zone' do + expect(actual.to_s).to eql( + '2025-01-07 14:56:03 -0500', + ) + end + end + + context 'with a timestamp with no zone specified' do + let(:input) do + '2025-01-07T19:56:03' + end + it 'parses it as UTC, then converts to configured zone' do + expect(actual.to_s).to eql( + '2025-01-07 14:56:03 -0500', + ) + end + end + + context 'with a timestamp with a different zone specified' do + let(:input) do + '2025-01-07T19:56:03 -0600' + end + it 'parses it as UTC, then converts to configured zone' do + expect(actual.to_s).to eql( + '2025-01-07 20:56:03 -0500', + ) + end + end + + context 'with an invalid time value' do + let(:input) { 'not even a time' } + it 'returns nil' do + expect(actual).to eql(nil) + end + end + + context 'with blank string' do + let(:input) { '' } + it 'returns nil' do + expect(actual).to eql(nil) + end + end + end + + describe '#run' do + subject(:command_output) do + instance.run + stdout.string + end + + let(:cloudwatch_events) do + [ + { + '@timestamp' => '2024-12-30 15:42:51.336', + '@message' => JSON.generate( + { + name: 'IdV: doc auth welcome submitted', + }, + ), + }, + ] + end + + before do + allow(instance).to receive(:cloudwatch_source) do |&block| + cloudwatch_events.each do |raw_event| + block.call(raw_event) + end + end + end + + it 'matches expected output' do + expect(command_output).to eql(<<~END) + ## Processed some events + * Processed 1 event(s) + + ## Identity verification started (December 30, 2024 at 10:42 AM EST) + * (10:42 AM) User abandoned identity verification + END + end + end +end diff --git a/spec/lib/event_summarizer/idv_matcher_spec.rb b/spec/lib/event_summarizer/idv_matcher_spec.rb new file mode 100644 index 00000000000..8c90dd3e9c4 --- /dev/null +++ b/spec/lib/event_summarizer/idv_matcher_spec.rb @@ -0,0 +1,56 @@ +require 'active_support' +require 'active_support/time' + +require 'event_summarizer/idv_matcher' + +RSpec.describe EventSummarizer::IdvMatcher do + describe '#handle_cloudwatch_event' do + let(:event) do + { + '@timestamp': '2024-01-02T03:04:05Z', + } + end + + subject(:matcher) do + described_class.new + end + + around do |example| + Time.use_zone('UTC') do + example.run + end + end + + context 'On unknown event' do + let(:event) { super().merge('name' => 'Some random event') } + it 'does not throw' do + matcher.handle_cloudwatch_event(event) + end + end + + context "On 'IdV: doc auth welcome submitted' event" do + let(:event) { super().merge('name' => 'IdV: doc auth welcome submitted') } + + it 'starts a new IdV attempt' do + matcher.handle_cloudwatch_event(event) + expect(matcher.current_idv_attempt).not_to eql(nil) + end + + context 'with an IdV attempt already started' do + before do + allow(matcher).to receive(:current_idv_attempt).and_return( + EventSummarizer::IdvMatcher::IdvAttempt.new( + started_at: Time.zone.now, + ), + ) + end + + it 'finishes it' do + expect(matcher.idv_attempts.length).to eql(0) + matcher.handle_cloudwatch_event(event) + expect(matcher.idv_attempts.length).to eql(1) + end + end + end + end +end diff --git a/spec/lib/event_summarizer/vendor_result_evaluators/instant_verify_spec.rb b/spec/lib/event_summarizer/vendor_result_evaluators/instant_verify_spec.rb new file mode 100644 index 00000000000..c22291b53f5 --- /dev/null +++ b/spec/lib/event_summarizer/vendor_result_evaluators/instant_verify_spec.rb @@ -0,0 +1,91 @@ +require 'json' +require 'event_summarizer/vendor_result_evaluators/instant_verify' + +RSpec.describe EventSummarizer::VendorResultEvaluators::InstantVerify do + let(:instant_verify_result) do + { + success: true, + errors: {}, + exception: nil, + timed_out: false, + } + end + + subject(:evaluation) do + described_class.evaluate_result( + JSON.parse(JSON.generate(instant_verify_result)), + ) + end + + context 'successful result' do + it 'looks correct' do + expect(evaluation).to eql( + { + type: :instant_verify_success, + description: 'Instant Verify call succeeded', + }, + ) + end + end + + context 'request timed out' do + let(:instant_verify_result) do + super().merge( + success: false, + errors: {}, + timed_out: true, + ) + end + + it 'reports the error appropriately' do + expect(evaluation).to eql( + { + type: :instant_verify_timed_out, + description: 'Instant Verify request timed out.', + }, + ) + end + end + + context 'failed result' do + let(:instant_verify_result) do + { + success: false, + errors: { + base: ["Verification failed with code: 'priority.scoring.model.verification.fail'"], + InstantVerify: [ + { + ProductType: 'InstantVerify', + ExecutedStepName: 'InstantVerify', + ProductConfigurationName: 'blah.config', + ProductStatus: 'fail', + ProductReason: { + Code: 'priority.scoring.model.verification.fail', + }, + Items: [ + { ItemName: 'Check1', ItemStatus: 'pass' }, + { ItemName: 'Check2', ItemStatus: 'fail' }, + { + ItemName: 'CheckWithCode', + ItemStatus: 'fail', + ItemReason: { Code: 'some_obscure_code ' }, + }, + ], + }, + ], + }, + exception: nil, + timed_out: false, + } + end + + it 'returns the correct result' do + expect(evaluation).to eql( + { + description: 'Instant Verify request failed. 2 checks failed: Check2, CheckWithCode (some_obscure_code )', # rubocop:disable Layout/LineLength + type: :instant_verify_error, + }, + ) + end + end +end