Working Down the Stack: Enabling ODBC Tracing with the SQL Server Driver for PHP
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 -3php-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.