FreeTDS Development Group

[Stefano Coletta <s.coletta AT uni.it>]

James K. Lowden wrote:

> On Fri, 09 Jan 2004, Stefano Coletta <s.coletta AT uni.it> wrote:
>  
>
> > Lowden, James K wrote:
> > 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.  
> >    
As you guessed I don't know why it returns three replies :(

>  
>
> > 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....
>  
Here it is the update trigger from Micro$oft :)

create trigger upd_0237C092D1BD4D6994046F96544217FB on [dbo].[RADPOOL] 
FOR UPDATE AS    if sessionproperty('replication_agent') = 1 and (select 
trigger_nestlevel()) = 1
      return    /* Declare variables */

  declare @article_rows_updated int
  select @article_rows_updated = count(*) from inserted
  declare @contents_rows_updated int, @updateerror int
  declare @bm varbinary(500), @missingbm varbinary(500), @lineage 
varbinary(255), @cv varbinary(2048)
  declare @tablenick int, @nick int, @ccols int, @partchange int, 
@joinchange int
  declare    @partchangebm varbinary(500), @joinchangebm varbinary(500)
  declare @oldmaxversion int
        set nocount on
  set @tablenick = 6522002      select @oldmaxversion= 
maxversion_at_cleanup from dbo.sysmergearticles where nickname = @tablenick
    /* Use intrinsic funtion to set bits for updated columns */
  set @bm = columns_updated()

  /* only do the map down when needed */
  set @missingbm = 0x00
      set @partchangebm = 0x00
      set @joinchangebm = 0x00
          if update([rowguid])
          begin
          if @@trancount > 0
              rollback tran
                        RAISERROR (20062, 16, -1)
          end
              
  /* See if the partition might have changed */
  if @partchangebm = 0x0
      set @partchange = 0
  else
      set @partchange= { fn INTERSECTBITMAPS (@bm, @partchangebm) }
    /* See if a column used in a join filter changed */
  if @joinchangebm = 0x0
      set @joinchange = 0
  else
      set @joinchange= { fn INTERSECTBITMAPS (@bm, @joinchangebm) }
   execute master..xp_mapdown_bitmap 0x0001, @bm output

  exec dbo.sp_MSgetreplnick @nickname = @nick output
  select @ccols = 9                  set @lineage = { fn 
UPDATELINEAGE(0x0, @nick, @oldmaxversion+1) }
          set @cv = { fn INITCOLVS(@ccols, @nick) }
          if (@@error <> 0)
              begin
              goto FAILURE
              end
          set @cv = { fn UPDATECOLVBM(@cv, @nick, @bm, @missingbm, { fn 
GETMAXVERSION(@lineage) }) }
          
  update ctsv_0237C092D1BD4D6994046F96544217FB
  set lineage = { fn UPDATELINEAGE(lineage, @nick, @oldmaxversion+1) },
      generation = A.gen_cur,
      joinchangegen = case when (@joinchange = 1) then A.gen_cur else 
joinchangegen end,
      partchangegen = case when (@partchange = 1) then A.gen_cur else 
partchangegen end,
                    colv1 = { fn UPDATECOLVBM(colv1, @nick, @bm, 
@missingbm, { fn GETMAXVERSION({ fn UPDATELINEAGE(lineage, @nick, 
@oldmaxversion+1) }) }) }    FROM inserted as I JOIN 
ctsv_0237C092D1BD4D6994046F96544217FB as V
  ON (I.rowguidcol=V.rowguid)
  and V.tablenick = @tablenick
  JOIN (select top 1 nickname, gen_cur = isnull(gen_cur, 0) from 
dbo.sysmergearticles where nickname = @tablenick) as A
  ON V.tablenick = A.nickname

  select @updateerror = @@error, @contents_rows_updated = @@rowcount
       if @article_rows_updated <> @contents_rows_updated
  begin

      insert into ctsv_0237C092D1BD4D6994046F96544217FB (tablenick, 
rowguid, lineage, colv1, generation, partchangegen, joinchangegen)
          select @tablenick, rowguidcol, @lineage, @cv, A.gen_cur,
          case when (@joinchange = 1 or @partchange = 1) then A.gen_cur 
else NULL end,
          case when @joinchange = 1 then A.gen_cur else NULL end
          from inserted,
          (select top 1 nickname, gen_cur = isnull(gen_cur, 0) from 
dbo.sysmergearticles where nickname = @tablenick) as A
          where rowguidcol not in (select rowguid from 
ctsv_0237C092D1BD4D6994046F96544217FB where tablenick = @tablenick)

      if @@error <> 0
          GOTO FAILURE
  end


  return
FAILURE:
              if @@trancount > 0
                  rollback tran
              raiserror (20041, 16, -1)
              return
               

I think you have a similar one on another replicated database table.

> 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.  
>  
I'm glad of this :) As always, if you need other infos just let me know.

Good luck!

> Regards, 
>
> --jkl
> _______________________________________________
> FreeTDS mailing list
> FreeTDS AT lists.ibiblio.org
> http://lists.ibiblio.org/mailman/listinfo/freetds
>  
--
Stefano Coletta

Unidata S.p.a.
Via Portuense, 1555 - 00050 Roma ( Ponte Galeria )
Italy

Tel +39 06650951
Fax +39 0665095002
E-mail s.coletta AT uni.it

http://www.mindcreations.com