FreeTDS Development Group

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

On Fri, 09 Jan 2004, Stefano Coletta <s.coletta AT uni.it> wrote:
> Lowden, James K wrote:
> 
> >>I'm almost sure to have found a bug in the freetds lib (even 0.62rc3) 
> >>that occurs only when I try to do an update or delete against 
> >>Microsoft 
> >>SQL Server 2000 SP3a while the database is in Merge Replication. The 
> >>problem arises when I try to read the "rows affected" property which 
> >>returns always -1 instead of the correct number of affected 
> >>rows. 
> >>    
> >If you could, please post a TDSDUMP log of the failed transaction, so
> >we can analyze the packets.  I assume you're using TDS 7.0 or 8.0, for
> >which the log will not contain the login packet, so you don't have to
> >worry about exposing username/password information.  Please keep the
> >session as brief as possible.  
> >
> >If the log is too large to post (>75 KB), it's better to make it
> >available on a website.  But if you can't do that, post it anyway, and
> >I'll release it.  It won't be *too* much bigger than that.  That can
> >mean a delay of some hours, however.   
> >  
> >
> Here they are. I've gzipped the files so they are very small.

Yes, you've found a bug.  Definitely a post-release issue, and a hard one,
IMO.  Thank you for the logs.  

The issue afaik isn't so much that one server is replicated, as one of how
it responds to your update statement.  I can't explain what I'm seeing. 
Let me parse the log for you, and show you what I mean.  

  ========

The good one, freetds.log.ok:

Received packet @ 2004-01-08 20:06:13.782263
0000  fd                <= TDS_DONE
         10 00          <= 0x0010, done count valid 
               c5 00    <= transaction state ??
                     01 00 00 00 <= 0x0001 row affected
                     
The transaction state should be between 0 and 5, not 0xC5.  Microsoft
evidently
uses different values, which we apparently half-understand; there's a bit
of
weirdness in tds_process_end(): 

        /* ignore error calling RAISERROR */
        if (TDS_IS_MSSQL(tds) && state == 0xf6)
                tmp &= ~TDS_DONE_ERROR;

Interesting to note, by the way, that your log reflects an unimplemented
ct_options call, one that's related to transactions:

2004-01-08 20:06:13.727183 ct_option: UNIMPLEMENTED 7

>From include/cspublic:

#define CS_OPT_CHAINXACTS       7

However, I doubt this matters.  IIRC, ct_options in 0.61.2 returned
CS_SUCCEED
all the time, and chained transactions are the default, so CS_SUCCEED was
accurate, even if accidentally.  

Anyway, the good log shows a normal TDS_DONE message, with 1 row affected.
 

  ========

The bad one, freetds.log.debug:

Received packet @ 2004-01-08 19:52:58.992128
0000  ff                <= TDS_DONEINPROC  
         01 00          <= 0x0010, done count valid 
               c0 00    <= transaction state 0x00c0 ?? (OK....)
                     00 00 00 00 <= zero rows affected
                     
      ff                <= TDS_DONEINPROC  
         11 00          <= 0x0011, done count valid, more coming 
               c1 00    <= transaction state 0x00c1 ?? (OK....)
                     01 00 00 00 <= 0x0001 row affected
 
      ff                <= TDS_DONEINPROC   
         01 00          <= 0x0010, done count valid  
               00 00    <= transaction state zero
                     00 00 00 00  <= zero rows affected

      79                <= TDS_RETURNSTATUS   
         00 00 00 00    <= procedure returned zero
         
0020  fd                <= TDS_DONE
         10 00          <= 0x0010, done count valid 
               c5 00    <= transaction state ??
                     00 00 00 00   <= zero rows affected       

  ========

Not quite the same, you know?  ;-)

First, you tell me how an UPDATE statement results in not one but three
"done in
proc" responses (when no procedure was invoked).  Then I'll tell you we
don't
expect that response for an UPDATE, and that's why our code falls down and
gives
you a -1 rows affected.  We don't manage, it would seem, to notice that
the
second "done in proc" indicates there was one row affected.  And to tell
the
truth, we don't know enough about how this is supposed to work to get it
right. 
:-(  Say I.  Maybe someone else knows better.  

Bill Thompson and Frediano have done most of the work lately decoding the
stream.  In working with cursors and dynamic SQL, they've seen some
oddball responses from the server, and they might well have some light to
shed.  Me?  I just fill your screen with words to keep your eyes busy.  

This is a hard one to do correctly.  We don't know you sent an UPDATE, we
just parse the server's responses.  It's totally unclear to me how we're
expected to divine that the second DONEINPROC carries good rows-affected
information, and to ignore the last TDS_DONE, which says no rows were.  

Peter says it might be triggers, which makes very good sense.  IF triggers
always react this way, and produce a reliable stream of DONEINPROC
messages that carry predictable rows-affected information, then maybe
maybe we have a shot at this.  But I know triggers can be nested and
chained and even IIRC recursive nowadays.  

I even tried a trivial trigger:

> create table t (t int not null)
> go
>       create trigger tup on t for update 
        as 
        select * from inserted
> go
> insert t values (1)
> go
(1 row affected)
> update t set t=2 where t=1
> go
 t          
 -----------
           2

(1 row affected, return status = 0)

The packet?  

Received packet @ 23:05:45.709557
0000 81 01 00 00 00 08 00 38-01 74 00 d1 02 00 00 00
0010 ff 11 00 c1 00 01 00 00-00 79 00 00 00 00 fd 10
0020 00 c5 00 01 00 00 00   -                       

Briefly: TDS7_RESULT, ROW, DONEINPROC (1 row affected), RETURNSTATUS, DONE
(1 row affected).  I guess we got lucky; the DONE message carries the
right answer.  

So, it's not merely triggers, but perhaps it's your particular
triggers....

For the record, there is one distinguishing mark on your second
DONEINPROC: the TDS_DONE_MORE_RESULTS bit (0x01) set in the status word. 
Obviously, I don't know if that's a reliable marker for anything, but it
might be a clue.  

Thanks again for the logs.  You've got Peter's attention, always a good
omen.  

Regards, 

--jkl