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

@@ -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