search

php / php-src

The PHP Interpreter
https://www.php.net
Other
38.35k stars 7.77k forks source link

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

Open NattyNarwhal opened 1 year ago

NattyNarwhal commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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:

NattyNarwhal commented 1 year ago

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 commented 1 year ago

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:

https://github.com/php/php-src/blob/5efd60ea904ebc0f259440f8128c8d1b5e2893e4/ext/pdo_odbc/odbc_stmt.c#L237-L246

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

https://github.com/php/php-src/blob/5efd60ea904ebc0f259440f8128c8d1b5e2893e4/ext/zend_test/test.c#L1104-L1111

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

NattyNarwhal commented 1 year ago

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.