APPEALS-29120 - Enhance hlr_sync_lock with logging (#19259)

* APPEALS-29120 - init commit, fixed linting and code climate issues rspec passes

* APPEALS-29120 - added Rails.logger.info for lock_key creation. confirmed in log works, and updated 1.9ruby hash syntax

* APPEALS-29120 - added Rails.logger for lock_key being deleted

* APPEALS-29120 - updated verbage from deleted to released

* APPEALS-29120 - refactored Rails.logger for release, added Error logging,and added to rspec test

* APPEALS-29120- fixed CodeClimate/Linting issues

* APPEALS-29120 - fixed more CodeClimate/Linting issues

* APPEALS-29120 - disabled FeatureEnvy smell

* APPEALS-29120 - fixed more linting issues

* added line break after frozen_string_literal

* APPEALS-29120 - add code coverage for new logger for hlr_sync_lock creation and release in request_issue_spec.rb

* removed end_product_establishment_ids variable since its now being used

* removed commas

* APPEALS-29120 - added magic comment

* commit to init GHA

---------

Co-authored-by: TuckerRose <[email protected]>

app/jobs/decision_issue_sync_job.rb

@@ -15,6 +15,7 @@ def perform(request_issue_or_effectuation)
       request_issue_or_effectuation.update_error!(error.inspect)
       request_issue_or_effectuation.update!(decision_sync_attempted_at: Time.zone.now - 11.hours - 55.minutes)
       capture_exception(error: error)
+      Rails.logger.error error.inspect
     rescue Errno::ETIMEDOUT => error
       # no Raven report. We'll try again later.
       Rails.logger.error error

app/models/concerns/sync_lock.rb

@@ -10,17 +10,22 @@ def hlr_sync_lock
     if decision_review.is_a?(HigherLevelReview) && block_given?
       redis = Redis.new(url: Rails.application.secrets.redis_url_cache)
       lock_key = "hlr_sync_lock:#{end_product_establishment.id}"
+      Rails.logger.info(lock_key + " has been created")
 
       begin
-        # create the sync lock with a key, value pair only IF it doesn't already exist and give it an expiration time upon creation
-        sync_lock_acquired = redis.set(lock_key, "lock is set", :nx => true, :ex => LOCK_TIMEOUT.to_i)
+        # create the sync lock with a key, value pair only IF it doesn't already exist
+        # and give it an expiration time upon creation.
+        sync_lock_acquired = redis.set(lock_key, "lock is set", nx: true, ex: LOCK_TIMEOUT.to_i)
+
+        fail Caseflow::Error::SyncLockFailed, message: Time.zone.now.to_s unless sync_lock_acquired
 
-        fail Caseflow::Error::SyncLockFailed, message: "#{Time.zone.now}" unless sync_lock_acquired
-        # set expire as another failsafe
-        redis.expire(lock_key, LOCK_TIMEOUT.to_i)
         yield
       ensure
         redis.del(lock_key)
+        # if lock_key is false then log has been released
+        unless redis.get(lock_key)
+          Rails.logger.info(lock_key + " has been released")
+        end
       end
     elsif block_given?
       yield

scripts/enable_features_dev.rb

@@ -59,9 +59,9 @@ def call
   cavc_dashboard_workflow
   poa_auto_refresh
   interface_version_2
-  cc_vacatur_visibility,
-  acd_disable_legacy_distributions,
-  acd_disable_nonpriority_distributions,
+  cc_vacatur_visibility
+  acd_disable_legacy_distributions
+  acd_disable_nonpriority_distributions
   acd_disable_legacy_lock_ready_appeals
 ]
 

scripts/remove_rs_claims_decision_issues_and_request_decision_issues.rb

@@ -1,5 +1,6 @@
+# frozen_string_literal: true
 
-end_product_establishment_ids = [4142,4143,4144,4145]
+# :reek:FeatureEnvy
 def remove_rs_claims_decision_issues_and_request_decision_issues(end_product_establishment_ids)
   request_issues = RequestIssue.where(end_product_establishment_id: end_product_establishment_ids)
   request_issues.each do |request_issue|
