Re: SQLGetTypeInfo() fails when it is called for the second time

Hello James,

Thank you very much for the extensive analysis of the log file, I sent
you. Since I have already found the temporary workaround, which I
mentioned in my previous post, I will use it for the time being and
consider the problem solved.

Thanks,
Marko


JKL> It appears that FreeTDS is violating the TDS protocol.  

JKL> Every call to SQLGetTypeInfo() initiates a query to the server:

JKL>         EXEC sp_datatype_info ...

JKL> The problem is that the packet header of each query has the "last packet"
JKL> flag set ON e.g.:

JKL> 15:42:07.350941 3197 (net.c:779):Sending packet
JKL> 0000 01 01 00 3c 00 00 01 00-20 00 45 00 58 00 45 00 |...<....  .E.X.E.|
JKL>         ^^ last packet flag == 1

JKL> Rules of the game are that after the client sends the last packet (so
JKL> marked) of the query, it must read the results from the server until a
JKL> DONE packet arrives.  Instead, your log shows 47 consecutive "last" writes
JKL> with no intervening reads:   

JKL> $ grep packet$ logs/18707/freetds.log | awk '{print $3, $4}' | uniq -c
JKL>    1 (login.c:735):quietly sending
JKL>    1 (net.c:671):Received packet
JKL>    1 (net.c:779):Sending packet
JKL>    1 (net.c:671):Received packet
JKL>   47 (net.c:779):Sending packet

JKL> Eventually the server gives up and disconnects.  I'm surprised it's so
JKL> patient. 

JKL> What's odd is that afaict you issued only *one* call to SQLGetTypeInfo: 

JKL> $ awk -F'[:(]' '/:SQL/ {print $6}' logs/18707/freetds.log  | uniq -c
JKL>    3 SQLGetInfo
JKL>    1 SQLAllocHandle
JKL>    4 SQLGetStmtAttr
JKL>   11 SQLGetInfo
JKL>    1 SQLSetStmtAttr
JKL>    2 SQLGetInfo
JKL>    8 SQLBindCol
JKL>    1 SQLGetTypeInfo
JKL>    2 SQLGetDiagRec
JKL>    2 SQLFreeStmt

JKL> Correct use of SQLGetTypeInfo is to fetch the results produced after each
JKL> call to it.  If you do that, it should work fine.  Trouble is, it seems
JKL> you *did* do that, but the driver wound up issuing the same query 47
JKL> times.  Based on the log, it appears the bug is somewhere in _SQLExecute
JKL> or functions it calls:

JKL> $ awk -F'[:(]' '/:_*SQL/ {print $6}' logs/18707/freetds.log  | uniq -c |
JKL> sed -ne '/Bind/,$p'
JKL>    8 SQLBindCol
JKL>    1 SQLGetTypeInfo
JKL>    2 _SQLExecute
JKL>    1 SQLGetDiagRec
JKL>    1 _SQLGetDiagRec
JKL>    1 SQLGetDiagRec
JKL>    1 _SQLGetDiagRec
JKL>    1 SQLFreeStmt
JKL>    1 _SQLFreeStmt
JKL>    1 SQLFreeStmt
JKL>    1 _SQLFreeStmt

JKL> $ grep _SQLExecute logs/18707/freetds.log
JKL> 15:42:07.344114 3197 (odbc.c:2965):_SQLExecute(0x208fe0)
JKL> 15:42:07.344130 3197 (odbc.c:2970):_SQLExecute() starting with state 0

JKL> _SQLExecute never produces a log message indicating it's fetching results
JKL> ("_SQLExecute: odbc_process_tokens returned result_type....").  Because it
JKL> contains no loop, the likely culprits are the tds_submit* functions.  

JKL> That's all I've got.  

JKL> HTH.