FreeTDS Development Group

["James K. Lowden" <jklowden AT freetds.org>]

Robin Smith wrote:
> > It might be time for more detailed information.  A TDSDUMP log will
> > show what calls are being made to the ODBC driver and what happens
> > next.   Maybe in conjunction with the ODBC trace that will reveal
> > something.  
>  
> Here are the logs.

There are a few differences, and IMO a minor error in odbc.c.  It looks
like the problem stems either from differences in the query or in the TDS
version.  There's a mysterious error toward the end of the PHP log.  

I generated a diff on your logs, stripped of timestamps and memory
addresses:

        $ for F in php isql; do perl -pe 's/^\d\d:\d\d:\d\d\.\d+ \d{4}//g;
s/0x[[:xdigit:]]{6,8}/{addr}/g;' freetds.$F.log  > $F; done; diff -u php
isql  | less -S

That lets us look at the real differences.  The first one is here:

--- php 2008-02-28 11:39:20.000000000 -0500
+++ isql        2008-02-28 11:39:20.000000000 -0500
...
@@ -7,14 +7,14 @@
  (iconv.c:363):iconv to convert client-side data to the "ISO-8859-1"
character
  (iconv.c:516):tds_iconv_info_init: converting "ISO-8859-1"->"UCS-2LE"
  (iconv.c:516):tds_iconv_info_init: converting "ISO-8859-1"->"UCS-2LE"
- (net.c:192):Connecting to 172.16.3.146 port 1433 (TDS version 8.0)
+ (net.c:192):Connecting to 172.16.3.146 port 1433 (TDS version 7.0)

With PHP you're running TDS 8.0.  Does the problem go away if you set it
to 7.0?  

That (I believe) leads to differences later e.g.:

- (odbc.c:5533):SQLGetInfo({addr}, 8, {addr}, 4, (nil))
- (odbc.c:4786):_SQLGetInfo({addr}, 8, {addr}, 4, (nil)
- (odbc.c:6157):SQLSetStmtOption({addr}, 6, 2)
- (odbc.c:5875):_SQLSetStmtAttr({addr}, 6, 0x2, -3)
- (odbc.c:3192):SQLExecDirect({addr}, {addr}, -3)
- (odbc.c:2949):_SQLExecute({addr})
- (odbc.c:2954):_SQLExecute() starting with state 0
- (query.c:2053):tds_cursor_declare() cursor id = 0
- (query.c:2103):tds_cursor_open() cursor id = 0
+ (odbc.c:4087):SQLPrepare({addr}, select * from pro , -3)
+ (odbc.c:4151):Creating prepared statement
  (mem.c:563):tds_free_all_results()
  (util.c:162):Changed query state from IDLE to QUERYING
- (query.c:2231):tds_cursor_open (): RPC call set up
- (query.c:2235):tds_cursor_open (): cursor open completed
+ (util.c:162):Changed query state from QUERYING to PENDING
  (net.c:739):Sending packet
-0000 03 01 00 60 00 00 01 00-ff ff 02 00 00 00 00 01 |...`.... ........|
-0010 26 04 00 00 00 63 22 00-00 00 09 04 d0 00 34 22 |&....c". ......4"|
-0020 00 00 00 53 00 45 00 4c-00 45 00 43 00 54 00 20 |...S.E.L .E.C.T. |
-0030 00 2a 00 20 00 46 00 52-00 4f 00 4d 00 20 00 50 |.*. .F.R .O.M. .P|
-0040 00 52 00 4f 00 00 01 26-04 04 02 00 00 00 00 01 |.R.O...& ........|
-0050 26 04 04 01 20 00 00 00-01 26 04 04 00 00 00 00 |&... ... .&......|
+0000 03 01 00 68 00 00 01 00-0a 00 73 00 70 00 5f 00 |...h.... ..s.p._.|
+0010 70 00 72 00 65 00 70 00-61 00 72 00 65 00 00 00 |p.r.e.p. a.r.e...|
+0020 00 01 26 04 00 00 00 63-00 00 00 00 ff ff ff ff |..&....c ........|
+0030 00 00 63 24 00 00 00 24-00 00 00 73 00 65 00 6c |..c$...$ ...s.e.l|
+0040 00 65 00 63 00 74 00 20-00 2a 00 20 00 66 00 72 |.e.c.t.  .*. .f.r|
+0050 00 6f 00 6d 00 20 00 70-00 72 00 6f 00 20 00 00 |.o.m. .p .r.o. ..|
+0060 00 26 04 04 01 00 00 00-                        |.&......|

where PHP executes SELECT while isql executes a prepared statement.  

Things diverge pretty far after that.  

I was fooled by these "errors" from the server:

  (odbc.c:2022):msgno 5703 20003

Freddy, this is a mistake in odbc.c.  It's not a 20003 TDSETIME error, as
line 2022 says:

        tdsdump_log(TDS_DBG_INFO1, "msgno %d %d\n", (int) msg->msgno,
TDSETIME);

It's just "Changed language setting to [foo].".

But PHP shows shows a real error, after which it stops sending anything:

- (odbc.c:2022):msgno 16902 20003

Message 16902 is "%hs: The value of parameter %hs is invalid."  

I don't know what that means. I did find this, but you said you're running
2000, not 7:  

http://support.microsoft.com/kb/252865

Conclusions:

1.  It might be something in the way TDS 8.0 is handled.  

2. Your application should report errors such as 16902.  Not sure why that
didn't turn up before. 

3.  odbc.c shouldn't log all errors as timeout messages.  

I think you discovered a bug.  Sorry I couldn't spot the actual real
problem.  Hope I got you and Frediano a little closer to its resolution. 
Thanks for the detailed problem report and for posting the logs.  

Regards, 

--jkl