A couple of weeks ago I ran into some problems when figuring out how to do backups and restores with the SQL Server Driver for PHP. The problem itself* isn’t the point of this post, but how the problem took me further down the stack is. The short story is that a query I was executing from PHP seemed to execute successfully (no errors were returned), but the results of the query were not what I expected. When I executed the same query from SQL Server Management Studio (SSMS), the query executed successfully and I got the results I expected. What was going on? I knew that SSMS uses classes in the .NET System.Data.SqlClient namespace to talk to SQL Server while the PHP driver (sqlsrv) uses the SNAC/ODBC driver to talk to the database. (I talked in a bit more detail about the architecture of the sqlsrv driver here.) So, I needed to see what was happening at the SNAC/ODBC level.

Fortunately, it is very easy to turn on ODBC tracing when using the sqlsrv driver. By specifying "TraceOn"=>1 and "TraceFile"=>"<path to file>" in the connection options, I was able to see exactly what the ODBC driver was doing. Here’s the code I used to connect:

$serverName = "(local)\sqlexpress";
$connOptions = array("Database"=>"master", "TraceOn"=>1, "TraceFile"=>"C:\Users\bswan\AppData\Local\Temp\SQL.LOG");
$conn = sqlsrv_connect($serverName, $connOptions);

Now when I executed a query (“RESTORE DATABASE TestDB FROM DISK = 'C:\Backups\TestDB_Backup.bak' WITH RECOVERY”, for example) I could see detailed information about what the ODBC driver did. I won’t look at the entire trace file, but I will take a look at a few of the entries in the file. For example, consider these entries that indicate a successful database connection:

php-cgi         1a14-1a18    ENTER SQLDriverConnectW
                HDBC                0x027B5B20
                HWND                0x00000000
                WCHAR *             0x61038634 [      -3] "******\ 0"
                SWORD                       -3
                WCHAR *             0x61038634
                SWORD                       -3
                SWORD *             0x00000000
                UWORD                        0 <SQL_DRIVER_NOPROMPT>

php-cgi         1a14-1a18    EXIT  SQLDriverConnectW  with return code 1 (SQL_SUCCESS_WITH_INFO)
                HDBC                0x027B5B20
                HWND                0x00000000
                WCHAR *             0x61038634 [      -3] "******\ 0"
                SWORD                       -3
                WCHAR *             0x61038634 <Invalid buffer length!> [-3]
                SWORD                       -3
                SWORD *             0x00000000
                UWORD                        0 <SQL_DRIVER_NOPROMPT>
                DIAG [01000] [Microsoft][SQL Server Native Client 10.0][SQL Server]Changed database context to 'master'. (5701)
                DIAG [01000] [Microsoft][SQL Server Native Client 10.0][SQL Server]Changed language setting to us_english. (5703)

I can see that the SQLDriverConnectW function (the Unicode version of SQLDriverConnect) was used to establish the database connection, that the connection succeeded (EXIT  SQLDriverConnectW  with return code 1 (SQL_SUCCESS_WITH_INFO)), and that two messages were returned by the server (Changed database context to 'master' and Changed language setting to us_english). These particular messages are expected and they are ignored by sqlsrv driver.

Note: The body of each trace file entry contains information about handles returned by the ODBC driver (HDBC, for example). The <Invalid buffer length!> message for the WCHAR handle is an expected message. It is the result of calling SQLDriverConnect with a constant (whose value is -3) which specifies that the string is null terminated.

Perhaps a more interesting example is the section that shows exactly what SQL was executed (this is the section I was interested in to hopefully solve my problem):

php-cgi         1b3c-1420    ENTER SQLExecDirectW
                HSTMT               0x025F5E00
                WCHAR *             0x016024A0 [      -3] "RESTORE DATABASE TestDB FROM DISK = 'C:\Backups\TestDB_Backup.bak' WITH RECOVERY\ 0"
                SDWORD                    -3

php-cgi         1b3c-1420    EXIT  SQLExecDirectW  with return code 1 (SQL_SUCCESS_WITH_INFO)
                HSTMT               0x025F5E00
                WCHAR *             0x016024A0 [      -3] "RESTORE DATABASE TestDB FROM DISK = 'C:\Backups\TestDB_Backup.bak' WITH RECOVERY\ 0"
                SDWORD                    -3
                DIAG [01000] [Microsoft][SQL Server Native Client 10.0][SQL Server]Processed 168 pages for database 'TestDB', file 'TestDB' on file 1. (4035)

From this, I can see that SQLExecDirectW (the Unicode version of SQLExecDirect) is used to execute my query, the exact query that was executed (RESTORE DATABASE TestDB FROM DISK = 'C:\Backups\TestDB_Backup.bak' WITH RECOVERY), that it executed successfully (EXIT  SQLDriverConnectW  with return code 1 (SQL_SUCCESS_WITH_INFO)), and the message returned by the server (Processed 168 pages for database 'TestDB', file 'TestDB' on file 1).

Unfortunately, this didn’t give me insight into my particular problem (more info below), but it definitely was interesting to see what was happening a little farther down the stack that the sqlsrv driver sits on. I’d be interested to know if anyone who is reading this post has had occasion to use the ODBC tracing functionality and what you used it for. And, of course, if you use it after reading this post, I’d like to hear that story too.

Hope this was helpful, or at least interesting.

Thanks.

-Brian

*I found that when I issued a RESTORE DATABASE…WITH RECOVERY statement from PHP my query seemed to execute without any errors, but the database was still left in the “restoring” state (i.e. the database was never “recovered” and was left in an unusable state). When the same query was issued from SQL Server Management Studio, it executed successfully and “recovered” the database as expected. I didn’t see anything in the trace file that indicated a problem at the ODBC level. I’m talking to the teams responsible for the PHP and ODBC drivers to find out if there is a bug that I can’t see, or if this is just “user error.” When I find out, I’ll blog about it.

Share this on Twitter