MySQL Bugs: #53865: Query > 300B throws System.ArgumentOutOfRangeException in QueryNormalizer

Bug #53865	Query > 300B throws System.ArgumentOutOfRangeException in QueryNormalizer
Submitted:	20 May 2010 17:53	Modified:	28 Jun 2010 13:21
Reporter:	Yvan Rodrigues	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Connector / NET	Severity:	S1 (Critical)
Version:	6.2.3	OS:	Any
Assigned to:	Vladislav Vaintroub	CPU Architecture:	Any
Tags:	ArgumentOutOfRangeException, CollapseValueList, query, QueryNormalizer

Description:
A query longer than 300 bytes is normalized at TracingDriver.SendQuery @ line 61. QueryNormalizer will tokenize the query and call CollapseValueList. A condition exists in which the counter field pos, passed by reference to CollapseValueList can exceed the size of the collection:

How to repeat:
Any query that exceeds 300 bytes and does not contain matching pairs of bracket tokens () will cause this problem.

Suggested fix:
The value of pos must be checked and the loop broken if required, before checking that the token is not a commma:

--- QueryNormalizer-revBASE.svn003.tmp.cs	Thu May 20 13:48:29 2010
+++ QueryNormalizer.cs	Thu May 20 13:47:51 2010
@@ -157,6 +157,7 @@
                     if (tok[pos].Type == TokenType.Symbol && tok[pos].Text == ")") break;
                 Debug.Assert(pos < tok.Count);
                 parenIndices.Add(pos);
+                if (pos == tok.Count) break;
 
                 // now find the next "real" token
                 while (++pos < tok.Count)

The assertion would also need adjustment.

Hi Yvan and thanks for your report.

As I already said, 5.2 is too old for me to check it.
Latest sources, however, work:
    MySqlConnection conn = new MySqlConnection();
    conn.ConnectionString = "DataSource=xx;Database=test;UserID=xx;Password=xx;PORT=xx;Allow Zero Datetime=False;allow user variables = true; respect binary flags=false; logging=true";
    conn.Open();

    MySqlCommand cmd = new MySqlCommand();
    cmd.Connection = conn;
    cmd.CommandText = "SELECT NOW() As T1, NOW() As T2, NOW() As T3, NOW() As T4, NOW() As T5, NOW() As T6, NOW() As T7, NOW() As T8, NOW() As T9, " +
    "NOW() As T10, NOW() As T11, NOW() As T12, NOW() As T13, NOW() As T14, NOW() As T15, NOW() As T16, NOW() As T17, NOW() As T18, NOW() As T19, NOW() As T20, " +
    "NOW() As T10, NOW() As T21, NOW() As T22, NOW() As T23, NOW() As T24, NOW() As T25, NOW() As T26, NOW() As T27, NOW() As T28, NOW() As T29";
    try
    {
        using (MySqlDataReader oReader1 = cmd.ExecuteReader())
        {
            int rowsRead = 0;
            while (oReader1.Read())
            {
                rowsRead++;
            }
            Console.WriteLine("Total rows read2: " + rowsRead.ToString());
        }
    }
    catch (Exception ex)
    {
        Console.Out.WriteLine(DateTime.UtcNow.ToLongTimeString() + "  " + "Exception: " + ex.Message);
    }

