8.0.24 connector odbc breaks previously working queries

[Amit Chaudhuri]

The recently released 8.0.24/25 versions of the mysql-connector-odbc behave
very differently to .23 in our application. SQL statements that used to work are now failing. OS is Centos7.

Using mysql database logging we can demonstrate that things look very different
from start up. In the working case, all entries appear as "Query" while in the
failing case we see a mix of "Query, Prepare, Execute" for the same actions.
I include an example of the mysql logging at the foot of this note.

We have tested combinations of 8.0.23,24,25 database with 8.0.23 connector and
all is good. But as soon as we try 8.0.24 connector-odbc we get SQL errors. Our
conclusion is that changes introduced in 8.0.24 are the trigger for what we see.

The error as reported from the connector looks like this.....

[STATE: 42000 CODE 1064 ERROR: [MySQL][ODBC 8.0(a) Driver][mysqld-8.0.24] \
You have an error in your SQL syntax; check the manual that corresponds to \
your MySQL server version for the right syntax to use near 'insert into \
interfaces (type,name,description,syntax,ikey,filename,hostname) val' \
at line 2

And it only occurs when the connector calls mysql_stmt_prepare in function
prepare in file driver/my_stmt.cc.

I think the error is decided by the mysql library in the cli_advanced_command
function (from client.cc in the mysql-server/libmysql directory) when the function command arg is COM_STMT_PREPARE.

Our application is using multiple threads and the statements that fail seem to
be just after a context switch. We note that the behaviour in 8.0.23 seemed to
be more disciplined in terms of where context switching occurred. Switches in
the new code seem to be more frequent and to occur "in the middle" of familiar
patterns that previously didn't appear to be interrupted this way.

We believe the use of multiple statements separated by ';' may be part of the
mix here, in combination with multiple threads calling into the connector.

The problem has also appeared to move suggesting timing might be a contributory
factor.

Here is an example of what I see between the threads immediately prior to
failure. In each thread a series of operations from COM_QUERY set max execution
time, through COM_STMT_PREPARE "select 1", COM_STMT_EXECUTE to COM_STMT_CLOSE to a second prepare are clearly interleaved. Previously we don't believe this was the case.

System starts
Executes lots of statements successfully
Then...

Main Thread Event Thread
CQ (set max execution time)|===========================
===========================|CQ (set autocommit=0)
===========================|CQ (set max execution time)
CP (select 1) |===========================
CE |===========================
CC |===========================
===========================|CP (select 1)
CP (Replace into ....) |===========================
CE |===========================
===========================|CE
===========================|CC
===========================|CP (Update ....)
===========================|**FAILURE**

Key
==== used to show context switch has occurred
.... = statement body omitted
CQ=COM_QUERY
CP=COM_STMT_PREPARE
CE=COM_STMT_EXECUTE
CC=COM_STMT_CLOSE

Has anyone else seen similar problems with the new connector-odbc? Does anyone
on the forum have any suggestions for how to get to an actionable bug report
(e.g. are there things we can turn on that would provide extra information).

Below are two extracts from the mysql logging that to us show very different behaviour. The only difference between the two is the odbc connector version.


// 8.0.23 log extract (happy case)

2021-05-18T14:43:41.620139Z 12 Connect xxx@localhost on xxxdb using
Socket
2021-05-18T14:43:41.620817Z 12 Query SET NAMES latin1
2021-05-18T14:43:41.621266Z 12 Query SET character_set_results = NULL
2021-05-18T14:43:41.621509Z 12 Query SET SQL_AUTO_IS_NULL = 0
2021-05-18T14:43:41.631293Z 12 Query set @@max_execution_time=30000
2021-05-18T14:43:41.631682Z 12 Query set @@sql_select_limit=DEFAULT
2021-05-18T14:43:41.631917Z 12 Query select 1
2021-05-18T14:43:41.632419Z 12 Query show status like 'wsrep_%'
2021-05-18T14:43:41.673510Z 12 Query set @@max_execution_time=30000
2021-05-18T14:43:41.673888Z 12 Query select 1
2021-05-18T14:43:41.674527Z 12 Query delete from channels

// 8.0.25 extract (broken case)

2021-05-18T14:39:23.127692Z 9 Connect xxx@localhost on xxxdb using
Socket
2021-05-18T14:39:23.338730Z 9 Query SET NAMES latin1
2021-05-18T14:39:23.339654Z 9 Query SET character_set_results = NULL
2021-05-18T14:39:23.339858Z 9 Query SET SQL_AUTO_IS_NULL = 0
2021-05-18T14:39:23.340504Z 9 Query set @@max_execution_time=30000
2021-05-18T14:39:23.373007Z 9 Prepare select 1
2021-05-18T14:39:23.373338Z 9 Query set @@sql_select_limit=DEFAULT
2021-05-18T14:39:23.373664Z 9 Execute select 1
2021-05-18T14:39:23.445888Z 9 Close stmt
2021-05-18T14:39:23.541445Z 9 Prepare show status like 'wsrep_%'
2021-05-18T14:39:23.541637Z 9 Execute show status like 'wsrep_%'
2021-05-18T14:39:23.597338Z 9 Close stmt
2021-05-18T14:39:23.597553Z 9 Query set @@max_execution_time=30000
2021-05-18T14:39:23.598021Z 9 Prepare select 1
2021-05-18T14:39:23.598123Z 9 Execute select 1
2021-05-18T14:39:23.598416Z 9 Close stmt
2021-05-18T14:39:23.616032Z 9 Prepare delete from channels
2021-05-18T14:39:23.616392Z 9 Execute delete from channels
2021-05-18T14:39:23.617779Z 9 Close stmt