"incorrect string value" error when using prepared statements

[tirsen]

I'm trying to use the new support for prepared statements but I'm having an issue in one of our unit tests.

Caused by: java.sql.SQLException: vtgate: http://76b5d68fad4d:27000/: transaction rolled back due to partial DML execution: Code: INVALID_ARGUMENT
target: contacts_hashed_aliases.80-.master, used tablet: test-4 (localhost): vttablet: rpc error: code = InvalidArgument desc = Incorrect string value: '\xFD\x83P\x00\x00\x00...' for column 'app_token' at row 2 (errno 1366) (sqlstate HY000) (CallerID: userData1): Sql: "insert into hashed_aliases(app_token, hashed_alias) values (:_app_token0, :_hashed_alias0),(:_app_token1, :_hashed_alias1) on duplicate key update id = id /* vtgate:: keyspace_id:ae1ff99631b6191f02ae1ae7710c6b6f,ae1ff99631b6191f02ae1ae7710c6b6f */", BindVars: {#maxLimit: "type:INT64 value:"10001" "_app_token0: "type:VARBINARY value:"from hashed_alias_lookup where 1 != 1she" "_app_token1: "type:VARBINARY value:"alias\014hashed_alias\014?\000\024\000\000\000\375\203P\000\000\000000000000" "_hashed_alias0: "type:VARBINARY value:"_alias_lookup\014hashed" "_hashed_alias1: "type:VARBINARY value:"\252\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\002" "v1: "type:VARBINARY value:"from hashed_alias_lookup where 1 != 1she" "v2: "type:VARBINARY value:"_alias_lookup\014hashed" "v3: "type:VARBINARY value:"alias\014hashed_alias\014?\000\024\000\000\000\375\203P\000\000\000000000000" "v4: "type:VARBINARY value:"\252\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\002" "}

[sougou]

@tirsen can you give us the client-side input values for the insert statement, and the schema of hashed_aliases? Specifically, we need the column type of app_token. We also need to know the character set of the connection string to mysql. I presume it will be utf8.
@saifalharthi the way to repro this is to prepare an insert statement with two rows and the input values given by @tirsen.

[tirsen]

I'm getting a different error now:

Hibernate: /* insert misk.hibernate.DbMovie */ insert into movies (created_at, name, release_date, updated_at) values (?, ?, ?, ?)
Hibernate: /* insert misk.hibernate.DbMovie */ insert into movies (created_at, name, release_date, updated_at) values (?, ?, ?, ?)
09:13:29.513 [main] WARN  o.h.e.jdbc.spi.SqlExceptionHelper - SQL Error: 1105, SQLState: HY000
09:13:29.514 [main] ERROR o.h.e.jdbc.spi.SqlExceptionHelper - vtgate: http://c2e5f582d655:27000/: __seq0: bind variable is nil

[tirsen]

Looks like the auto inc isn't being dealt with properly for prepared statements? I think this is a regression that can possibly mask the error I reported in this bug.

[tirsen]

This is reproduced by turning on prepared statements in misk in this PR: cashapp/misk#1202

You should be able to reproduce that locally by checking out that branch. You can change the Vitess image used in docker here: https://github.com/cashapp/misk/blob/jontirsen/2019-09-20/prep-stmt/misk-hibernate/src/main/kotlin/misk/vitess/StartVitessService.kt#L43

[PrismaPhonic]

@tirsen I believe the bug you're encountering is one we just fixed. When you have some free time would you please try this build: https://github.com/planetscale/vitess-releases/releases/tag/fae58cc.

[gedgar]

FYI @tirsen, we just fixed another bug with prepared statements: #5562

[tirsen]

I'm getting another error now:
vtgate: http://04f6124051bb:27000/: __seq0: bind variable is nil

[tirsen]

phew I finally managed to coax the actual statement and its variables out of Hibernate:

2019-12-30 10:06:01 [main] DEBUG org.hibernate.SQL - /* insert misk.hibernate.DbMovie */ insert into movies (created_at, name, release_date, updated_at) values (?, ?, ?, ?)
2019-12-30 10:06:01 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [TIMESTAMP] - [2018-01-01T00:00:00Z]
2019-12-30 10:06:01 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - [Star Wars]
2019-12-30 10:06:01 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [3] as [DATE] - [1977-05-25]
2019-12-30 10:06:01 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [4] as [TIMESTAMP] - [2018-01-01T00:00:00Z]
2019-12-30 10:06:01 [main] ERROR o.h.e.jdbc.spi.SqlExceptionHelper - vtgate: http://91f863e921f2:27000/: __seq0: bind variable is nil

[tirsen]

movies is a table with an auto inc so my guess is that it's the auto inc that is causing the problem because of the name of the variable that is nil.

[tirsen]

I'll report this as a separate issue. This particular issue is probably resolved.

[morgo]

Thanks! I will close it, but feel free to re-open later as necessary.