Dolt Stored Procedures don't work with CALL functionality in some connectors

[timsehn]

A customer reported this line in his Java code did not work:

CallableStatement callableStatement = connection.prepareCall("{call dolt_checkout(?)}");

It seems prepareds don't mix with Dolt stored procedures right now.

Will get a quick repro soon.

[timsehn]

I can't get this to reproduce with the python MySQL Connector.

Here is the code:

mport mysql.connector
import sys

def main():
    connection = mysql.connector.connect(user = 'root',
                                         host = "127.0.0.1",
                                         port = 3306,
                                         database='test_dolt_stored_w_prepareds')


    cursor = connection.cursor(prepared=True)
    query = "CALL dolt_checkout('-b', %s)"
    cursor.execute(query, ('foo',))
    try:
        results = cursor.fetchall()
        print(results)
    except mysql.connector.errors.InterfaceError:
        pass

    cursor.execute('select * from dolt_branches')
    try:
        results = cursor.fetchall()
        print(results)
    except mysql.connector.errors.InterfaceError:
        pass

    cursor.close()

    connection.close()

    exit(0)

main()

Here is the output:

test-dolt-stored-w-prepareds $ python test.py 
[(0,)]
[('foo', 'nl0ncgc9lmek3407ljijlgvra1eflpch', 'Tim Sehn', 'tim@dolthub.com', datetime.datetime(2022, 5, 16, 19, 49, 10), 'Initialize data repository'), ('main', 'nl0ncgc9lmek3407ljijlgvra1eflpch', 'Tim Sehn', 'tim@dolthub.com', datetime.datetime(2022, 5, 16, 19, 49, 10), 'Initialize data repository')]

And here is the server log in trace mode indicating prepareds were used.