produces:
...
mysql Information: 10 : 1: Set Database: test
mysql Information: 3 : 1: Query Opened: SELECT NOW() As T1, NOW() As T2, NOW() As T3, NOW() As T4, NOW() As T5, NOW() As T6, NOW() As T7, NOW() As T8, NOW() As T9, NOW() As T10, NOW() As T11, NOW() As T12, NOW() As T13, NOW() As T14, NOW() As T15, NOW() As T16, NOW() As T17, NOW() As T18, NOW() As T19, NOW() As T20, NOW() As T10, NOW() As
mysql Information: 14 : 1: Query Normalized: SELECT NOW() AS T1, NOW() AS T2, NOW() AS T3, NOW() AS T4, NOW() AS T5, NOW() AS T6, NOW() AS T7, NOW() AS T8, NOW() AS T9, NOW() AS T10, NOW() AS T11, NOW() AS T12, NOW() AS T13, NOW() AS T14, NOW() AS T15, NOW() AS T16, NOW() AS T17, NOW() AS T18, NOW() AS T19, NOW() AS T20, NOW() AS T10, NOW() AS
mysql Information: 4 : 1: Resultset Opened: field(s) = 30, affected rows = -1, inserted id = -1
Total rows read2: 1
mysql Information: 5 : 1: Resultset Closed. Total rows=1, skipped rows=0, size (bytes)=600
mysql Information: 6 : 1: Query Closed

Hi Tonci, apparently I can't read. The version with the bug is 6.2.3.
The exception occurs when a bracket pair overlaps the 300B limit, e.g.:

INSERT INTO foo (id, Xml) VALUES (2, '<long xml snippet here>');

In this example the ( bracket after "VALUES" and the closing ) bracket are tokenized in separate passes.

Another almost identical bug occurs in QueryNormalized.ConsumeQuotedToken(). If when the while loop exits, pos == fullSql.Length, the call to fullSql.Substring will throw ArgumentOutOfRangeException, because pos was incremented after the loop without first checking to see if it is the same length. The fix is:

--- /Local/Temp/QueryNormalizer.c-revBASE.svn001.tmp.cs	Fri May 28 14:15:08 2010
+++ /MySql/Source/common/QueryNormalizer.cs	Fri May 28 14:15:03 2010
@@ -314,7 +314,8 @@
                     escaped = true;
                 pos++;
             }
-            pos++;
+            if(pos < fullSql.Length)
+                pos++;
             if (c == '\'')
                 tokens.Add(new Token(TokenType.String, "?"));
             else

In your test case above it is unlikely that any tokens will be processed in separate packets. For the bug to present itself, tokens such as () `` or '' must end up split between 300B segments. In my first case, my query was split like:

INSERT INTO foo (xml) VALUES ('long text here                  <split>     more long text ')

In the latter case it was a column name that was quoted like:

SELECT blah blah blah blah, `my <split> column` FROM foo;

Yvan, this is what happens when you presume too much... I am convinced, much like you are, that you are seeing a problem but without a proper test case you make me run in circles.

Can't repeat with latest code in trunk (test case is the same, only SELECT changed as per your remarks, matching () is enforced with CONCAT("loooong text")):
            MySqlCommand cmd = new MySqlCommand();
            cmd.Connection = conn;
            cmd.CommandText = "SELECT CONCAT('2010-05-27 16:42:57 Good writeup, but I dont think it has to be that complicated - at first. Theres still an issue that theres an implicit hierarchy, even in the interfaces."+
                "', ' I.e. a java.sql.CallableStatement is a java.sql.PreparedStatement is a java.sql.Statement (so you might as well bring the other implementations along via inheritence). What I was thinking, "+
                "is just taking a look at your patch, in the methods you fixed where you use instance of, first, copy those methods to CallableStatement...(i.e. override the same method thats in PreparedStatement).',' "+
                "Then remove the instanceof. This hides true problem... Its the only way to sanely assemble the functionality. True problem is that half of the patch is dealing with mixup in zero-1-based structs. "+
                "Then factor out the differences, leave the differences in the overriden method, which may require you to have a method that does nothing in prepared statement when called, but does something with those "+
                "parameters in callable statement. Once youve done that, you should see what is exactly different for callable statement. Either leave *that*, or fix up the parameter numbering. Then in version 6 we can flush all that code :P :') As Col1";
            try
...

