From ccf75107fe89de779b7fa7e98ba449824d727de3 Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Wed, 19 Mar 2025 17:21:55 -0400 Subject: [PATCH 1/9] rescuing the ActiveRecord::Deadlocked error too. * Adding different tests for LockWaitTimeout error vs Deadlocked error. * Bumping gem to rails 7.1 so brakeman will pass. * Adding error class to log message so we can see which type of error was thrown. * The "innodb_status_cmd" was throwing errors in tests. * Added Installation instructions to README --- Gemfile.lock | 49 ++++++++++++++++++++---------- README | 20 +++++++++++++ deadlock_retry.gemspec | 2 +- lib/deadlock_retry.rb | 4 +-- test/deadlock_retry_test.rb | 59 ++++++++++++++++++++++++++++++++----- 5 files changed, 109 insertions(+), 25 deletions(-) diff --git a/Gemfile.lock b/Gemfile.lock index 2a5e9f6..f7318c0 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,39 +1,58 @@ PATH remote: . specs: - deadlock_retry (1.2.0) + deadlock_retry (2.1.0) 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) - concurrent-ruby (~> 1.0, >= 1.0.2) + activemodel (7.2.2.1) + activesupport (= 7.2.2.1) + activerecord (7.2.2.1) + activemodel (= 7.2.2.1) + activesupport (= 7.2.2.1) + timeout (>= 0.4.0) + activesupport (7.2.2.1) + base64 + benchmark (>= 0.3) + bigdecimal + concurrent-ruby (~> 1.0, >= 1.3.1) + connection_pool (>= 2.2.5) + drb i18n (>= 1.6, < 2) + logger (>= 1.4.2) minitest (>= 5.1) - tzinfo (~> 2.0) - zeitwerk (~> 2.3) - concurrent-ruby (1.2.0) - i18n (1.12.0) + securerandom (>= 0.3) + tzinfo (~> 2.0, >= 2.0.5) + 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) 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) + byebug deadlock_retry! + minitest-color mocha BUNDLED WITH diff --git a/README b/README index 5353dde..1f8005f 100644 --- a/README +++ b/README @@ -15,3 +15,23 @@ 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 +``` 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..59a5603 100644 --- a/lib/deadlock_retry.rb +++ b/lib/deadlock_retry.rb @@ -12,12 +12,12 @@ 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 + rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked => e raise if in_nested_transaction? raise if retry_count >= MAXIMUM_RETRIES_ON_DEADLOCK retry_count += 1 - logger.info { "Deadlock detected on retry #{retry_count}, restarting transaction" } + logger.info { "Deadlock detected on retry #{retry_count}, restarting transaction [#{e.class}]" } log_innodb_status if DeadlockRetry.innodb_status_cmd exponential_pause(retry_count) retry diff --git a/test/deadlock_retry_test.rb b/test/deadlock_retry_test.rb index f015b63..8c315c7 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 @@ -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,13 +109,31 @@ def test_no_errors_with_lock_timeout assert errors.empty? end - def test_error_if_limit_exceeded + def test_error_if_limit_exceeded_with_deadlock + assert_raises(ActiveRecord::StatementInvalid) do + MockModel.transaction { raise ActiveRecord::Deadlocked, DEADLOCK_ERROR } + end + end + + def test_error_if_limit_exceeded_with_lock_timeout assert_raises(ActiveRecord::StatementInvalid) do - MockModel.transaction { raise ActiveRecord::LockWaitTimeout, DEADLOCK_ERROR } + MockModel.transaction { raise ActiveRecord::LockWaitTimeout, TIMEOUT_ERROR } + end + end + + 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 + [1, 2, 3].each do |i| + assert_match(/INFO -- : Deadlock detected on retry #{i}, restarting transaction \[ActiveRecord::Deadlocked\]/, logs) end end - def test_logs_at_level_info_by_default + def test_logs_at_level_info_by_default_with_lock_timeout log_io = StringIO.new log = Logger.new(log_io) MockModel.logger = log @@ -113,7 +141,7 @@ def test_logs_at_level_info_by_default 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_match(/INFO -- : Deadlock detected on retry #{i}, restarting transaction \[ActiveRecord::LockWaitTimeout\]/, logs) end end @@ -133,7 +161,7 @@ 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_lock_timeout tries = 0 errors = 0 @@ -149,4 +177,21 @@ def test_error_in_nested_transaction_should_retry_outermost_transaction assert_equal 4, tries end + + 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, "MySQL::Error: Deadlock found when trying to get lock" unless errors > 3 + end + end + end + + assert_equal 4, tries + end end From 5d7ec237a9853f1e9278156e98d49b427469e6d3 Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Thu, 20 Mar 2025 09:44:21 -0400 Subject: [PATCH 2/9] Bumping the gem version from 2.1.0 to 2.2.0 --- lib/deadlock_retry/version.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/deadlock_retry/version.rb b/lib/deadlock_retry/version.rb index 33a774e..d9eda66 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.0' end From 820b64bbd596ff54144b8ebe5a5e9f06533af0eb Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Thu, 20 Mar 2025 09:45:58 -0400 Subject: [PATCH 3/9] Updating Gemfile.lock with the new version number, 2.2.0 --- Gemfile.lock | 22 ++++++++++++---------- 1 file changed, 12 insertions(+), 10 deletions(-) diff --git a/Gemfile.lock b/Gemfile.lock index f7318c0..da13913 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,29 +1,30 @@ PATH remote: . specs: - deadlock_retry (2.1.0) + deadlock_retry (2.2.0) GEM remote: http://rubygems.org/ specs: - activemodel (7.2.2.1) - activesupport (= 7.2.2.1) - activerecord (7.2.2.1) - activemodel (= 7.2.2.1) - activesupport (= 7.2.2.1) + 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.2.2.1) + activesupport (7.1.5.1) base64 benchmark (>= 0.3) bigdecimal - concurrent-ruby (~> 1.0, >= 1.3.1) + 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, >= 2.0.5) + tzinfo (~> 2.0) base64 (0.2.0) benchmark (0.4.0) bigdecimal (3.1.9) @@ -39,6 +40,7 @@ GEM 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) @@ -49,7 +51,7 @@ PLATFORMS aarch64-linux DEPENDENCIES - activerecord (~> 7.1) + activerecord (~> 7.1.5.1) byebug deadlock_retry! minitest-color From aaacd5764d9600245d9a1bdf372583ba91e7a23c Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Thu, 20 Mar 2025 11:36:08 -0400 Subject: [PATCH 4/9] Adding more logging so we can see the full flow Adding logs for when the max retries has been reached and when we are in a nested transaction. Switching the tests to non-regex matches, because they were getting more brittle with text escaping (brackets, paranthesis). --- README | 6 ++ lib/deadlock_retry.rb | 25 +++++-- test/deadlock_retry_test.rb | 133 ++++++++++++++++++++++++++++++++---- 3 files changed, 143 insertions(+), 21 deletions(-) diff --git a/README b/README index 1f8005f..0a762c5 100644 --- a/README +++ b/README @@ -35,3 +35,9 @@ exit # run the the test suite make test ``` + +## Development + +``` +make guard +``` diff --git a/lib/deadlock_retry.rb b/lib/deadlock_retry.rb index 59a5603..b8a1f2d 100644 --- a/lib/deadlock_retry.rb +++ b/lib/deadlock_retry.rb @@ -13,13 +13,21 @@ def transaction(requires_new: nil, isolation: nil, joinable: true, &block) begin super(requires_new: requires_new, isolation: isolation, joinable: joinable, &block) rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked => e - raise if in_nested_transaction? + if in_nested_transaction? + logger.info { "DeadlockRetry: [NESTED_TRANSACTION] Deadlock detected in a nested transaction, not retrying. [#{e.class}]" } + raise + end + + if retry_count >= MAXIMUM_RETRIES_ON_DEADLOCK + logger.info { "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 [#{e.class}]" } + pause_seconds = exponential_pause_seconds(retry_count) + logger.info { "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/test/deadlock_retry_test.rb b/test/deadlock_retry_test.rb index 8c315c7..3474250 100644 --- a/test/deadlock_retry_test.rb +++ b/test/deadlock_retry_test.rb @@ -71,7 +71,7 @@ def adapter_name end module NoPause - def exponential_pause(_) + def sleep_pause(_) # No pause! end end @@ -85,6 +85,13 @@ def setup DeadlockRetry.class_variable_set(:@@deadlock_logger_severity, nil) end + def print_logs(logs) + puts "\n" + puts "*" * 100 + puts logs + puts "@" * 100 + end + def test_no_errors assert_equal :success, MockModel.transaction { :success } end @@ -110,14 +117,20 @@ def test_no_errors_with_lock_timeout end def test_error_if_limit_exceeded_with_deadlock - assert_raises(ActiveRecord::StatementInvalid) do - MockModel.transaction { raise ActiveRecord::Deadlocked, DEADLOCK_ERROR } + 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::StatementInvalid) do - MockModel.transaction { raise ActiveRecord::LockWaitTimeout, TIMEOUT_ERROR } + 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 @@ -128,9 +141,10 @@ def test_logs_at_level_info_by_default_with_deadlock test_no_errors_with_deadlock log_io.rewind logs = log_io.read - [1, 2, 3].each do |i| - assert_match(/INFO -- : Deadlock detected on retry #{i}, restarting transaction \[ActiveRecord::Deadlocked\]/, logs) - end + + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : 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 @@ -140,9 +154,48 @@ def test_logs_at_level_info_by_default_with_lock_timeout 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 \[ActiveRecord::LockWaitTimeout\]/, logs) + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : 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 + + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked]") + refute_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") + assert_includes(logs, "INFO -- : 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 + + test_no_errors_with_lock_timeout + log_io.rewind + logs = log_io.read + + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout]") + refute_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::LockWaitTimeout]") end def test_error_if_unrecognized_error @@ -161,7 +214,7 @@ 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_with_lock_timeout + def test_error_in_nested_transaction_should_retry_outermost_transaction_with_deadlock tries = 0 errors = 0 @@ -170,7 +223,7 @@ def test_error_in_nested_transaction_should_retry_outermost_transaction_with_loc MockModel.transaction do MockModel.transaction do errors += 1 - raise ActiveRecord::LockWaitTimeout, "MySQL::Error: Lock wait timeout exceeded" unless errors > 3 + raise ActiveRecord::Deadlocked, DEADLOCK_ERROR unless errors > 3 end end end @@ -178,7 +231,7 @@ def test_error_in_nested_transaction_should_retry_outermost_transaction_with_loc assert_equal 4, tries end - def test_error_in_nested_transaction_should_retry_outermost_transaction_with_deadlock + def test_error_in_nested_transaction_should_retry_outermost_transaction_with_lock_timeout tries = 0 errors = 0 @@ -187,11 +240,63 @@ def test_error_in_nested_transaction_should_retry_outermost_transaction_with_dea MockModel.transaction do MockModel.transaction do errors += 1 - raise ActiveRecord::Deadlocked, "MySQL::Error: Deadlock found when trying to get lock" 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 + + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked]") + refute_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::Deadlocked]") + assert_equal 8, logs.scan("DeadlockRetry: [NESTED_TRANSACTION] Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked]").size + end + + def test_logs_in_nested_transaction_with_deadlock + 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 + + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout]") + refute_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") + assert_includes(logs, "INFO -- : DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::LockWaitTimeout]") + assert_equal 8, logs.scan("DeadlockRetry: [NESTED_TRANSACTION] Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout]").size + end end From bd13d4956aaf46e5f0502e034bc358e4b302434f Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Thu, 20 Mar 2025 16:00:36 -0400 Subject: [PATCH 5/9] updating the changelog for v2.2.0 --- CHANGELOG.md | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 82b4d04..b84224b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ deadlock_retry changes +== v2.2.0 + +* Retry on ActiveRecord::Deadlocked, in addition to ActiveRecord::LockWaitTimeout + == v2.1.0 * update for rails 5 keyword args From 3994020b41ea467eaad49d5e537262abfda078ca Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Thu, 20 Mar 2025 16:37:38 -0400 Subject: [PATCH 6/9] Making logging messages more consistent --- lib/deadlock_retry.rb | 6 ++-- test/deadlock_retry_test.rb | 56 ++++++++++++++++++------------------- 2 files changed, 31 insertions(+), 31 deletions(-) diff --git a/lib/deadlock_retry.rb b/lib/deadlock_retry.rb index b8a1f2d..4046313 100644 --- a/lib/deadlock_retry.rb +++ b/lib/deadlock_retry.rb @@ -14,18 +14,18 @@ def transaction(requires_new: nil, isolation: nil, joinable: true, &block) super(requires_new: requires_new, isolation: isolation, joinable: joinable, &block) rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked => e if in_nested_transaction? - logger.info { "DeadlockRetry: [NESTED_TRANSACTION] Deadlock detected in a nested transaction, not retrying. [#{e.class}]" } + 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 { "DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: #{MAXIMUM_RETRIES_ON_DEADLOCK}), not retrying. [#{e.class}]" } + 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 retry_count += 1 pause_seconds = exponential_pause_seconds(retry_count) - logger.info { "DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry #{retry_count}, retrying transaction in #{pause_seconds} seconds. [#{e.class}]" } + 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 sleep_pause(pause_seconds) retry diff --git a/test/deadlock_retry_test.rb b/test/deadlock_retry_test.rb index 3474250..80f97aa 100644 --- a/test/deadlock_retry_test.rb +++ b/test/deadlock_retry_test.rb @@ -142,9 +142,9 @@ def test_logs_at_level_info_by_default_with_deadlock log_io.rewind logs = log_io.read - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [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]") end def test_logs_at_level_info_by_default_with_lock_timeout @@ -154,9 +154,9 @@ def test_logs_at_level_info_by_default_with_lock_timeout test_no_errors_with_lock_timeout log_io.rewind logs = log_io.read - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [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]") end def test_logs_if_limit_exceeded_with_deadlock @@ -171,11 +171,11 @@ def test_logs_if_limit_exceeded_with_deadlock log_io.rewind logs = log_io.read - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked]") - refute_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") - assert_includes(logs, "INFO -- : 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 @@ -191,11 +191,11 @@ def test_logs_if_limit_exceeded_with_lock_timeout log_io.rewind logs = log_io.read - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout]") - refute_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") - assert_includes(logs, "INFO -- : 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 @@ -266,12 +266,12 @@ def test_logs_in_nested_transaction_with_deadlock log_io.rewind logs = log_io.read - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::Deadlocked]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::Deadlocked]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::Deadlocked]") - refute_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::Deadlocked]") - assert_equal 8, logs.scan("DeadlockRetry: [NESTED_TRANSACTION] Deadlock detected in a nested transaction, not retrying. [ActiveRecord::Deadlocked]").size + 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_deadlock @@ -292,11 +292,11 @@ def test_logs_in_nested_transaction_with_deadlock log_io.rewind logs = log_io.read - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 1, retrying transaction in 0 seconds. [ActiveRecord::LockWaitTimeout]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 2, retrying transaction in 1 seconds. [ActiveRecord::LockWaitTimeout]") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 3, retrying transaction in 2 seconds. [ActiveRecord::LockWaitTimeout]") - refute_includes(logs, "INFO -- : DEADLOCK_RETRY_RETRYING_TRANSACTION Deadlock detected on retry 4") - assert_includes(logs, "INFO -- : DEADLOCK_RETRY_MAXIMUM_RETRIES_EXCEEDED Deadlock detected and maximum retries exceeded (maximum: 3), not retrying. [ActiveRecord::LockWaitTimeout]") - assert_equal 8, logs.scan("DeadlockRetry: [NESTED_TRANSACTION] Deadlock detected in a nested transaction, not retrying. [ActiveRecord::LockWaitTimeout]").size + 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 From 6ded6a9903acb48267ebe2407a67f0192c3e3b10 Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Thu, 20 Mar 2025 17:03:11 -0400 Subject: [PATCH 7/9] Adding more info for log tests and fixing one of the tests with logical issue. --- test/deadlock_retry_test.rb | 67 +++++++++++++++++++++++++++++++++++-- 1 file changed, 65 insertions(+), 2 deletions(-) diff --git a/test/deadlock_retry_test.rb b/test/deadlock_retry_test.rb index 80f97aa..4b7862f 100644 --- a/test/deadlock_retry_test.rb +++ b/test/deadlock_retry_test.rb @@ -171,6 +171,18 @@ def test_logs_if_limit_exceeded_with_deadlock 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]") @@ -187,10 +199,21 @@ def test_logs_if_limit_exceeded_with_lock_timeout MockModel.transaction { raise ActiveRecord::LockWaitTimeout, TIMEOUT_ERROR } end - test_no_errors_with_lock_timeout 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]") @@ -266,6 +289,26 @@ def test_logs_in_nested_transaction_with_deadlock 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]") @@ -274,7 +317,7 @@ def test_logs_in_nested_transaction_with_deadlock 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_deadlock + def test_logs_in_nested_transaction_with_lock_timeout log_io = StringIO.new log = Logger.new(log_io) MockModel.logger = log @@ -292,6 +335,26 @@ def test_logs_in_nested_transaction_with_deadlock 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]") From 475cb837124cabbaab0e9ec24cb2dade8b3a3449 Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Fri, 21 Mar 2025 10:33:25 -0400 Subject: [PATCH 8/9] Bumping version to 2.2.1 --- CHANGELOG.md | 2 +- Gemfile.lock | 2 +- README | 14 ++++++++++++++ lib/deadlock_retry/version.rb | 2 +- 4 files changed, 17 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b84224b..a71dd92 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ deadlock_retry changes -== v2.2.0 +== v2.2.1 * Retry on ActiveRecord::Deadlocked, in addition to ActiveRecord::LockWaitTimeout diff --git a/Gemfile.lock b/Gemfile.lock index da13913..4df0533 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,7 +1,7 @@ PATH remote: . specs: - deadlock_retry (2.2.0) + deadlock_retry (2.2.1) GEM remote: http://rubygems.org/ diff --git a/README b/README index 0a762c5..2ac798d 100644 --- a/README +++ b/README @@ -41,3 +41,17 @@ make test ``` 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/lib/deadlock_retry/version.rb b/lib/deadlock_retry/version.rb index d9eda66..b624d65 100644 --- a/lib/deadlock_retry/version.rb +++ b/lib/deadlock_retry/version.rb @@ -1,3 +1,3 @@ module DeadlockRetry - VERSION = '2.2.0' + VERSION = '2.2.1' end From 48c9637c28482f5ea0f758e8704e601a644bf723 Mon Sep 17 00:00:00 2001 From: Tom Hallett Date: Fri, 21 Mar 2025 15:29:59 -0400 Subject: [PATCH 9/9] Removing unneeded test utility method. Bumping to 2.2.2 --- CHANGELOG.md | 2 +- Gemfile.lock | 2 +- lib/deadlock_retry/version.rb | 2 +- test/deadlock_retry_test.rb | 7 ------- 4 files changed, 3 insertions(+), 10 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a71dd92..aacd470 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ deadlock_retry changes -== v2.2.1 +== v2.2.2 * Retry on ActiveRecord::Deadlocked, in addition to ActiveRecord::LockWaitTimeout diff --git a/Gemfile.lock b/Gemfile.lock index 4df0533..b05a965 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,7 +1,7 @@ PATH remote: . specs: - deadlock_retry (2.2.1) + deadlock_retry (2.2.2) GEM remote: http://rubygems.org/ diff --git a/lib/deadlock_retry/version.rb b/lib/deadlock_retry/version.rb index b624d65..8816c05 100644 --- a/lib/deadlock_retry/version.rb +++ b/lib/deadlock_retry/version.rb @@ -1,3 +1,3 @@ module DeadlockRetry - VERSION = '2.2.1' + VERSION = '2.2.2' end diff --git a/test/deadlock_retry_test.rb b/test/deadlock_retry_test.rb index 4b7862f..7221669 100644 --- a/test/deadlock_retry_test.rb +++ b/test/deadlock_retry_test.rb @@ -85,13 +85,6 @@ def setup DeadlockRetry.class_variable_set(:@@deadlock_logger_severity, nil) end - def print_logs(logs) - puts "\n" - puts "*" * 100 - puts logs - puts "@" * 100 - end - def test_no_errors assert_equal :success, MockModel.transaction { :success } end