FreeTDS Development Group

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

On Tue, 31 Dec 2002 16:48:27 +0100, Daniel Schwager
<Daniel.Schwager AT dtnet.de> wrote:
> James K. Lowden freetds AT lists.ibiblio.org  wrote:
> > Daniel, 
> > 
> > Perhaps in certain cases the output coming back from the server
> > confuses FreeTDS.  The DBI traces don't have enough detail to make
> > that clear.  
> 
> > Please turn on the FreeTDS log (TDSDUMP) and post the last 500 lines
> > or so(for a failed case).  If there's a protocol-level problem, it
> > will show up there.  
> 
> Hallo James,
> 
> you asked for some DUMP-Files ....

Hello Daniel, 

I don't know what's wrong.  There might be some sort of race condition. 
Let me tell you what I've found out so far.  

You're using TDS 8.0.  Your query returns three columns and about 113
rows.  The datatypes of the result set are:

        81  ->  TDS 7 result set token
        ==      ======================
        03 00   3 columns
[column 1]
        00 00 08 00 (not deciphered)
        a7      type a7 (XSYBVARCHAR)
        19 00   25 bytes (0x19) wide
        07      its name is 7 characters long
        5400 4100 5300 4b00 4b00 4500 5900
                "TASKKEY"
[column 2]
        00 00 08 00  (not deciphered)
        a7      type a7 (XSYBVARCHAR)
        19 00   25 bytes (0x19) wide
        0b      its name is 11 characters long
        5200 4500 5300 4f00 5500 5200 4300 4500 4b00 4500 5900 
                "RESOURCEKEY"
[column 3]
        00 00 09 00  (not deciphered, but different)
        6d      type 6d (SYBFLTN) [no size offered]
        08      8 bytes wide
        00      its name is 0 characters long
+++             

In Case #1, line 1775, you issue an update statement:

        "update distInfo set OriginalUnits = '0',  ActualUnits = '75' where
PROJECTID = ' 02061301' AND TASKKEY = 'EL' AND RESOURCEKEY = 'cg' AND
START1 = 'NOV 25 2002 12:00AM'"

That succeeds, returns no rows (of course), and you issue a ct_cancel()
(AFAICT needlessly).  You then issue your select-group-by query, returning
the above result set.  In ct_results(), process_result_tokens() returns
type 4043 (TDS_STATUS_RESULT).  

One peculiar thing about the result set processing is that the server
returns four consecutive TDS_RETURNSTATUS_TOKEN (0x79) tokens.  The log
shows only one.  

The log ends abruptly inside ct_describe at 12:31:09.506727.  That's very
odd.  It looks like your program stopped without closing down the database
connection.  

In Case #2, I don't see the same query.  The last query you send is: 

        "select RemainingUnits from distInfo where PROJECTID = '02061301' AND
TASKKEY = '93' AND RESOURCEKEY = 'dts' AND START1 = 'DEC 30 2002 12:00AM'"

but it returns zero rows.  You issue ct_cancel() and close out the session
normally.  

In Case #3, the situation is more like Case 1.  You issue the update
statement, followed by the extraneous cancel, followed by the group-by
query.  The results arrive.  Before you process the results, however, you
issue a ct_cancel() on line 835:  


2002-12-31 12:26:04.714891 inside ct_cancel()
Sending packet @ 2002-12-31 12:26:04.714951
0000  06 01 00 08 00 00 01 00                            |........|

I don't know if that's significant; the log is mute about what type of
cancel was sent or what the consequence was.  We make a left turn here,
though:  The result set is then processed by tds_process_default_tokens()
instead of process_result_tokens().  I doubt the result set is returned
the (perl) client; the data from the server are being parsed while
awaiting an acknowledgement of the cancel request.  Finally...

2002-12-31 12:26:04.762641 inside tds_process_end() more_results = 0,
was_cancelled = 1 
2002-12-31 12:26:04.765029 inside ct_close()
2002-12-31 12:26:04.765229 inside ct_con_drop()

...the server acknowledges the cancel request, and you close the session. 


+++

I think it is result processing that is having problems.  Based on the DBD
trace in your first message, I'd say there's some confusion between us and
DBD::Sybase about the output of ct_res_info().   Maybe we've changed the
width of the column count, or something.  The log clearly shows three
columns coming back, never anything like 15704.  If DBD::Sybase walks off
the end looking for column #4, it's bound to do something silly.  

The cancel processing is making things a little too interesting.  I'll put
some more stuff in the the log for ct_cancel().  Cancel processing is not
our strength; it's poorly understood by application programmers and has
changed over the years.  

We should change the name of TDS_RETURNSTATUS_TOKEN and/or its
documentation in doc/tds.html.  The latter says it's the "return value of
a stored procedure".  Ain't necessarily so.  Seems W2K servers send lots
of them whenever they feel like it.  

I would focus your attention on two things.  One, your application
shouldn't issue a cancel after every query, and it looks like there might
be a sychronization issue where sometimes you're cancelling results you
mean to read.  Two, try to isolate the 15704 column problem.  See if you
can reduce it to one query.  Perhaps I can log the output of
ct_res_info(), to help expose where perl's confusion stems from.  

--jkl


> 
> /etc/freetds.conf:
>         dump file = /var/log/freetds.log
>         debug level = 10
> 
> Here we are (-: 3 x Attachments )
> 
> regards
> Danny
> 
> 
> 
> - Die 31.12.2002 12:21, danny
> 
> ***** CASE 2:
> *stdout:
> Query: select RemainingUnits from distInfo where PROJECTID = '02061301'
> AND TASKKEY = '93' AND RESOURCEKEY = 'dts' AND START1 = 'DEC 30 2002
> 12:00AM' ct_res_info() returned 0 columns at
> /usr/lib/perl5/site_perl/5.005/i586-linux/DBI.pm line 1253.
> dbih_setup_fbav: invalid number of fields: -29744, NUM_OF_FIELDS
> attribute probably not set right at
> /usr/lib/perl5/site_perl/5.005/i586-linux/DBI.pm line \ 1577.
> 
> * FAILED
> FREETDS-Dump:
> Attachment: freetdsdump-case2.txt
> 
> 
> ***** CASE 3:
> *stdout
> sql: select TASKKEY, RESOURCEKEY, SUM(ActualUnits) from distInfo  where
> PROJECTID = '02061301'  group by TASKKEY, RESOURCEKEY ct_res_info()
> returned 0 columns at sdi_control_sdi2ps8.pm line 195. go 1
> dbih_setup_fbav: invalid number of fields: -400, NUM_OF_FIELDS attribute
> probably not set right at sdi_control_sdi2ps8.pm line 202.
> 
> *FAILED
> Attachment: freetdsdump-case3.txt
> 
> 
> ***** CASE 1:
> *stdout
> sql: select TASKKEY, RESOURCEKEY, SUM(ActualUnits) from distInfo  where
> PROJECTID = '02061301'  group by TASKKEY, RESOURCEKEY
> Speicherzugriffsfehler
> 
> *FAILED
> Attachment: freetdsdump-case1.txt
> 
> 
>