Merge pull request #43 from alphagov/error-handling-2

Properly set up logging for worker; log errors

lib/document_sync_worker.rb

@@ -18,12 +18,19 @@ def self.configure
     yield(configuration)
   end
 
+  def self.logger
+    configuration.logger
+  end
+
   def self.run
+    logger.info("Starting DocumentSyncWorker")
     GovukMessageQueueConsumer::Consumer.new(
       queue_name: DocumentSyncWorker.configuration.message_queue_name,
       processor: DocumentSyncWorker::MessageProcessor.new(
         repository: configuration.repository,
       ),
     ).run
+  rescue Interrupt
+    logger.info("Stopping DocumentSyncWorker (received interrupt)")
   end
 end

lib/document_sync_worker/configuration.rb

@@ -3,7 +3,18 @@ class Configuration
     attr_accessor :logger, :message_queue_name, :repository
 
     def initialize
-      @logger = Logger.new($stdout, progname: "DocumentSyncWorker")
+      @logger = ActiveSupport::Logger.new($stdout, progname: "DocumentSyncWorker")
+      @logger.formatter = proc do |level, datetime, progname, message|
+        hash = {
+          message:,
+          level:,
+          progname:,
+          "@timestamp": datetime.utc.iso8601(3),
+          tags: %w[document_sync_worker],
+        }
+
+        "#{hash.to_json}\n"
+      end
     end
   end
 end

lib/document_sync_worker/message_processor.rb

@@ -13,19 +13,24 @@ def process(message)
       document.synchronize_to(repository)
 
       message.ack
-    rescue StandardError
+    rescue StandardError => e
       # TODO: Consider options for handling errors more granularly, and for differentiating between
       # retriable (e.g. transient connection issue in repository) and fatal (e.g. malformed document
-      # on queue) errors. For now while we aren't live, send the message to Sentry and reject it to
-      # avoid unnecessary retries that would probably fail again while we're very actively
-      # iterating.
-      extra_info = if message.payload.is_a?(Hash)
-                     # Omit details as it may be large and take us over the Sentry metadata limit
-                     message.payload.except("details")
-                   else
-                     { message_payload: message.payload.to_s }
-                   end
-      GovukError.notify("Failed to process incoming document message", extra: extra_info)
+      # on queue) errors. For now while we aren't live, log an error, send the error to Sentry, and
+      # reject the message to avoid unnecessary retries that would probably fail again while we're
+      # very actively iterating.
+      payload = if message.payload.is_a?(Hash)
+                  # Omit details as it may be large and is probably unnecessary
+                  message.payload.except("details")
+                else
+                  message.payload
+                end
+      DocumentSyncWorker.logger.error(<<~MSG)
+        Failed to process incoming document message:
+        #{e.class}: #{e.message}
+        Message content: #{payload.inspect}
+      MSG
+      GovukError.notify(e)
 
       message.discard
     end

lib/tasks/document_sync_worker.rake

@@ -29,7 +29,7 @@ namespace :document_sync_worker do
       # TODO: Once we have access to the search product and written a repository for it, this should
       #  be set to the real repository. Until then, this allows us to verify that the pipeline is
       #  working as expected through the logs.
-      config.repository = Repositories::Null::Repository.new
+      config.repository = Repositories::Null::Repository.new(logger: config.logger)
       config.message_queue_name = ENV.fetch("PUBLISHED_DOCUMENTS_MESSAGE_QUEUE_NAME")
     end
 

spec/lib/document_sync_worker/message_processor_spec.rb

@@ -31,18 +31,29 @@
     end
 
     context "when creating the document fails" do
+      let(:logger) { instance_double(Logger, error: nil) }
+      let(:error) { RuntimeError.new("Something went wrong") }
+
       before do
-        allow(DocumentSyncWorker::Document).to receive(:for).and_raise("Something went wrong")
+        allow(DocumentSyncWorker::Document).to receive(:for).and_raise(error)
+        allow(DocumentSyncWorker).to receive(:logger).and_return(logger)
         allow(GovukError).to receive(:notify)
       end
 
-      it "reports the error to Sentry" do
+      it "logs the error" do
+        processor.process(message)
+
+        expect(logger).to have_received(:error).with(<<~MSG)
+          Failed to process incoming document message:
+          RuntimeError: Something went wrong
+          Message content: {\"I am\"=>\"a message\"}
+        MSG
+      end
+
+      it "sends the error to Sentry" do
         processor.process(message)
 
-        expect(GovukError).to have_received(:notify).with(
-          "Failed to process incoming document message",
-          extra: payload,
-        )
+        expect(GovukError).to have_received(:notify).with(error)
       end
 
       it "rejects the message" do