Wrap all test background threads in Rails executors; better test logg…

…ing/debugging (#1077)

.github/workflows/test.yml

@@ -68,7 +68,7 @@ jobs:
       - name: bin/setup
         run: bin/rails db:test:prepare
       - name: bin/rspec
-        run: bin/rspec
+        run: bin/rspec --require ./spec/support/pre_documentation_formatter.rb --format PreDocumentationFormatter
 
   test:
     name: Test

app/models/good_job/base_record.rb

@@ -30,10 +30,10 @@ def self.migrated?
 
     # Runs the block with self.logger silenced.
     # If self.logger is nil, simply runs the block.
-    def self.with_logger_silenced(&block)
+    def self.with_logger_silenced(silent: true, &block)
       # Assign to a local variable, just in case it's modified in another thread concurrently
       logger = self.logger
-      if logger.respond_to? :silence
+      if silent && logger.respond_to?(:silence)
         logger.silence(&block)
       else
         yield

spec/app/models/concerns/good_job/advisory_lockable_spec.rb

@@ -128,7 +128,7 @@
 
       it 'does not invoke the block if the key is already locked' do
         model_class.advisory_lock_key(execution.lockable_key) do
-          promise = Concurrent::Promises.future do
+          promise = rails_promise do
             result = model_class.advisory_lock_key(execution.lockable_key) { raise }
             expect(result).to be_nil
           end
@@ -189,7 +189,7 @@
       expect(execution.advisory_locked?).to be true
       expect(execution.owns_advisory_lock?).to be true
 
-      other_thread_owns_advisory_lock = Concurrent::Promises.future(execution, &:owns_advisory_lock?).value!
+      other_thread_owns_advisory_lock = rails_promise(execution, &:owns_advisory_lock?).value!
       expect(other_thread_owns_advisory_lock).to be false
 
       execution.advisory_unlock
@@ -198,7 +198,7 @@
     it 'returns true or false if the lock is acquired' do
       expect(execution.advisory_lock).to be true
 
-      expect(Concurrent::Promises.future(execution, &:advisory_lock).value!).to be false
+      expect(rails_promise(execution, &:advisory_lock).value!).to be false
 
       execution.advisory_unlock
     end
@@ -250,7 +250,7 @@
     it 'returns true or false if the unlock operation is successful' do
       execution.advisory_lock
 
-      expect(Concurrent::Promises.future(execution, &:advisory_unlock).value!).to be false
+      expect(rails_promise(execution, &:advisory_unlock).value!).to be false
       expect(execution.advisory_unlock).to be true
 
       unless RUBY_PLATFORM.include?('java')
@@ -317,7 +317,7 @@
     execution.advisory_lock!
 
     expect do
-      Concurrent::Promises.future(execution, &:advisory_lock!).value!
+      rails_promise(execution, &:advisory_lock!).value!
     end.to raise_error GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError
 
     execution.advisory_unlock

spec/app/models/good_job/job_spec.rb

@@ -261,10 +261,9 @@ def perform
 
     context 'when job is already locked' do
       it 'raises an Error' do
-        ActiveRecord::Base.clear_active_connections!
         job.with_advisory_lock do
           expect do
-            Concurrent::Promises.future(job, &:retry_job).value!
+            rails_promise(job, &:retry_job).value!
           end.to raise_error GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError
         end
       end

spec/integration/adapter_spec.rb

@@ -108,14 +108,11 @@ def perform(*_args, **_kwargs)
     let(:adapter) { GoodJob::Adapter.new(execution_mode: :async_all, _capsule: capsule) }
 
     it 'executes the job', :skip_if_java do
-      elephant_adapter = GoodJob::Adapter.new execution_mode: :async_all
       elephant_ajob = TestJob.set(queue: 'elephants').perform_later
 
       sleep_until { RUN_JOBS.include? elephant_ajob.provider_job_id }
 
       expect(RUN_JOBS).to include(elephant_ajob.provider_job_id)
-
-      elephant_adapter.shutdown
     end
   end
 

spec/lib/good_job/systemd_service_spec.rb

@@ -70,8 +70,7 @@ def read(maxlen = 16)
     systemd_socket.read
     expect(systemd.notifying?).to be(true)
 
-    sleep 0.3
-    expect(systemd_socket.read).to eq('WATCHDOG=1')
+    wait_until(max: 1) { expect(systemd_socket.read).to eq('WATCHDOG=1') }
 
     systemd.stop
   end

spec/lib/good_job_spec.rb

@@ -32,9 +32,12 @@
       expect { described_class.restart }.not_to change(described_class, :shutdown?).from(true)
     end
 
-    it 'restarts down all capsule instances' do
-      GoodJob::Capsule.new(configuration: configuration)
-      expect { described_class.restart }.to change(described_class, :shutdown?).from(true).to(false)
+    it 'restarts all capsule instances' do
+      capsule = GoodJob::Capsule.new(configuration: configuration)
+      expect { described_class.restart }.to change(capsule, :shutdown?).from(true).to(false)
+      capsule.shutdown
+
+      described_class.shutdown
     end
 
     context 'when in webserver but not in async mode' do

spec/support/database_cleaner.rb

@@ -6,6 +6,8 @@
   config.use_transactional_fixtures = false
 
   config.before(:suite) do
+    ApplicationRecord.clear_active_connections!
+    ApplicationRecord.connection_pool.disconnect
     ApplicationRecord.connection_pool.with_connection do |connection|
       connection.truncate_tables(*connection.tables)
     end
@@ -14,6 +16,8 @@
   config.around do |example|
     example.run
 
+    ApplicationRecord.clear_active_connections!
+    ApplicationRecord.connection_pool.disconnect
     ApplicationRecord.connection_pool.with_connection do |connection|
       connection.truncate_tables(*connection.tables)
     end

spec/support/logger.rb

@@ -3,6 +3,7 @@
 RSpec.configure do |config|
   config.around do |example|
     Rails.logger.debug { "\n\n---- START EXAMPLE: #{example.full_description} (#{example.location})" }
+    Thread.current.name = "RSpec: #{example.description}"
     example.run
     Rails.logger.debug { "---- END EXAMPLE: #{example.full_description} (#{example.location})\n\n" }
   end

spec/support/postgres_notices.rb

@@ -11,6 +11,7 @@
     next unless raw_connection.respond_to? :set_notice_receiver
 
     raw_connection.set_notice_receiver do |result|
+      Rails.logger.warn(result.error_message.strip)
       POSTGRES_NOTICES << result.error_message
     end
   }

