Merge pull request #5334 from coopdevs/output-logs-in-djs-log-file

Output logs in Delayed Job's log file

app/jobs/job_logger.rb

@@ -0,0 +1,18 @@
+# frozen_string_literal: false
+
+module JobLogger
+  class Formatter < ::Logger::Formatter
+    def call(_severity, timestamp, _progname, msg)
+      time = timestamp.strftime('%FT%T%z')
+      "#{time}: #{msg.is_a?(String) ? msg : msg.inspect}\n"
+    end
+  end
+
+  def self.logger
+    @logger ||= begin
+                  logger = Delayed::Worker.logger.clone
+                  logger.formatter = Formatter.new
+                  logger
+                end
+  end
+end

app/jobs/subscription_confirm_job.rb

@@ -24,7 +24,7 @@ class SubscriptionConfirmJob
 
     # Confirm these proxy orders
     ProxyOrder.where(id: unconfirmed_proxy_orders_ids).each do |proxy_order|
-      Rails.logger.info "Confirming Order for Proxy Order #{proxy_order.id}"
+      JobLogger.logger.info "Confirming Order for Proxy Order #{proxy_order.id}"
       confirm_order!(proxy_order.order)
     end
 

app/jobs/subscription_placement_job.rb

@@ -28,7 +28,7 @@ class SubscriptionPlacementJob
   end
 
   def place_order_for(proxy_order)
-    Rails.logger.info "Placing Order for Proxy Order #{proxy_order.id}"
+    JobLogger.logger.info("Placing Order for Proxy Order #{proxy_order.id}")
     proxy_order.initialise_order!
     place_order(proxy_order.order)
   end

engines/order_management/app/services/order_management/subscriptions/summarizer.rb

@@ -18,7 +18,7 @@ module OrderManagement
       end
 
       def record_issue(type, order, message = nil)
-        Rails.logger.info "Issue in Subscription Order #{order.id}: #{type}"
+        JobLogger.logger.info("Issue in Subscription Order #{order.id}: #{type}")
         summary_for(order).record_issue(type, order, message)
       end
 
@@ -28,7 +28,7 @@ module OrderManagement
         error = "Subscription#{type.to_s.camelize}Error"
         line1 = "#{error}: Cannot process order #{order.number} due to errors"
         line2 = "Errors: #{order.errors.full_messages.join(', ')}"
-        Rails.logger.info("#{line1}\n#{line2}")
+        JobLogger.logger.info("#{line1}\n#{line2}")
         record_issue(type, order, line2)
       end
 

engines/order_management/spec/services/order_management/subscriptions/summarizer_spec.rb

@@ -8,7 +8,7 @@ module OrderManagement
       let(:order) { create(:order) }
       let(:summarizer) { OrderManagement::Subscriptions::Summarizer.new }
 
-      before { allow(Rails.logger).to receive(:info) }
+      before { allow(JobLogger.logger).to receive(:info) }
 
       describe "#summary_for" do
         let(:order) { double(:order, distributor_id: 123) }

spec/jobs/job_logger_spec.rb

@@ -0,0 +1,28 @@
+require 'spec_helper'
+
+describe JobLogger do
+  describe '.logger' do
+    it 'passes the message to the Logger instance' do
+      job_logger = instance_double(::Logger)
+      allow(job_logger).to receive(:formatter=)
+      allow(job_logger).to receive(:info)
+
+      worker_logger = instance_double(::Logger, clone: job_logger)
+      allow(Delayed::Worker).to receive(:logger) { worker_logger }
+
+      JobLogger.logger.info('log message')
+
+      expect(job_logger).to have_received(:info).with('log message')
+    end
+  end
+
+  describe JobLogger::Formatter do
+    describe '#call' do
+      it 'outputs timestamps, progname and message' do
+        timestamp = DateTime.new(2020,5,6, 22, 36, 0)
+        log_line = JobLogger::Formatter.new.call(nil, timestamp, 'progname', 'message')
+        expect(log_line).to eq("2020-05-06T22:36:00+0000: message\n")
+      end
+    end
+  end
+end