diff --git a/CHANGELOG.md b/CHANGELOG.md index 82b4d04..aacd470 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ deadlock_retry changes +== v2.2.2 + +* Retry on ActiveRecord::Deadlocked, in addition to ActiveRecord::LockWaitTimeout + == v2.1.0 * update for rails 5 keyword args diff --git a/Gemfile.lock b/Gemfile.lock index 2a5e9f6..b05a965 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,39 +1,60 @@ PATH remote: . specs: - deadlock_retry (1.2.0) + deadlock_retry (2.2.2) GEM remote: http://rubygems.org/ specs: - activemodel (6.1.7.2) - activesupport (= 6.1.7.2) - activerecord (6.1.7.2) - activemodel (= 6.1.7.2) - activesupport (= 6.1.7.2) - activesupport (6.1.7.2) + activemodel (7.1.5.1) + activesupport (= 7.1.5.1) + activerecord (7.1.5.1) + activemodel (= 7.1.5.1) + activesupport (= 7.1.5.1) + timeout (>= 0.4.0) + activesupport (7.1.5.1) + base64 + benchmark (>= 0.3) + bigdecimal concurrent-ruby (~> 1.0, >= 1.0.2) + connection_pool (>= 2.2.5) + drb i18n (>= 1.6, < 2) + logger (>= 1.4.2) minitest (>= 5.1) + mutex_m + securerandom (>= 0.3) tzinfo (~> 2.0) - zeitwerk (~> 2.3) - concurrent-ruby (1.2.0) - i18n (1.12.0) + base64 (0.2.0) + benchmark (0.4.0) + bigdecimal (3.1.9) + byebug (11.1.3) + concurrent-ruby (1.3.5) + connection_pool (2.5.0) + drb (2.2.1) + i18n (1.14.7) concurrent-ruby (~> 1.0) - minitest (5.17.0) + logger (1.6.6) + minitest (5.25.5) + minitest-color (0.0.2) + minitest (~> 5) mocha (2.0.2) ruby2_keywords (>= 0.0.5) + mutex_m (0.3.0) ruby2_keywords (0.0.5) + securerandom (0.4.1) + timeout (0.4.3) tzinfo (2.0.6) concurrent-ruby (~> 1.0) - zeitwerk (2.6.6) PLATFORMS aarch64-linux DEPENDENCIES - activerecord (~> 6.0) + activerecord (~> 7.1.5.1) + byebug deadlock_retry! + minitest-color mocha BUNDLED WITH diff --git a/README b/README index 5353dde..2ac798d 100644 --- a/README +++ b/README @@ -15,3 +15,43 @@ Add it to your Rails application by installing the gem: and including a reference to it in your application's Gemfile: gem 'deadlock_retry' + + +## Installation + +``` +cd ~/dev +git clone git@github.com:cdd/deadlock_retry.git +cd deadlock_retry + +# build the docker container +make + +# manually update the Gemfile.lock +make shell +bundle install +exit + +# run the the test suite +make test +``` + +## Development + +``` +make guard +``` + +## Bumping the version + +1. Bump the version number in `lib/deadlock_retry/version.rb` + +2. Add an entry to `CHANGELOG.md` + +3. Run the following so Gemfile.lock is updated: + +``` +make shell +bundle install +exit +``` diff --git a/deadlock_retry.gemspec b/deadlock_retry.gemspec index 4fbb03f..16731b3 100644 --- a/deadlock_retry.gemspec +++ b/deadlock_retry.gemspec @@ -15,7 +15,7 @@ Gem::Specification.new do |s| s.homepage = %q{http://github.com/mperham/deadlock_retry} s.require_paths = ["lib"] s.add_development_dependency 'mocha' - s.add_development_dependency 'activerecord', ENV['ACTIVERECORD_VERSION'] || ' ~>6.0' + s.add_development_dependency 'activerecord', ENV['ACTIVERECORD_VERSION'] || ' ~> 7.1.5.1' s.add_development_dependency 'byebug' s.add_development_dependency 'minitest-color' end diff --git a/lib/deadlock_retry.rb b/lib/deadlock_retry.rb index 4b6689d..4046313 100644 --- a/lib/deadlock_retry.rb +++ b/lib/deadlock_retry.rb @@ -12,14 +12,22 @@ def transaction(requires_new: nil, isolation: nil, joinable: true, &block) begin super(requires_new: requires_new, isolation: isolation, joinable: joinable, &block) - rescue ActiveRecord::LockWaitTimeout => error - raise if in_nested_transaction? + rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked => e + if in_nested_transaction? + logger.info { "CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [#{e.class}]" } + raise + end + + if retry_count >= MAXIMUM_RETRIES_ON_DEADLOCK + logger.info { "CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: #{MAXIMUM_RETRIES_ON_DEADLOCK}), not retrying. [#{e.class}]" } + raise + end - raise if retry_count >= MAXIMUM_RETRIES_ON_DEADLOCK retry_count += 1 - logger.info { "Deadlock detected on retry #{retry_count}, restarting transaction" } + pause_seconds = exponential_pause_seconds(retry_count) + logger.info { "CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry #{retry_count}, retrying transaction in #{pause_seconds} seconds. [#{e.class}]" } log_innodb_status if DeadlockRetry.innodb_status_cmd - exponential_pause(retry_count) + sleep_pause(pause_seconds) retry end end @@ -28,11 +36,14 @@ def transaction(requires_new: nil, isolation: nil, joinable: true, &block) WAIT_TIMES = [0, 1, 2, 4, 8, 16, 32] - def exponential_pause(count) - sec = WAIT_TIMES[count-1] || 32 + def exponential_pause_seconds(count) # sleep 0, 1, 2, 4, ... seconds up to the MAXIMUM_RETRIES. # Cap the pause time at 32 seconds. - sleep(sec) if sec != 0 + WAIT_TIMES[count-1] || 32 + end + + def sleep_pause(seconds) + sleep(seconds) if seconds != 0 end def in_nested_transaction? diff --git a/lib/deadlock_retry/version.rb b/lib/deadlock_retry/version.rb index 33a774e..8816c05 100644 --- a/lib/deadlock_retry/version.rb +++ b/lib/deadlock_retry/version.rb @@ -1,3 +1,3 @@ module DeadlockRetry - VERSION = '2.1.0' + VERSION = '2.2.2' end diff --git a/test/deadlock_retry_test.rb b/test/deadlock_retry_test.rb index f015b63..7221669 100644 --- a/test/deadlock_retry_test.rb +++ b/test/deadlock_retry_test.rb @@ -2,7 +2,7 @@ require_relative 'test_helper' # Change the version if you want to test a different version of ActiveRecord -gem 'activerecord', ENV['ACTIVERECORD_VERSION'] || ' ~>6.0' +gem 'activerecord', ENV['ACTIVERECORD_VERSION'] || ' ~> 7.1.5.1' require 'active_record' require 'active_record/version' puts "Testing ActiveRecord #{ActiveRecord::VERSION::STRING}" @@ -52,6 +52,16 @@ def select_value(sql) true end + def select_all(sql) + if sql == 'show innodb status' + "FAKE INNODB STATUS HERE" + elsif sql = 'show engine innodb status' + "FAKE ENGINE INNODB STATUS HERE" + else + raise "Unknown SQL: #{sql}" + end + end + def adapter_name "MySQL" end @@ -61,7 +71,7 @@ def adapter_name end module NoPause - def exponential_pause(_) + def sleep_pause(_) # No pause! end end @@ -89,7 +99,7 @@ def test_no_errors_with_hash_kw_params def test_no_errors_with_deadlock errors = [ DEADLOCK_ERROR ] * 3 - assert_equal :success, MockModel.transaction { raise ActiveRecord::LockWaitTimeout, errors.shift unless errors.empty?; :success } + assert_equal :success, MockModel.transaction { raise ActiveRecord::Deadlocked, errors.shift unless errors.empty?; :success } assert errors.empty? end @@ -99,22 +109,109 @@ def test_no_errors_with_lock_timeout assert errors.empty? end - def test_error_if_limit_exceeded - assert_raises(ActiveRecord::StatementInvalid) do - MockModel.transaction { raise ActiveRecord::LockWaitTimeout, DEADLOCK_ERROR } + def test_error_if_limit_exceeded_with_deadlock + assert_raises(ActiveRecord::Deadlocked) do + MockModel.transaction do + # this code will run a few times, but the raise will eventually break through + raise ActiveRecord::Deadlocked, DEADLOCK_ERROR + end + end + end + + def test_error_if_limit_exceeded_with_lock_timeout + assert_raises(ActiveRecord::LockWaitTimeout) do + MockModel.transaction do + # this code will run a few times, but the raise will eventually break through + raise ActiveRecord::LockWaitTimeout, TIMEOUT_ERROR + end end end - def test_logs_at_level_info_by_default + def test_logs_at_level_info_by_default_with_deadlock + log_io = StringIO.new + log = Logger.new(log_io) + MockModel.logger = log + test_no_errors_with_deadlock + log_io.rewind + logs = log_io.read + + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked]") + end + + def test_logs_at_level_info_by_default_with_lock_timeout log_io = StringIO.new log = Logger.new(log_io) MockModel.logger = log test_no_errors_with_lock_timeout log_io.rewind logs = log_io.read - [1, 2, 3].each do |i| - assert_match(/INFO -- : Deadlock detected on retry #{i}, restarting transaction/, logs) + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout]") + end + + def test_logs_if_limit_exceeded_with_deadlock + log_io = StringIO.new + log = Logger.new(log_io) + MockModel.logger = log + + assert_raises(ActiveRecord::Deadlocked) do + MockModel.transaction { raise ActiveRecord::Deadlocked, DEADLOCK_ERROR } + end + + log_io.rewind + logs = log_io.read + + # here is an example output of the logs: + # I, [2025-03-20T20:54:47.157839 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked] + # W, [2025-03-20T20:54:47.157844 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:54:47.157847 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:54:47.157851 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked] + # W, [2025-03-20T20:54:47.157853 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:54:47.157855 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:54:47.157858 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked] + # W, [2025-03-20T20:54:47.157860 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:54:47.157862 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:54:47.157865 #8] INFO -- : CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::Deadlocked] + + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked]") + refute_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::Deadlocked]") + end + + def test_logs_if_limit_exceeded_with_lock_timeout + log_io = StringIO.new + log = Logger.new(log_io) + MockModel.logger = log + + assert_raises(ActiveRecord::LockWaitTimeout) do + MockModel.transaction { raise ActiveRecord::LockWaitTimeout, TIMEOUT_ERROR } end + + log_io.rewind + logs = log_io.read + + # here is an example output of the logs: + # I, [2025-03-20T20:54:15.136562 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout] + # W, [2025-03-20T20:54:15.136566 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:54:15.136568 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:54:15.136572 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout] + # W, [2025-03-20T20:54:15.136575 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:54:15.136577 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:54:15.136580 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout] + # W, [2025-03-20T20:54:15.136583 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:54:15.136585 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:54:15.136588 #8] INFO -- : CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::LockWaitTimeout] + + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout]") + refute_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::LockWaitTimeout]") end def test_error_if_unrecognized_error @@ -133,7 +230,24 @@ def test_innodb_status_availability assert_equal "show innodb status", DeadlockRetry.innodb_status_cmd end - def test_error_in_nested_transaction_should_retry_outermost_transaction + def test_error_in_nested_transaction_should_retry_outermost_transaction_with_deadlock + tries = 0 + errors = 0 + + MockModel.transaction do + tries += 1 + MockModel.transaction do + MockModel.transaction do + errors += 1 + raise ActiveRecord::Deadlocked, DEADLOCK_ERROR unless errors > 3 + end + end + end + + assert_equal 4, tries + end + + def test_error_in_nested_transaction_should_retry_outermost_transaction_with_lock_timeout tries = 0 errors = 0 @@ -142,11 +256,103 @@ def test_error_in_nested_transaction_should_retry_outermost_transaction MockModel.transaction do MockModel.transaction do errors += 1 - raise ActiveRecord::LockWaitTimeout, "MySQL::Error: Lock wait timeout exceeded" unless errors > 3 + raise ActiveRecord::LockWaitTimeout, TIMEOUT_ERROR unless errors > 3 end end end assert_equal 4, tries end + + def test_logs_in_nested_transaction_with_deadlock + log_io = StringIO.new + log = Logger.new(log_io) + MockModel.logger = log + + assert_raises(ActiveRecord::Deadlocked) do + MockModel.transaction do + MockModel.transaction do + MockModel.transaction do + raise ActiveRecord::Deadlocked, DEADLOCK_ERROR + end + end + end + end + + log_io.rewind + logs = log_io.read + + # here is an example output of the logs: + # I, [2025-03-20T20:51:44.959981 #8] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked] + # I, [2025-03-20T20:51:44.959996 #8] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked] + # I, [2025-03-20T20:51:44.960000 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked] + # W, [2025-03-20T20:51:44.960003 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:51:44.960005 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:51:44.960009 #8] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked] + # I, [2025-03-20T20:51:44.960022 #8] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked] + # I, [2025-03-20T20:51:44.960026 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked] + # W, [2025-03-20T20:51:44.960041 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:51:44.960043 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:51:44.960047 #8] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked] + # I, [2025-03-20T20:51:44.960059 #8] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked] + # I, [2025-03-20T20:51:44.960063 #8] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked] + # W, [2025-03-20T20:51:44.960085 #8] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:51:44.960088 #8] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:51:44.960108 #8] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked] + # I, [2025-03-20T20:51:44.960124 #8] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked] + # I, [2025-03-20T20:51:44.960128 #8] INFO -- : CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::Deadlocked] + + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked]") + refute_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::Deadlocked]") + assert_equal 8, logs.scan("CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked]").size + end + + def test_logs_in_nested_transaction_with_lock_timeout + log_io = StringIO.new + log = Logger.new(log_io) + MockModel.logger = log + + assert_raises(ActiveRecord::LockWaitTimeout) do + MockModel.transaction do + MockModel.transaction do + MockModel.transaction do + raise ActiveRecord::LockWaitTimeout, TIMEOUT_ERROR + end + end + end + end + + log_io.rewind + logs = log_io.read + + # here is an example output of the logs: + # I, [2025-03-20T20:53:01.650127 #7] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout] + # I, [2025-03-20T20:53:01.650143 #7] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout] + # I, [2025-03-20T20:53:01.650147 #7] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout] + # W, [2025-03-20T20:53:01.650150 #7] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:53:01.650152 #7] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:53:01.650156 #7] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout] + # I, [2025-03-20T20:53:01.650169 #7] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout] + # I, [2025-03-20T20:53:01.650172 #7] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout] + # W, [2025-03-20T20:53:01.650175 #7] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:53:01.650177 #7] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:53:01.650180 #7] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout] + # I, [2025-03-20T20:53:01.650192 #7] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout] + # I, [2025-03-20T20:53:01.650196 #7] INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout] + # W, [2025-03-20T20:53:01.650199 #7] WARN -- : INNODB Status follows: + # W, [2025-03-20T20:53:01.650201 #7] WARN -- : FAKE INNODB STATUS HERE + # I, [2025-03-20T20:53:01.650205 #7] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout] + # I, [2025-03-20T20:53:01.650216 #7] INFO -- : CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout] + # I, [2025-03-20T20:53:01.650220 #7] INFO -- : CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::LockWaitTimeout] + + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout]") + refute_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") + assert_includes(logs, "INFO -- : CDD_DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::LockWaitTimeout]") + assert_equal 8, logs.scan("CDD_DEADLOCK_RETRY_NESTED_TRANSACTION Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout]").size + end end