@@ -16,7 +17,7 @@ def remove_rs_claims_decision_issues_and_request_decision_issues(end_product_est
         decision_review_remanded: di.decision_review,
         benefit_type: di.benefit_type
       )
-      supplemental_claim.destroy if supplemental_claim
+      supplemental_claim&.destroy if supplemental_claim
       di.destroy
     end
     request_issue.update(closed_at: nil, closed_status: nil)

spec/jobs/decision_issue_sync_job_spec.rb

@@ -5,7 +5,7 @@
   let(:request_issue) { create(:request_issue, end_product_establishment: epe) }
   let(:no_ratings_err) { Rating::NilRatingProfileListError.new("none!") }
   let(:bgs_transport_err) { BGS::ShareError.new("network!") }
-  let(:sync_lock_err) {Caseflow::Error::SyncLockFailed.new("#{Time.zone.now}")}
+  let(:sync_lock_err) { Caseflow::Error::SyncLockFailed.new(Time.zone.now.to_s) }
 
   subject { described_class.perform_now(request_issue) }
 
@@ -47,11 +47,13 @@
   it "logs SyncLock errors" do
     capture_raven_log
     allow(request_issue).to receive(:sync_decision_issues!).and_raise(sync_lock_err)
+    allow(Rails.logger).to receive(:error)
 
     subject
     expect(request_issue.decision_sync_error).to eq("#<Caseflow::Error::SyncLockFailed: #{Time.zone.now}>")
     expect(request_issue.decision_sync_attempted_at).to be_within(5.minutes).of 12.hours.ago
     expect(@raven_called).to eq(false)
+    expect(Rails.logger).to have_received(:error).with(sync_lock_err)
   end
 
   it "ignores error on success" do

spec/models/request_issue_spec.rb

@@ -2191,15 +2191,18 @@
           it "prevents a request issue from acquiring the SyncLock when there is already a lock using the EPE's ID" do
             redis = Redis.new(url: Rails.application.secrets.redis_url_cache)
             lock_key = "hlr_sync_lock:#{epe.id}"
-            redis.set(lock_key, "lock is set", :nx => true, :ex => 5.seconds)
+            redis.set(lock_key, "lock is set", nx: true, ex: 5.seconds)
             expect { request_issue1.sync_decision_issues! }.to raise_error(sync_lock_err)
             redis.del(lock_key)
           end
 
           it "allows a request issue to sync if there is no existing lock using the EPE's ID" do
+            epe_id = request_issue2.end_product_establishment.id.to_s
+            allow(Rails.logger).to receive(:info)
             expect(request_issue2.sync_decision_issues!).to eq(true)
+            expect(Rails.logger).to have_received(:info).with("hlr_sync_lock:" + epe_id + " has been created")
             expect(request_issue2.processed?).to eq(true)
-
+            expect(Rails.logger).to have_received(:info).with("hlr_sync_lock:" + epe_id + " has been released")
             expect(SupplementalClaim.count).to eq(1)
           end
 
@@ -2213,11 +2216,11 @@
             sc = SupplementalClaim.first
             expect(sc.request_issues.count).to eq(2)
             supplemental_claim_request_issue1 = sc.request_issues.first
-            supplemental_claim_request_issue2= sc.request_issues.last
+            supplemental_claim_request_issue2 = sc.request_issues.last
 
             # both request issues link to the same SupplementalClaim
-            expect(sc.id).to eq (request_issue1.end_product_establishment.source.remand_supplemental_claims.first.id)
-            expect(sc.id).to eq (request_issue2.end_product_establishment.source.remand_supplemental_claims.first.id)
+            expect(sc.id).to eq(request_issue1.end_product_establishment.source.remand_supplemental_claims.first.id)
+            expect(sc.id).to eq(request_issue2.end_product_establishment.source.remand_supplemental_claims.first.id)
 
             # DecisionIssue ID should match contested_decision_issue_id
             expect(DecisionIssue.count).to eq(2)
@@ -2227,7 +2230,6 @@
             expect(decision_issue1.id).to eq(supplemental_claim_request_issue1.contested_decision_issue_id)
             expect(decision_issue2.id).to eq(supplemental_claim_request_issue2.contested_decision_issue_id)
           end
-
         end
       end
     end