From 655c10610173991ae8ec8b74abf2697630f081f2 Mon Sep 17 00:00:00 2001
From: Alan Guo Xiang Tan <gxtan1990@gmail.com>
Date: Wed, 27 Dec 2023 14:40:00 +0800
Subject: [PATCH] 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                    |  8 ++++++++
 lib/turbo_tests/documentation_formatter.rb     | 13 +++++++++++++
 lib/turbo_tests/json_example.rb                |  1 +
 plugins/chat/spec/system/single_thread_spec.rb |  2 +-
 spec/rails_helper.rb                           | 16 ++++++++++++++++
 5 files changed, 39 insertions(+), 1 deletion(-)

diff --git a/config/environments/test.rb b/config/environments/test.rb
index cbe58e0890c..9106df9b909 100644
--- a/config/environments/test.rb
+++ b/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 =
diff --git a/lib/turbo_tests/documentation_formatter.rb b/lib/turbo_tests/documentation_formatter.rb
index 0fab466ab2b..10d9b5630c3 100644
--- a/lib/turbo_tests/documentation_formatter.rb
+++ b/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}"
diff --git a/lib/turbo_tests/json_example.rb b/lib/turbo_tests/json_example.rb
index e3eb6e35f4b..9426d469ae4 100644
--- a/lib/turbo_tests/json_example.rb
+++ b/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,
       }
diff --git a/plugins/chat/spec/system/single_thread_spec.rb b/plugins/chat/spec/system/single_thread_spec.rb
index 5bf51077d9e..dea9cbb6891 100644
--- a/plugins/chat/spec/system/single_thread_spec.rb
+++ b/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)
diff --git a/spec/rails_helper.rb b/spec/rails_helper.rb
index 7f703d3ea2a..d9e932d0f8d 100644
--- a/spec/rails_helper.rb
+++ b/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