Bug #30668 connection pooling failures
Submitted: 28 Aug 2007 13:03 Modified: 5 Sep 2007 15:57
Reporter: simon elliston ball Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Proxy Severity:S3 (Non-critical)
Version:0.6.0 trunk OS:Any
Assigned to: Jan Kneschke CPU Architecture:Any

[28 Aug 2007 13:03] simon elliston ball
Description:
network-conn-pool.c: network_connection_pool_get

has an additional parameter GString *default_db which is not used, and should really be checked while finding a pool connection.

In addition, the pool fails to pick up connections which it definitely has, because it appears to be failing to release connections properly once a query has been executed. 

For example: 
[connect_server] 
  [1].connected_clients = 9
  [1].idling_connections = 0
  [1].type = 1
  [1].state = 1
  [1] open new connection
[disconnect_client]
[read_query]
  current backend   = 0
  client default db = 
  client username   = user2
  sending to backend : sqldb.cromwells.co.uk:3306
    is_slave         : false
    server default db: 
    server username  : user2
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db2
[read_query]
  current backend   = 0
  client default db = db2
  client username   = user2
  query             = EXPLAIN SELECT * FROM test
network-conn-pool.c.75: no pool-entry for user2 found
(read_query) /usr/local/share/mysql-proxy/rw-splitting.lua:276: attempt to index local 's' (a nil value)
network-mysqld-proxy.c.2815: I have no server backend, closing connection
network-mysqld.c.1161: plugin_call(CON_STATE_READ_QUERY) failed

This snapshot was taken while only one client was connected to the proxy, though the proxy seems to think 9 are, and has not released the connections it has into the idle pool. 

How to repeat:
export LUA_PATH="/usr/local/share/mysql-proxy/?.lua"
/usr/local/sbin/mysql-proxy --proxy-lua-script=/usr/local/share/mysql-proxy/rw-splitting.lua \
--proxy-backend-addresses=sqldb.example.com:3306 \
--proxy-read-only-backend-addresses=sqldb1.example.com:3306 \
--proxy-read-only-backend-addresses=sqldb2.example.com:3306 

repeated select queries on different user/db combinations.
[28 Aug 2007 15:27] simon elliston ball
Some more info about reproducing this bug:

I have some databases setup db1...db10 and users user1...user10, each db contains a table called test:
CREATE TABLE `test` (
  `id` int(11) NOT NULL auto_increment,
  `data` varchar(255) default NULL,
  PRIMARY KEY  (`id`)
) 

The queries executed, with lua debug, are:

user1@db1 SELECT * FROM test;

[connect_server] 
  [1].connected_clients = 0
  [1].idling_connections = 0
  [1].type = 1
  [1].state = 0
  [1] open new connection

[connect_server] 
  [1].connected_clients = 1
  [1].idling_connections = 0
  [1].type = 1
  [1].state = 1
  [1] open new connection
[disconnect_client]
[read_query]
  current backend   = 0
  client default db = 
  client username   = user1
  sending to backend : sqldb.cromwells.co.uk:3306
    is_slave         : false
    server default db: 
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db1
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
  query             = EXPLAIN SELECT * FROM test
  sending to backend : sqldb.cromwells.co.uk:3306
    is_slave         : false
    server default db: db1
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
  query             = SELECT * FROM test
  sending to backend : sqldb.cromwells.co.uk:3306
    is_slave         : false
    server default db: db1
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
[disconnect_client]

user1@db1 SELECT * FROM test;

[connect_server] 
  [1].connected_clients = 0
  [1].idling_connections = 1
  [1].type = 1
  [1].state = 1
  [2].connected_clients = 0
  [2].idling_connections = 0
  [2].type = 2
  [2].state = 0
  [2] open new connection

[connect_server] 
  [1].connected_clients = 0
  [1].idling_connections = 1
  [1].type = 1
  [1].state = 1
  [2].connected_clients = 1
  [2].idling_connections = 0
  [2].type = 2
  [2].state = 1
  [2] open new connection
[disconnect_client]
[read_query]
  current backend   = 0
  client default db = 
  client username   = user1
  sending to backend : sqldb.cromwells.co.uk:3306
    is_slave         : false
    server default db: db1
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db1
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
  query             = EXPLAIN SELECT * FROM test
    server default db: 
    client default db: db1
    syncronizing
  sending to backend : sqldb1.cromwells.co.uk:3306
    is_slave         : true
    server default db: 
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db1
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
  query             = SELECT * FROM test
  sending to backend : sqldb1.cromwells.co.uk:3306
    is_slave         : true
    server default db: db1
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
[disconnect_client]

user2@db2 SELECT * FROM test;

[connect_server] 
  [1].connected_clients = 0
  [1].idling_connections = 1
  [1].type = 1
  [1].state = 1
  [2].connected_clients = 0
  [2].idling_connections = 1
  [2].type = 2
  [2].state = 1
  [3].connected_clients = 0
  [3].idling_connections = 0
  [3].type = 2
  [3].state = 0
  [3] open new connection
