Bug #60568 issue with MySQL proxy 0.9.0 and read write splitting
Submitted: 21 Mar 2011 15:31 Modified: 27 Feb 2012 11:59
Reporter: Richard Shade Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Proxy: Core Severity:S1 (Critical)
Version:0.9.0 OS:Linux (Ubuntu 10.04)
Assigned to: CPU Architecture:Any
Tags: mysql proxy, regression

[21 Mar 2011 15:31] Richard Shade
Description:
In response to https://answers.launchpad.net/mysql-proxy/+question/149625
I start mysql proxy, it takes approximately 20 queries before it dies even with a simple query. Below is the info this looks close to the same as https://answers.launchpad.net/mysql-proxy/+question/144570. I am using the basic rw-splittling.lua from trunk/lib

:./mysql-provy -V:
mysql-proxy 0.9.0
  chassis: mysql-proxy 0.9.0
  glib2: 2.24.1
  libevent: 1.4.13-stable
  LUA: Lua 5.1.4
    package.path: /usr/lib/mysql-proxy/lua/?.lua
    package.cpath: /usr/lib/mysql-proxy/lua/?.so
-- modules
  admin: 0.9.0
  proxy: 0.9.0

:lsb_release -a:
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 10.04.1 LTS
Release: 10.04
Codename: lucid
x86_64

:cmd:
gdb --args ./mysql-proxy --proxy-lua-script=/usr/share/mysql-proxy/rw-splitting.lua --proxy-backend-addresses=master.host.com:3306 --proxy-read-only-backend-addresses=slave.host.com:3306 --log-level=debug --log-file=/var/log/mysql-proxy.log --admin-username=admin --admin-password=admin --admin-lua-script=/usr/lib/mysql-proxy/lua/admin.lua

:query:
for i in `seq 1 20`; do
 mysql -uuser -h127.0.0.1 -P4040 -ppass -D example -e'select * from users where id=1'
done

:/var/log/mysql-proxy.log:
2011-03-18 18:46:39: [global] (debug) max open file-descriptors = 1024
2011-03-18 18:46:39: [global] (message) proxy listening on port :4040
2011-03-18 18:46:39: [global] (message) added read/write backend: master.host.com:3306
2011-03-18 18:46:39: [global] (message) added read-only backend: slave.host.com:3306
2011-03-18 18:47:22: [global] (message) network-address.c:316: is-local family 0 != 2
2011-03-18 18:47:23: [global] last message repeated 9 times

2011-03-18 18:47:23: [global] (debug) [network-mysqld.c:944]: error on a connection (fd: -1 event: 0). closing client connection.
2011-03-18 18:47:23: [global] (message) network-address.c:316: is-local family 0 != 2
2011-03-18 18:47:23: [global] (debug) [network-mysqld.c:944]: error on a connection (fd: -1 event: 0). closing client connection.
2011-03-18 18:47:23: [global] (message) network-address.c:316: is-local family 0 != 2
2011-03-18 18:47:23: [global] (debug) [network-mysqld.c:944]: error on a connection (fd: -1 event: 0). closing client connection.
2011-03-18 18:47:23: [global] (message) network-address.c:316: is-local family 0 != 2
2011-03-18 18:47:23: [global] (debug) [network-mysqld.c:944]: error on a connection (fd: -1 event: 0). closing client connection.
2011-03-18 18:47:23: [global] (critical) network_mysqld_con_idle_handle: ioctl(16, FIONREAD, ...) said there is something to read, oops: 37
2011-03-18 18:47:23: [global] (debug) [network-mysqld.c:944]: error on a connection (fd: -1 event: 0). closing client connection.
2011-03-18 18:47:23: [global] (message) network-address.c:316: is-local family 0 != 2
2011-03-18 18:47:23: [global] (debug) [network-mysqld.c:944]: error on a connection (fd: -1 event: 0). closing client connection.
2011-03-18 18:47:32: [global] (message) network-address.c:316: is-local family 0 != 2
2011-03-18 18:47:32: [global] (debug) [network-mysqld.c:944]: error on a connection (fd: -1 event: 0). closing client connection.
2011-03-18 18:47:32: [global] (critical) network_mysqld_con_idle_handle: ioctl(15, FIONREAD, ...) said there is something to read, oops: 37
2011-03-18 18:47:32: [global] (debug) [network-mysqld.c:944]: error on a connection (fd: -1 event: 0). closing client connection.
2011-03-18 18:47:32: [global] (message) network-address.c:316: is-local family 0 != 2

:GDB:

Thread 1 (Thread 0x7ffff7fea700 (LWP 11989)):
#0 0x00007ffff6bed5e1 in writev () from /lib/libc.so.6
No symbol table info available.
#1 0x00007ffff70ccead in network_socket_write_writev (con=0x63f200, send_chunks=<value optimized out>) at network-socket.c:687
        chunk = 0xffffffffffffffff
        chunk_count = 1
        len = <value optimized out>
        chunk_id = <value optimized out>
        os_errno = <value optimized out>
        max_chunk_count = <value optimized out>
