MySQL Bugs: #35202: Huge SQL statement make mysql-proxy abort.

Bug #35202	Huge SQL statement make mysql-proxy abort.
Submitted:	11 Mar 2008 2:58	Modified:	15 Oct 2009 6:55
Reporter:	Meiji KIMURA	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Proxy: Core	Severity:	S3 (Non-critical)
Version:	0.6.1, 0.8.0 r	OS:	Any
Assigned to:	Jan Kneschke	CPU Architecture:	Any

Description:
When mysql-proxy use lua scipt, Huge SQL statement (200M) make mysql-proxy abort.

In Windows environment, mysql-proxy disply this message,

D:\MySQL\mysql-proxy-0.6.1-win32-x86>mysql-proxy --proxy-lua-script=insert_log.lua
\cygwin\home\mysqldev\mysql-proxy\src\mysql-proxy-0.6.1\src\network-mysqld-proxy
.c.3523: COM_(0x32) is not handled

And two windows message are displayed like these,

(1) Unspecified fatal error encountered, aborting.
(2) Runtime Error!
    Program: D:\MySQL\mysql\proxy-0.6.1-win32-x86-mysql-proxy.exe

After mysql-proxy abortion, client display this error message.
ERROR 2013 (HY000) at line 1: Lost connection to MySQL server during query

How to repeat:
(1) I made a lua script for outputing INSERT SQL statement to log like this,

ocal log_file = 'c:\\insert.log'
local fh = io.open(log_file, "a+")

function read_query( packet )
  if (string.byte(packet) == proxy.COM_QUERY) or (string.byte(packet) == proxy.COM_STMT_PREPARE) then
    local query = string.sub(packet, 2)
    local action = " "
    if string.match(string.lower(query), "^insert") then action = "I"
    end

    if action ~= " " then
      fh:write(string.format("%s|%s| -- %s \n",os.date('%Y-%m-%d %H:%M:%S'), action, query))
      fh:flush()
    end
  end
end

(2) I made a table 't1' for testing on test database like this,

create table t1(i1 int);

(3) I made a huge INSERT SQL file like this,

insert into t1 values(1),(2),(3),.........

Total size of the file is 210MB. It contains single huge insert statement.

(4) Activate mysql-proxy with lua script like this.
D:\MySQL\mysql-proxy-0.6.1-win32-x86>mysql-proxy.exe --proxy-lua-script=insert_l
og.lua

(5) Activate mysql CUI command with huge insert SQL file(insert.sql) like this.
D:\mysql\bin>mysql -u root -h 127.0.0.1 -P 4040 test < insert.sql

(6) It takes a long time in my environment (abound 1-hour) and abort.
    The message(see 'Description:' part of this report) are output.

Suggested fix:
N/A

What is the max_allowed_packet of the backend mysqld?

I think the issue is that we buffer up the packets you send to the proxy to call the Lua script and then after the callback runs we pass it on to the server, which in turn closes the connection because the packet is too large.

Could you also obtain a stacktrace, please?

Kay

>What is the max_allowed_packet of the backend mysqld?

I set it lager than whole SQL statement.

>Could you also obtain a stacktrace, please?

How can I get stacktrace ? I have to use debug build of MySQL-proxy ?

Now the Proxy process does not abort, but you still get this message on the log

(critical) network-mysqld-packet.c:615: COM_(0xffffffff) is not handled
(debug) [network-mysqld.c:784]: error on a connection (fd: -1 event: 0). closing client connection.

Simpler steps to reproduce the bug:

You do not need a lua script, so you can start the proxy like this:

$ ./sbin/mysql-proxy --proxy-backend-addresses=127.0.0.1:5132

Generate a 32M sql file

$ echo "insert into t1 values" > bug-35202.sql
$ for i in {1..30000}; do echo "($i)," >> bug-35202.sql; done;
$ for i in {1..5}; do cat bug-35202.sql >> bug-35202.2.sql; cat bug-35202.2.sql >> bug-35202.sql ; done;

Run the generated sql file

$ mysql -h127.0.0.1 -P4040 test -e "source  bug-35202.sql "

Note, if you have a smaller sql file, you get 
"ERROR 1153 (08S01): Got a packet bigger than 'max_allowed_packet' bytes"

mem agent debug log

Attachment: bug35202-agent-debug.log (application/octet-stream, text), 4.04 KiB.

It looks because of this bug proxy will not properly handle SQL-statements longer than 16Mb .

Jan Kneschke writes: 
Simplified the test-case a bit more:

    $ perl -e 'printf("SELECT 1 AS %s", "o" x 16777216)' | mysql --port=4040 

As long as the packet we send is larger than 16M, it triggers the same behaviour.

Pushed a cleanup for the packet-id handling and test-cases to trunk, will be in 0.8.0

revno: 796
committer: jan@mysql.com
branch nick: trunk
timestamp: Thu 2009-08-27 19:37:33 +0200
message:
  after we append all packets (raw) the packet sequence checks should be
  reset as the next we expect is the client sending another command
------------------------------------------------------------
revno: 795
committer: jan@mysql.com
branch nick: trunk
timestamp: Thu 2009-08-27 19:31:23 +0200
message:
  added tests for the >16M packet handling
------------------------------------------------------------
revno: 794
committer: jan@mysql.com
branch nick: trunk
timestamp: Tue 2009-08-25 18:17:38 +0200
message:
  moved the packet-id handling down into the core
  
    * no direct get/set of ->packet_id in the plugins
    * network_mysqld_queue_append() tracks the packet_id's itself
    * replaced network_queue_append() by network_mysqld_queue_append_raw() 
      to track the packet-ids
    * added _reset() to figure out when a packet-id-sequence is finished
------------------------------------------------------------
revno: 793
committer: jan@mysql.com
branch nick: trunk
timestamp: Mon 2009-08-17 12:30:34 +0200
message:
  rewrote the >16MByte packet handling
  
    * removed the PACKET_LEN_UNSET handling from the plugins
    * removed network_mysqld_con_parse.packet_len, use network_mysqld_proto_get_packet_len() instead
    * changed network_mysqld_queue_append() to take a *int instead of int as _append()
      may increment the packet_id a few times for >16Mbyte packets 
    * removed ->is_overlong_packet, this is hidden from the upper layers for now
    * merge overlong packets into one string as the scripting layer expects it like this
------------------------------------------------------------
revno: 792
committer: jan@mysql.com
branch nick: trunk
timestamp: Mon 2009-08-17 12:28:57 +0200
message:
  added a test for the >16MByte packet handling

Diego Medina writes: 
Verified fixed on 0.8 r798

A note has been added to the 0.8.0 changelog: 

 MySQL Proxy would raise an error when processing query packets larger than 16MB in size.

bash script to generate SQL file with large statement

Attachment: test.sh (application/octet-stream, text), 373 bytes.

related to bug 54063