From ee94101edda9b967dc988ee1c0f46f3a2cc1086f Mon Sep 17 00:00:00 2001 From: Pau Perez Date: Thu, 30 Apr 2020 17:36:48 +0200 Subject: [PATCH] Log subs jobs to DJ's log file There's a bunch of logging bits we need to find out what happened in `#5294`, the first of which is logging as we are used to for Rails itself. Turns out we were already logging but the log lines weren't displayed. That's because workers have no access to the Rails logger unless we hack things a bit in the config/initializer. If we want to keep DJ's logs in a different file, which I think is good for debugging purposes, we need to diverge from Rails.logger. However, there's no access to Delayed::Worker.logger in custom job classes either so there's no way other than mimicking that logger's format if we want log lines to be consistent. Now the current logs will see the light like: ``` 2020-05-07T14:09:42+0000: [Worker(host:8dc5e7e6f434 pid:1)] Job SubscriptionPlacementJob (id=54) RUNNING 2020-05-07T14:09:42+0000: Placing Order for Proxy Order 1 2020-05-07T14:09:42+0000: Issue in Subscription Order 2: complete 2020-05-07T14:09:42+0000: Placing Order for Proxy Order 7 2020-05-07T14:09:42+0000: Issue in Subscription Order 3: complete 2020-05-07T14:09:43+0000: [Worker(host:8dc5e7e6f434 pid:1)] Job SubscriptionPlacementJob (id=54) COMPLETED after 0.3378 2020-05-07T14:09:43+0000: [Worker(host:8dc5e7e6f434 pid:1)] 1 jobs processed at 2.8054 j/s, 0 failed ``` We'll see if we need to format these messages differently to make them more greppeable. --- app/jobs/job_logger.rb | 18 ++++++++++++ app/jobs/subscription_confirm_job.rb | 2 +- app/jobs/subscription_placement_job.rb | 2 +- .../subscriptions/summarizer.rb | 4 +-- .../subscriptions/summarizer_spec.rb | 2 +- spec/jobs/job_logger_spec.rb | 28 +++++++++++++++++++ 6 files changed, 51 insertions(+), 5 deletions(-) create mode 100644 app/jobs/job_logger.rb create mode 100644 spec/jobs/job_logger_spec.rb 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