2027 (HY000): iteration count is not equal to 1 using Rust sqlx

[mcronce]

Overview of the Issue

When using Rust's sqlx library backed by Vitess, DML statements fail with the following error:

error: while executing migrations: error returned from database: 2027 (HY000): iteration count is not equal to 1

This functions when running against a plain old MySQL container.

Interestingly, DDL and SET statements seem to be fine. The following all work:

SET sql_mode=(SELECT CONCAT(@@sql_mode, ',NO_ENGINE_SUBSTITUTION')),time_zone='+00:00';
SET NAMES utf8mb4 COLLATE utf8mb4_unicode_ci;
-- This one fails on release-7.0 branch (with a different error), but succeeds on master
SET sql_mode=(SELECT CONCAT(@@sql_mode, ',NO_ENGINE_SUBSTITUTION')),time_zone='+00:00',NAMES utf8mb4 COLLATE utf8mb4_unicode_ci;
CREATE TABLE IF NOT EXISTS _sqlx_migrations (
    version BIGINT PRIMARY KEY,
    description TEXT NOT NULL,
    installed_on TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP,
    success BOOLEAN NOT NULL,
    checksum BLOB NOT NULL,
    execution_time BIGINT NOT NULL
);

But the following fail:

SELECT version, NOT success FROM _sqlx_migrations ORDER BY version DESC LIMIT 1;
INSERT INTO todos ( description ) VALUES ( ? );

The pattern seems to be that DML statements fail, but with a total sample size of 7, grain of salt and all that.

Could be a protocol version mismatch or strictly something they're sending malformed? It looks like sqlx did spin their own client implementation from the wire protocol up. When I run all of these queries with the regular CLI mysql client everything works fine.

Reproduction Steps

Background: sqlx includes a feature where it will connect to a database with your schema installed at compile time, and type check all your query parameters/returns. This is super cool because it gets you all the "safety" of an ORM, but without obfuscating the SQL (joins, for example, are still easy), and without the run-time cost. However, there's another Vitess issue (not yet reported) that causes this compile-time check to fail - so these steps include standing up a plain MySQL to compile against.

1. Install Rust toolchain
2. docker run --rm -d --name=mysql -e MYSQL_ROOT_PASSWORD=password -e MYSQL_DATABASE=test1 -p3306:3306 mysql

• Wait for MySQL to come up healthy

3. git clone https://github.com/launchbadge/sqlx.git
4. cd sqlx/examples/mysql/todos
5. Run schema DDL from 20200718111257_todos.sql (sqlx does have a migration tool in beta, but it's written in sqlx and fails for this and one other reason) against Vitess database
6. cat migrations/20200718111257_todos.sql | mysql -h127.0.0.1 -uroot -ppassword test1
7. DATABASE_URL=mysql://root:password@127.0.0.1:3306/test1 cargo build
8. DATABASE_URL=url_for_your_Vitess_database cargo run -- add 'todo description 1'
9. If you want to see working output, DATABASE_URL=mysql://root:password@127.0.0.1:3306/test1 cargo run -- add 'todo description 1'

If you want sqlx to print every query as it runs them, the following patch will enable that:

diff --git a/sqlx-core/src/mysql/connection/executor.rs b/sqlx-core/src/mysql/connection/executor.rs
index 509ab0d1..2298ba7d 100644
--- a/sqlx-core/src/mysql/connection/executor.rs
+++ b/sqlx-core/src/mysql/connection/executor.rs
@@ -89,6 +89,7 @@ impl MySqlConnection {
         arguments: Option<MySqlArguments>,
         persistent: bool,
     ) -> Result<impl Stream<Item = Result<Either<MySqlDone, MySqlRow>, Error>> + 'e, Error> {
+        println!("run(): {}", sql);
         let mut logger = QueryLogger::new(sql);
 
         self.stream.wait_until_ready().await?;

Binary version

Version: f315cb35e (Git branch 'master') built on Fri Aug 28 13:21:19 UTC 2020

Operating system and Environment details

In the vtgate container:

vitess@mc-test1-mc1local-vtgate-afe64d24-747ddd7f88-fhwrb:/$ cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 9 (stretch)"
NAME="Debian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
VERSION_CODENAME=stretch
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
vitess@mc-test1-mc1local-vtgate-afe64d24-747ddd7f88-fhwrb:/$ uname -sr
Linux 4.19.107
vitess@mc-test1-mc1local-vtgate-afe64d24-747ddd7f88-fhwrb:/$ uname -m
x86_64

On the host, where I'm running the client:

[mc@mc-thinkpad todos]$ cat /etc/os-release 
NAME="Manjaro Linux"
ID=manjaro
ID_LIKE=arch
BUILD_ID=rolling
PRETTY_NAME="Manjaro Linux"
ANSI_COLOR="32;2;24;144;200"
HOME_URL="https://manjaro.org/"
DOCUMENTATION_URL="https://wiki.manjaro.org/"
SUPPORT_URL="https://manjaro.org/"
BUG_REPORT_URL="https://bugs.manjaro.org/"
LOGO=manjarolinux
[mc@mc-thinkpad todos]$ uname -sr
Linux 5.6.16-1-MANJARO
[mc@mc-thinkpad todos]$ uname -m
x86_64

Log Fragments

The only log message from vtgate when I run the binary is:

I0828 15:31:32.638461       1 set.go:250] Ignored inapplicable SET time_zone = '+00:00'