2022-05-16T13:13:45-07:00 INFO [conn 3] NewConnection {DisableClientMultiStatements=false}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Starting query {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES 'utf8mb4' COLLATE 'utf8mb4_general_ci'}
2022-05-16T13:13:45-07:00 TRACE [conn 3] beginning execution {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES 'utf8mb4' COLLATE 'utf8mb4_general_ci'}
2022-05-16T13:13:45-07:00 TRACE [conn 3] beginning new transaction {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES 'utf8mb4' COLLATE 'utf8mb4_general_ci'}
2022-05-16T13:13:45-07:00 TRACE [conn 3] spooling result row [] {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES 'utf8mb4' COLLATE 'utf8mb4_general_ci'}
2022-05-16T13:13:45-07:00 TRACE [conn 3] committing transaction DoltTransaction {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES 'utf8mb4' COLLATE 'utf8mb4_general_ci'}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] returning result &{[] 1 0  [[]] <nil>} {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES 'utf8mb4' COLLATE 'utf8mb4_general_ci'}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Query took 0ms {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES 'utf8mb4' COLLATE 'utf8mb4_general_ci'}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Starting query {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES utf8mb4}
2022-05-16T13:13:45-07:00 TRACE [conn 3] beginning execution {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES utf8mb4}
2022-05-16T13:13:45-07:00 TRACE [conn 3] beginning new transaction {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES utf8mb4}
2022-05-16T13:13:45-07:00 TRACE [conn 3] spooling result row [] {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES utf8mb4}
2022-05-16T13:13:45-07:00 TRACE [conn 3] committing transaction DoltTransaction {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES utf8mb4}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] returning result &{[] 1 0  [[]] <nil>} {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES utf8mb4}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Query took 0ms {connectTime=2022-05-16T13:13:45-07:00, query=SET NAMES utf8mb4}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Starting query {connectTime=2022-05-16T13:13:45-07:00, query=set autocommit=0}
2022-05-16T13:13:45-07:00 TRACE [conn 3] beginning execution {connectTime=2022-05-16T13:13:45-07:00, query=set autocommit=0}
2022-05-16T13:13:45-07:00 TRACE [conn 3] beginning new transaction {connectTime=2022-05-16T13:13:45-07:00, query=set autocommit=0}
2022-05-16T13:13:45-07:00 TRACE [conn 3] spooling result row [] {connectTime=2022-05-16T13:13:45-07:00, query=set autocommit=0}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] returning result &{[] 1 0  [[]] <nil>} {connectTime=2022-05-16T13:13:45-07:00, query=set autocommit=0}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Query took 1ms {connectTime=2022-05-16T13:13:45-07:00, query=set autocommit=0}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Starting query {connectTime=2022-05-16T13:13:45-07:00, query=CALL dolt_checkout('-b', ?)}
2022-05-16T13:13:45-07:00 TRACE [conn 3] beginning execution {connectTime=2022-05-16T13:13:45-07:00, query=CALL dolt_checkout('-b', ?)}
2022-05-16T13:13:45-07:00 TRACE [conn 3] optimizing prepared plan for query: CALL dolt_checkout('-b', ?) {connectTime=2022-05-16T13:13:45-07:00, query=CALL dolt_checkout('-b', ?)}
2022-05-16T13:13:45-07:00 TRACE [conn 3] plan before re-opt: CALL dolt_checkout("-b", "foo") {connectTime=2022-05-16T13:13:45-07:00, query=CALL dolt_checkout('-b', ?)}
2022-05-16T13:13:45-07:00 TRACE [conn 3] plan after re-opt: CALL dolt_checkout("-b", "foo") {connectTime=2022-05-16T13:13:45-07:00, query=CALL dolt_checkout('-b', ?)}
2022-05-16T13:13:45-07:00 TRACE [conn 3] spooling result row [INT64(0)] {connectTime=2022-05-16T13:13:45-07:00, query=CALL dolt_checkout('-b', ?)}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] returning result &{[name:"status"  type:INT64  charset:33] 1 0  [[INT64(0)]] <nil>} {connectTime=2022-05-16T13:13:45-07:00, query=CALL dolt_checkout('-b', ?)}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Query took 1ms {connectTime=2022-05-16T13:13:45-07:00, query=CALL dolt_checkout('-b', ?)}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Starting query {connectTime=2022-05-16T13:13:45-07:00, query=select * from dolt_branches}
2022-05-16T13:13:45-07:00 TRACE [conn 3] beginning execution {connectTime=2022-05-16T13:13:45-07:00, query=select * from dolt_branches}
2022-05-16T13:13:45-07:00 TRACE [conn 3] optimizing prepared plan for query: select * from dolt_branches {connectTime=2022-05-16T13:13:45-07:00, query=select * from dolt_branches}
2022-05-16T13:13:45-07:00 TRACE [conn 3] plan before re-opt: Table(dolt_branches) {connectTime=2022-05-16T13:13:45-07:00, query=select * from dolt_branches}
2022-05-16T13:13:45-07:00 TRACE [conn 3] plan after re-opt: Exchange(parallelism=16)
 └─ Table(dolt_branches)
 {connectTime=2022-05-16T13:13:45-07:00, query=select * from dolt_branches}
2022-05-16T13:13:45-07:00 TRACE [conn 3] spooling result row [TEXT("foo") TEXT("nl0ncgc9lmek3407ljijlgvra1eflpch") TEXT("Tim Sehn") TEXT("tim@dolthub.com") DATETIME("2022-05-16 19:49:10.977") TEXT("Initialize data repository")] {connectTime=2022-05-16T13:13:45-07:00, query=select * from dolt_branches}
2022-05-16T13:13:45-07:00 TRACE [conn 3] spooling result row [TEXT("main") TEXT("nl0ncgc9lmek3407ljijlgvra1eflpch") TEXT("Tim Sehn") TEXT("tim@dolthub.com") DATETIME("2022-05-16 19:49:10.977") TEXT("Initialize data repository")] {connectTime=2022-05-16T13:13:45-07:00, query=select * from dolt_branches}
2022-05-16T13:13:45-07:00 DEBUG [conn 3] Query took 0ms {connectTime=2022-05-16T13:13:45-07:00, query=select * from dolt_branches}
2022-05-16T13:13:45-07:00 INFO [conn 3] ConnectionClosed {}

[timsehn]

Using callproc I get the following error which I think is similar to the Java client:

test-dolt-stored-w-prepareds $ python test.py
Traceback (most recent call last):
  File "/Users/timsehn/liquidata/dolt/test-dolt-stored-w-prepareds/test.py", line 33, in <module>
    main()
  File "/Users/timsehn/liquidata/dolt/test-dolt-stored-w-prepareds/test.py", line 12, in main
    cursor.callproc('dolt_checkout', ('-b','foo'))
  File "/usr/local/lib/python3.9/site-packages/mysql/connector/cursor_cext.py", line 894, in callproc
    raise errors.NotSupportedError()
