DEV: Capture and log AR debug logs on GitHub actions for flaky tests (d…

…iscourse#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 @@
   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 @@ def example_passed(notification)
                     :success,
                   )
 
+      output_activerecord_debug_logs(output, notification.example)
+
       output.flush
     end
 
@@ -31,11 +33,22 @@ def example_failed(notification)
                     :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 @@ def to_json
           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 @@
 
     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 @@ class SpecTimeoutError < StandardError
     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