DEV: Capture and log AR debug logs on GitHub actions for flaky tests (#25048)

Why this change?

We have been running into flaky tests which seems to be related to
AR transaction problems. However, we are not able to reproduce this
locally and do not have sufficient information on our builds now to
debug the problem.

What does this change do?

Noe the following changes only applies when `ENV["GITHUB_ACTIONS"]` is
present.

This change introduces an RSpec around hook when `capture_log: true` has
been set for a test. The responsibility of the hook is to capture the
ActiveRecord debug logs and print them out.

config/environments/test.rb

@@ -50,6 +50,14 @@ Discourse::Application.configure do
   config.assets.compile = true
   config.assets.digest = false
 
+  config.active_record.verbose_query_logs = true
+
+  config.after_initialize do
+    ActiveRecord::LogSubscriber.backtrace_cleaner.add_silencer do |line|
+      line =~ %r{lib/freedom_patches}
+    end
+  end
+
   if ENV["RAILS_ENABLE_TEST_LOG"]
     config.logger = Logger.new(STDOUT)
     config.log_level =

lib/turbo_tests/documentation_formatter.rb

@@ -11,6 +11,8 @@ module TurboTests
                     :success,
                   )
 
+      output_activerecord_debug_logs(output, notification.example)
+
       output.flush
     end
 
@@ -31,11 +33,22 @@ module TurboTests
                     :failure,
                   )
 
+      output_activerecord_debug_logs(output, notification.example)
+
       output.flush
     end
 
     private
 
+    def output_activerecord_debug_logs(output, example)
+      if ENV["GITHUB_ACTIONS"] &&
+           active_record_debug_logs = example.metadata[:active_record_debug_logs]
+        output.puts "::group::ActiveRecord Debug Logs"
+        output.puts active_record_debug_logs
+        output.puts "::endgroup::"
+      end
+    end
+
     def output_example(example)
       output =
         +"[#{example.process_id}] (##{example.metadata[:process_pid]}) #{example.full_description}"

lib/turbo_tests/json_example.rb

@@ -20,6 +20,7 @@ module TurboTests
           run_duration_ms: @rspec_example.metadata[:run_duration_ms],
           process_pid: Process.pid,
           js_deprecations: @rspec_example.metadata[:js_deprecations],
+          active_record_debug_logs: @rspec_example.metadata[:active_record_debug_logs],
         },
         location_rerun_argument: @rspec_example.location_rerun_argument,
       }

plugins/chat/spec/system/single_thread_spec.rb

@@ -20,7 +20,7 @@ describe "Single thread in side panel", type: :system do
 
     before { channel.update!(threading_enabled: false) }
 
-    it "does not open the side panel for a single thread" do
+    it "does not open the side panel for a single thread", capture_log: true do
       thread =
         chat_thread_chain_bootstrap(channel: channel, users: [current_user, Fabricate(:user)])
       chat_page.visit_channel(channel)

spec/rails_helper.rb

@@ -475,6 +475,22 @@ RSpec.configure do |config|
     end
   end
 
+  if ENV["GITHUB_ACTIONS"]
+    config.around :each, capture_log: true do |example|
+      original_logger = ActiveRecord::Base.logger
+      io = StringIO.new
+      io_logger = Logger.new(io)
+      io_logger.level = Logger::DEBUG
+      ActiveRecord::Base.logger = io_logger
+
+      example.run
+
+      RSpec.current_example.metadata[:active_record_debug_logs] = io.string
+    ensure
+      ActiveRecord::Base.logger = original_logger
+    end
+  end
+
   config.before :each do
     # This allows DB.transaction_open? to work in tests. See lib/mini_sql_multisite_connection.rb
     DB.test_transaction = ActiveRecord::Base.connection.current_transaction