Prisma tool compatibility

[zachmu]

Customer reports that the prisma tool fails with dolt but works with MySQL. Full repro here:

https://github.com/alexn-s/prisma-dolt-debug

Running the test in the repo should produce this error output:

$ pnpm exec prisma migrate dev
Prisma schema loaded from prisma/schema.prisma
Datasource "db": MySQL database "obsidian" at "localhost:3306"

Error: unknown error: table not found: _prisma_migrations
   0: migration_core::state::DevDiagnostic
             at migration-engine/core/src/state.rs:251

[timsehn]

 dolt sql-server --loglevel=debug
Starting server with Config HP="localhost:3306"|T="28800000"|R="false"|L="debug"
2022-10-10T18:06:28+02:00 INFO [conn 1] NewConnection {DisableClientMultiStatements=false}
2022-10-10T18:06:28+02:00 DEBUG [conn 1] Starting query {connectTime=2022-10-10T18:06:28+02:00, connectionDb=obsidian, query=SELECT @@max_allowed_packet}
2022-10-10T18:06:28+02:00 DEBUG [conn 1] Query finished in 1 ms {connectTime=2022-10-10T18:06:28+02:00, connectionDb=obsidian, query=SELECT @@max_allowed_packet}
2022-10-10T18:06:28+02:00 DEBUG [conn 1] Starting query {connectTime=2022-10-10T18:06:28+02:00, connectionDb=obsidian, query=SELECT @@wait_timeout}
2022-10-10T18:06:28+02:00 DEBUG [conn 1] Query finished in 0 ms {connectTime=2022-10-10T18:06:28+02:00, connectionDb=obsidian, query=SELECT @@wait_timeout}
2022-10-10T18:06:28+02:00 DEBUG [conn 1] Starting query {connectTime=2022-10-10T18:06:28+02:00, connectionDb=obsidian, query=SELECT @@version, @@GLOBAL.version}
2022-10-10T18:06:28+02:00 DEBUG [conn 1] Query finished in 0 ms {connectTime=2022-10-10T18:06:28+02:00, connectionDb=obsidian, query=SELECT @@version, @@GLOBAL.version}
2022-10-10T18:06:28+02:00 DEBUG [conn 1] Starting query {connectTime=2022-10-10T18:06:28+02:00, connectionDb=obsidian, query=SELECT @@lower_case_table_names} 2022-10-10T18:06:28+02:00 DEBUG [conn 1] Query finished in 1 ms {connectTime=2022-10-10T18:06:28+02:00, connectionDb=obsidian, query=SELECT @@lower_case_table_names}
2022-10-10T18:06:28+02:00 INFO [no conn] kill query: pid 4 {}
2022-10-10T18:06:28+02:00 INFO [no conn] kill query: pid 6 {}
2022-10-10T18:06:28+02:00 INFO [conn 1] ConnectionClosed {}
2022-10-10T18:06:30+02:00 INFO [conn 2] NewConnection {DisableClientMultiStatements=false}
2022-10-10T18:06:30+02:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T18:06:30+02:00, connectionDb=obsidian, query=SELECT @@max_allowed_packet}
2022-10-10T18:06:30+02:00 DEBUG [conn 2] Query finished in 1 ms {connectTime=2022-10-10T18:06:30+02:00, connectionDb=obsidian, query=SELECT @@max_allowed_packet}
2022-10-10T18:06:30+02:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T18:06:30+02:00, connectionDb=obsidian, query=SELECT @@wait_timeout}
2022-10-10T18:06:30+02:00 DEBUG [conn 2] Query finished in 1 ms {connectTime=2022-10-10T18:06:30+02:00, connectionDb=obsidian, query=SELECT @@wait_timeout}
2022-10-10T18:06:30+02:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T18:06:30+02:00, connectionDb=obsidian, query=SELECT @@version, @@GLOBAL.version}
2022-10-10T18:06:30+02:00 DEBUG [conn 2] Query finished in 0 ms {connectTime=2022-10-10T18:06:30+02:00, connectionDb=obsidian, query=SELECT @@version, @@GLOBAL.version}
2022-10-10T18:06:30+02:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T18:06:30+02:00, connectionDb=obsidian, query=SELECT @@lower_case_table_names} 2022-10-10T18:06:30+02:00 DEBUG [conn 2] Query finished in 0 ms {connectTime=2022-10-10T18:06:30+02:00, connectionDb=obsidian, query=SELECT @@lower_case_table_names}
2022-10-10T18:06:30+02:00 ERROR [no conn] Error reading packet from client 2 (127.0.0.1:49431): read tcp 127.0.0.1:3306->127.0.0.1:49431: wsarecv: An existing connection was forcibly closed by the remote host.
io.ReadFull(header size) failed {}
2022-10-10T18:06:30+02:00 INFO [no conn] kill query: pid 11 {}
2022-10-10T18:06:30+02:00 INFO [no conn] kill query: pid 13 {}
2022-10-10T18:06:30+02:00 INFO [conn 2] ConnectionClosed {}