spec/support/pre_documentation_formatter.rb

@@ -10,6 +10,7 @@ class PreDocumentationFormatter < RSpec::Core::Formatters::BaseTextFormatter
   def initialize(output)
     super
     @group_level = 0
+    @failed_examples = []
   end
 
   def example_group_started(notification)
@@ -33,7 +34,9 @@ def example_pending(pending)
   end
 
   def example_failed(failure)
+    @failed_examples << failure.example
     output.puts failure_output(failure.example)
+    output.puts failure.fully_formatted(@failed_examples.size)
   end
 
   def example_started(notification)

spec/support/reset_good_job.rb

@@ -2,22 +2,30 @@
 
 THREAD_ERRORS = Concurrent::Array.new
 
+ActiveSupport.on_load :active_record do
+  ActiveRecord::ConnectionAdapters::AbstractAdapter.set_callback :checkout, :before, lambda { |conn|
+    thread_name = Thread.current.name || Thread.current.object_id
+    conn.exec_query("SET application_name = '#{thread_name}'", "Set application name")
+  }
+end
+
 RSpec.configure do |config|
   config.around do |example|
     GoodJob.preserve_job_records = true
-    GoodJob::CurrentThread.reset
 
     PgLock.current_database.advisory_lock.owns.all?(&:unlock) if PgLock.advisory_lock.owns.count > 0
     PgLock.current_database.advisory_lock.others.each(&:unlock!) if PgLock.advisory_lock.others.count > 0
     expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
 
