Bug #93378 Out parameters error on second call when statement is a prepared statement
Submitted: 28 Nov 2018 1:00 Modified: 12 Dec 2018 14:44
Reporter: Kurt Peterson Email Updates:
Status: Verified Impact on me:
None 
Category:Connector / ODBC Severity:S2 (Serious)
Version:8.0, 5.3.11 OS:Microsoft Windows
Assigned to: CPU Architecture:Any
Tags: ADO, C++, microsoft, ODBC, stored procedure

[28 Nov 2018 1:00] Kurt Peterson
Description:
ADO Prepared statements with out put parameters error out with:

[MySQL][ODBC 8.0(a) Driver][mysqld-5.7.15-log]OUT or INOUT argument 1 for routine <stored procedure name> is not a variable or NEW pseudo-variable in BEFORE trigger

where argument 1 is the out parameter. 

This happens on the second call of my statement. This error is very misleading and it is unclear what the problem is. I was able to discover the problem by creating a simple C++ ADO program and comparing what that was doing to my larger application. In the logs (C:\ProgramData\MySQL\MySQL Server 5.7\Data) I compared the successful case to the failing case and found the failing case used the word "query" after the first execution of the stored procedure whereas the successful case used the "Prepare, Execute, Close stmt" paradigm. 

Failing case:
2018-11-09T13:22:34.247680Z	   20 Prepare	call INSERT_STEP_RESULT(?, ?)
2018-11-09T13:22:34.251680Z	   20 Query	SELECT @@tx_isolation
2018-11-09T13:22:34.273681Z	   20 Query	set @@sql_select_limit=DEFAULT
2018-11-09T13:22:34.273681Z	   20 Execute	call INSERT_STEP_RESULT('48', '888')
2018-11-09T13:22:34.325684Z	   20 Close stmt	
2018-11-09T13:22:34.326684Z	   20 Query	call INSERT_STEP_RESULT(48, 888) <-- Fail 
2018-11-09T13:22:34.360686Z	   20 Query	call INSERT_STEP_RESULT(50, 888) <-- Fail 

Successful Case:
2018-11-09T14:47:31.254072Z	    9 Query	set @@max_execution_time=30000
2018-11-09T14:47:31.255072Z	    9 Prepare	call INSERT_STEP_RESULT(?, ?)
2018-11-09T14:47:31.255072Z	    9 Execute	call INSERT_STEP_RESULT('-1163005939', '888')
2018-11-09T14:47:31.286074Z	    9 Close stmt
2018-11-09T14:47:31.254074Z	    9 Query	set @@max_execution_time=30000
2018-11-09T14:47:31.255074Z	    9 Prepare	call INSERT_STEP_RESULT(?, ?)
2018-11-09T14:47:31.255074Z	    9 Execute	call INSERT_STEP_RESULT('-1163005939', '888')
2018-11-09T14:47:31.286076Z	    9 Close stmt

I found a number of bug reports on this but it does not seem like any of them were fixed or the bug was reintroduced:
https://bugs.mysql.com/bug.php?id=17898 
https://bugs.mysql.com/bug.php?id=24724 
https://bugs.mysql.com/bug.php?id=26382 
https://bugs.mysql.com/bug.php?id=27632 
 
References: 
https://docs.microsoft.com/en-us/sql/ado/reference/ado-api/prepared-property-ado?view=sql-...
https://stackoverflow.com/questions/4731228/enabling-query-log-in-mysql-5-on-windows-7 

How to repeat:
SQL For DB:
CREATE DATABASE `kurtp_reduced` /*!40100 DEFAULT CHARACTER SET utf8 */;

use `kurtp_reduced`; 

CREATE TABLE `step_result` (
  `ID` int(11) NOT NULL AUTO_INCREMENT,
  `UUT_RESULT` int(11) DEFAULT NULL,
  PRIMARY KEY (`ID`)
) ENGINE=InnoDB AUTO_INCREMENT=26 DEFAULT CHARSET=utf8;

DELIMITER $$
CREATE DEFINER=`root`@`%` PROCEDURE `INSERT_STEP_RESULT`(
    OUT ID INT,
    IN UUT_RESULT INT4
)
BEGIN
    INSERT INTO `STEP_RESULT` VALUES (
		default,
        UUT_RESULT        
    );
    
    SET ID = last_insert_id();
    
END$$
DELIMITER ;

CPP:
// MySQL Stored Procedure.cpp : Defines the entry point for the console application.
//

#include "stdafx.h"
#include <iostream>
#import "C:\\Windows\\winsxs\\x86_microsoft-windows-m..ents-mdac-ado15-dll_31bf3856ad364e35_6.1.7601.22012_none_0ebfc67ce80861b4\\msado15.dll" \
	rename ("EOF", "AdoEOF")

using namespace std; 