This is the debug logs of the server. The last query is fine:

debug> select @@lower_case_table_names;
+----------------------------------+
| @@SESSION.lower_case_table_names |
+----------------------------------+
| 0                                |
+----------------------------------+
1 row in set (0.00 sec)

Something else is going on.

[zachmu]

I dug into this because I was curious what could be causing the issue. The tool is issuing these commands to MySQL in this order:

mysql> select convert(a.argument using utf8) from mysql.general_log a order by event_time limit 20;
+------------------------------------------------------------------------------------------------+
| convert(a.argument using utf8)                                                                 |
+------------------------------------------------------------------------------------------------+
| SHOW GLOBAL STATUS                                                                             |
| SHOW GLOBAL STATUS                                                                             |
| zachmu@localhost on obsidian using TCP/IP                                                      |
| SELECT @@socket                                                                                |
| SELECT @@max_allowed_packet                                                                    |
| SELECT @@wait_timeout                                                                          |
| SELECT @@version, @@GLOBAL.version                                                             |
| SELECT @@version, @@GLOBAL.version                                                             |
| SELECT @@lower_case_table_names                                                                |
| SELECT @@lower_case_table_names                                                                |
| zachmu@localhost on obsidian using TCP/IP                                                      |
| SELECT @@socket                                                                                |
| SELECT @@max_allowed_packet                                                                    |
| SELECT @@wait_timeout                                                                          |
| SELECT @@version, @@GLOBAL.version                                                             |
| SELECT @@version, @@GLOBAL.version                                                             |
| SELECT @@lower_case_table_names                                                                |
| SELECT @@lower_case_table_names                                                                |
| CREATE DATABASE `prisma_migrate_shadow_db_7ee26bfc-575e-4c83-9e20-04bbed41de68`                |
| zachmu@localhost on prisma_migrate_shadow_db_7ee26bfc-575e-4c83-9e20-04bbed41de68 using TCP/IP |
+------------------------------------------------------------------------------------------------+

In dolt, it doesn't get nearly that far. Specifically, it dies before it gets to the CREATE DATABASE call:

2022-10-10T16:38:44-07:00 DEBUG [conn 1] Starting query {connectTime=2022-10-10T16:38:44-07:00, connectionDb=obsidian, query=SELECT @@socket}
2022-10-10T16:38:44-07:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T16:38:44-07:00, connectionDb=obsidian, query=SELECT @@max_allowed_packet}
2022-10-10T16:38:44-07:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T16:38:44-07:00, connectionDb=obsidian, query=SELECT @@wait_timeout}
2022-10-10T16:38:44-07:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T16:38:44-07:00, connectionDb=obsidian, query=SELECT @@max_allowed_packet}
2022-10-10T16:38:44-07:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T16:38:44-07:00, connectionDb=obsidian, query=SELECT @@wait_timeout}
2022-10-10T16:38:44-07:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T16:38:44-07:00, connectionDb=obsidian, query=SELECT @@version, @@GLOBAL.version}
2022-10-10T16:38:44-07:00 DEBUG [conn 2] Starting query {connectTime=2022-10-10T16:38:44-07:00, connectionDb=obsidian, query=SELECT @@lower_case_table_names}
2022-10-10T16:38:45-07:00 DEBUG [conn 3] Starting query {connectTime=2022-10-10T16:38:45-07:00, connectionDb=obsidian, query=SELECT @@socket}
2022-10-10T16:38:45-07:00 DEBUG [conn 4] Starting query {connectTime=2022-10-10T16:38:45-07:00, connectionDb=obsidian, query=SELECT @@max_allowed_packet}
2022-10-10T16:38:45-07:00 DEBUG [conn 4] Starting query {connectTime=2022-10-10T16:38:45-07:00, connectionDb=obsidian, query=SELECT @@wait_timeout}
2022-10-10T16:38:45-07:00 DEBUG [conn 4] Starting query {connectTime=2022-10-10T16:38:45-07:00, connectionDb=obsidian, query=SELECT @@max_allowed_packet}
2022-10-10T16:38:45-07:00 DEBUG [conn 4] Starting query {connectTime=2022-10-10T16:38:45-07:00, connectionDb=obsidian, query=SELECT @@wait_timeout}
2022-10-10T16:38:45-07:00 DEBUG [conn 4] Starting query {connectTime=2022-10-10T16:38:45-07:00, connectionDb=obsidian, query=SELECT @@version, @@GLOBAL.version}
2022-10-10T16:38:45-07:00 DEBUG [conn 4] Starting query {connectTime=2022-10-10T16:38:45-07:00, connectionDb=obsidian, query=SELECT @@lower_case_table_names}