+    GoodJob::CurrentThread.reset
     THREAD_ERRORS.clear
-    Thread.current.name = "RSpec: #{example.description}"
     GoodJob.on_thread_error = lambda do |exception|
       THREAD_ERRORS << [Thread.current.name, exception, exception.backtrace]
     end
 
     example.run
+
+    expect(THREAD_ERRORS).to be_empty
   end
 
   config.after do
@@ -34,8 +42,6 @@
     )
     GoodJob._shutdown_all(executables, timeout: -1)
 
-    expect(THREAD_ERRORS).to be_empty
-
     expect(GoodJob::Notifier.instances).to all be_shutdown
     GoodJob::Notifier.instances.clear
 
@@ -59,14 +65,14 @@
 
     other_locks = PgLock.current_database.advisory_lock.others
     if other_locks.any?
-      puts "There are #{other_locks.count} advisory locks still open."
+      puts "There are #{other_locks.count} advisory locks still open AFTER test run."
       puts "\n\nAdvisory Locks:"
-      other_locks.includes(:pg_stat_activity).find_each do |pg_lock|
+      other_locks.includes(:pg_stat_activity).all.each do |pg_lock| # rubocop:disable Rails/FindEach
         puts "  - #{pg_lock.pid}: #{pg_lock.pg_stat_activity.application_name}"
       end
 
       puts "\n\nCurrent connections:"
-      PgStatActivity.find_each do |pg_stat_activity|
+      PgStatActivity.all.each do |pg_stat_activity| # rubocop:disable Rails/FindEach
         puts "  - #{pg_stat_activity.pid}: #{pg_stat_activity.application_name}"
       end
     end
@@ -77,13 +83,6 @@
   end
 end
 
-ActiveSupport.on_load :active_record do
-  ActiveRecord::ConnectionAdapters::AbstractAdapter.set_callback :checkout, :before, lambda { |conn|
-    thread_name = Thread.current.name || Thread.current.object_id
-    conn.exec_query("SET application_name = '#{thread_name}'", "Set application name")
-  }
-end
-
 module PostgresXidExtension
   def initialize_type_map(map = type_map)
     if respond_to?(:register_class_with_limit, true)

spec/support/thread_helper.rb

@@ -0,0 +1,12 @@
+# frozen_string_literal: true
+
+module ThreadHelper
+  def rails_promise(*args)
+    wrapped_task = proc do |*proc_args|
+      Rails.application.executor.wrap { yield(*proc_args) }
+    end
+    Concurrent::Promises.future(*args, &wrapped_task)
+  end
+end
+
+RSpec.configure { |c| c.include ThreadHelper }

spec/support/uuid.rb

@@ -0,0 +1,14 @@
+# frozen_string_literal: true
+
+RSpec::Matchers.define :be_a_uuid do
+  match do |actual|
+    regexp = /\A\h{8}-\h{4}-(\h{4})-\h{4}-\h{12}\z/
+    actual.is_a?(String) && actual.match?(regexp)
+  end
+
+  description { "a UUID" }
+  failure_message { "expected #{description}" }
+  failure_message_when_negated { "did not expect #{description}" }
+end
+
+RSpec::Matchers.alias_matcher :a_uuid, :be_a_uuid

spec/test_app/config/environments/test.rb

@@ -5,7 +5,7 @@
 
 Rails.application.configure do
   config.cache_classes = true
-  config.eager_load = true
+  config.eager_load = ENV["CI"].present?
 
   config.active_job.queue_adapter = :test
 
@@ -16,6 +16,7 @@
     config.i18n.raise_on_missing_translations = true
   end
 
+  config.colorize_logging = false if ENV["CI"]
   if ActiveModel::Type::Boolean.new.cast(ENV['RAILS_LOG_TO_STDOUT'])
     logger = ActiveSupport::Logger.new(STDOUT)
     logger.formatter = config.log_formatter