SQLPutData errors are not handled, causing a function sequence error in SQLParamData

[NattyNarwhal]

Description

Edit: I blamed the wrong extension initially, but the problem remains the same. See the comment I posted for what I actually think is going on now that I understand more here.

A user reported to me an issue where PDO_ODBC procedural ODBC was returning a function sequence error. Unfortunately, it's a little hard to reproduce independently (large Laravel application, large dataset), but I can clearly see what's causing the error, and that it's obscuring another error that's the source of the actual problem.

The relevant part of the unixODBC trace (I'm not posting the full file because it's ~100k lines):

[ODBC][718][1678733794.839656][SQLAllocHandle.c][560]
		Entry:
			Handle Type = 3
			Input Handle = 0x56088464f120
[ODBC][718][1678733794.839724][SQLAllocHandle.c][1105]
		Exit:[SQL_SUCCESS]
			Output Handle = 0x56088467eaa0
[ODBC][718][1678733794.839741][SQLPrepare.c][196]
		Entry:
			Statement = 0x56088467eaa0
			SQL = [select id from new table (insert into documents (id, title, body, keywords, user_id, category_id, role_id, categoryname, created...][length = 198 (SQL_NTS)]
[ODBC][718][1678733794.840339][SQLPrepare.c][377]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840394][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 1
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840414][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840441][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 1
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = -5 SQL_BIGINT
			Col Def = 20
			Scale = 0
			Rgb Value = 0x7f6bcd1ceaf0
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd04d8c0
[ODBC][718][1678733794.840459][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840475][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 2
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840502][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840517][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 2
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = 12 SQL_VARCHAR
			Col Def = 500
			Scale = 0
			Rgb Value = 0x7f6bcd1ce820
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd050460
[ODBC][718][1678733794.840531][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840546][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 3
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840562][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840576][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 3
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = -1 SQL_LONGVARCHAR
			Col Def = 65536
			Scale = 0
			Rgb Value = 0x7f6bcd1ce780
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd04d940
[ODBC][718][1678733794.840592][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840608][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 4
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840624][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840655][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 4
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = -1 SQL_LONGVARCHAR
			Col Def = 65536
			Scale = 0
			Rgb Value = 0x7f6bcd1ce690
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd04df00
[ODBC][718][1678733794.840670][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840686][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 5
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840701][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840715][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 5
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = -5 SQL_BIGINT
			Col Def = 20
			Scale = 0
			Rgb Value = 0x7f6bcd1ce9b0
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd04d800
[ODBC][718][1678733794.840729][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840744][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 6
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840760][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840790][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 6
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = -5 SQL_BIGINT
			Col Def = 20
			Scale = 0
			Rgb Value = 0x7f6bcd1ce8c0
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd041b20
[ODBC][718][1678733794.840806][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840822][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 7
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840847][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840861][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 7
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = -5 SQL_BIGINT
			Col Def = 20
			Scale = 0
			Rgb Value = 0x7f6bcd1ce960
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd0439c0
[ODBC][718][1678733794.840875][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840890][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 8
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840905][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840919][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 8
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = 12 SQL_VARCHAR
			Col Def = 500
			Scale = 0
			Rgb Value = 0x7f6bcd1cea00
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd04d900
[ODBC][718][1678733794.840933][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.840949][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 9
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.840971][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.840985][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 9
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = 93 SQL_TYPE_TIMESTAMP
			Col Def = 26
			Scale = 6
			Rgb Value = 0x7f6bcd1ceb90
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd043c20
[ODBC][718][1678733794.840999][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.841015][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 10
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.841030][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.841044][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 10
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = 93 SQL_TYPE_TIMESTAMP
			Col Def = 26
			Scale = 6
			Rgb Value = 0x7f6bcd1ce4b0
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd041ce0
[ODBC][718][1678733794.841057][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.841072][SQLDescribeParam.c][185]
		Entry:
			Statement = 0x56088467eaa0
			Parameter Number = 11
			SQL Type = 0x7ffc4db00cd2
			Param Def = 0x7ffc4db00cd8
			Scale = 0x7ffc4db00cd4
			Nullable = 0x7ffc4db00cd6
[ODBC][718][1678733794.841088][SQLDescribeParam.c][338]
		Exit:[SQL_SUCCESS]                
			SQL Type = 0x7ffc4db00ba0                
			Param Def = 0x7ffc4db00ab0                
			Scale = 0x7ffc4db009c0                
			Nullable = 0x7ffc4db008d0
[ODBC][718][1678733794.841102][SQLBindParameter.c][217]
		Entry:
			Statement = 0x56088467eaa0
			Param Number = 11
			Param Type = 1
			C Type = 1 SQL_C_CHAR
			SQL Type = 93 SQL_TYPE_TIMESTAMP
			Col Def = 26
			Scale = 6
			Rgb Value = 0x7f6bcd1ce730
			Value Max = 0
			StrLen Or Ind = 0x7f6bcd04d7c0
[ODBC][718][1678733794.841115][SQLBindParameter.c][434]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.841132][SQLExecute.c][187]
		Entry:
			Statement = 0x56088467eaa0
[ODBC][718][1678733794.841148][SQLExecute.c][357]
		Exit:[SQL_NEED_DATA]
[ODBC][718][1678733794.841163][SQLParamData.c][166]
		Entry:
			Statement = 0x56088467eaa0
			Value = 0x7ffc4db00ea0
[ODBC][718][1678733794.841177][SQLParamData.c][362]
		Exit:[SQL_NEED_DATA]
			Value = 0x7f6bcd1ceaf0
[ODBC][718][1678733794.841190][SQLPutData.c][148]
		Entry:
			Statement = 0x56088467eaa0
			Data = 0x7f6bcd04d838
			StrLen = 3
[ODBC][718][1678733794.841205][SQLPutData.c][315]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.841218][SQLParamData.c][166]
		Entry:
			Statement = 0x56088467eaa0
			Value = 0x7ffc4db00ea0
[ODBC][718][1678733794.841231][SQLParamData.c][362]
		Exit:[SQL_NEED_DATA]
			Value = 0x7f6bcd1ce820
[ODBC][718][1678733794.841244][SQLPutData.c][148]
		Entry:
			Statement = 0x56088467eaa0
			Data = 0x7f6bcd1d2be8
			StrLen = 20
[ODBC][718][1678733794.841258][SQLPutData.c][315]
		Exit:[SQL_SUCCESS]
[ODBC][718][1678733794.841271][SQLParamData.c][166]
		Entry:
			Statement = 0x56088467eaa0
			Value = 0x7ffc4db00ea0
[ODBC][718][1678733794.841285][SQLParamData.c][362]
		Exit:[SQL_NEED_DATA]
			Value = 0x7f6bcd1ce780
[ODBC][718][1678733794.841299][SQLPutData.c][148]
		Entry:
			Statement = 0x56088467eaa0
			Data = 0x7f6bcd186e18
			StrLen = 2106
[ODBC][718][1678733794.841808][SQLPutData.c][315]
		Exit:[SQL_ERROR]
[ODBC][718][1678733794.841826][SQLParamData.c][166]
		Entry:
			Statement = 0x56088467eaa0
			Value = 0x7ffc4db00ea0
[ODBC][718][1678733794.841838][SQLParamData.c][189]Error: HY010
[ODBC][718][1678733794.841867][SQLGetDiagRec.c][677]
		Entry:
			Statement = 0x56088467eaa0
			Rec Number = 1
			SQLState = 0x7f6bccf98718
			Native = 0x7f6bccf98920
			Message Text = 0x7f6bccf9871e
			Buffer Length = 511
			Text Len Ptr = 0x7ffc4db00a22
[ODBC][718][1678733794.841887][SQLGetDiagRec.c][726]
		Exit:[SQL_SUCCESS]
			SQLState = HY010
			Native = 0x7f6bccf98920 -> 0 (32 bits)
			Message Text = [[unixODBC][Driver Manager]Function sequence error]
[ODBC][718][1678733794.841901][SQLGetDiagRec.c][677]
		Entry:
			Statement = 0x56088467eaa0
			Rec Number = 2
			SQLState = 0x7ffc4db00a2a
			Native = 0x7ffc4db00a24
			Message Text = 0x7ffc4db00a30
			Buffer Length = 1023
			Text Len Ptr = 0x7ffc4db00a22
[ODBC][718][1678733794.841915][SQLGetDiagRec.c][726]
		Exit:[SQL_NO_DATA]

As you can see, there's some DATA_AT_EXEC going on (the unixODBC trace makes it hard to determine what parameter is bound as such), so PDO_ODBC starts with an SQLParamData, and calls SQLPutData (alternative call site) in a loop as needed.

The problem is that failures in SQLPutData are not correctly handled. As you can see in the trace, one of the later the SQLPutData call is returning an error (unfortunately, unixODBC tracing doesn't decide to find specifics on its own), but PDO_ODBC procedural ODBC doesn't actually do anything with the error code it stores (if it stores it at all) store the error and act on it. Instead, it continues on, calling SQLParamData again, which is now in an invalid state and within its rights to return HY010 (as documented, though it's not clear that only successful SQLPutData or exec calls are valid).

The actual error we care about is for the SQLPutData call, but that's not being surfaced, and the misleading function sequence error is returned instead because it ignores that previous error.

If it helps, I also have the application's Laravel log from trying to insert the rows, although this does include the user's data. I'm also trying to get the schema and mapping from them as well. It's using the Db2i driver as well, but on Linux.

PHP Version

PHP 8.1.16

Operating System

Ubuntu 22.04

[NattyNarwhal]

Mea culpa (though there's still an issue); I had assumed their application was using PDO_ODBC, when it's actually using procedural ODBC. The PDO_ODBC case would have to fail now that I read it clearly, because it would break out of the while (rc == SQL_NEED_DATA) loop. The error reporting wouldn't be specific for the function, but it would show the right error.

However, procedural ODBC does not check for errors in SQLPutData, so it would fail in the next iteration of the loop on SQLParamData. In fact, the error reporting for that chunk of code seems pretty sketchy in general.

I think I'll get the user to try PDO_ODBC and see if that works better.

[NattyNarwhal]

My mea culpa has a mea culpa - it is PDO_ODBC that the user was running. However, I think both extensions suffer this issue from reading their source, but it's not clear to me why PDO_ODBC is also suffering.

I stepped through PDO_ODBC in gdb and found out:

• The underlying cause was a driver reporting an error on SQLPutData - specifically, character conversion to match the column's type failed. (That was worked around by a driver connection string option, though it doesn't solve this issue).
• It is the PDO_ODBC_CONV_NOT_REQUIRED case that gets used.
• However, it does call SQLParamData again, which shouldn't happen, because rc gets set to rc1, which is SQL_ERROR, not SQL_NEED_DATA.

[NattyNarwhal]

For procedural ODBC, the fix would probably be this, but I haven't tested it, just built:

diff --git a/ext/odbc/php_odbc.c b/ext/odbc/php_odbc.c
index a26a1a43c6..587d312b6a 100644
--- a/ext/odbc/php_odbc.c
+++ b/ext/odbc/php_odbc.c
@@ -1025,7 +1025,11 @@ PHP_FUNCTION(odbc_execute)
 				rc = SQLParamData(result->stmt, (void*)&fp);
 				if (rc == SQL_NEED_DATA) {
 					while ((nbytes = read(fp, &buf, 4096)) > 0) {
-						SQLPutData(result->stmt, (void*)&buf, nbytes);
+						SQLRETURN rc1 = SQLPutData(result->stmt, (void*)&buf, nbytes);
+						if (!(rc1 == SQL_SUCCESS || rc1 == SQL_SUCCESS_WITH_INFO)) {
+							rc = rc1;
+							break; /* out of the read loop */
+						}
 					}
 				}
 			}

[nielsdos]

I would say that makes sense. Strangely, the similar loop in PDO_ODBC does not break upon failure. The PDO_ODBC code strikes me a bit as odd:

php-src/ext/pdo_odbc/odbc_stmt.c

Lines 237 to 246 in 5efd60e

	do {
	len = php_stream_read(stm, buf, 8192);
	if (len == 0) {
	break;
	}
	rc1 = SQLPutData(S->stmt, buf, len);
	if (rc1 != SQL_SUCCESS && rc1 != SQL_SUCCESS_WITH_INFO) {
	rc = rc1;
	}
	} while (1);

Something I did some time ago to reliably test rare error conditions in .phpt is to interpose the function. Something like this:

php-src/ext/zend_test/test.c

Lines 1104 to 1111 in 5efd60e

	PHP_ZEND_TEST_API ssize_t copy_file_range(int fd_in, off64_t *off_in, int fd_out, off64_t *off_out, size_t len, unsigned int flags)
	{
	ssize_t (*original_copy_file_range)(int, off64_t *, int, off64_t *, size_t, unsigned int) = dlsym(RTLD_NEXT, "copy_file_range");
	if (ZT_G(limit_copy_file_range) >= Z_L(0)) {
	len = ZT_G(limit_copy_file_range);
	}
	return original_copy_file_range(fd_in, off_in, fd_out, off_out, len, flags);
	}

Perhaps this information is useful for you if you want to write a test for a potential PR for this.

[NattyNarwhal]

Yeah, I think the loop you linked in PDO_ODBC is basically an adapted version of the one in procedural ODBC and should also be fixed - and both are for bound file streams (though the one in procedural ODBC operating against directly a file descriptor that it opens is slightly wild - I've had users accidentally trigger that before!).

Now knowing what caused the failure, I should be able to recreate it consistently with the same database and driver, at least. I'm hoping i.e. MariaDB's ODBC driver exhibits similar behaviour, so it'll be easier to reconstruct.