v-makouz
commented
5 months ago Can you provide ODBC trace? Hopefully it'll have something more helpful there to explain what error is actually happening
Open redclov3r opened 5 months ago
v-makouz
commented
5 months ago Can you provide ODBC trace? Hopefully it'll have something more helpful there to explain what error is actually happening
redclov3r
commented
5 months ago Yes of course:
[...]
[ODBC][2224273][1718694304.812055][SQLSetEnvAttr.c][192]
Entry:
Environment = 0x558713540e80
Attribute = SQL_ATTR_ODBC_VERSION
Value = 0x3
StrLen = -6
[ODBC][2224273][1718694304.812066][SQLSetEnvAttr.c][384]
Exit:[SQL_SUCCESS]
[ODBC][2224273][1718694304.812077][SQLSetEnvAttr.c][192]
Entry:
Environment = 0x558713540e80
Attribute = SQL_ATTR_CONNECTION_POOLING
Value = 0x2
StrLen = -5
[ODBC][2224273][1718694304.812088][SQLSetEnvAttr.c][384]
Exit:[SQL_SUCCESS]
[ODBC][2224273][1718694304.816088][SQLAllocHandle.c][469]
Entry:
Handle Type = 2
Input Handle = 0x55871351df30
[ODBC][2224273][1718694304.816116][SQLAllocHandle.c][585]
Exit:[SQL_SUCCESS]
Output Handle = 0x558713568340
[ODBC][2224273][1718694304.816183][SQLSetConnectAttr.c][399]
Entry:
Connection = 0x558713568340
Attribute = 1400
Value = 0x2
StrLen = -4
[ODBC][2224273][1718694304.816201][SQLSetConnectAttr.c][716]
Exit:[SQL_SUCCESS]
[ODBC][2224273][1718694304.816272][SQLDriverConnectW.c][298]
Entry:
Connection = 0x558713568340
Window Hdl = (nil)
Str In = [Server={[warehouse-id].datawarehouse.fabric.microsoft.com};UID={[my-username]};PWD...][length = XXX]
Str Out = (nil)
Str Out Max = 0
Str Out Ptr = 0x7fffd815b19a
Completion = 0
Threading Level set from Driver Entry in ODBCINST.INI 99 from '99'
Threading Level set from [ODBC] Section in ODBCINST.INI 0 from '0'
UNICODE Using encoding ASCII 'UTF-8' and UNICODE 'UCS-2LE'
[ODBC][2224273][1718694304.944901][__handles.c][493]
Exit:[SQL_SUCCESS]
Environment = 0x5587135d5d30
[ODBC][2224273][1718694304.944955][SQLGetEnvAttr.c][157]
Entry:
Environment = 0x5587135d5d30
Attribute = 65002
Value = 0x7fffd8155bb0
Buffer Len = 128
StrLen = 0x7fffd8155b4c
[ODBC][2224273][1718694304.944975][SQLGetEnvAttr.c][273]
Exit:[SQL_SUCCESS]
[ODBC][2224273][1718694304.944994][SQLFreeHandle.c][225]
Entry:
Handle Type = 1
Input Handle = 0x5587135d5d30
[ODBC][2224273][1718694304.945036][SQLDriverConnectW.c][870]
Exit:[SQL_ERROR]
[ODBC][2224273][1718694304.945061][SQLGetDiagRecW.c][535]
Entry:
Connection = 0x558713568340
Rec Number = 1
SQLState = 0x7fffd815a814
Native = 0x7ff7efa016f0
Message Text = 0x7fffd815a820
Buffer Length = 1025
Text Len Ptr = 0x7fffd815a7fc
[ODBC][2224273][1718694304.945081][SQLGetDiagRecW.c][596]
Exit:[SQL_NO_DATA]
[ODBC][2224273][1718694304.945132][SQLFreeHandle.c][324]
Entry:
Handle Type = 2
Input Handle = 0x558713568340I omitted the first ~600 lines of calls to SQLSetEnvAttr.c, setting SQL_ATTR_ODBC_VERSION and SQL_ATTR_CONNECTION_POOLING as well as calls to SQLFreeHandle.c here. You can find the complete log for the above PHP-script below:
v-makouz
commented
5 months ago Thank you, I'm looking through it now. One more question: what version of unixODBC is on this machine?
redclov3r
commented
5 months ago Thanks to you, too! The unixODBC version is 2.3.12
v-makouz
commented
5 months ago Not too sure why it's not giving a proper error yet, but can I see ODBC trace for the successful case (sqlcmd)? It must be doing something different if the connection works there.
redclov3r
commented
5 months ago Yes, surely. This is the trace when running sqlcmd:
$ sqlcmd -S [warehouse-id].datawarehouse.fabric.microsoft.com -U '[my-username]' -G[ODBC][4191667][1718865131.159775][__handles.c][493]
Exit:[SQL_SUCCESS]
Environment = 0x16f3830
[ODBC][4191667][1718865131.159842][SQLSetEnvAttr.c][192]
Entry:
Environment = 0x16f3830
Attribute = SQL_ATTR_ODBC_VERSION
Value = 0x3
StrLen = 0
[ODBC][4191667][1718865131.159923][SQLSetEnvAttr.c][384]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865131.159961][SQLAllocHandle.c][469]
Entry:
Handle Type = 2
Input Handle = 0x16f3830
[ODBC][4191667][1718865131.159998][SQLAllocHandle.c][585]
Exit:[SQL_SUCCESS]
Output Handle = 0x16f7f60
[ODBC][4191667][1718865131.160060][SQLSetConnectAttrW.c][335]
Entry:
Connection = 0x16f7f60
Attribute = 1223
Value = 0x1
StrLen = -5
[ODBC][4191667][1718865131.160095][SQLSetConnectAttrW.c][652]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865131.160151][SQLSetConnectAttr.c][399]
Entry:
Connection = 0x16f7f60
Attribute = SQL_ATTR_LOGIN_TIMEOUT
Value = 0x8
StrLen = 4
[ODBC][4191667][1718865131.160184][SQLSetConnectAttr.c][716]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865131.160219][SQLSetConnectAttrW.c][335]
Entry:
Connection = 0x16f7f60
Attribute = SQL_ATTR_PACKET_SIZE
Value = 0x1000
StrLen = 4
[ODBC][4191667][1718865131.160273][SQLSetConnectAttrW.c][652]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865131.160499][SQLDriverConnectW.c][298]
Entry:
Connection = 0x16f7f60
Window Hdl = (nil)
Str In = [DRIVER={ODBC Driver 18 for SQL Server};SERVER={[warehouse-id].datawarehouse.fabric.micro...][length = XXX (SQL_NTS)]
Str Out = (nil)
Str Out Max = 0
Str Out Ptr = (nil)
Completion = 0
Threading Level set from Driver Entry in ODBCINST.INI 99 from '99'
Threading Level set from [ODBC] Section in ODBCINST.INI 0 from '0'
UNICODE Using encoding ASCII 'UTF-8' and UNICODE 'UCS-2LE'
[ODBC][4191667][1718865139.159007][__handles.c][493]
Exit:[SQL_SUCCESS]
Environment = 0x7fb6bc29c9f0
[ODBC][4191667][1718865139.159089][SQLGetEnvAttr.c][157]
Entry:
Environment = 0x7fb6bc29c9f0
Attribute = 65002
Value = 0x7fb6c11fa8a0
Buffer Len = 128
StrLen = 0x7fb6c11fa83c
[ODBC][4191667][1718865139.159116][SQLGetEnvAttr.c][273]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865139.159138][SQLFreeHandle.c][225]
Entry:
Handle Type = 1
Input Handle = 0x7fb6bc29c9f0
[ODBC][4191667][1718865139.159170][SQLDriverConnectW.c][1090]
Exit:[SQL_SUCCESS_WITH_INFO]
Connection Out [[NULL]]
[ODBC][4191667][1718865139.159277][SQLAllocHandle.c][632]
Entry:
Handle Type = 3
Input Handle = 0x16f7f60
[ODBC][4191667][1718865139.159363][SQLAllocHandle.c][1177]
Exit:[SQL_SUCCESS]
Output Handle = 0x16f93f0
[ODBC][4191667][1718865139.159408][SQLSetStmtAttrW.c][166]
Entry:
Statement = 0x16f93f0
Attribute = SQL_ATTR_QUERY_TIMEOUT
Value = (nil)
StrLen = -5
[ODBC][4191667][1718865139.159433][SQLSetStmtAttrW.c][720]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865139.159574][SQLExecDirectW.c][177]
Entry:
Statement = 0x16f93f0
SQL = [SET QUOTED_IDENTIFIER OFF][length = 25 (SQL_NTS)]
[ODBC][4191667][1718865139.185330][SQLExecDirectW.c][456]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865139.185543][SQLSetStmtAttrW.c][166]
Entry:
Statement = 0x16f93f0
Attribute = SQL_ATTR_QUERY_TIMEOUT
Value = (nil)
StrLen = -5
[ODBC][4191667][1718865139.185638][SQLSetStmtAttrW.c][720]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865139.185796][SQLExecDirectW.c][177]
Entry:
Statement = 0x16f93f0
SQL = [SET TEXTSIZE 4096][length = 17 (SQL_NTS)]
[ODBC][4191667][1718865139.260033][SQLExecDirectW.c][456]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865140.695169][SQLGetConnectAttrW.c][236]
Entry:
Connection = 0x16f7f60
Attribute = 1244
Value = 0x7fffbdc0da9c
Buffer Length = -6
StrLen = 0x7fffbdc0da98
[ODBC][4191667][1718865140.695287][SQLGetConnectAttrW.c][785]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865140.695322][SQLFreeHandle.c][421]
Entry:
Handle Type = 3
Input Handle = 0x16f93f0
[ODBC][4191667][1718865140.695377][SQLFreeHandle.c][524]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865140.695461][SQLDisconnect.c][208]
Entry:
Connection = 0x16f7f60
[ODBC][4191667][1718865140.697275][SQLDisconnect.c][358]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865140.697325][SQLFreeHandle.c][324]
Entry:
Handle Type = 2
Input Handle = 0x16f7f60
[ODBC][4191667][1718865140.697354][SQLFreeHandle.c][373]
Exit:[SQL_SUCCESS]
[ODBC][4191667][1718865140.697379][SQLFreeHandle.c][225]
Entry:
Handle Type = 1
Input Handle = 0x16f3830
Hey @v-makouz, could you find anything that might be a hint to the problem's root? Or any idea what I might try to get there?
v-makouz
commented
5 months ago I wasn't able to reproduce this yet, but one more thing to try is to strace -f the commands to see what they actually call and see if there is any difference between what driver/unixODBC are loaded by the sqlcmd versus the PHP driver.
redclov3r
commented
4 months ago Okay, today I managed to run both commands with strace -f and tried to find the critical point and possible differences in both calls.
TBH, analysing these kind of log files feels a little bit like stumbling in the dark for me, but if I'm not mistaken in the screenshot below is the moment both versions start their connection to the server.
The left one is the successful connection with sqlcmd, the right is the broken PHP version. At the start of it, it looks like both commands are able to resolve the address to an IP, so far so good. The interesting part (at least to me) is around the highlightet lines:
Both commands read some random bytes from /dev/urandom but after receiving something from a socket (recvfrom :grey_question: ) the left side goes on initiating a SSL handshake while the right one just logs into the odbc logfile.
From this, I can't really tell what the problem might be. If you have anything, I'd be glad to hear...
v-makouz
commented
4 months ago Thanks, I'll see if I can figure anything from the screenshot. Any chance I can get these as text files? It would make it easier to search through. The option for a file output is -o, as in strace -f -o logfile.txt sqlcmd....
redclov3r
commented
4 months ago Yes, I'll provide text files tomorrow (these contain a bit more private info, so I'll need to redact a few things). Thank you!
redclov3r
commented
4 months ago I put both logfiles in a gist here: https://gist.github.com/redclov3r/6df35e94899cd22b4f21626efa81b94e
Let me know if there is something that could point me in a direction.
v-makouz
commented
4 months ago Thanks, I'm looking through them now, will let you know what I find
v-makouz
commented
4 months ago Looking at the traces, it appears that the connection failure happens during the start of the login sequence, which is very unusual. To investigate further, could you do a WireShark capture of both cases? That way we can see if the prelogin sequences sent to and received from the server are different between them.
The other thing that could be helpful is BIDTrace, which will give more detailed logging of ODBC driver, so we may be able to narrow down where exactly the failure happens. To enable it in /etc/odbcinst.ini file in the driver section add the following:
[ODBC Driver 18 for SQL Server]
BIDTrace=yes
BIDTraceFile=/path/to/file.txt
BIDTraceFileSize=10485760
...Size is in bytes, the actual files that will be created will be called file1.txt, file2.txt etc. But in this case there shouldn't be more then one
redclov3r
commented
4 months ago Good news for once... By capturing the connection sequence with WireShark and comparing the captures, I finally found the one minor - but obviously significant - difference between the two!
Both captures showed TCP packets for a pre-login request, after which the PHP version just stopped and the sqlcmd kept on with doing SSL handshake, login, etc. I then exported both captures to textfiles to compare them line by line with vimdiff and the only meaningful difference (apart from timestamps, sequencenumbers and so on) was this:
Option: MARS
Option Token: MARS (4)
Option offset: 48
Option length: 1
MARS: On (1)The php-mssql connection had MultipleActiveResultSets=1 while sqlcmd had MultipleActiveResultSets=0. I never set this manually so this must be the default values.
After setting it to false in PHP the connection finally just worked...
While my main issue seems to be resolved there are a few questions left:
In any case: Thank you very much for your effort on resolving this. Much appreciated!
v-makouz
commented
4 months ago Great! In retrospect it makes sense, since data warehouse doesn't support MARS and it's on by default in PHP driver. But the lack of a clear error makes it difficult to figure out. I will be looking at the docs to add this for sure, as this is a very unintuitive issue otherwise.
PHP version: 8.3.8 PHP SQLSRV or PDO_SQLSRV version 5.12.0 Microsoft ODBC Driver version 18.3.3.1-1 Client operating system Fedora Linux
Problem description
I am trying to connect to an SQL-Endpoint of a DataWarehouse / -Lakehouse which is running inside of Microsoft Fabric. The connection works as expected when using DBeaver (which uses JDBC internally) and also with
sqlcmd.When I try to establish the same connection with
sqlsrv_connectin PHP, I get the following behavior:This fails almost instantly and without any hint of the possible error. I enabled logging for SQLSRV and all I get is
sqlsrv_connect: enteringand immediately after that thevar_dump($conn)returning false.By now, I've found out that as soon as I add an instancename, like:
the command will try to connect for ~15 seconds and then fail with one of these two errors:
TCP Provider: Error code 0x2AF9MAX_PROVS: Error Locating Server/Instance Specified [xFFFFFFFF]Since I don't know the instance name (if there is one) this doesn't really help me that much.
Expected behavior and actual behavior
I expect the
sqlsrv_connectcommand to at least try to connect to the given server URL, even when there is no instance specified. Furthermore I would expect some kind of error message detailing why the function returnedfalse.