int _tmain(int argc, _TCHAR* argv[])
{
	CoInitialize(nullptr);
	HRESULT hr = 0;
	string DAM = "My DB";

	try 
	{
		// declare connection variables 

		ADODB::_ConnectionPtr	MySQLConn;
		ADODB::_ConnectionPtr   MSSQLServerConn;
		ADODB::_CommandPtr		StepStoredProc;

		_variant_t				Step_Col_ID_Param1;
		_variant_t				Step_UUT_Res_Param2;
		int						StepParamCount = 0;

		// Connection Strings [TODO]: Change this to connect to your database
		_bstr_t MySQLConnString = "Driver={MySQL ODBC 8.0 ANSI Driver};Server=10.2.101.6;Database=kurtp_reduced;Uid=root;Pwd=password";

		hr = MySQLConn.CreateInstance(__uuidof(ADODB::Connection));
		hr = MySQLConn->Open(MySQLConnString, "", "", ADODB::adConnectUnspecified);

		// Initialize Command
		StepStoredProc.CreateInstance(__uuidof(ADODB::Command));
		StepStoredProc->ActiveConnection = MySQLConn;
		StepStoredProc->CommandText = "INSERT_STEP_RESULT";
		StepStoredProc->CommandType = ADODB::adCmdStoredProc;
		
		StepStoredProc->Parameters->Refresh();

		StepParamCount = StepStoredProc->Parameters->GetCount();
		
		StepStoredProc->Parameters->Item[_variant_t((long)0)]->Value = VT_NULL;
		StepStoredProc->Parameters->Item[_variant_t((long)1)]->Value = 2001;
		
		//StepStoredProc->PutPrepared(false);
		
		// Causes Error: [MySQL][ODBC 8.0(a) Driver][mysqld-5.7.15-log]OUT or INOUT argument 1 for routine kurtp_reduced.INSERT_STEP_RESULT is not a variable or NEW pseudo-variable in BEFORE trigger
		StepStoredProc->PutPrepared(true);
		variant_t isPrepared = VT_NULL;
		for (int i = 0; i < 2; i++)
		{
			isPrepared = StepStoredProc->Prepared;
			StepStoredProc->Execute(NULL, NULL, ADODB::adCmdStoredProc);

			Step_Col_ID_Param1 = StepStoredProc->Parameters->Item[_variant_t((long)0)]->Value;
			Step_UUT_Res_Param2 = StepStoredProc->Parameters->Item[_variant_t((long)1)]->Value;
		}

		MySQLConn->Close(); 	
	}

	catch (_com_error& e)
	{ 
		_bstr_t myError = e.Description();
	}

	return 0;
}

Suggested fix:
N/A

Work around: Set prepared to false. For my simple case, this does not matter much, but I think this matter much more with large stored procedures.
[28 Nov 2018 1:12] Kurt Peterson
Zip file with C++ project and SQL to create database

Attachment: Prepared Statement.zip (application/x-zip-compressed, text), 2.33 MiB.

[28 Nov 2018 11:25] Miguel Solorzano
Thank you for the bug report. I compiled your program test case however it exits without error messages. Any idea?

On debug mode:
First-chance exception at 0x00007FFB5E62A388 in MySQL Stored Procedure.exe: Microsoft C++ exception: _com_error at memory location 0x000000079C0FF500.
<cut>
The program '[12112] MySQL Stored Procedure.exe' has exited with code 0 (0x0).
[29 Nov 2018 16:38] Kurt Peterson
Hey Miguel, 

It looks like you are getting the error, it's handled by my try/catch block because I never print the error description. Modify the catch block to be this:

catch (_com_error& e)
{ 
	_bstr_t myError = e.Description();
	cout << myError;
	getchar();
}

This should print out the error and wait for a key entry before exiting.
[30 Nov 2018 15:32] Miguel Solorzano
Thank you for the feedback. Is the below error message what you get tto?

C:\tmp>"MySQL Stored Procedure.exe"
Item cannot be found in the collection corresponding to the requested name or ordinal.
[10 Dec 2018 21:56] Kurt Peterson
Hey Miguel, 

I have never seen that error before. Can you tell me what line of code is throwing that exception? You should be able to attach the debugger and enable breaking on all the following exceptions through the debug menu:

Debug >> Exceptions 
and then check 
"C++ Exceptions" 
"Win32 Exception" 

This should break on your exception. For me, the exception is thrown at line 57: 

StepStoredProc->Execute(NULL, NULL, ADODB::adCmdStoredProc);

And is on this stack frame:

>	MySQL Stored Procedure.exe!wmain(argc=1, argv=0x004216a0) Line 57	C++

I did a search of that error and it looks like it occurs when you try to retrieve a field that isn't in a record. This makes no sense to me because there is no record we are trying to retrieve. The code is trying to execute a stored procedure. 

Also, what versions of MySQL Driver and Server are you using? My driver is what it is reported here, 8.0, and the version of MySQL Server is 5.7.15.
[11 Dec 2018 12:57] Miguel Solorzano
Test case result

Attachment: 93378.png (image/png, text), 61.71 KiB.

[11 Dec 2018 13:01] Miguel Solorzano
Hi Kurt,
Thank you for the feedback. I compiled again your test case now querying a MySQL Server 5.7 running on Linux local network and I was able to repeat the issue reported.
[12 Dec 2018 14:44] Kurt Peterson
Great, Miguel. Let me know if you need anything else.
[4 Mar 8:05] Bogdan Degtyariov
Posted by developer:
 
Intermediate diagnosis:

The second call to the stored procedure fails because the statement is closed after the results of the first call have been received.

2018-11-09T13:22:34.273681Z	   20 Execute	call INSERT_STEP_RESULT('48', '888')
2018-11-09T13:22:34.325684Z	   20 Close stmt
2018-11-09T13:22:34.326684Z	   20 Query	call INSERT_STEP_RESULT(48, 888) <-- Fail