Metrics for block-level sync

app/controllers/api/v3/facilities_controller.rb

@@ -16,9 +16,11 @@ def current_facility_records
   end
 
   def other_facility_records
-    Facility
-      .with_discarded
-      .updated_on_server_since(other_facilities_processed_since, limit)
+    Statsd.instance.time("other_facility_records.Facility") do
+      Facility
+        .with_discarded
+        .updated_on_server_since(other_facilities_processed_since, limit)
+    end
   end
 
   def disable_audit_logs?
@@ -39,15 +41,16 @@ def response_process_token
   end
 
   def force_resync?
-    Rails.logger.info "Resync token modified in resource #{controller_name}" if resync_token_modified?
     resync_token_modified?
   end
 
   def records_to_sync
-    other_facility_records
-      .with_block_region_id
-      .includes(:facility_group)
-      .where.not(facility_group: nil)
+    Statsd.instance.time("records_to_sync.Facility") do
+      other_facility_records
+        .with_block_region_id
+        .includes(:facility_group)
+        .where.not(facility_group: nil)
+    end
   end
 
   private

app/controllers/api/v3/protocols_controller.rb

@@ -16,9 +16,11 @@ def current_facility_records
   end
 
   def other_facility_records
-    Protocol
-      .with_discarded
-      .updated_on_server_since(other_facilities_processed_since, limit)
+    Statsd.instance.time("other_facility_records.Protocol") do
+      Protocol
+        .with_discarded
+        .updated_on_server_since(other_facilities_processed_since, limit)
+    end
   end
 
   def disable_audit_logs?
@@ -37,7 +39,6 @@ def response_process_token
   end
 
   def force_resync?
-    Rails.logger.info "Resync token modified in resource #{controller_name}" if resync_token_modified?
     resync_token_modified?
   end
 end

app/controllers/api/v3/sync_controller.rb

@@ -11,10 +11,14 @@ def __sync_from_user__(params)
   end
 
   def __sync_to_user__(response_key)