[read_query]
  current backend   = 0
  client default db = 
  client username   = user2
network-conn-pool.c.75: no pool-entry for user2 found
  sending to backend : sqldb.cromwells.co.uk:3306
    is_slave         : false
(read_query) /usr/local/share/mysql-proxy/rw-splitting.lua:289: attempt to index local 's' (a nil value)
network-mysqld-proxy.c.2815: I have no server backend, closing connection
network-mysqld.c.1161: plugin_call(CON_STATE_READ_QUERY) failed
[disconnect_client]

[connect_server] 
  [1].connected_clients = 0
  [1].idling_connections = 1
  [1].type = 1
  [1].state = 1
  [2].connected_clients = 0
  [2].idling_connections = 1
  [2].type = 2
  [2].state = 1
  [3].connected_clients = 0
  [3].idling_connections = 1
  [3].type = 2
  [3].state = 1
  opening new connection on: 1
[read_query]
  current backend   = 0
  client default db = 
  client username   = user2
  sending to backend : sqldb.cromwells.co.uk:3306
    is_slave         : false
    server default db: 
    server username  : user2
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db2
[read_query]
  current backend   = 0
  client default db = db2
  client username   = user2
  query             = EXPLAIN SELECT * FROM test
network-conn-pool.c.75: no pool-entry for user2 found
(read_query) /usr/local/share/mysql-proxy/rw-splitting.lua:276: attempt to index local 's' (a nil value)
network-mysqld-proxy.c.2815: I have no server backend, closing connection
network-mysqld.c.1161: plugin_call(CON_STATE_READ_QUERY) failed
[disconnect_client]
[30 Aug 2007 10:12] simon elliston ball
With the latest trunk (rev 197) I seem to be having problems with the connected_clients field on the backend not being reduced properly, consequently the connect scripts do not work, leading to user not found in pool messages. The first backend will just grow more and more connections, while the read query will eventually fail with a lost connection error 2013 because it will try to use the second backend, which has never received a connection for the client's user due to the fact that there is never more than one idling connection on the main backend. See log below using rw-splitting.lua from r197. The queries were generated from a simple php client which was just requested repeatedly. Note the ever increasing [1].connected_clients = 1

[connect_server] 
  [1].connected_clients = 1
  [1].idling_connections = 1
  [1].type = 1
  [1].state = 1
  [1].address = sqldb.example.com:3306
  [2].connected_clients = 0
  [2].idling_connections = 1
  [2].type = 2
  [2].state = 1
  [2].address = sqldb1.example.com:3306
  opening new connection on: 1
[read_query]
  current backend   = 1
  client default db = 
  client username   = user1
  sending to backend : sqldb.example.com:3306
    is_slave         : false
    server default db: 
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
[read_query_result]
   releasing backend : 1
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
  query             = SELECT * FROM test
  sending to backend : sqldb1.example.com:3306
    is_slave         : true
    server default db: db1
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
[read_query_result]
   releasing backend : 2
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
[disconnect_client]

[connect_server] 
  [1].connected_clients = 2
  [1].idling_connections = 1
  [1].type = 1
  [1].state = 1
  [1].address = sqldb.example.com:3306
  [2].connected_clients = 0
  [2].idling_connections = 1
  [2].type = 2
  [2].state = 1
  [2].address = sqldb1.example.com:3306
  opening new connection on: 1
[read_query]
  current backend   = 1
  client default db = 
  client username   = user1
sending to backend : sqldb.example.com:3306
    is_slave         : false
    server default db: 
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
[read_query_result]
   releasing backend : 1
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
  query             = SELECT * FROM test
  sending to backend : sqldb1.example.com:3306
    is_slave         : true
    server default db: db1
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
[read_query_result]
   releasing backend : 2
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
[disconnect_client]

[connect_server] 
  [1].connected_clients = 3
  [1].idling_connections = 1
  [1].type = 1
  [1].state = 1
  [1].address = sqldb.example.com:3306
  [2].connected_clients = 0
  [2].idling_connections = 1
  [2].type = 2
  [2].state = 1
  [2].address = sqldb1.example.com:3306
  opening new connection on: 1
[read_query]
  current backend   = 1
  client default db = 
  client username   = user1
  sending to backend : sqldb.example.com:3306
    is_slave         : false
    server default db: 
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
[read_query_result]
   releasing backend : 1
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
  query             = SELECT * FROM test
  sending to backend : sqldb1.example.com:3306
    is_slave         : true
    server default db: db1
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
[read_query_result]
   releasing backend : 2
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
[disconnect_client]

