AP-513 improving order of operations (#21)

* AP-513 improving logging order of operations
- co-authored with @danschmidt5189
- some logs were still not getting request_id logged
- we believe there an issue with when the two around_performs were
  called
* serializes request_id when queued

Author: jason-raitz

app/jobs/application_job.rb

@@ -1,24 +1,33 @@
 class ApplicationJob < ActiveJob::Base
-  attr_reader :request_id
+  attr_accessor :request_id
 
-  before_enqueue do
-    arguments << { request_id: Current.request_id } if Current.request_id
+  before_enqueue do |job|
+    job.request_id = 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
+  before_perform :restore_request_id, :log_job_metadata
+
+  def serialize
+    super.merge('request_id' => request_id)
   end
 
-  around_perform :log_job_metadata
+  def deserialize(job_data)
+    super
+    self.request_id = job_data['request_id']
+  end
 
   def today
     @today ||= Time.zone.now.strftime('%Y%m%d')
   end
 
+  private
+
+  def restore_request_id
+    self.request_id ||= Current.request_id
+  end
+
   def log_job_metadata
-    logger.with_fields = { activejob_id: job_id, request_id: @request_id }
-    yield
+    logger.with_fields = { activejob_id: job_id, request_id: request_id }
   end
 
   # Log an exception

spec/jobs/application_job_spec.rb

@@ -22,19 +22,15 @@ def perform(*args); 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 }
+        end.to have_enqueued_job(TestJob)
 
-        expect(job.instance_variable_get(:@request_id)).to eq(request_id)
-        expect(job.arguments).to eq(['some_arg'])
+        enqueued_job = ActiveJob::Base.queue_adapter.enqueued_jobs.last
+        expect(enqueued_job[:args]).to eq(['some_arg'])
+        expect(enqueued_job['request_id']).to eq(request_id)
       end
 
       it 'logs the activejob_id and request_id' do
-        job = TestJob.new('some_arg', { request_id: request_id })
+        job = TestJob.new('some_arg')
         allow(job.logger).to receive(:with_fields=)
 
         perform_enqueued_jobs { job.perform_now }
@@ -50,14 +46,17 @@ def perform(*args); end
         expect do
           TestJob.perform_later('some_arg')
         end.to have_enqueued_job(TestJob).with('some_arg')
+
+        enqueued_job = ActiveJob::Base.queue_adapter.enqueued_jobs.last
+        expect(enqueued_job['request_id']).to be_nil
       end
 
-      it 'does not set @request_id if not provided' do
+      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'])
+        expect(job.request_id).to be_nil
       end
 
       it 'logs the activejob_id without a request_id' do