-    AuditLog.create_logs_async(current_user, records_to_sync, "fetch", Time.current) unless disable_audit_logs?
+    records = records_to_sync
+
+    AuditLog.create_logs_async(current_user, records, "fetch", Time.current) unless disable_audit_logs?
+    log_block_level_sync_metrics(response_key)
+
     render(
       json: {
-        response_key => records_to_sync.map { |record| transform_to_response(record) },
+        response_key => records.map { |record| transform_to_response(record) },
         "process_token" => encode_process_token(response_process_token)
       },
       status: :ok
@@ -35,6 +39,27 @@ def disable_audit_logs?
     false
   end
 
+  def log_block_level_sync_metrics(response_key)
+    Rails.logger.tagged("Block Sync") do
+      if resync_token_modified?
+        Rails.logger.info msg: "Resync token modified", resource: response_key
+      end
+
+      if current_user
+        if sync_region_modified?
+          Rails.logger.info msg: "Sync region ID modified",
+                            region_type: current_sync_region.class.name,
+                            region_id: current_sync_region.id,
+                            resource: response_key
+        end
+
+        if block_level_sync?
+          Rails.logger.info msg: "The current_sync_region set to block", block_id: current_block.id
+        end
+      end
+    end
+  end
+
   def params_with_errors(params, errors)
     error_ids = errors.map { |error| error[:id] }
     params

app/controllers/api_controller.rb

@@ -38,10 +38,7 @@ def current_sync_region
     # allow other region types as well
     return current_facility_group if requested_sync_region_id.blank?
     return current_facility_group if requested_sync_region_id == current_facility_group.id
-    if block_level_sync?
-      Rails.logger.info "current_sync_region set to block #{current_block.id} for user #{current_user.id}"
-      return current_block
-    end
+    return current_block if block_level_sync?
 
     current_facility_group
   end

app/controllers/concerns/api/v3/sync_to_user.rb

@@ -8,23 +8,29 @@ def region_records
     end
 
     def current_facility_records
-      region_records
-        .where(patient: prioritized_patients)
-        .updated_on_server_since(current_facility_processed_since, limit)
+      Statsd.instance.time("current_facility_records.#{model.name}") do
+        region_records
+          .where(patient: prioritized_patients)
+          .updated_on_server_since(current_facility_processed_since, limit)
+      end
     end
 
     def other_facility_records
-      other_facilities_limit = limit - current_facility_records.count
+      Statsd.instance.time("other_facility_records.#{model.name}") do
+        other_facilities_limit = limit - current_facility_records.count
 
-      region_records
-        .where.not(patient: prioritized_patients)
-        .updated_on_server_since(other_facilities_processed_since, other_facilities_limit)
+        region_records
+          .where.not(patient: prioritized_patients)
+          .updated_on_server_since(other_facilities_processed_since, other_facilities_limit)
+      end
     end
 
     private
 
     def records_to_sync
-      current_facility_records + other_facility_records
+      Statsd.instance.time("records_to_sync.#{model.name}") do
+        current_facility_records + other_facility_records
+      end
     end
 
     def prioritized_patients
@@ -68,8 +74,6 @@ def current_facility_processed_since
     end
 
     def force_resync?
-      Rails.logger.info "[force_resync] Resync token modified in resource #{controller_name}" if resync_token_modified?
-      Rails.logger.info "[force_resync] Sync region modified in resource #{controller_name}" if sync_region_modified?
       resync_token_modified? || sync_region_modified?
     end
 

app/services/report_duplicate_passports.rb

@@ -0,0 +1,56 @@
+class ReportDuplicatePassports
+  include Memery
+
+  IDENTIFIER_TYPES = %w[simple_bp_passport]
+  delegate :logger, to: Rails
+
+  def self.report
+    new.report
+  end
+
+  def report
+    logger.tagged("ReportDuplicatePassports") do
+      logger.info msg: "#{duplicate_passports_count} passports have duplicate patients across facilities"
+    end
+
+    Statsd.instance.gauge("ReportDuplicatePassports.size", duplicate_passports_count)
+  end
+
+  memoize def duplicate_passports_count
+    passports_at_multiple_facilities
+      .where(identifier: passports_with_multiple_patients)
+      .where(identifier_type: IDENTIFIER_TYPES)
+      .pluck(:identifier)
+      .count
+  end
+
+  # this is a utility function for fetching the actual duplicate passports
+  # you could call this and get counts from it but duplicate_passports_count is faster
+  # leaving this here as useful method for debugging
+  def duplicate_passports
+    PatientBusinessIdentifier
+      .where(identifier_type: IDENTIFIER_TYPES)
+      .where(identifier: passports_at_multiple_facilities)
+      .where(identifier: passports_with_multiple_patients)
+  end
+
+  def passports_at_multiple_facilities
+    PatientBusinessIdentifier
+      .group(:identifier)
+      .having("COUNT(DISTINCT #{passport_assigning_facility}) > 1")
+      .select(:identifier)
+  end
+
+  def passports_with_multiple_patients
+    PatientBusinessIdentifier
+      .group(:identifier)
+      .having("COUNT(DISTINCT patient_id) > 1")
+      .select(:identifier)
+  end
+
+  private
+
+  def passport_assigning_facility
+    "COALESCE((metadata->'assigning_facility_id'), (metadata->'assigningFacilityUuid'))::text"
+  end
+end

config/schedule.rb

@@ -40,6 +40,10 @@ def local(time)
   rake "db:seed_users_data"
 end
 
+every :day, at: local("05:00 am"), roles: [:cron] do
+  runner "ReportDuplicatePassports.report"
+end
+
 every :monday, at: local("6:00 am"), roles: [:cron] do
   if Flipper.enabled?(:weekly_telemed_report)
     rake "reports:telemedicine"

lib/statsd.rb

@@ -7,5 +7,5 @@ def initialize
 
   attr_reader :statsd
 
-  delegate :increment, :time, :timing, to: :statsd
+  delegate :increment, :time, :timing, :gauge, to: :statsd
 end

lib/tasks/block_level_sync.rake

@@ -39,9 +39,11 @@ def set_block_level_sync(user, enable)
       else
         Flipper.disable(:block_level_sync, user)
       end
-      Rails.logger.info "Block level sync #{enable ? "enabled" : "disabled"} for #{user.id}"
+      Rails.logger.info msg: "Block level sync #{enable ? "enabled" : "disabled"} for #{user.id}",
+                        block_level_sync_enabled_user_id: user.id
     else
-      Rails.logger.info "User #{user.id} does not have a phone number authentication"
+      Rails.logger.info msg: "User #{user.id} does not have a phone number authentication",
+                        block_level_sync_disabled_user_id: user.id
     end
   end
 end

spec/services/report_duplicate_passports_spec.rb

@@ -0,0 +1,56 @@
+require "rails_helper"
+
+RSpec.describe ReportDuplicatePassports do
+  describe ".duplicate_passports" do
+    context "for passports with the same identifiers" do
+      let!(:identifier) { SecureRandom.uuid }
+
+      it "does not have passports with same patient at the same facility" do
+        facility_id = SecureRandom.uuid
+        patient = create(:patient, business_identifiers: [])
+        create_list(:patient_business_identifier, 2, identifier: identifier, patient: patient, metadata: {assigningFacilityUuid: facility_id})
+
+        expect(described_class.new.duplicate_passports).to be_empty
+      end
+
+      it "does not have passports with duplicate patients (different by id) at the same facility" do
+        facility_id = SecureRandom.uuid
+        patients = create_list(:patient, 2, business_identifiers: [])
+        patients.map do |patient|
+          create(:patient_business_identifier, identifier: identifier, patient: patient, metadata: {assigningFacilityUuid: facility_id})
+        end
+
+        expect(described_class.new.duplicate_passports).to be_empty
+      end
+
+      it "does not have passports with the same patient assigned to it at different facilities" do
+        patient = create(:patient, business_identifiers: [])
+        create(:patient_business_identifier, identifier: identifier, patient: patient, metadata: {assigningFacilityUuid: SecureRandom.uuid})
+        create(:patient_business_identifier, identifier: identifier, patient: patient, metadata: {assigningFacilityUuid: SecureRandom.uuid})
+
+        expect(described_class.new.duplicate_passports).to be_empty
+      end
+
+      it "only has different patients assigned to a passport at different facilities" do
+        patients = create_list(:patient, 2, business_identifiers: [])
+        identifiers =
+          [create(:patient_business_identifier, identifier: identifier, patient: patients.first, metadata: {assigningFacilityUuid: SecureRandom.uuid}),
+            create(:patient_business_identifier, identifier: identifier, patient: patients.second, metadata: {assigningFacilityUuid: SecureRandom.uuid})]
+
+        expect(described_class.new.duplicate_passports).to match_array identifiers
+        expected_count = described_class.new.duplicate_passports.group(:identifier).count.keys.count
+        expect(described_class.new.duplicate_passports_count).to eq(expected_count)
+      end
+    end
+
+    context "for passports without the same identifiers" do
+      it "does not count them" do
+        patients = create_list(:patient, 2, business_identifiers: [])
+        create(:patient_business_identifier, identifier: SecureRandom.uuid, patient: patients.first, metadata: {assigningFacilityUuid: SecureRandom.uuid})
+        create(:patient_business_identifier, identifier: SecureRandom.uuid, patient: patients.second, metadata: {assigningFacilityUuid: SecureRandom.uuid})
+
+        expect(described_class.new.duplicate_passports).to be_empty
+      end
+    end
+  end
+end