Merge pull request #2691 from govuk-forms/add-start-stop-logs-tasks

Log start and end for rake tasks

Author: SamJamCul

app/lib/application_logger.rb

@@ -32,7 +32,11 @@ def as_hash(msg, attribs = {})
     msg = yield if block_given?
 
     begin
-      message_to_hash(msg).merge(attribs || {}).merge(CurrentLoggingAttributes.attributes).compact
+      message_to_hash(msg)
+        .merge(attribs || {})
+        .merge(CurrentLoggingAttributes.attributes)
+        .merge(CurrentTaskLoggingAttributes.attributes)
+        .compact
     rescue NameError
       # if logs aren't attached to a request, CurrentLoggingAttributes will be uninitialized
       message_to_hash(msg).merge(attribs || {})

app/models/current_task_logging_attributes.rb

@@ -0,0 +1,3 @@
+class CurrentTaskLoggingAttributes < ActiveSupport::CurrentAttributes
+  attribute :task_name
+end

lib/tasks/logging.rake

@@ -0,0 +1,43 @@
+require "English"
+
+Rake::Task.define_task(:environment).enhance do
+  task_finished_normally = false
+
+  at_exit do
+    unless task_finished_normally
+      exit_cause = $ERROR_INFO ? $ERROR_INFO.class.name : "Signal or exit"
+
+      Rails.logger.error "Task terminated early", {
+        task: Rake.application.top_level_tasks.first,
+        exit_cause:,
+      }
+    end
+  end
+
+  Rake.application.top_level_tasks.each do |task_name|
+    task_name_clean = task_name.gsub(/\[.*\]$/, "")
+    next unless Rake::Task.task_defined?(task_name_clean)
+
+    task = Rake::Task[task_name_clean]
+    original_actions = task.actions.dup
+    task.actions.clear
+
+    task.enhance do |t, args|
+      CurrentTaskLoggingAttributes.task_name = task_name_clean
+      Rails.logger.info "Task started", { args: args.to_a }
+
+      begin
+        original_actions.each { |action| action.call(t, args) }
+        Rails.logger.info "Task finished"
+      rescue SystemExit => e
+        Rails.logger.error "Task aborted", { exit_message: e.message }
+        raise e
+      rescue StandardError => e
+        Rails.logger.error "Task failed", { exception: [e.class.name, e.message] }
+        raise e
+      ensure
+        task_finished_normally = true
+      end
+    end
+  end
+end

spec/lib/application_logger_spec.rb

@@ -26,6 +26,25 @@
     end
   end
 
+  context "when CurrentTaskLoggingAttributes has attributes set" do
+    before do
+      CurrentTaskLoggingAttributes.task_name = "task:example"
+      logger.info("A message")
+    end
+
+    it "includes the message as a field" do
+      expect(log_line["message"]).to eq "A message"
+    end
+
+    it "includes attributes with values on the log line" do
+      expect(log_line["task_name"]).to eq "task:example"
+    end
+
+    it "does not include attributes without values on the log line" do
+      expect(log_line.keys).not_to include "user_id"
+    end
+  end
+
   context "when a hash is passed as an argument" do
     before do
       CurrentLoggingAttributes.request_id = "a-request-id"

spec/lib/tasks/logging.rake_spec.rb

@@ -0,0 +1,72 @@
+require "rake"
+require "rails_helper"
+
+RSpec.describe "Logging Rake Tasks" do
+  let(:rake) { Rake::Application.new }
+
+  before do
+    Rake.application = rake
+
+    Rake::Task.define_task(:environment)
+    my_task
+
+    allow(rake).to receive(:top_level_tasks).and_return(%w[my_task])
+
+    load Rails.root.join("lib/tasks/logging.rake")
+
+    rake["environment"].invoke
+  end
+
+  context "when the task runs successfully" do
+    let(:my_task) { Rake::Task.define_task(my_task: :environment) }
+
+    it "logs when the task starts and finishes" do
+      expect(Rails.logger).to receive(:info).with("Task started", hash_including(:args))
+
+      expect(Rails.logger).to receive(:info).with("Task finished")
+
+      rake["my_task"].invoke
+    end
+
+    it "logs the arguments passed in to the task" do
+      expect(Rails.logger).to receive(:info).with("Task started", hash_including(args: %w[arg1 arg2]))
+
+      allow(Rails.logger).to receive(:info).with("Task finished")
+
+      rake["my_task"].invoke("arg1", "arg2")
+    end
+  end
+
+  context "when the task raises an error" do
+    let(:my_task) do
+      Rake::Task.define_task(my_task: :environment) do
+        raise StandardError, "Something went wrong"
+      end
+    end
+
+    it "logs an error with the exception" do
+      allow(Rails.logger).to receive(:info).with("Task started", hash_including(:args))
+      expect(Rails.logger).to receive(:error).with(
+        "Task failed",
+        { exception: ["StandardError", "Something went wrong"] },
+      )
+
+      expect { rake["my_task"].invoke }.to raise_error(StandardError, "Something went wrong")
+    end
+  end
+
+  context "when the task is aborted with SystemExit" do
+    let(:my_task) do
+      Rake::Task.define_task(my_task: :environment) do
+        raise SystemExit.new(0, "exit")
+      end
+    end
+
+    it "logs an error with the exit message" do
+      allow(Rails.logger).to receive(:info).with("Task started", hash_including(:args))
+      expect(Rails.logger).to receive(:error).with("Task aborted", { exit_message: "exit" })
+
+      expect { rake["my_task"].invoke }.to output(/exit/).to_stderr
+    end
+  end
+end