Add logging to data scripts runner (#6201)

app/models/data_update_script.rb

@@ -8,17 +8,23 @@ class DataUpdateScript < ApplicationRecord
   enum status: STATUSES
   validates :file_name, uniqueness: true
 
-  def self.filenames
-    Dir.glob("*.rb", base: DIRECTORY).map do |f|
-      Pathname.new(f).basename(".rb").to_s
+  class << self
+    def filenames
+      Dir.glob("*.rb", base: DIRECTORY).map do |f|
+        Pathname.new(f).basename(".rb").to_s
+      end
     end
-  end
 
-  def self.load_script_ids
-    filenames.
-      map { |file_name| find_or_create_by(file_name: file_name) }.
-      select(&:enqueued?).
-      map(&:id)
+    def load_script_ids
+      filenames.
+        map { |file_name| find_or_create_by(file_name: file_name) }.
+        select(&:enqueued?).
+        map(&:id)
+    end
+
+    def scripts_to_run
+      DataUpdateScript.where(id: load_script_ids).select(&:enqueued?)
+    end
   end
 
   def mark_as_run!

app/workers/data_update_worker.rb

@@ -3,11 +3,10 @@ class DataUpdateWorker
   sidekiq_options queue: :high_priority, retry: 5
 
   def perform
-    script_ids = DataUpdateScript.load_script_ids
-    scripts_to_run = DataUpdateScript.where(id: script_ids).select(&:enqueued?)
-
-    scripts_to_run.each do |script|
+    DataUpdateScript.scripts_to_run.each do |script|
       script.mark_as_run!
+      log_status(script)
+
       run_script(script)
     end
   end
@@ -16,10 +15,28 @@ class DataUpdateWorker
 
   def run_script(script)
     require script.file_path
+
     script.file_class.new.run
+
     script.mark_as_finished!
+    log_status(script)
   rescue StandardError => e
     script.mark_as_failed!
+    log_status(script)
+
     Honeybadger.notify(e, context: { script_id: script.id })
   end
+
+  def log_status(script)
+    status = script.status
+    file_name = script.file_name
+
+    logger_destination = status == :failed ? :error : :info
+    Rails.logger.public_send(
+      logger_destination,
+      "time=#{Time.current.rfc3339}, script=#{file_name}, status=#{status}",
+    )
+
+    DatadogStatsClient.increment("data_update_scripts.status", tags: ["status:#{status}", "script_name:#{file_name}"])
+  end
 end

config/environments/development.rb

@@ -114,11 +114,13 @@ Rails.application.configure do
     # acts-as-taggable-on has super weird eager loading problems: <https://github.com/mbleigh/acts-as-taggable-on/issues/91>
     Bullet.add_whitelist(type: :n_plus_one_query, class_name: "ActsAsTaggableOn::Tagging", association: :tag)
 
+    # Check if there are any data update scripts to run during startup
     if %w[c console runner s server].include?(ENV["COMMAND"])
-      script_ids = DataUpdateScript.load_script_ids
-      scripts_to_run = DataUpdateScript.where(id: script_ids).select(&:enqueued?)
-      if scripts_to_run.any?
-        raise "Data update scripts need to be run before you can start the application. Please run rake data_updates:run"
+      if DataUpdateScript.scripts_to_run.any?
+        message = <<~ERROR
+          Data update scripts need to be run before you can start the application. Please run "rails data_updates:run"
+        ERROR
+        raise message
       end
     end
   end

docs/installation/docker.md

@@ -95,9 +95,11 @@ Please execute the script itself to view all additional options:
   ![docker gui](https://user-images.githubusercontent.com/47985/74210448-b63b7c80-4c83-11ea-959b-02249b2a6952.png)
 
 - In case `rails server` doesn't start with the following message:
+
   ```
-  Data update scripts need to be run before you can start the application. Please run rake data_updates:run (RuntimeError)
+  Data update scripts need to be run before you can start the application. Please run rails data_updates:run (RuntimeError)
   ```
+
   run the following command:
 
   ```shell

spec/models/data_update_script_spec.rb

@@ -12,12 +12,12 @@ RSpec.describe DataUpdateScript do
   end
 
   it "default orders scripts by name" do
-    script1 = FactoryBot.create(:data_update_script, file_name: "456_test_script")
-    script2 = FactoryBot.create(:data_update_script, file_name: "123_test_script")
+    script1 = create(:data_update_script, file_name: "456_test_script")
+    script2 = create(:data_update_script, file_name: "123_test_script")
     expect(described_class.pluck(:id)).to eq([script2.id, script1.id])
   end
 
-  describe "::load_script_ids" do
+  describe ".load_script_ids" do
     let(:test_directory) { Rails.root.join("spec/support/fixtures/data_update_scripts") }
 
     before { stub_const "#{described_class}::DIRECTORY", test_directory }
@@ -29,21 +29,43 @@ RSpec.describe DataUpdateScript do
     end
 
     it "returns script ids that need to be run" do
-      script = FactoryBot.create(:data_update_script)
+      script = create(:data_update_script)
       need_running_ids = described_class.load_script_ids
       expect(need_running_ids).to include(script.id)
     end
 
     it "does not return script ids that are running" do
-      script = FactoryBot.create(:data_update_script, run_at: Time.now.utc, status: :working)
+      script = create(:data_update_script, run_at: Time.current, status: :working)
       need_running_ids = described_class.load_script_ids
       expect(need_running_ids).not_to include(script.id)
     end
   end
 
+  describe ".scripts_to_run" do
+    let(:test_directory) { Rails.root.join("spec/support/fixtures/data_update_scripts") }
+
+    before { stub_const "#{described_class}::DIRECTORY", test_directory }
+
+    it "creates new DataUpdateScripts from files" do
+      expect do
+        described_class.scripts_to_run
+      end.to change(described_class, :count).by(1)
+    end
+
+    it "returns scripts that need to be run" do
+      script = create(:data_update_script)
+      expect(described_class.scripts_to_run).to include(script)
+    end
+
+    it "does not return script ids that are running" do
+      script = create(:data_update_script, run_at: Time.current, status: :working)
+      expect(described_class.scripts_to_run).not_to include(script)
+    end
+  end
+
   describe "#mark_as_finished!" do
     it "marks data update script as finished" do
-      test_script = FactoryBot.create(:data_update_script)
+      test_script = create(:data_update_script)
       expect(test_script.finished_at).to be_nil
       expect(test_script).to be_enqueued
       test_script.mark_as_finished!
@@ -54,7 +76,7 @@ RSpec.describe DataUpdateScript do
 
   describe "#mark_as_run!" do
     it "marks data update script as working" do
-      test_script = FactoryBot.create(:data_update_script)
+      test_script = create(:data_update_script)
       expect(test_script.run_at).to be_nil
       expect(test_script).to be_enqueued
       test_script.mark_as_run!
@@ -65,7 +87,7 @@ RSpec.describe DataUpdateScript do
 
   describe "#mark_as_failed!" do
     it "marks data update script as failed" do
-      test_script = FactoryBot.create(:data_update_script)
+      test_script = create(:data_update_script)
       expect(test_script.finished_at).to be_nil
       expect(test_script).to be_enqueued
       test_script.mark_as_failed!

spec/workers/data_update_worker_spec.rb

@@ -2,8 +2,9 @@ require "rails_helper"
 require Rails.root.join("app/models/data_update_script.rb")
 
 RSpec.describe DataUpdateWorker, type: :worker do
-  let(:test_directory) { Rails.root.join("spec/support/fixtures/data_update_scripts") }
-  let(:worker) { described_class.new }
+  let_it_be(:test_directory) { Rails.root.join("spec/support/fixtures/data_update_scripts") }
+  let_it_be(:worker) { described_class.new }
+  let_it_be(:statuses) { %w[working succeeded] }
 
   before do
     stub_const "DataUpdateScript::DIRECTORY", test_directory
@@ -26,9 +27,32 @@ RSpec.describe DataUpdateWorker, type: :worker do
     expect do
       worker.perform
     end.to change(DataUpdateScript, :count).by(1)
-    dus = DataUpdateScript.find_by(file_name: "20200214151804_data_update_test_script")
+
+    dus = DataUpdateScript.last
     expect(dus.finished_at).not_to be_nil
     expect(dus).to be_succeeded
     expect(dus.run_at).not_to be_nil
   end
+
+  it "logs data to stdout", :aggregate_failures do
+    allow(Rails.logger).to receive(:info)
+    worker.perform
+
+    statuses.each do |status|
+      expect(Rails.logger).to have_received(:info).once.with(/#{status}/)
+    end
+  end
+
+  it "logs data to Datadog", :aggregate_failures do
+    allow(DatadogStatsClient).to receive(:increment)
+    worker.perform
+
+    statuses.each do |status|
+      expected_args = [
+        "data_update_scripts.status",
+        { tags: ["status:#{status}", "script_name:20200214151804_data_update_test_script"] },
+      ]
+      expect(DatadogStatsClient).to have_received(:increment).once.with(*expected_args)
+    end
+  end
 end