AP-513 & AP-186 improve log tracing (#18)

* adds a few values to good_job logs when available
When active_jobs are enqueued, this will add current_attributes for jobid, request_id, and ip_address.

Closes AP-513 & AP-186

Co-authored-by @steve-sullivan

Author: jason-raitz

app/controllers/application_controller.rb

@@ -3,6 +3,8 @@ class ApplicationController < ActionController::Base
   include AuthSupport
   include ExceptionHandling
 
+  before_action :set_current_request_id
+
   # @!group Class Attributes
   # @!attribute [rw]
   # Value of the "Questions?" mailto link in the footer
@@ -19,6 +21,10 @@ class ApplicationController < ActionController::Base
 
   private
 
+  def set_current_request_id
+    Current.request_id = request.request_id
+  end
+
   helper_method :authenticated?
 
   # @return Regexp Pattern determining whether a request should be "hidden"

app/jobs/application_job.rb

@@ -1,8 +1,26 @@
 class ApplicationJob < ActiveJob::Base
+  attr_reader :request_id
+
+  before_enqueue do
+    arguments << { request_id: Current.request_id } if Current.request_id
+  end
+
+  around_perform do |job, block|
+    @request_id = job.arguments.pop[:request_id] if job.arguments.last.is_a?(Hash) && job.arguments.last.key?(:request_id)
+    block.call
+  end
+
+  around_perform :log_job_metadata
+
   def today
     @today ||= Time.zone.now.strftime('%Y%m%d')
   end
 
+  def log_job_metadata
+    logger.with_fields = { activejob_id: job_id, request_id: @request_id }
+    yield
+  end
+
   # Log an exception
   def log_error(error)
     # TODO: share code w/ApplicationController

app/models/current.rb

@@ -0,0 +1,5 @@
+# see AP-513. We're bringing in Current here in order to attach the original request_id to a queued job
+class Current < ActiveSupport::CurrentAttributes
+  attribute :request_id
+
+end

spec/jobs/application_job_spec.rb

@@ -0,0 +1,73 @@
+require 'rails_helper'
+
+class TestJob < ApplicationJob
+  def perform(*args); end
+end
+
+RSpec.describe ApplicationJob, type: :job do
+  include ActiveJob::TestHelper
+
+  after do
+    ActiveJob::Base.queue_adapter.enqueued_jobs.clear
+  end
+
+  describe 'jobs with request_id' do
+    let(:request_id) { SecureRandom.uuid }
+
+    context 'when Current.request_id is set' do
+      before do
+        allow(Current).to receive(:request_id).and_return(request_id)
+      end
+
+      it 'enqueues the job with the request_id' do
+        expect do
+          TestJob.perform_later('some_arg')
+        end.to have_enqueued_job(TestJob).with('some_arg', { request_id: request_id })
+      end
+
+      it 'sets @request_id and removes it from the arguments' do
+        job = TestJob.new('some_arg', { request_id: request_id })
+        perform_enqueued_jobs { job.perform_now }
+
+        expect(job.instance_variable_get(:@request_id)).to eq(request_id)
+        expect(job.arguments).to eq(['some_arg'])
+      end
+
+      it 'logs the activejob_id and request_id' do
+        job = TestJob.new('some_arg', { request_id: request_id })
+        allow(job.logger).to receive(:with_fields=)
+
+        perform_enqueued_jobs { job.perform_now }
+
+        expect(job.logger).to have_received(:with_fields=).with(hash_including(activejob_id: job.job_id, request_id: request_id))
+      end
+    end
+  end
+
+  describe 'jobs without a request_id' do
+    context 'when Current.request_id is not set' do
+      it 'enqueues the job without a request_id' do
+        expect do
+          TestJob.perform_later('some_arg')
+        end.to have_enqueued_job(TestJob).with('some_arg')
+      end
+
+      it 'does not set @request_id if not provided' do
+        job = TestJob.new('some_arg')
+        perform_enqueued_jobs { job.perform_now }
+
+        expect(job.instance_variable_get(:@request_id)).to be_nil
+        expect(job.arguments).to eq(['some_arg'])
+      end
+
+      it 'logs the activejob_id without a request_id' do
+        job = TestJob.new('some_arg')
+        allow(job.logger).to receive(:with_fields=)
+
+        perform_enqueued_jobs { job.perform_now }
+
+        expect(job.logger).to have_received(:with_fields=).with(hash_including(activejob_id: job.job_id, request_id: nil))
+      end
+    end
+  end
+end