produces correct result (as can be seen in general query log):
mysql Information: 10 : 1: Set Database: test
mysql Information: 3 : 1: Query Opened: SELECT CONCAT('2010-05-27 16:42:57 Good writeup, but I dont think it has to be that complicated - at first. Theres still an issue that theres an implicit hierarchy, even in the interfaces.', ' I.e. a java.sql.CallableStatement is a java.sql.PreparedStatement is a java.sql.Statement (so you might as 
mysql Information: 14 : 1: Query Normalized: SELECT CONCAT(?, ?
mysql Information: 4 : 1: Resultset Opened: field(s) = 1, affected rows = -1, inserted id = -1
Total rows read2: 1
mysql Information: 5 : 1: Resultset Closed. Total rows=1, skipped rows=0, size (bytes)=1188
mysql Information: 6 : 1: Query Closed
mysql Information: 2 : 1: Connection Closed

I can reproduce your problem by, let's say, improperly forming a long string value, i.e. instead of writing
 cmd.CommandText = "SELECT CONCAT('2010-05-27 16:42:57 Good writeup, but I dont think it has to be that complicated - at first. Theres still an issue that theres an implicit hierarchy, even in the interfaces."+

I can do
 cmd.CommandText = "SELECT CONCAT('2010-05-27 16:42:57 Good writeup, but I don't think it has to be that complicated - at first. There's still an issue that there's an implicit hierarchy, even in the interfaces."+

(check the "don't" and 2x "There's" which actually break my long string!) but that is not a bug in parser...

Frank, thanks for your (private) comment but I do not have your tables... Until I see the actual test case attached I can't do much.

Example tables to reproduce the bug.

Attachment: connector_net_bug_53865.sql (application/octet-stream, text), 714 bytes.

Query causing the NullReferenceException

Attachment: connector_net_bug_53865_query.qbquery (application/octet-stream, text), 319 bytes.

Hi,
I can confirm getting ArgumentOutOfRangeException from QueryNormalizer when "logging=true" is in my connection string. In console trace only about 300 characters of query text are visible. "Update Model from Database" in EF designer also fails with ArgumentOutOfRangeException.

Without "logging=true" everything works ok.

Thanks to Frank and Maciej I was able to verify the problem.

Using Frank's DDL and query with this following case produces:
12:21:55  Exception: Object reference not set to an instance of an object.
when logging=true

            MySqlConnection conn = new MySqlConnection();
            conn.ConnectionString = "DataSource=**;Database=test;UserID=**;Password=**;allow user variables = true; respect binary flags=false;logging=true";
            conn.Open();

            MySqlCommand cmd = new MySqlCommand();
            cmd.Connection = conn;
            cmd.CommandText = "SELECT tblb.x_coord, tblb.y_coord, tblb.z_coord, tbl_c.x_coord, tbl_c.y_coord, tbl_c.z_coord, tbl_a.edge_id, tbl_a.life_id, tbl_a.daset_id, tbl_a.sect_id, tbl_a.yetanother_id, IFNULL(tbl_a.xyz_id,0) FROM extable_2 tbl_a, extable_1 tblb, extable_1 tbl_c WHERE tbl_a.daset_id=208 AND tbl_a.sect_id IN (1,2,3,4,5,6,7);";
            try
            {
                using (MySqlDataReader oReader1 = cmd.ExecuteReader())
                {
                    int rowsRead = 0;
                    while (oReader1.Read())
                    {
                        rowsRead++;
                    }
                    Console.WriteLine("Total rows read2: " + rowsRead.ToString());
                }
            }
            catch (Exception ex)
            {
                Console.Out.WriteLine(DateTime.UtcNow.ToLongTimeString() + "  " + "Exception: " + ex.Message);
            }

Bug #54152 was marked as duplicate of this report. Please check together.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/111312

859 Vladislav Vaintroub	2010-06-16
      Bug #53865 , Bug #54152 -fixed crashes in long queries when logging is turned on.
      Crashes mostly result from the assumption that query is welll-formed, the assumption will be wrong in most cases, since query is  truncated to 300 chars,

queued to 6.2 +

fixed in 6.0.7, 6.1.5, 6.2.4, and 6.3.3+

Changelog updated (duplicate of #54152)