ruby dbi connection to Mariadb break after beeing idle for 10 minutes

[Hubert Krause]

ruby dbi connection to Mariadb break after beeing idle for 10 minutes

I use:

* debian squeeze
* mariadb 5.3.7-mariadb116~squeeze
* libdbd-mysql-ruby1.8 0.4.4-1
* libdbi-ruby1.8 0.4.3-2
* libmysql-ruby1.8 2.8.2-1
* libruby1.8 1.8.7.302-2squeeze1
* libmysqlclient16 5.3.7-mariadb116~squeeze

ruby dbi connection to Mariadb break after beeing idle for 10 minutes and doing
a query again. Code to reproduce:

#!/usr/bin/env ruby

require 'dbi'
require 'date'

DBNAME='test'
DBSOCKET='/var/run/mysqld/mysqld.sock'
DBUSER='test'
DBPASS='test'

# for testing purpose just create a test db:
# create database test;
# and grant select:
# grant select on test.* to 'test'@'localhost' identified by 'test';

wait_min=[9,10,11]

db = DBI.connect("DBI:Mysql:database=#{DBNAME};socket=#{DBSOCKET}", DBUSER, DBPASS)

wait_min.each do | n |
 i = n*60
 puts DateTime.now()
 puts "do query: SELECT 1;"
 query=db.prepare("SELECT 1;")
 query.execute
 query.fetch_array
 query.finish
 puts "sleep for #{n} min."
 sleep(i)
end

puts "Disconnect:"
db.disconnect

Waiting for 9 minutes and doing a 'SELECT 1;' works, waiting for 10 minutes lead to the error:

/usr/lib/ruby/1.8/dbd/Mysql.rb:106:in `error': MySQL server has gone away (DBI::DatabaseError)
        from /usr/lib/ruby/1.8/dbd/mysql/statement.rb:42:in `execute'
        from /usr/lib/ruby/1.8/dbi/handles/statement.rb:116:in `execute'
        from test_db2.rb:25
        from test_db2.rb:20:in `each'
        from test_db2.rb:20

An excerpt of an strace log running these program:

connect(3, {sa_family=AF_FILE, path="/var/run/mysqld/mysqld.sock"}, 110) = 0
setsockopt(3, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0
setsockopt(3, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0
brk(0xde7000) = 0xde7000
setsockopt(3, SOL_IP, IP_TOS, [8], 4) = -1 EOPNOTSUPP (Operation not supported)
setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
read(3, "c\0\0\0\n5.3.7-MariaDB-mariadb116~sq"..., 16384) = 103
stat("/usr/share/mysql/charsets/Index.xml", {st_mode=S_IFREG|0644, st_size=18261, ...}) = 0
open("/usr/share/mysql/charsets/Index.xml", O_RDONLY) = 4
read(4, "<?xml version='1.0' encoding=\"ut"..., 18261) = 18261
close(4) = 0
write(3, "U\0\0\1\215\242\10\0\0\0\0@\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 89) = 89
read(3, "\7\0\0\2\0\0\0\2\0\0\0", 16384) = 11
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f489e3d4000
write(1, "2012-08-10T11:51:16+02:00\n", 26) = 26
write(1, "do query: SELECT 1;\n", 20) = 20
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(3, "\n\0\0\0\3SELECT 1;", 14) = 14
read(3, "\1\0\0\1\1\27\0\0\2\3def\0\0\0\0011\0\f?\0\1\0\0\0\10\201\0\0\0\0"..., 16384) = 56
write(1, "sleep for 9 min.\n", 17) = 17
select(0, NULL, NULL, NULL, {540, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(1, "2012-08-10T12:00:16+02:00\n", 26) = 26
write(1, "do query: SELECT 1;\n", 20) = 20
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(3, "\n\0\0\0\3SELECT 1;", 14) = 14
read(3, "\1\0\0\1\1\27\0\0\2\3def\0\0\0\0011\0\f?\0\1\0\0\0\10\201\0\0\0\0"..., 16384) = 56
write(1, "sleep for 10 min.\n", 18) = 18
select(0, NULL, NULL, NULL, {600, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
brk(0xe0a000) = 0xe0a000
brk(0xe05000) = 0xe05000
write(1, "2012-08-10T12:10:16+02:00\n", 26) = 26
write(1, "do query: SELECT 1;\n", 20) = 20
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 1 ([{fd=3, revents=POLLIN|POLLHUP}])
read(3, "", 8192) = 0
shutdown(3, 2 /* send and receive */) = 0
close(3) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(2, "/usr/lib/ruby/1.8/dbd/Mysql.rb:1"..., 45) = 45
write(2, ": ", 2) = 2
write(2, "MySQL server has gone away", 26) = 26
write(2, " (", 2) = 2
write(2, "DBI::DatabaseError", 18) = 18
write(2, ")\n", 2) = 2
write(2, "\tfrom /usr/lib/ruby/1.8/dbd/mysq"..., 63) = 63
write(2, "\tfrom /usr/lib/ruby/1.8/dbi/hand"..., 66) = 66
write(2, "\tfrom test_db2.rb:25\n", 21) = 21
write(2, "\tfrom test_db2.rb:20:in `each'\n", 31) = 31
write(2, "\tfrom test_db2.rb:20\n", 21) = 21
rt_sigaction(SIGINT, {SIG_DFL, [INT], SA_RESTORER|SA_RESTART, 0x7f489d0a8230}, {0x7f489df4fd60, [], SA_RESTORER, 0x7f489dcabff0}, 8) = 0
exit_group(1) = ?

I have tested this Program with mysqld 5.1.63 and it works as expected. The difference between mysqld 5.1.63 and
mariadb 5.3.7-mariadb116~squeeze is that the poll before sending the new query will be answered by Mariadb after 10 minutes idle,
but not by mysqld 5.1.63. (look at line 19,27,37 of the strace log).

The only workaround I can imagin is to do keep alive querys on idle connections.

[Elena Stepanova (elenst)]

Hi,

I ran your script on MariaDB 5.3.7 (my local installation from a binary tarball), and I didn't hit the issue, both 10 and 11 min work as expected.

What you observe looks like you have wait_timeout=600 configured somewhere for your MariaDB instance (but not for MySQL).

Could you please connect to your servers, both of them, and check the value of wait_timeout?
Only, if you do it with an interactive client, you need to check the GLOBAL value, e.g.

SELECT @@global.wait_timeout;

(It is important because the session timeout would be initialized differently).

Thanks.

[Hubert Krause (hubert-krause)]

Hi,

Sorry, I've send my reply with the wrong email adress, thats why it take so long. Now here my reply:

I am Sorry for this wrong Bugreport because:

> SELECT @@global.wait_timeout;

gives 28800 on the mysql5.1 server and 600 on the mariadb server. If I
delete the setting "wait_timeout = 600" from my.cnf (yes, I didn't look
there before reporting this bug... sorry again) "SELECT @@global.wait_timeout;"
gives 28800.

But nevertheless it is a strange default in my.cnf for wait_timeout
because the difference between internal default of 28800 and the
configured default of 600 in the my.cnf delivered by
mysql-common_5.3.7-mariadb116~squeeze package from
http://mirror2.hs-esslingen.de/mariadb/repo/5.3/debian is big. Maybe
this setting should be removed in future versions of this package.

Thank you very much for your help,

Hubert Krause