LP:1035271 - ruby dbi connection to Mariadb break after beeing idle for 10 minutes

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'

1. for testing purpose just create a test db:
2. create database test;
3. and grant select:
4. 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
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.