Random failures using prepared statements

[catphish]

While investigating some random errors in my MySQL connections, I have discovered that using prepared statements as described in the mysql2 documentation will almost invariably result in random errors, most notably Commands out of sync.

Example code:

gem 'mysql2', '0.5.0'
require 'mysql2'

mysql_spec = {
  host: ENV['HOSTNAME'],
  username: ENV['USERNAME'],
  password: ENV['PASSWORD'],
  database: ENV['DATABASE']
}

connection_1 =  Mysql2::Client.new(mysql_spec)

1000.times do |n|
  statement_1 = connection_1.prepare("SELECT * FROM test WHERE test_id = ?")
  result_1    = statement_1.execute(1).to_a
end

The above code has been tested across various MySQL / Maria installations using both mysql 0.4.10 and 0.5.0, and usually fails before completing 1000 iterations:

/home/charlie/.rvm/gems/ruby-2.4.0/gems/mysql2-0.5.0/lib/mysql2/statement.rb:7:in `_execute': Commands out of sync; you can't run this command now (Mysql2::Error)
	from /home/charlie/.rvm/gems/ruby-2.4.0/gems/mysql2-0.5.0/lib/mysql2/statement.rb:7:in `block in execute'
	from /home/charlie/.rvm/gems/ruby-2.4.0/gems/mysql2-0.5.0/lib/mysql2/statement.rb:6:in `handle_interrupt'
	from /home/charlie/.rvm/gems/ruby-2.4.0/gems/mysql2-0.5.0/lib/mysql2/statement.rb:6:in `execute'
	from mysqltest2.rb:15:in `block in <main>'
	from mysqltest2.rb:13:in `times'
	from mysqltest2.rb:13:in `<main>'

By trial and error, I discovered 2 ways to resolve this. Firstly the problem doesn't occur when GC is disabled.

GC.disable

Alternatively, this can be resolved by changing the code to explicitly close the statement after each execute has completed.

1000.times do |n|
  statement_1 = connection_1.prepare("SELECT * FROM test WHERE test_id = ?")
  result_1    = statement_1.execute(1).to_a
  statement_1.close
end

I would appreciate any advice on whether this is a bug, or whether I am simply using the API incorrectly. If it is the latter, could this be a documentation problem? Thanks!

[kamipo]

This is a same issue with #694 which was fixed by #705 in 0.4.4.

[adamcooke]

This is reproducible using 0.5.0 so perhaps a regression has appeared somewhere?

/Users/adam/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/mysql2-0.5.0/lib/mysql2/statement.rb:7:in `_execute': Commands out of sync; you can't run this command now (Mysql2::Error)
	from /Users/adam/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/mysql2-0.5.0/lib/mysql2/statement.rb:7:in `block in execute'
	from /Users/adam/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/mysql2-0.5.0/lib/mysql2/statement.rb:6:in `handle_interrupt'
	from /Users/adam/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/mysql2-0.5.0/lib/mysql2/statement.rb:6:in `execute'
	from mysql.rb:14:in `block in <main>'

Can't reproduce on 0.4.3 or 0.4.4 but can on 0.4.2.

[kamipo]

ah... will investigate this tomorrow.

[sodabrew]

Thank you! Yes, sounds like another GC race :(