Merge pull request #107 from alphagov/better-logging

Improve logging across sync code

app/models/concerns/publishing_api/metadata.rb

@@ -59,12 +59,12 @@ def metadata
       }.compact_blank
     end
 
-  private
-
     def link
       document_hash[:base_path].presence || document_hash.dig(:details, :url)
     end
 
+  private
+
     def link_relative?
       link&.start_with?("/")
     end

app/models/publishing_api_document.rb

@@ -20,15 +20,29 @@ def initialize(
 
   def synchronize
     if publish?
+      log("put")
       put_service.call(content_id, metadata, content:, payload_version:)
     elsif unpublish?
+      log("delete")
       delete_service.call(content_id, payload_version:)
     else
-      Rails.logger.info("Ignoring document '#{content_id}': #{ignore_reason}")
+      log("ignore (#{ignore_reason})")
     end
   end
 
 private
 
   attr_reader :document_hash, :put_service, :delete_service
+
+  def log(message)
+    combined_message = sprintf(
+      "[%s] Processing document to %s with content_id:%s link:%s payload_version:%d",
+      self.class.name,
+      message,
+      content_id,
+      link,
+      payload_version,
+    )
+    Rails.logger.info(combined_message)
+  end
 end

app/services/discovery_engine/delete.rb

@@ -1,6 +1,7 @@
 module DiscoveryEngine
   class Delete
     include DocumentName
+    include Logging
 
     def initialize(client: ::Google::Cloud::DiscoveryEngine.document_service(version: :v1))
       @client = client
@@ -9,15 +10,21 @@ def initialize(client: ::Google::Cloud::DiscoveryEngine.document_service(version
     def call(content_id, payload_version: nil)
       client.delete_document(name: document_name(content_id))
 
-      Rails.logger.info(sprintf("[GCDE][DELETE %s@v%s]", content_id, payload_version))
+      log(Logger::Severity::INFO, "Successfully deleted", content_id:, payload_version:)
     rescue Google::Cloud::NotFoundError => e
       # TODO: Should we eventually send this to Sentry? A document not existing is a relatively
       # common error initially as an unpublish request may come through before we've imported the
       # document to begin with.
-      Rails.logger.warn(sprintf("[GCDE][DELETE %s@v%s] %s", content_id, payload_version, e.message))
+      log(
+        Logger::Severity::WARN,
+        "Failed to delete document as it doesn't exist remotely (#{e.message})",
+        content_id:, payload_version:,
+      )
     rescue Google::Cloud::Error => e
-      Rails.logger.error(
-        sprintf("[GCDE][DELETE %s@v%s] %s", content_id, payload_version, e.message),
+      log(
+        Logger::Severity::ERROR,
+        "Failed to delete document due to an error (#{e.message})",
+        content_id:, payload_version:,
       )
       GovukError.notify(e)
     end

app/services/discovery_engine/logging.rb

@@ -0,0 +1,14 @@
+module DiscoveryEngine
+  module Logging
+    def log(level, message, content_id:, payload_version:)
+      combined_message = sprintf(
+        "[%s] %s content_id:%s payload_version:%d",
+        self.class.name,
+        message,
+        content_id,
+        payload_version,
+      )
+      Rails.logger.add(level, combined_message)
+    end
+  end
+end

app/services/discovery_engine/put.rb

@@ -3,13 +3,14 @@ class Put
     MIME_TYPE = "text/html".freeze
 
     include DocumentName
+    include Logging
 
     def initialize(client: ::Google::Cloud::DiscoveryEngine.document_service(version: :v1))
       @client = client
     end
 
     def call(content_id, metadata, content: "", payload_version: nil)
-      doc = client.update_document(
+      client.update_document(
         document: {
           id: content_id,
           name: document_name(content_id),
@@ -23,9 +24,13 @@ def call(content_id, metadata, content: "", payload_version: nil)
         allow_missing: true,
       )
 
-      Rails.logger.info(sprintf("[GCDE][PUT %s@v%s] -> %s", content_id, payload_version, doc.name))
+      log(Logger::Severity::INFO, "Successfully added/updated", content_id:, payload_version:)
     rescue Google::Cloud::Error => e
-      Rails.logger.error(sprintf("[GCDE][PUT %s@v%s] %s", content_id, payload_version, e.message))
+      log(
+        Logger::Severity::ERROR,
+        "Failed to add/update document due to an error (#{e.message})",
+        content_id:, payload_version:,
+      )
       GovukError.notify(e)
     end
 

spec/services/discovery_engine/delete_spec.rb

@@ -2,7 +2,7 @@
   subject(:delete) { described_class.new(client:) }
 
   let(:client) { double("DocumentService::Client", delete_document: nil) }
-  let(:logger) { double("Logger", info: nil, warn: nil, error: nil) }
+  let(:logger) { double("Logger", add: nil) }
 
   before do
     allow(Rails).to receive(:logger).and_return(logger)
@@ -23,7 +23,10 @@
     end
 
     it "logs the delete operation" do
-      expect(logger).to have_received(:info).with("[GCDE][DELETE some_content_id@v1]")
+      expect(logger).to have_received(:add).with(
+        Logger::Severity::INFO,
+        "[DiscoveryEngine::Delete] Successfully deleted content_id:some_content_id payload_version:1",
+      )
     end
   end
 
@@ -37,7 +40,10 @@
     end
 
     it "logs the failure" do
-      expect(logger).to have_received(:warn).with("[GCDE][DELETE some_content_id@v1] It got lost")
+      expect(logger).to have_received(:add).with(
+        Logger::Severity::WARN,
+        "[DiscoveryEngine::Delete] Failed to delete document as it doesn't exist remotely (It got lost) content_id:some_content_id payload_version:1",
+      )
     end
 
     it "does not send the error to Sentry" do
@@ -55,7 +61,10 @@
     end
 
     it "logs the failure" do
-      expect(logger).to have_received(:error).with("[GCDE][DELETE some_content_id@v1] Something went wrong")
+      expect(logger).to have_received(:add).with(
+        Logger::Severity::ERROR,
+        "[DiscoveryEngine::Delete] Failed to delete document due to an error (Something went wrong) content_id:some_content_id payload_version:1",
+      )
     end
 
     it "send the error to Sentry" do

spec/services/discovery_engine/put_spec.rb

@@ -2,7 +2,7 @@
   subject(:put) { described_class.new(client:) }
 
   let(:client) { double("DocumentService::Client", update_document: nil) }
-  let(:logger) { double("Logger", info: nil, error: nil) }
+  let(:logger) { double("Logger", add: nil) }
 
   before do
     allow(Rails).to receive(:logger).and_return(logger)
@@ -40,7 +40,10 @@
     end
 
     it "logs the put operation" do
-      expect(logger).to have_received(:info).with("[GCDE][PUT some_content_id@v1] -> document-name")
+      expect(logger).to have_received(:add).with(
+        Logger::Severity::INFO,
+        "[DiscoveryEngine::Put] Successfully added/updated content_id:some_content_id payload_version:1",
+      )
     end
   end
 
@@ -54,7 +57,10 @@
     end
 
     it "logs the failure" do
-      expect(logger).to have_received(:error).with("[GCDE][PUT some_content_id@v1] Something went wrong")
+      expect(logger).to have_received(:add).with(
+        Logger::Severity::ERROR,
+        "[DiscoveryEngine::Put] Failed to add/update document due to an error (Something went wrong) content_id:some_content_id payload_version:1",
+      )
     end
 
     it "send the error to Sentry" do