My initial theory was that this problem was caused by an incompatibility in how dolt names result set columns. Specifically, in mysql we get this result:

mysql> SELECT @@lower_case_table_names;
+--------------------------+
| @@lower_case_table_names |
+--------------------------+
|                        1 |
+--------------------------+

Whereas in Dolt we get this:

obsidian> SELECT @@lower_case_table_names;
+----------------------------------+
| @@SESSION.lower_case_table_names |
+----------------------------------+
| 1                                |
+----------------------------------+

We've seen this cause compatibility bugs in client libraries in the past, because the library has a hard-coded expectation of a column name. But after patching dolt to match the SQL behavior for this query, the original problem remains.

(The result set column naming issue is a real bug, but doesn't seem to be causing this issue).

Something else more subtle is going on here.

[timsehn]

I find these two line in Prisma's MySQL connection/migration codebase a little suspicious.

https://github.com/prisma/prisma-engines/blob/810aaacead8837bb6f5b6a051d719353d2c360fb/migration-engine/connectors/sql-migration-connector/src/flavour/mysql/connection.rs#L115

I'm not sure what conn.lock() is doing but it might be sending a SQL statement header we don't understand.

https://github.com/prisma/prisma-engines/blob/810aaacead8837bb6f5b6a051d719353d2c360fb/migration-engine/connectors/sql-migration-connector/src/flavour/mysql.rs#L153

Appending mysql to the connection string may not work because Dolt doesn't allow you to connect to it.

$ mysql -h 127.0.0.1 mysql -uroot
ERROR 1105 (HY000): unknown error: database not found: mysql
$ mysql -h 127.0.0.1 -uroot      
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.7.9-Vitess 

Copyright (c) 2000, 2022, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| mysql              |
| test_remotes_table |
+--------------------+
3 rows in set (0.00 sec)

mysql> use mysql
ERROR 1105 (HY000): unknown error: database not found: mysql

[alexn-s]

by the way: i experienced the same problem with typeorm.
if you like i can also create a repo for that.

my guess without knowing the dolt code base from what i experienced is a general compatibility issue with nodeJS ORMs

[timsehn]

Can you please make a new bug a repro for that?

We're actively working this and we suspect it is something in the connection library. Interestingly, those aren't written in Node but in Rust. So, it makes sense if both these packages use the same connection library, they would experience the same issue.

[alexn-s]

huh interesting. always assumed that the libs were js/ ts and perhaps addons with c++.
i will create a repo for typeorm (probably tomorrow)

[timsehn]

Prisma thread we opened. prisma/prisma#15788

[PavelSafronov]

We were able to use Wireshark to get detailed MySQL wire logs, and those showed exactly what the issue is.

Prisma is attempting to prepare this statement, which references the non-existent table _prisma_migrations:

SELECT `id`, `checksum`, `finished_at`, `migration_name`, `logs`, `rolled_back_at`, `started_at`, `applied_steps_count` FROM `_prisma_migrations` ORDER BY `started_at` ASC

MySQL handles this by returning error code 1146 with the error message Table 'obsidian._prisma_migrations' doesn't exist.
Dolt handles this differently, by returning error code 1105 with the error message unknown error: table not found: _prisma_migrations.

Here's a repo that reproduces this issue: https://github.com/PavelSafronov/dolt-prepare-missing-table

Prisma is expecting the 1146 code, but not the 1105 code, and that's why the migration fails. We're now looking into the underlying issue.

[fulghum]

I made a quick hack in vitess to return the same error code as MySQL (1146) when a table isn't found and confirmed our hypothesis about the error codes being the culprit here. Fixing just that one error code for "table not found" enabled prisma migrate dev to complete successfully.

I'm guessing there will be similar problems for other errors that don't match MySQL's error codes, so I'd like to get some of the Prisma tests set up to run against Dolt to help us proactively find any other problems. It looks like these are the MySQL specific integration tests for Prisma, but I've just started poking around and see some other tests in the eco-system-test repo that may be a better fit.

In parallel, we'll figure out a clean way to pass the right error codes back from dolt/go-mysql-server through to vitess, which is what ultimately writes them to the wire for us.