mysql.connector.errors.NotSupportedError: Unknown error

Code here:

test-dolt-stored-w-prepareds $ cat test.py 
import mysql.connector
import sys

def main():
    connection = mysql.connector.connect(user = 'root',
                                         host = "127.0.0.1",
                                         port = 3306,
                                         database='test_dolt_stored_w_prepareds')

    
    cursor = connection.cursor(prepared=True)
    cursor.callproc('dolt_checkout', ('-b','foo'))
    try:
        results = cursor.fetchall()
        print(results)
    except mysql.connector.errors.InterfaceError:
        pass

    cursor.execute('select * from dolt_branches')
    try:
        results = cursor.fetchall()
        print(results)
    except mysql.connector.errors.InterfaceError:
        pass
    
    cursor.close()

    connection.close()

    exit(0)

main()

[Hydrocharged]

The Python code is faulty. With connection.cursor(prepared=True), it looks like cursor.callproc just does not work. I created dummy dolt stored procedures on a MySQL instance so that I could use the exact same statements across both Dolt and MySQL, and introducing prepared=True causes the mysql.connector.errors.NotSupportedError: Unknown error error.

From my limited research, it appears that the expected workflow for prepared=True involves using cursor.execute, which does work for both MySQL and Dolt. On top of this, giving non-existent stored procedures returns the appropriate ...does not exist error, which indicates the aforementioned NotSupportedError is a different error altogether, and I think it's saying that cursor.callproc is not supported (with prepared=True).

With that being said, I was unable to find a way to fail any stored procedure in Dolt that also did not fail MySQL, so whatever Java is doing is different than what Python is doing. I'm attempting to create a Java project that uses the CallableStatement class, which I think comes from the Spring JDBC framework, so that I can exactly replicate their issue for further debugging.

I have three guesses about what could be their issue.

The first guess is fairly simple: if they're getting a no such procedure found error, then it's possible that they haven't selected their database. Stored procedures (including our dolt_ ones) are tied to databases, so if no database is found, no stored procedure will be found.

The second guess deals with what prepared statements are. I initially thought that prepared statements used PREPARE and EXECUTE, but we're using parameter bindings which we refer to as prepared statements. We currently do not support PREPARE/EXECUTE. Their error doesn't say anything about the PREPARE keyword (which we would error on), but the framework might swallow that error and return something about the procedure itself instead.

The third guess is that Spring JDBC is running SHOW CREATE PROCEDURE for some reason and running into the bug where external procedures don't show.

[Hydrocharged]

The bug has been found, and the PR fixing this issue has been linked. This is the Java code that ended up working:

import java.sql.*;

public class Main {
    public static void main(String[] args) throws SQLException {
        Connection conn = DriverManager.getConnection("jdbc:mysql://localhost:3308/test_dolt_stored_w_prepareds", "root", "");

        CallableStatement callableStatement = conn.prepareCall("{call dolt_checkout(?)}");
        callableStatement.setString(1, "main");
        callableStatement.execute();

        ResultSet resultSet = callableStatement.getResultSet();
        ResultSetMetaData metaData = resultSet.getMetaData();
        int colCount = metaData.getColumnCount();
        while (resultSet.next()) {
            for (int i = 1; i <= colCount; i++) {
                if (i > 1) {
                    System.out.print(",  ");
                }
                System.out.print(metaData.getColumnName(i) + ": " + resultSet.getString(i));
            }
            System.out.println("");
        }
    }
}

There were two issues. The first is that JDBC does a SHOW CREATE PROCEDURE call on every stored procedure that is used by prepareCall. This ran into #3428. After fixing that, we ran into a second issue, as JDBC also checks that the CREATE PROCEDURE statement is a valid statement. It does not seem to matter whether the statement is even related to a stored procedure (for example, SELECT 1; works just fine), just that it's a valid statement. External stored procedures (such as dolt_checkout) are implemented in Dolt's source code rather than as a series of SQL expressions, so as a workaround we create fake CREATE PROCEDURE statements for all external stored procedures now.