MySQL Bugs: #66576: bad connections after a few master requests

Bug #66576	bad connections after a few master requests
Submitted:	28 Aug 2012 13:58	Modified:	15 May 2013 17:35
Reporter:	Kiriakos Krastillis	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Proxy: Core	Severity:	S2 (Serious)
Version:	0.8.2	OS:	Linux (3.4.7-1-ARCH)
Assigned to:		CPU Architecture:	Any
Tags:	mysql-proxy rw-splitting

Description:
After some successful connections to the master backend the proxy starts spitting out connection errors of the type:

this is not fixed by the old_passwords workaround. http://bugs.mysql.com/bug.php?id=30304 and http://bugs.mysql.com/bug.php?id=31574

the proxy log goes as follows:

2012-08-28 12:36:17: (message) mysql-proxy 0.8.2 started
2012-08-28 12:36:17: (debug) max open file-descriptors = 1024
2012-08-28 12:36:17: (message) proxy listening on port :4040
2012-08-28 12:36:17: (message) added read/write backend: 10.235.51.37:3306
2012-08-28 12:36:17: (message) added read-only backend: :3306
2012-08-28 12:42:54: (debug) [network-mysqld.c:937]: error on a connection (fd: -1 event: 0). closing client conn
ection.
2012-08-28 12:43:52: (debug) last message repeated 2 times
2012-08-28 12:43:52: (debug) [network-mysqld.c:937]: error on a connection (fd: -1 event: 0). closing client conn
ection.
2012-08-28 12:45:27: (debug) last message repeated 1 times
2012-08-28 12:45:27: (debug) [network-mysqld.c:937]: error on a connection (fd: -1 event: 0). closing client conn
ection.

From the connection error and onwards only every second attempt gets processed and even for those I get disconnections.

the call line is:
/usr/local/bin/mysql-proxy \
  --proxy-address=:4040 \
  --proxy-backend-addresses=${MASTER_IP}:3306 \
  --proxy-read-only-backend-addresses=:3306 \
  --proxy-lua-script=/usr/local/share/doc/mysql-proxy/rw-splitting.lua \
  --pid-file=/run/daemons/mysql-proxy \
  --log-file=/var/log/mysql-proxy.log \
  --log-level=debug --daemon

mysql-proxy -V
mysql-proxy 0.8.2
  chassis: mysql-proxy 0.8.2
  glib2: 2.16.6
  libevent: 1.4.13-stable
  LUA: Lua 5.1.4
    package.path: /usr/local/lib/mysql-proxy/lua/?.lua;
    package.cpath: /usr/local/lib/mysql-proxy/lua/?.so;
-- modules
  proxy: 0.8.2

mysql -V
mysql  Ver 14.14 Distrib 5.5.25a, for Linux (x86_64) using readline 5.1

my.cnf: 

[client]
port		   = 3306
socket		= /var/run/mysqld/mysqld.sock

[mysqld]
port		   = 3306
socket		= /var/run/mysqld/mysqld.sock
datadir		= /var/lib/mysql
skip-external-locking
key_buffer_size = 16M
max_allowed_packet = 1M
table_open_cache = 64
sort_buffer_size = 512K
net_buffer_length = 8K
read_buffer_size = 256K
read_rnd_buffer_size = 512K
myisam_sort_buffer_size = 8M
old_passwords=0 
log-error           = /var/log/mysqld-error.log
log-slow-queries
log-queries-not-using-indexes
log-output=FILE
slow-query-log-file = /var/log/mysqld-slowly.log
relay-log           = relay.bin-log
relay-log-info-file = relay.bin-log.info
relay-log-index     = relay.bin-index
log-bin=mysql-bin
binlog_format=mixed
server-id=2009642047
report-host=xxxxxxxxxxxx.xxxxxx.xxxxxx.xxxx.com
innodb_data_home_dir = /var/lib/mysql
innodb_data_file_path = ibdata1:10M:autoextend
innodb_log_group_home_dir = /var/lib/mysql
innodb_buffer_pool_size = 16M
innodb_additional_mem_pool_size = 2M
innodb_log_file_size = 5M
innodb_log_buffer_size = 8M
innodb_flush_log_at_trx_commit = 1
sync_binlog = 1

[mysqldump]
quick
max_allowed_packet = 16M

[mysql]
no-auto-rehash

[myisamchk]
key_buffer_size = 20M
sort_buffer_size = 20M
read_buffer = 2M
write_buffer = 2M

[mysqlhotcopy]
interactive-timeout

The thing is that apparently normal transactional queries are served without probelm.

eg:
n=0; while [ $? -eq 0 ]; do sleep 0.1; let n=$n+1; echo $n; mysql --port=43306 -u kindstudiosgr -p'rFghJi876ZgbvfV000er45t6gmQ1d' kindstudios-core -e "BEGIN; select master_email,date_login from kind_user; COMMIT"; done

will run without a hitch.

but when running transactional queries through a web application (in this case a php application) you will get a: "failed to open the DB connection: SQLSTATE[HY000] [1156] Got packets out of order" error that is logged on mysql-proxy.log as:

2012-08-28 14:49:49: (debug) last message repeated 1 times
2012-08-28 14:49:49: (debug) [network-mysqld.c:937]: error on a connection (fd: -1 event: 0). closing client conn
ection.

also if you repeat the failed request you will get:

2012-08-28 14:53:16: (debug) [network-mysqld.c:937]: error on a connection (fd: -1 event: 0). closing client conn
ection.
2012-08-28 14:53:16: (critical) ioctl(15, FIONREAD, ...) said there is something to read, oops: 37
2012-08-28 14:53:18: (debug) [network-mysqld.c:937]: error on a connection (fd: -1 event: 0). closing client conn
ection.
2012-08-28 14:53:20: (debug) network-mysqld.c.1471: network_mysqld_write(CON_STATE_SEND_QUERY) returned an error
2012-08-28 14:53:20: (debug) [network-mysqld.c:937]: error on a connection (fd: -1 event: 0). closing client conn
ection.
2012-08-28 14:53:20: (critical) ioctl(15, FIONREAD, ...) said there is something to read, oops: 37

Since I have hit a dead end by researching the error on the mysql-proxy side; I am currently looking if there is any possibility this being php related and not proxy related. Also I'm setting up logging to see what queries the application executes, maybe it does something fancy I do not remember.

Any leads?

How to repeat:
Test a transactional web application that connects @ port 4040? preferably on an up to date arch box?

Thank you for the report.

Could you please send us information about what your web application is doing? Like which transactions does it run? Does it fail on any specific query? Ideally would be repeatable test case.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Hi., 
I also also facing the same problem. It happens only in the case when slave is up from proxy. But i didn't get solution.

Regards,
Dileep

dileep,

thank you for the feedback. But we need repeatable test case to be able to fix it.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Hi., 

Here is the test case, I added all backends and readonly backends. And then connected to proxy using 4041 port., and checked the result of select * from backends. All the nodes added are unknown., And made all the nodes up. Then to rest the r/w i connected to proxy 4040 port from another ip address. I continuously connect and disconnect using the command mysql -u root -ppassword -P4040. After 5 to 7 successful connections it says "Unknown Command" for the new connection. After leaving it for few hours we can connect back., and if we repeat the connection like the previous the same problem come in. 

Regards,
Dileep Ch

Thank you for the feedback.

I still can not repeat described behavior.

Please try with current version 0.8.3 and inform us if problem still exists in your environment.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".