diff --git a/app/jobs/job_logger.rb b/app/jobs/job_logger.rb new file mode 100644 index 0000000000..c45f2fa32d --- /dev/null +++ b/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 diff --git a/app/jobs/subscription_confirm_job.rb b/app/jobs/subscription_confirm_job.rb index 748257a340..9ed8223d0e 100644 --- a/app/jobs/subscription_confirm_job.rb +++ b/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 diff --git a/app/jobs/subscription_placement_job.rb b/app/jobs/subscription_placement_job.rb index 44a4a27c75..adfbe5cba1 100644 --- a/app/jobs/subscription_placement_job.rb +++ b/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 diff --git a/engines/order_management/app/services/order_management/subscriptions/summarizer.rb b/engines/order_management/app/services/order_management/subscriptions/summarizer.rb index 0642e22044..8029716338 100644 --- a/engines/order_management/app/services/order_management/subscriptions/summarizer.rb +++ b/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 diff --git a/engines/order_management/spec/services/order_management/subscriptions/summarizer_spec.rb b/engines/order_management/spec/services/order_management/subscriptions/summarizer_spec.rb index 09013c204c..d6eca4d26a 100644 --- a/engines/order_management/spec/services/order_management/subscriptions/summarizer_spec.rb +++ b/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) } diff --git a/spec/jobs/job_logger_spec.rb b/spec/jobs/job_logger_spec.rb new file mode 100644 index 0000000000..768f050150 --- /dev/null +++ b/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