[connect_server] 
  [1].connected_clients = 4
  [1].idling_connections = 1
  [1].type = 1
  [1].state = 1
  [1].address = sqldb.example.com:3306
  [2].connected_clients = 0
  [2].idling_connections = 1
  [2].type = 2
  [2].state = 1
  [2].address = sqldb1.example.com:3306
  opening new connection on: 1
[read_query]
  current backend   = 1
  client default db = 
  client username   = user1
  sending to backend : sqldb.example.com:3306
    is_slave         : false
    server default db: 
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
[read_query_result]
   releasing backend : 1
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
  query             = SELECT * FROM test
  sending to backend : sqldb1.example.com:3306
    is_slave         : true
    server default db: db1
    server username  : user1
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
[read_query_result]
   releasing backend : 2
[read_query]
  current backend   = 0
  client default db = db1
  client username   = user1
[disconnect_client]
[31 Aug 2007 16:33] simon elliston ball
I think I may have tracked down the source of this problem. 

When the connect_server script checks for least_idle_connections, and assigns a discovered index to the proxy.connections.backend_ndx userdata field, the function  network-mysqld-proxy.c:proxy_connection_set gets called. This will lead to a proxy_connection_pool_swap, which will increment the connected_clients field of the backend. 

However, the end of the function will then allow a connect to continue on the backend, leading to network-mysqld-proxy.c:NETWORK_MYSQLD_PLUGIN_PROTO(proxy_connect_server) also increasing the backends connection count. 

The read_auth successfully decrements on of these, but not the other, which means you will have a spare connection which always remains a 'connected' part of the pool and is not available either to queries, or to the disconnect client hook. 

A transcript of the lua debug, with some extra debug inserted into network-mysqld-proxy.c shows the problem, and where the decrement is not happening. The backend index in the debug from the c code is incremented to match the lua indexes for clarity.

[connect_server] 
  [1].connected_clients = 0
  [1].idling_connections = 4
  [1].type = 1
  [1].state = 1
  [1].address = sqldb.cromwells.co.uk:3306
  [2].connected_clients = 0
  [2].idling_connections = 1
  [2].type = 2
  [2].state = 1
  [2].address = sqldb1.cromwells.co.uk:3306
  [3].connected_clients = 0
  [3].idling_connections = 1
  [3].type = 2
  [3].state = 1
  [3].address = sqldb.cromwells.co.uk:3306
Least idle connections on : 2 backend is 0
network-mysqld-proxy.c:634: proxy_connection_pool_swap: Connected clients increased on 2 to 1
network-mysqld-proxy.c:576: proxy_connection_pool_add_connection: Connected clients reduced on 2 to 0
network-mysqld-proxy.c:3624: proxy_connect_server: Connected client increased on 1 to 1
[read_auth_result]
backend : 1
network-mysqld-proxy.c:576: proxy_connection_pool_add_connection: Connected clients reduced on 1 to 0
[read_query]
  current backend   = 0
  client default db = 
  client username   = test
  cmd               = COM_INIT_DB
  schema            = db1
network-mysqld-proxy.c:634: proxy_connection_pool_swap: Connected clients increased on 1 to 1
  running an init db : c= s= setting to db1
  sending to backend : sqldb.cromwells.co.uk:3306
    is_slave         : false
    server default db: 
    server username  : test
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : false
[read_query_result]
  inj.id      : 1
  inj.query   : db1
(read_query_result) releasing backend 1
network-mysqld-proxy.c:576: proxy_connection_pool_add_connection: Connected clients reduced on 1 to 0
[read_query]
  current backend   = 0
  client default db = db1
  client username   = test
  cmd               = COM_QUERY
  query             = SELECT * FROM test
network-mysqld-proxy.c:634: proxy_connection_pool_swap: Connected clients increased on 2 to 1
  sending to backend : sqldb1.cromwells.co.uk:3306
    is_slave         : true
    server default db: db1
    server username  : test
    in_trans        : false
    in_calc_found   : false
    COM_QUERY       : true
[read_query_result]
  inj.id      : 1
  inj.query   : SELECT * FROM test
(read_query_result) releasing backend 2
network-mysqld-proxy.c:576: proxy_connection_pool_add_connection: Connected clients reduced on 2 to 0
[read_query]
  current backend   = 0
  client default db = db1
  client username   = test
  cmd               = COM_QUIT
[disconnect_client] 0
[5 Sep 2007 15:57] Jan Kneschke
fixed in [210]

* addr.str per network_socket
  - duplicate the string on network_socket_init()
  - free on network_socket_free()
  - moved addr.str for the client into the accept() call
  - added proxy.connection.client.address to rw-splitting.lua
* leaking con->server when rw-splitting is used
  - if proxy.connection.backend_ndx = ... is used in rw-splitting and we
    have a idle connection in the pool con->server is set too
      in proxy_connect_server() we were calling pool_get() a second time
    and overwriting con->server. This leaked the con->server handles.