diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 473508f..b862225 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -3,6 +3,8 @@ name: CI on: push: pull_request: + schedule: + - cron: '0 13 * * *' jobs: build: @@ -13,21 +15,31 @@ jobs: fail-fast: false matrix: ruby-version: - - '2.6' - - '2.7' - - '3.0' - '3.1' + - '3.2' + - '3.3' + - '3.4' + - '3' activerecord-version: - - '6' - - '7' + - '6_1' + - '7_0' + - '7_1' + - '7_2' + - '8_0' + - 'latest' + mysql-version: + - '8.0' exclude: - - # activerecord-7 doesn't support Ruby 2.6 - ruby-version: '2.6' - activerecord-version: '7' + # Exclude conditions that don't meat the minimal requirement + - ruby-version: '3.1' + activerecord-version: '8_0' + # Exclude duplicate conditions + - ruby-version: '3.1' + activerecord-version: 'latest' # equivalent to '7_2' services: mysql: - image: mysql:5.7 + image: mysql:${{ matrix.mysql-version }} ports: - 3306:3306 options: >- @@ -43,16 +55,16 @@ jobs: BUNDLE_GEMFILE: gemfiles/activerecord_${{ matrix.activerecord-version }}.gemfile steps: - - uses: actions/checkout@v2 + - uses: actions/checkout@v4 - name: Set up Ruby ${{ matrix.ruby-version }} uses: ruby/setup-ruby@v1 with: ruby-version: ${{ matrix.ruby-version }} bundler-cache: true - - name: Build and test with Rake + - name: Show activerecord version + run: bundle info activerecord + - name: Run tests run: | - bundle config path vendor/bundle - bundle install --jobs 4 --retry 3 bundle exec rake env: MYSQL_HOST: 127.0.0.1 diff --git a/README.md b/README.md index 11f6509..69aa4ad 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,6 @@ # ActiveRecord::DebugErrors -![](https://github.com/abicky/activerecord-debug_errors/workflows/CI/badge.svg?branch=master) +[![CI](https://github.com/abicky/activerecord-debug_errors/actions/workflows/test.yml/badge.svg?branch=master)](https://github.com/abicky/activerecord-debug_errors/actions/workflows/test.yml) ActiveRecord::DebugErrors is an extension of activerecord to display useful debug logs on errors. @@ -118,12 +118,14 @@ Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 *** WE ROLL BACK TRANSACTION (2) ``` +Note that the user requires the PROCESS priviledge to collect the information. + ### ActiveRecord::ConnectionTimeoutError When `ActiveRecord::ConnectionTimeoutError` occurs, you can see the information of connection owners (threads): ``` -ActiveRecord::ConnectionTimeoutError occured: +ActiveRecord::ConnectionTimeoutError occurred: connection owners: Thread # status=sleep priority=0 /path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:32:in `join' diff --git a/activerecord-debug_errors.gemspec b/activerecord-debug_errors.gemspec index fceb061..a0c52bb 100644 --- a/activerecord-debug_errors.gemspec +++ b/activerecord-debug_errors.gemspec @@ -10,7 +10,7 @@ Gem::Specification.new do |spec| spec.description = %q{ActiveRecord::DebugErrors is an extension of activerecord to display useful debug logs on errors.} spec.homepage = "https://github.com/abicky/activerecord-debug_errors" spec.license = "MIT" - spec.required_ruby_version = Gem::Requirement.new(">= 2.6.0") + spec.required_ruby_version = Gem::Requirement.new(">= 3.0.0") spec.metadata["homepage_uri"] = spec.homepage spec.metadata["source_code_uri"] = spec.homepage @@ -22,5 +22,5 @@ Gem::Specification.new do |spec| spec.executables = spec.files.grep(%r{^exe/}) { |f| File.basename(f) } spec.require_paths = ["lib"] - spec.add_runtime_dependency "activerecord", ">= 6", "< 8" + spec.add_runtime_dependency "activerecord", ">= 6.1" end diff --git a/gemfiles/activerecord_6.gemfile b/gemfiles/activerecord_6.gemfile deleted file mode 100644 index dcd6b25..0000000 --- a/gemfiles/activerecord_6.gemfile +++ /dev/null @@ -1,2 +0,0 @@ -eval_gemfile("../Gemfile") -gem "activerecord", "~> 6.0" diff --git a/gemfiles/activerecord_6_1.gemfile b/gemfiles/activerecord_6_1.gemfile new file mode 100644 index 0000000..45a7048 --- /dev/null +++ b/gemfiles/activerecord_6_1.gemfile @@ -0,0 +1,5 @@ +eval_gemfile("../Gemfile") +gem "activerecord", "~> 6.1.0" +gem "base64" +gem "bigdecimal" +gem "mutex_m" diff --git a/gemfiles/activerecord_7.gemfile b/gemfiles/activerecord_7.gemfile deleted file mode 100644 index 830ef3f..0000000 --- a/gemfiles/activerecord_7.gemfile +++ /dev/null @@ -1,2 +0,0 @@ -eval_gemfile("../Gemfile") -gem "activerecord", "~> 7.0" diff --git a/gemfiles/activerecord_7_0.gemfile b/gemfiles/activerecord_7_0.gemfile new file mode 100644 index 0000000..2d07c82 --- /dev/null +++ b/gemfiles/activerecord_7_0.gemfile @@ -0,0 +1,4 @@ +eval_gemfile("../Gemfile") +gem "activerecord", "~> 7.0.0" +gem "mutex_m" +gem "bigdecimal" diff --git a/gemfiles/activerecord_7_1.gemfile b/gemfiles/activerecord_7_1.gemfile new file mode 100644 index 0000000..afdf59b --- /dev/null +++ b/gemfiles/activerecord_7_1.gemfile @@ -0,0 +1,2 @@ +eval_gemfile("../Gemfile") +gem "activerecord", "~> 7.1.0" diff --git a/gemfiles/activerecord_7_2.gemfile b/gemfiles/activerecord_7_2.gemfile new file mode 100644 index 0000000..74aab1c --- /dev/null +++ b/gemfiles/activerecord_7_2.gemfile @@ -0,0 +1,2 @@ +eval_gemfile("../Gemfile") +gem "activerecord", "~> 7.2.0" diff --git a/gemfiles/activerecord_8_0.gemfile b/gemfiles/activerecord_8_0.gemfile new file mode 100644 index 0000000..b0bbd51 --- /dev/null +++ b/gemfiles/activerecord_8_0.gemfile @@ -0,0 +1,2 @@ +eval_gemfile("../Gemfile") +gem "activerecord", "~> 8.0.0" diff --git a/gemfiles/activerecord_latest.gemfile b/gemfiles/activerecord_latest.gemfile new file mode 100644 index 0000000..dd22286 --- /dev/null +++ b/gemfiles/activerecord_latest.gemfile @@ -0,0 +1 @@ +eval_gemfile("../Gemfile") diff --git a/lib/activerecord/debug_errors/ext/connection_adapters/abstract_mysql_adapter.rb b/lib/activerecord/debug_errors/ext/connection_adapters/abstract_mysql_adapter.rb index 9022dec..c1f5bfc 100644 --- a/lib/activerecord/debug_errors/ext/connection_adapters/abstract_mysql_adapter.rb +++ b/lib/activerecord/debug_errors/ext/connection_adapters/abstract_mysql_adapter.rb @@ -49,7 +49,14 @@ def display_processlist end def display_innodb_status_section(section_name) - status = ActiveRecord::Base.connection.execute("SHOW ENGINE INNODB STATUS").first[2] + sql = "SHOW ENGINE INNODB STATUS" + status = nil + begin + status = ActiveRecord::Base.connection.execute(sql).first[2] + rescue ActiveRecord::StatementInvalid => e + logger.error "Failed to execute '#{sql}': #{e.message}" + return + end prev_line = nil in_deadlock_section = false @@ -73,6 +80,13 @@ def display_innodb_status_section(section_name) end end +ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter.descendants.each do |adapter| + adapter.prepend(ActiveRecord::DebugErrors::DisplayMySQLInformation) +end + class ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter - prepend ActiveRecord::DebugErrors::DisplayMySQLInformation + def self.inherited(base) + super + base.prepend(ActiveRecord::DebugErrors::DisplayMySQLInformation) + end end diff --git a/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb b/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb index f12e9f4..eb4c738 100644 --- a/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb +++ b/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb @@ -15,7 +15,7 @@ def acquire_connection(*args) def dump_threads logger = ActiveRecord::Base.logger - logger.error "ActiveRecord::ConnectionTimeoutError occured:" + logger.error "ActiveRecord::ConnectionTimeoutError occurred:" dump_thread = ->(thread) { logger.error " Thread #{thread} status=#{thread.status} priority=#{thread.priority}" diff --git a/lib/activerecord/debug_errors/version.rb b/lib/activerecord/debug_errors/version.rb index c61ec85..9e96801 100644 --- a/lib/activerecord/debug_errors/version.rb +++ b/lib/activerecord/debug_errors/version.rb @@ -1,5 +1,5 @@ module ActiveRecord module DebugErrors - VERSION = "0.1.1" + VERSION = "0.1.4" end end diff --git a/spec/activerecord/debug_errors/ext/connection_adapters/abstract_mysql_adapter_spec.rb b/spec/activerecord/debug_errors/ext/connection_adapters/abstract_mysql_adapter_spec.rb index b91d8cc..03d0dfd 100644 --- a/spec/activerecord/debug_errors/ext/connection_adapters/abstract_mysql_adapter_spec.rb +++ b/spec/activerecord/debug_errors/ext/connection_adapters/abstract_mysql_adapter_spec.rb @@ -1,4 +1,5 @@ require "spec_helper" +require "support/cyclic_barrier" RSpec.describe ActiveRecord::DebugErrors::DisplayConnectionOwners do let(:log) { StringIO.new } @@ -18,46 +19,67 @@ describe "#execute" do context "when ActiveRecord::Deadlocked occurs" do - it "displays latest detected deadlock" do + def cause_deadlock(role:) + barrier = CyclicBarrier.new(2) + ths = [] ths << Thread.new do - User.transaction do - User.lock.find_by!(name: 'foo') - sleep 0.1 - User.lock.find_by!(name: 'bar') + ActiveRecord::Base.connected_to(role: role) do + User.transaction do + User.lock.find_by!(name: 'foo') + barrier.await(1) + User.lock.find_by!(name: 'bar') + end end end ths << Thread.new do - User.transaction do - User.lock.find_by!(name: 'bar') - sleep 0.1 - User.lock.find_by!(name: 'foo') + ActiveRecord::Base.connected_to(role: role) do + User.transaction do + User.lock.find_by!(name: 'bar') + barrier.await(1) + User.lock.find_by!(name: 'foo') + end end end - expect { - ths.each(&:join) - }.to raise_error(ActiveRecord::Deadlocked) - expect(log.string).to include("LATEST DETECTED DEADLOCK") - expect(log.string).to include("WE ROLL BACK TRANSACTION") + ths.each(&:join) + end + + context "when the user has the permission to execute 'SHOW ENGINE INNODB STATUS'" do + it "displays latest detected deadlock" do + expect { + cause_deadlock(role: :writing) + }.to raise_error(ActiveRecord::Deadlocked) + expect(log.string).to include("LATEST DETECTED DEADLOCK") + expect(log.string).to include("WE ROLL BACK TRANSACTION") + end + end + + context "when the user doesn't have the permission to execute 'SHOW ENGINE INNODB STATUS'" do + it "displays an error message" do + expect { + ActiveRecord::Base.connected_to(role: :reading) do + cause_deadlock(role: :reading) + end + }.to raise_error(ActiveRecord::Deadlocked) + expect(log.string).to include("Failed to execute") + end end end context "when ActiveRecord::LockWaitTimeout occurs" do it "displays transactions and processlist" do - ths = [] - ths << Thread.new do - User.transaction do - User.lock.find_by!(name: 'foo') - sleep 2 - end - end + barrier = CyclicBarrier.new(2) - ths << Thread.new do - User.transaction do - User.lock.find_by!(name: 'foo') - sleep 2 + ths = Array.new(2) do + Thread.new do + Thread.current.abort_on_exception = true + User.transaction do + barrier.await(1) + User.lock.find_by!(name: 'foo') + sleep 5 + end end end diff --git a/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb b/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb index 7a86bc7..556bf4d 100644 --- a/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb +++ b/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb @@ -1,4 +1,5 @@ require "spec_helper" +require "support/cyclic_barrier" RSpec.describe ActiveRecord::DebugErrors::DisplayConnectionOwners do let(:log) { StringIO.new } @@ -20,16 +21,23 @@ it "displays connection owners and other threads" do Thread.new { sleep 10 } # another thread + barrier = CyclicBarrier.new(ActiveRecord::Base.connection_pool.size) + expect { ActiveRecord::Base.connection # Ensure to acquire a connection Array.new(ActiveRecord::Base.connection_pool.size) do Thread.new do ActiveRecord::Base.connection_pool.checkout(0.1) + barrier.await(1) + rescue Timeout::Error + # CyclicBarrier#await is expected to raise Timeout::Error + # because it is not called ActiveRecord::Base.connection_pool.size times + # due to ActiveRecord::ConnectionTimeoutError end end.each(&:join) }.to raise_error(ActiveRecord::ConnectionTimeoutError) - expect(log.string).to include("ActiveRecord::ConnectionTimeoutError occured:") + expect(log.string).to include("ActiveRecord::ConnectionTimeoutError occurred:") expect(log.string).to include("connection owners:") expect(log.string).to include("other threads") diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 0414ced..534d250 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -1,29 +1,9 @@ require "bundler/setup" -require "activerecord/debug_errors" - -ActiveRecord::Base.establish_connection( - adapter: "mysql2", - host: ENV['MYSQL_HOST'], - port: ENV['MYSQL_PORT'], - username: ENV['MYSQL_USERNAME'], - password: ENV['MYSQL_PASSWORD'], - database: ENV['MYSQL_DATABASE'], - variables: { - innodb_lock_wait_timeout: 1, - }, -) - -unless ActiveRecord::Base.connection.table_exists?('users') - ActiveRecord::Base.connection.create_table('users') do |t| - t.string 'name' - t.index ['name'], name: 'ux_name', unique: true - end +if Bundler.definition.specs.find { |s| s.name == "activerecord" }.version < Gem::Version.new("7.1") + # Workaround for https://github.com/rails/rails/issues/54260 + require "logger" end - -class User < ActiveRecord::Base; end - -User.find_or_create_by!(name: 'foo') -User.find_or_create_by!(name: 'bar') +require "activerecord/debug_errors" RSpec.configure do |config| # Enable flags like --only-failures and --next-failure @@ -35,4 +15,51 @@ class User < ActiveRecord::Base; end config.expect_with :rspec do |c| c.syntax = :expect end + + config.before(:all) do + base_db_config = { + adapter: "mysql2", + host: ENV['MYSQL_HOST'], + port: ENV['MYSQL_PORT'], + username: ENV['MYSQL_USERNAME'], + password: ENV['MYSQL_PASSWORD'], + database: ENV['MYSQL_DATABASE'], + variables: { + innodb_lock_wait_timeout: 1, + }, + } + + user_for_replica = 'activerecord-debug_errors' + ActiveRecord::Base.configurations = { + default_env: { + primary: base_db_config, + primary_replica: base_db_config.merge(username: user_for_replica, replica: true), + } + } + + ActiveRecord::Base.establish_connection(:default_env) + + unless ActiveRecord::Base.connection.table_exists?('users') + ActiveRecord::Base.connection.create_table('users') do |t| + t.string 'name' + t.index ['name'], name: 'ux_name', unique: true + end + end + + class ApplicationRecord < ActiveRecord::Base + self.abstract_class = true + connects_to database: { writing: :primary, reading: :primary_replica } + end + class User < ApplicationRecord; end + + User.find_or_create_by!(name: 'foo') + User.find_or_create_by!(name: 'bar') + + ActiveRecord::Base.connection.execute(<<~SQL) + CREATE USER IF NOT EXISTS '#{user_for_replica}'@'%' IDENTIFIED BY '#{ENV['MYSQL_PASSWORD']}' + SQL + ActiveRecord::Base.connection.execute(<<~SQL) + GRANT SELECT, LOCK TABLES ON *.* To '#{user_for_replica}'@'%' + SQL + end end diff --git a/spec/support/cyclic_barrier.rb b/spec/support/cyclic_barrier.rb new file mode 100644 index 0000000..a588f83 --- /dev/null +++ b/spec/support/cyclic_barrier.rb @@ -0,0 +1,21 @@ +# This class is a simple implementation of CyclicBarrier in Java +class CyclicBarrier + def initialize(parties) + @cv = ConditionVariable.new + @mutex = Mutex.new + @parties = parties + @number_waiting = 0 + end + + def await(timeout = nil) + @mutex.synchronize do + @number_waiting += 1 + if @number_waiting == @parties + @cv.broadcast + else + @cv.wait(@mutex, timeout) + raise Timeout::Error if @number_waiting != @parties + end + end + end +end