dolthub / dolt

Dolt – Git for Data
Apache License 2.0
17.41k stars 490 forks source link

"SQLSTATE[HY093]: Invalid parameter number" with Laravel 10 #6852

Closed kde99 closed 9 months ago

kde99 commented 9 months ago

Hello everyone!

I am using Laravel 10.28 for my project and added the laravel-adjacency-list package to my project and tried to use it, but was greeted by this error message. (You can find the issue I submitted there at https://github.com/staudenmeir/laravel-adjacency-list/issues/204 )

I tried migrating my DB back to MySQL 8 and test there (same code, just different DB), and it runs there so I assume the issue is with something related to Dolt. I have just installed the latest Dolt (1.21.0) and the issue is still present. I have shared the error screen on Flare (see https://flareapp.io/share/Lm89AYMP#context-request-headers ). The query in question is (that should be running, i.e. already parameters bound):

with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '/', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`

The query is correct and gives correct results in both Dolt and MySQL when ran from the console directly.

I have logged out the query and the binding Laravel is trying to execute (dd at runQueryCallback) :

// $query in runQueryCallback's try...catch
"with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, ?, `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte` ◀" // vendor\laravel\framework\src\Illuminate\Database\Connection.php:788

// $bindings in runQueryCallback's try...catch
array:1 [▼ // vendor\laravel\framework\src\Illuminate\Database\Connection.php:788
  0 => "'/'"
]

I am a bit at loss here since there is only one parameter and only one binding so should work, but for some reason (not sure if PHP, PDO, Laravel, or something else related) it doesn't work under Dolt, but does under MySQL with only the DB server being different.

I am hoping somebody with a bit more knowledge can look into this issue, and have it resolved.

Thanks for your help.

timsehn commented 9 months ago

Thanks. This seems at first glance to be an issue with Dolt handling that CTE.

@max-hoffman is the expert in these.

timsehn commented 9 months ago

Nevermind, you said it returned in Dolt but the value on the wire is messing up Laravel. Not @max-hoffman :-)

timsehn commented 9 months ago

We may be able to do this faster if you pop over to our Discord.

https://discord.gg/gqr7K4VNKe

Could you run Dolt in loglevel=trace and then past the log lines around the offending query?

Also, we have had problems with $conn->setAttribute(PDO::ATTR_EMULATE_PREPARES,false); which I know Laravel sets. This looks like it might have something to do with the prepared aspect of the query. Could you try turnbing that to true and see if you get the same error?

timsehn commented 9 months ago

Also, if you give me a step-by-step guide to reproduce the error on my Mac, I'm happy to do it and start to debug on my side. I have Laravel installed already from supporting another customer :-)

kde99 commented 9 months ago

Query with original setup and trace

So it looks like the query doesn't even hit dolt(?), running with trace and executing the page yields:

Starting server with Config HP="localhost:3306"|T="28800000"|R="false"|L="trace"
2023-10-20T07:29:26+02:00 DEBUG [no conn] Loading events {}
2023-10-20T07:29:26+02:00 TRACE [no conn] Starting eventExecutor {}
2023-10-20T07:29:26+02:00 INFO [no conn] Server ready. Accepting connections. {}
2023-10-20T07:29:26+02:00 WARN [no conn] secure_file_priv is set to "", which is insecure. {}
2023-10-20T07:29:26+02:00 WARN [no conn] Any user with GRANT FILE privileges will be able to read any file which the sql-server process can read. {}
2023-10-20T07:29:26+02:00 WARN [no conn] Please consider restarting the server with secure_file_priv set to a safe (or non-existant) directory. {}
2023-10-20T07:29:40+02:00 INFO [conn 1] NewConnection {DisableClientMultiStatements=false}
2023-10-20T07:29:40+02:00 DEBUG [conn 1] Starting query {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=use `partner`;}
2023-10-20T07:29:40+02:00 TRACE [conn 1] beginning execution {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=use `partner`;}
2023-10-20T07:29:40+02:00 TRACE [conn 1] beginning new transaction {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=use `partner`;}
2023-10-20T07:29:40+02:00 TRACE [conn 1] committing transaction DoltTransaction {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=use `partner`;}
2023-10-20T07:29:40+02:00 TRACE [conn 1] returning empty result {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=use `partner`;}
2023-10-20T07:29:40+02:00 DEBUG [conn 1] Query finished in 1 ms {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=use `partner`;}
2023-10-20T07:29:40+02:00 DEBUG [conn 1] Starting query {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set names 'utf8mb4' collate 'utf8mb4_unicode_ci'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] beginning execution {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set names 'utf8mb4' collate 'utf8mb4_unicode_ci'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] beginning new transaction {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set names 'utf8mb4' collate 'utf8mb4_unicode_ci'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] spooling result row [] {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set names 'utf8mb4' collate 'utf8mb4_unicode_ci'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] committing transaction DoltTransaction {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set names 'utf8mb4' collate 'utf8mb4_unicode_ci'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] returning result &{[] 1 0  [[]] <nil>} {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set names 'utf8mb4' collate 'utf8mb4_unicode_ci'}
2023-10-20T07:29:40+02:00 DEBUG [conn 1] Query finished in 1 ms {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set names 'utf8mb4' collate 'utf8mb4_unicode_ci'}
2023-10-20T07:29:40+02:00 DEBUG [conn 1] Starting query {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] beginning execution {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] beginning new transaction {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] spooling result row [] {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] committing transaction DoltTransaction {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'}
2023-10-20T07:29:40+02:00 TRACE [conn 1] returning result &{[] 1 0  [[]] <nil>} {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'}
2023-10-20T07:29:40+02:00 DEBUG [conn 1] Query finished in 1 ms {connectTime=2023-10-20T07:29:40+02:00, connectionDb=partner, query=set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'}
2023-10-20T07:29:41+02:00 INFO [conn 1] ConnectionClosed {}

so there is no trace of the query even being sent over to Dolt, which is weird.

Query when ATTR_EMULATE_PREPARES is true

Interestingly enough by setting PDO::ATTR_EMULATE_PREPARES => true it does work and Dolt generates this log for the query:

2023-10-20T07:55:27+02:00 DEBUG [conn 1] Starting query {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 TRACE [conn 1] beginning execution {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 TRACE [conn 1] beginning new transaction {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 TRACE [conn 1] spooling result row [UINT64(1) UINT64(1) NULL UINT64(1) TEXT("Item 1") NULL NULL INT64(0) TEXT("1")] {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 TRACE [conn 1] spooling result row [UINT64(5) UINT64(1) NULL UINT64(1) TEXT("Item 2") NULL NULL INT64(0) TEXT("5")] {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 TRACE [conn 1] spooling result row [UINT64(2) UINT64(1) UINT64(1) UINT64(1) TEXT("Item 1.1") NULL NULL INT64(1) TEXT("1'/'2")] {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 TRACE [conn 1] spooling result row [UINT64(3) UINT64(1) UINT64(2) UINT64(1) TEXT("Item 1.1.1") NULL NULL INT64(2) TEXT("1'/'2'/'3")] {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 TRACE [conn 1] spooling result row [UINT64(4) UINT64(1) UINT64(2) UINT64(1) TEXT("Item 1.2.1") NULL NULL INT64(2) TEXT("1'/'2'/'4")] {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 TRACE [conn 1] committing transaction DoltTransaction {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}
2023-10-20T07:55:27+02:00 DEBUG [conn 1] Query finished in 4 ms {connectTime=2023-10-20T07:55:27+02:00, connectionDb=laravel, query=with recursive `laravel_cte` as ((select *, 0 as `depth`, cast(`id` as char(65535)) as `path` from `ticket_esemenyek` where `parent_id` is null) union all (select `ticket_esemenyek`.*, `depth` + 1 as `depth`, concat(`path`, '\'/\'', `ticket_esemenyek`.`id`) from `ticket_esemenyek` inner join `laravel_cte` on `laravel_cte`.`id` = `ticket_esemenyek`.`parent_id`)) select * from `laravel_cte`}

Test case creation

To create a test case:

composer create-project laravel/laravel dolt-testcase
cd dolt-testcase
composer require staudenmeir/laravel-adjacency-list

Edit the .env file and change the DB_ connection parameters. In your dolt instance create a database and execute these instructions the make the table and add data (easier than migrations):

CREATE TABLE `ticket_esemenyek` (
    `id` BIGINT(20) UNSIGNED NOT NULL AUTO_INCREMENT,
    `ticket_id` BIGINT(20) UNSIGNED NOT NULL,
    `parent_id` BIGINT(20) UNSIGNED NULL DEFAULT NULL,
    `creator_id` BIGINT(20) UNSIGNED NOT NULL,
    `esemeny_neve` VARCHAR(255) NOT NULL COLLATE 'utf8mb4_unicode_ci',
    `created_at` TIMESTAMP NULL DEFAULT NULL,
    `updated_at` TIMESTAMP NULL DEFAULT NULL,
    PRIMARY KEY (`id`),
    INDEX `ticket_id` (`ticket_id`)
) ENGINE=InnoDB;

INSERT INTO `ticket_esemenyek` (`id`, `ticket_id`, `parent_id`, `creator_id`, `esemeny_neve`, `created_at`, `updated_at`) VALUES (1, 1, NULL, 1, 'Item 1', NULL, NULL);
INSERT INTO `ticket_esemenyek` (`id`, `ticket_id`, `parent_id`, `creator_id`, `esemeny_neve`, `created_at`, `updated_at`) VALUES (2, 1, 1, 1, 'Item 1.1', NULL, NULL);
INSERT INTO `ticket_esemenyek` (`id`, `ticket_id`, `parent_id`, `creator_id`, `esemeny_neve`, `created_at`, `updated_at`) VALUES (3, 1, 2, 1, 'Item 1.1.1', NULL, NULL);
INSERT INTO `ticket_esemenyek` (`id`, `ticket_id`, `parent_id`, `creator_id`, `esemeny_neve`, `created_at`, `updated_at`) VALUES (4, 1, 2, 1, 'Item 1.2.1', NULL, NULL);
INSERT INTO `ticket_esemenyek` (`id`, `ticket_id`, `parent_id`, `creator_id`, `esemeny_neve`, `created_at`, `updated_at`) VALUES (5, 1, NULL, 1, 'Item 2', NULL, NULL);

Create a TicketEsemenyek.php in app\Models with:

<?php

namespace App\Models;

use Illuminate\Database\Eloquent\Model;
use Staudenmeir\LaravelAdjacencyList\Eloquent\HasRecursiveRelationships;

class TicketEsemenyek extends Model
{
    use HasRecursiveRelationships;
    protected $table = "ticket_esemenyek";
    protected function getPathSeparator(): string
    {
        return "'/'";
    }
}

in routes\web.php change the original route for "/" to:

Route::get('/', function () {
    dd(\App\Models\TicketEsemenyek::tree()->get());
});

Now in your terminal run:

php artisan serve

and you can access the local server at http://127.0.0.1:8000/ showing you this exact error message of "SQLSTATE[HY093]: Invalid parameter number". If you now copy the generated query (that long thing in the top box) and run it in Dolt it will work and give the correct result.

If you want to set ATTR_EMULATE_PREPARES then you can in config\database.php in the big array under mysql add this to the options array:

PDO::ATTR_EMULATE_PREPARES => true,

and now the query runs normally.

timsehn commented 9 months ago

Thanks for the repro! I'm glad we found a workaround for you with setting PDO::ATTR_EMULATE_PREPARES => true.

I'll test this today and see if we can figure out how to fix root cause.

bpf120 commented 9 months ago

@kde99 , we'd love to learn about your use case sometime too. Feel free to email me or swing by our Discord if you are up for sharing. Thanks!

fulghum commented 9 months ago

@kde99, thank you for the awesome repro instructions! I've got your repro running in the debugger now, and I see where the Vitess library we use isn't finding the bind variable in the statement that's being prepared. I'm stepping through that code now to see what's going on and will update again soon. This is likely some small bug where a node in the parsed tree isn't properly dispatching to its children, but we should know more soon.

fulghum commented 9 months ago

Update... as we were suspecting, part of the statement wasn't getting properly traversed when the Vitess layer was searching for bind variables in the statement being prepared, so it missed the bind var and then complained about the execute statement sending the wrong number of bind vars. PR https://github.com/dolthub/vitess/pull/284 fixes that issue and I verified that with that change, your repro now loads a page successfully.

I'll work on getting this bug fix released for you today, and I'm also going to spend some time looking at why we didn't have any clues in the logs about what was going on. Seems like there may be a gap there we need to fill, too.

We also have a new test harness we're working on that should be able to help proactively identify issues like this before customers hit them. I'll sync up with that developer and we'll brainstorm about how we can use that new harness to get more coverage over our prepared tests. The way we currently test prepared statements doesn't go over a sql-server connection, so the code in the Vitess layer doesn't get executed and that's why our tests missed this case.

Thank you again for taking the time to report this issue and provide such an easy to use repro! We'll keep you updated as we get the fixed released.

fulghum commented 9 months ago

@kde99 – We just released Dolt version 1.21.1 with the fix for this issue.

Thanks for letting us know about this problem so we could fix it! 🙏 Let us know if you hit any other issues and we'll be happy to help.