#2 network_socket_write (con=0x63f200, send_chunks=<value optimized out>) at network-socket.c:817
No locals.
#3 0x00007ffff70bc43b in network_mysqld_con_handle (event_fd=-1, events=0, user_data=0x652970) at network-mysqld.c:1199
        ostate = <value optimized out>
        srv = 0x608b20
        call_ret = <value optimized out>
        __PRETTY_FUNCTION__ = "network_mysqld_con_handle"
#4 0x00007ffff64c9194 in event_base_loop () from /usr/lib/libevent-1.4.so.2
No symbol table info available.
#5 0x00007ffff79d1689 in chassis_event_thread_loop (event_thread=0x616960) at chassis-event-thread.c:363
        timeout = {tv_sec = 1, tv_usec = 0}
        r = <value optimized out>
        __PRETTY_FUNCTION__ = "chassis_event_thread_loop"
#6 0x00007ffff79d108e in chassis_mainloop (_chas=<value optimized out>) at chassis-mainloop.c:351
        chas = 0x608b20
        i = 4294960272
        ev_sigterm = {ev_next = {tqe_next = 0x7fffffffe300, tqe_prev = 0x616cb0}, ev_active_next = {tqe_next = 0x606980, tqe_prev = 0x7fffffffe490}, ev_signal_next = {tqe_next = 0x0, tqe_prev = 0x616e30},
          min_heap_idx = 4294967295, ev_base = 0x616c80, ev_fd = 15, ev_events = 24, ev_ncalls = 0, ev_pncalls = 0x0, ev_timeout = {tv_sec = 6336512, tv_usec = 6332432}, ev_pri = 0,
          ev_callback = 0x7ffff79d0e00 <sigterm_handler>, ev_arg = 0x0, ev_res = 0, ev_flags = 130}
        ev_sigint = {ev_next = {tqe_next = 0x7fffffffe280, tqe_prev = 0x7fffffffe380}, ev_active_next = {tqe_next = 0x616af0, tqe_prev = 0x608f20}, ev_signal_next = {tqe_next = 0x0, tqe_prev = 0x616d60},
          min_heap_idx = 4294967295, ev_base = 0x616c80, ev_fd = 2, ev_events = 24, ev_ncalls = 0, ev_pncalls = 0x0, ev_timeout = {tv_sec = 140737347619208, tv_usec = 140737354115488}, ev_pri = 0,
          ev_callback = 0x7ffff79d0e00 <sigterm_handler>, ev_arg = 0x0, ev_res = 0, ev_flags = 130}
        ev_sighup = {ev_next = {tqe_next = 0x637c98, tqe_prev = 0x7fffffffe300}, ev_active_next = {tqe_next = 0x1, tqe_prev = 0x0}, ev_signal_next = {tqe_next = 0x0, tqe_prev = 0x616d50},
          min_heap_idx = 4294967295, ev_base = 0x616c80, ev_fd = 1, ev_events = 24, ev_ncalls = 0, ev_pncalls = 0x0, ev_timeout = {tv_sec = 140737354130560, tv_usec = 140737488347984}, ev_pri = 0,
          ev_callback = 0x7ffff79d11a0 <sighup_handler>, ev_arg = 0x608b20, ev_res = 0, ev_flags = 130}
        mainloop_thread = <value optimized out>
        __PRETTY_FUNCTION__ = "chassis_mainloop"
#7 0x000000000040302a in main_cmdline (argc=1, argv=0x7fffffffe5b8) at mysql-proxy-cli.c:658
        srv = <value optimized out>
        sigsegv_sa = {__sigaction_handler = {sa_handler = 0x402290 <sigsegv_handler>, sa_sigaction = 0x402290 <sigsegv_handler>}, sa_mask = {__val = {0 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0}
        option_ctx = 0x0
        main_entries = 0x60b000
        frontend = 0x60a010
        opts = 0x606980
        gerr = 0x0
        log = 0x606890
        exit_code = <value optimized out>
        exit_location = <value optimized out>
#8 0x00007ffff6b2dc4d in __libc_start_main () from /lib/libc.so.6
No symbol table info available.
#9 0x00000000004021c9 in _start ()
No symbol table info available.

How to repeat:
:cmd:
gdb --args ./mysql-proxy --proxy-lua-script=/usr/share/mysql-proxy/rw-splitting.lua --proxy-backend-addresses=master.host.com:3306 --proxy-read-only-backend-addresses=slave.host.com:3306 --log-level=debug --log-file=/var/log/mysql-proxy.log --admin-username=admin --admin-password=admin --admin-lua-script=/usr/lib/mysql-proxy/lua/admin.lua

:query:
for i in `seq 1 20`; do
 mysql -uuser -h127.0.0.1 -P4040 -ppass -D example -e'select * from users where id=1'
done
[21 Mar 2011 18:17] Sveta Smirnova
Thank you for the report.

Verified as described though in my case it dies immediately.
[27 Feb 2012 11:59] Miguel Araujo
Cannot reproduce the bug on the latest branch of MySQL Proxy.