FreeTDS Development Group

[Frediano Ziglio <freddy77 AT gmail.com>]

Il giorno gio, 28/02/2008 alle 13.18 -0500, James K. Lowden ha scritto:
> 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, 
> 

Looking at

10:08:32.852823 2698 (net.c:739):Sending packet
0000 03 01 00 2e 00 00 01 00-ff ff 07 00 02 00 00 00 |........ ........|
0010 26 04 04 f0 de bc 0a 00-00 26 04 04 02 00 00 00 |&....... .&......|
0020 00 00 26 04 00 00 00 26-04 04 00 00 00 00       |..&....& ......|

10:08:32.852884 2698 (token.c:495):tds_process_tokens(0x8021b7e8, 0xbfc644c4, 
0xbfc644c0, 0x6d00)
10:08:32.852900 2698 (util.c:162):Changed query state from PENDING to READING
10:08:32.853500 2698 (net.c:547):Received header
0000 04 01 00 a1 00 45 01 00-                        |.....E..|

10:08:32.853525 2698 (net.c:626):Received packet
0000 aa 88 00 06 42 00 00 07-10 3a 00 73 00 70 00 5f |....B... .:.s.p._|
0010 00 63 00 75 00 72 00 73-00 6f 00 72 00 66 00 65 |.c.u.r.s .o.r.f.e|
0020 00 74 00 63 00 68 00 3a-00 20 00 54 00 68 00 65 |.t.c.h.: . .T.h.e|
0030 00 20 00 76 00 61 00 6c-00 75 00 65 00 20 00 6f |. .v.a.l .u.e. .o|
0040 00 66 00 20 00 70 00 61-00 72 00 61 00 6d 00 65 |.f. .p.a .r.a.m.e|
0050 00 74 00 65 00 72 00 20-00 27 00 6e 00 72 00 6f |.t.e.r.  .'.n.r.o|
0060 00 77 00 73 00 27 00 20-00 69 00 73 00 20 00 69 |.w.s.'.  .i.s. .i|
0070 00 6e 00 76 00 61 00 6c-00 69 00 64 00 2e 00 04 |.n.v.a.l .i.d....|
0080 45 00 52 00 50 00 37 00-00 01 00 79 01 00 00 00 |E.R.P.7. ...y....|
0090 fe 10 00 e0 00 00 00 00-00                      |........ .|

sp_cursorfetch don't like 0 as nrows... I agree.

sp_cursorfetch is issued in _SQLFetch called by SQLExtendedFetch which
override (corretcly) row numbers (stmt->ard->header.sql_desc_array_size
in SQLFetch) with stmt->sql_rowset_size. The problem is that
stmt->sql_rowset_size is initialized as SQL_BIND_BY_COLUMN while should
be initialized with 1... I think also that stmt->sql_rowset_size cannot
be <1.

I think that replacing

    /* is not the same of using APD sql_desc_bind_type */
    stmt->sql_rowset_size = SQL_BIND_BY_COLUMN;

with 

    stmt->sql_rowset_size = 1;

should fix the problem (I know, comment remove is not necessary... but
it's wrong :) )

Here is too late to test this issue... good night! 

freddy77