Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

log_innodb_status is not safe #5

Merged
merged 4 commits into from

2 participants

@osheroff

Hi,
(btw, this is the issue Simon Winstow was talking about)
I don't know if you'd want to use this code or work out another fix, but deadlock_retry can actually quite dangerous in a limited set of circumstances, due to the attempt to execute "SHOW INNODB STATUS". Here's what happens:

  • transaction deadlocks
  • call to log_innodb_status is made
  • SHOW INNODB STATUS command fails, for a variety of reasons -- including that the user doesn't have permission to execute this command.
  • the "rescue Exception" block kicks in, but mysql has already silently rolled-back our transaction because of the error in SHOW INNODB STATUS.
  • the transaction continues, but is fundamentally broken and we've silently lost data.
Ben Osheroff... added some commits
Ben Osheroff and Simon Wistow Turn off deadlock_retry logging by default -- this was causing any de…
…adlocked transaction to fail silently and nastily
84cd4ac
Ben Osheroff and Simon Wistow update gemspec 29c098c
Ben Osheroff and Simon Wistow merge upstream 60523e8
@mperham
Owner

I suggest you try to run the command at startup and en/disable based on whether it works. This way the user need do nothing to get the logging if permissions are ok. don't clutter up the code with configuration; just print out a warning if perms are wrong.

@osheroff

Ok, try that on for size -- before we run the first transaction we're asked to run we'll check and see if "show innodb status" crashes.

@osheroff osheroff closed this
@osheroff osheroff reopened this
@mperham mperham merged commit ddb62b5 into mperham:master
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on May 12, 2011
  1. @osheroff

    Turn off deadlock_retry logging by default -- this was causing any de…

    Ben Osheroff and Simon Wistow authored osheroff committed
    …adlocked transaction to fail silently and nastily
  2. @osheroff

    update gemspec

    Ben Osheroff and Simon Wistow authored osheroff committed
  3. @osheroff

    merge upstream

    Ben Osheroff and Simon Wistow authored osheroff committed
Commits on May 13, 2011
  1. @osheroff
This page is out of date. Refresh to see the latest.
View
2  deadlock_retry.gemspec
@@ -2,7 +2,7 @@
Gem::Specification.new do |s|
s.name = %q{deadlock_retry}
- s.version = "1.1.0"
+ s.version = "1.1.1"
s.authors = ["Jamis Buck", "Mike Perham"]
s.description = s.summary = %q{Provides automatic deadlock retry and logging functionality for ActiveRecord and MySQL}
s.email = %q{mperham@gmail.com}
View
37 lib/deadlock_retry.rb
@@ -1,5 +1,4 @@
module DeadlockRetry
-
def self.included(base)
base.extend(ClassMethods)
base.class_eval do
@@ -9,6 +8,16 @@ class << self
end
end
+ @@innodb_status_available = nil
+
+ def self.innodb_status_available?
+ @@innodb_status_available
+ end
+
+ def self.innodb_status_available=(bool)
+ @@innodb_status_available = bool
+ end
+
module ClassMethods
DEADLOCK_ERROR_MESSAGES = [
"Deadlock found when trying to get lock",
@@ -17,9 +26,12 @@ module ClassMethods
MAXIMUM_RETRIES_ON_DEADLOCK = 3
+
def transaction_with_deadlock_handling(*objects, &block)
retry_count = 0
+ check_innodb_status_available
+
begin
transaction_without_deadlock_handling(*objects, &block)
rescue ActiveRecord::StatementInvalid => error
@@ -28,7 +40,7 @@ def transaction_with_deadlock_handling(*objects, &block)
raise if retry_count >= MAXIMUM_RETRIES_ON_DEADLOCK
retry_count += 1
logger.info "Deadlock detected on retry #{retry_count}, restarting transaction"
- log_innodb_status
+ log_innodb_status if DeadlockRetry.innodb_status_available?
retry
else
raise
@@ -43,10 +55,27 @@ def in_nested_transaction?
connection.open_transactions != 0
end
+ def show_innodb_status
+ self.connection.select_value("show innodb status")
+ end
+
+ # Should we try to log innodb status -- if we don't have permission to,
+ # we actually break in-flight transactions, silently (!)
+ def check_innodb_status_available
+ return unless DeadlockRetry.innodb_status_available?.nil?
+
+ begin
+ show_innodb_status
+ DeadlockRetry.innodb_status_available = true
+ rescue
+ DeadlockRetry.innodb_status_available = false
+ end
+ end
+
def log_innodb_status
# show innodb status is the only way to get visiblity into why
# the transaction deadlocked. log it.
- lines = connection.select_value("show innodb status")
+ lines = show_innodb_status
logger.warn "INNODB Status follows:"
lines.each_line do |line|
logger.warn line
@@ -59,4 +88,4 @@ def log_innodb_status
end
end
-ActiveRecord::Base.send(:include, DeadlockRetry)
+ActiveRecord::Base.send(:include, DeadlockRetry)
View
20 test/deadlock_retry_test.rb
@@ -32,6 +32,14 @@ def self.logger
@logger ||= Logger.new(nil)
end
+ def self.show_innodb_status
+ []
+ end
+
+ def self.reset_innodb_status_availability
+ DeadlockRetry.innodb_status_availability = nil
+ end
+
include DeadlockRetry
end
@@ -39,6 +47,9 @@ class DeadlockRetryTest < Test::Unit::TestCase
DEADLOCK_ERROR = "MySQL::Error: Deadlock found when trying to get lock"
TIMEOUT_ERROR = "MySQL::Error: Lock wait timeout exceeded"
+ def setup
+ end
+
def test_no_errors
assert_equal :success, MockModel.transaction { :success }
end
@@ -71,6 +82,13 @@ def test_included_by_default
assert ActiveRecord::Base.respond_to?(:transaction_with_deadlock_handling)
end
+ def test_innodb_status_availability
+ DeadlockRetry.innodb_status_available = nil
+ MockModel.transaction {}
+ assert_equal true, DeadlockRetry.innodb_status_available?
+ end
+
+
def test_error_in_nested_transaction_should_retry_outermost_transaction
tries = 0
errors = 0
@@ -84,7 +102,7 @@ def test_error_in_nested_transaction_should_retry_outermost_transaction
end
end
end
-
+
assert_equal 4, tries
end
end
Something went wrong with that request. Please try again.