[dkhenry]

@mcronce you don't happen to have a tcpdump of the interactions do you? Specifically Vitess has rolled its own MySQL Implementation as well and it will return different packets from the stock mysql client

[mcronce]

I don't but I can take a pcap

…

On Sat, Sep 5, 2020, 8:32 PM Daniel Kozlowski ***@***.***> wrote: @mcronce <https://github.com/mcronce> you don't happen to have a tcpdump of the interactions do you? Specifically Vitess has rolled its own MySQL Implementation as well and it will return different packets from the stock mysql client — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6643 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAGMFEST2WAX6CGUPK7KHU3SELKDDANCNFSM4QOJTRHQ> .

[dkhenry]

If you could take two please. One through Vitess and one through stock MySQL. That would be great.

…

On Sat, Sep 5, 2020, 5:35 PM Mike Cronce ***@***.***> wrote: I don't but I can take a pcap On Sat, Sep 5, 2020, 8:32 PM Daniel Kozlowski ***@***.***> wrote: > @mcronce <https://github.com/mcronce> you don't happen to have a tcpdump > of the interactions do you? Specifically Vitess has rolled its own MySQL > Implementation as well and it will return different packets from the stock > mysql client > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > <#6643 (comment)>, > or unsubscribe > < https://github.com/notifications/unsubscribe-auth/AAGMFEST2WAX6CGUPK7KHU3SELKDDANCNFSM4QOJTRHQ > > . > — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#6643 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADXRKYZKPNX2RLUMQWFQPLSELKN3ANCNFSM4QOJTRHQ> .

[mcronce]

https://drive.google.com/file/d/1kJG2PMPSwRRP6DYZr15-sIaeepBq4Qvv/view?usp=sharing has the Vitess pcap
https://drive.google.com/file/d/1-ylJqJmaOBWae-TDlNn6SviQvQ2apkSi/view?usp=sharing has the MySQL pcap

For anybody interested, you can append ?ssl-mode=DISABLED to the connection string for sqlx and it will make it much easier for you to take packet captures ;)

[harshit-gangal]

I checked the tcp dump, the iteration count in both COM_STMT_EXECUTE Request is 0
Based on the MySQL Protocol it should be 1.
The iteration-count is always 1.

Why this works on mysql is because mysql assumes that iterator count is always 1 and ignores to read the 4 bytes of iteration count data from the data packet - code reference link

We can also do the same thing @systay @sougou @aquarapid ?

[mcronce]

If this is a case of the client lib behaving badly I'll make a PR to the client lib :)

That said, maybe it does make sense to mimic MySQL behavior? It seems weird to specify in the protocol that the value must be 1, but ignore incorrect values - I'm wondering if there are other clients out there that people have implemented greenfield, which might have a similar issue

[harshit-gangal]

Client sending the right data is the best way to move forward.

[harshit-gangal]

Fixed via launchbadge/sqlx#739

[harshit-gangal]

Closing as this is fixed in sqlx