FreeTDS Development Group

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

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. 
> >    
> ... 
>  
>
> > I've tested the Rows Affected property in Microsoft Access 
> > Visual Basic 
> > with an ADP project and it behaves correctly returning proper values.
> >    
>
> (Do you mean ADO?)
>  
No, I mean ADP: Access Data Project, a special M$ Access file that 
permits you to connect easily with SQL Server.

This is the VB code I used to make the test:

Public Function Test()

Dim m_oRecordset As ADODB.Recordset

Dim oConnection1 As ADODB.Connection
Dim affected As Long
Set oConnection1 = New ADODB.Connection

' m_sConnStr = "Provider='SQLOLEDB';Data Source='DBNAME-NOREPLICA';" & _
'             "Initial Catalog='test'; " & _
'             "User ID='sa';Password='******';"

m_sConnStr = "Provider='SQLOLEDB';Data Source='DBNAME-WITHREPLICA';" & _
            "Initial Catalog='test'; " & _
            "User ID='sa';Password='******';"

oConnection1.Open (m_sConnStr)


Set m_oRecordset = New ADODB.Recordset

'sSQL = "update radonline set v_username='test' where v_username='oldtest'"
sSQL = "update radonline set v_username='oldtest' where v_username='test'"

oConnection1.Execute sSQL, affected

'm_oRecordset.Open sSQL, oConnection1, adOpenKeyset

MsgBox "Rows: " & CStr(affected)

' MsgBox "RecordCount: " & CStr(m_oRecordset.RecordCount)
' MsgBox "Conn state: " & GetState(oConnection1.State)

oConnection1.Close

End Function

Public Function GetState(intState As Integer) As String

  Select Case intState
     Case adStateClosed
        GetState = "adStateClosed"
     Case adStateOpen
        GetState = "adStateOpen"
  End Select

End Function

You can play with this for your tests. But believe in me, it returns 
correct values, it speaks native M$ language. ;)

> > It seems to behave this way only with MERGE REPLICATION and not with 
> > other types of replication.
> >    
>
> It may be that the TDS stream is sending us a surprise from the downstream
> database.  I can't think of any other reason that FreeTDS would react
> differently to the two databases.  What you're doing is a little unusual; it
> could well be that you're the first one to update a replicated database with
> FreeTDS.  I suppose that's progress....
>  
Oh, maybe :) We use FreeTDS in mission critical services here. We use it 
mainly to interface our OTRS Trouble Ticketing system (Perl) with SQL 
Server and our Centralized Radius Authentication cluster (Perl).
However it is very strange that behaviour because from my point of view 
an application has not to be replica aware. In fact SQL Server is 
supposed to present the API for connections and transactions exactly the 
same as it is on one single DB. Isn't it?

> 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.

The files that end with "ok" are the correct updates against a single SQL 
Server database.
The others that end with "debug" are the failed updates against a replicated 
SQL Server database with merge replication.
IMPORTANT NOTE: I mean 'failed' only for affected rows result! The updates 
are being correctly made in the database table!

The logs contains only the minimum data you need to discover the bug. There 
is the Radiator inizialization and update query.

To ease your work I've attached even the radiator log to see what it says 
about the error.
Note the line that say:

DEBUG: rc is: X

This is not Radiator debug code but a line of code that I've inserted on my 
own to show you the rc (rowcount) variable content of the original Radiator 
code.

I've attached the freetds.conf also to let you check what parameters I'm 
using.

With both correct & odd logs you can simply make an eyes diff :)

However I've noticed that against the replicated DB the results of call ct_fetch() are negative numbers. 
Maybe this can help.

2004-01-08 19:52:58.994002 inside ct_fetch() process_row_tokens returned -2

Is it normal?

> If you can post a log before the weekend, perhaps we can incorporate a
> remedy into the upcoming 0.62 release.  I'd like to see that.  The only
> difficulty I foresee is that none of the developers has your particular
> setup, so we'd be relying on you to test any potential fix.  
>  
I'm glad to help you and even my company because we plan to use FreeTDS 
for any Linux software that has to deal with M$ Sql Server :)

However to make it easy for you to test the patch I've a suggestion for you:

1) Download VMWare Workstation 4.0.5 Evaluation (It works for 30 days).
2) Install and create a VM with Windows 2000 or 2003 (I use both 2000 and 
2003 configurations) and use the Disk on File mode to emulate the Hard Disk 
(do not use a real partition, is uncomfortable for our purpose).
3) Install SQL Server and configure it on the newly installed VM Win.
4) Make a copy of your new OS (ie just make a copy of the file) and you have 
another perfectly functional operating system with SQL Server.
5) Make changes to the 2nd OS configuration like: IP address, machine name 
and so on...
6) Run both VMs at the same time and create the test DB.
7) Configure the MSSQL replica.
Well done you have a perfectly functional test system without using two real 
servers :)
NOTE: I don't know if Windows complains about SID, anyway there are a lot of 
tools out there to change the SID of WIndows, like Norton Ghost does to make 
multiple installations at the same time from a single Windows Image.

However feel free to send me patches and I'll test it for you.

Good luck :)

--
Stefano Coletta

Unidata S.p.a.
Via Portuense, 1555 - 00050 Roma ( Ponte Galeria )
Tel +39 06650951
Fax +39 0665095002
E-mail s.coletta AT uni.it
Italy

http://www.mindcreations.com


#
#
#   $Id: freetds.conf,v 1.7 2002/10/17 15:11:02 castellano Exp $
#
# The freetds.conf file is a replacement for the original interfaces
# file developed by Sybase.  You may use either this or the interfaces
# file, but not both.
#
# FreeTDS will search for a conf file in the following order:
#
#     1) check if a file was set programatically via dbsetifile() and
#        is in .conf format, if so use that,
#
#     2) otherwise, if env variable FREETDSCONF specifies a properly 
#        formatted config file, use it,
#
#     3) otherwise, look in ~/.freetds.conf,
#
#     4) otherwise, look in @sysconfdir@/freetds.conf
#
# If FreeTDS has found no suitable conf file it will then search for
# an interfaces file in the following order:
#
#     1) check if a file was set programatically via dbsetifile() and 
#        is in interfaces format, if so use that,
#
#     2) look in ~/.interfaces
#
#     3) look in $SYBASE/interfaces (where $SYBASE is an environment
#        variable)
#
# Only hostname, port number, and protocol version can be specified
# using the interfaces format.
#
# The conf file format follows a modified Samba style layout.  There
# is a [global] section which will affect all database servers and
# basic program behaviour, and a section headed with the database
# server's name which will have settings which override the global
# ones.
#
# Note that environment variables TDSVER, TDSDUMP, TDSPORT, TDSQUERY, 
# and TDSHOST will override values set by a .conf or .interfaces file.
#
# To review the processing of the above, set env variable TDSDUMPCONFIG
# to a file name to log configuration processing.
#
# Global settings, any value here may be overridden by a database
# server specific section
[global]
        # TDS protocol version
        tds version = 4.2

        initial block size = 512

        swap broken dates = no

        swap broken money = no

        # Database server login method, if both server and domain
        # logins are enabled, domain login is tried first if a domain
        # is specified, and if that fails the server login will be used.
        try server login = yes
        try domain login = no

        # The default authentication domain, can be overridden by
        # specifying a username with a domain prefix, e.g. DOMAIN\username
;       nt domain = WORKGROUP

        # If the server responds with different domain try that one?
        cross domain login = no

        # Whether to write a TDSDUMP file for diagnostic purposes
        # (setting this to /tmp is insecure on a multi-user system)
        dump file = /tmp/freetds.log
        debug level = 10

        # Command and connection timeouts
;       timeout = 10
;       connect timeout = 10
        
        # If you get out of memory errors, it may mean that your client
        # is trying to allocate a huge buffer for a TEXT field.  
        # (Microsoft servers sometimes pretend TEXT columns are
        # 4 GB wide!)   If you have this problem, try setting 
        # 'text size' to a more reasonable limit 
        text size = 64512

# This is a Sybase hosted database server, if you are directly on the
# net you can use it to test.
[JDBC]
        host = 192.138.151.39
        port = 4444
        tds version = 5.0

# The same server, using TDS 4.2.  Used in configuration examples for the
# pool server, since the pool server supports only TDS 4.2.
[JDBC_42]
        host = 192.138.151.39
        port = 4444
        tds version = 4.2

# The client connecting to the pool server will use this to find its
# listening socket.  This entry assumes that the client is on the same
# system as the pool server.
[mypool]
        host = 127.0.0.1
        port = 5000
        tds version = 4.2

# A typical Microsoft SQL Server 7.0 configuration      
;[MyServer70]
;       host = ntmachine.domain.com
;       port = 1433
;       tds version = 7.0

# A typical Microsoft SQL Server 7.0 configuration using domain logins
;[MyServer70]
;       host = ntmachine.domain.com
;       port = 1433
;       tds version = 7.0
;       try domain login = yes
;       try server login = no
;       nt domain = MYDOMAIN
        
# A typical Microsoft SQL Server 6.x configuration      
;[MyServer65]
;       host = ntmachine.domain.com
;       port = 1433
;       tds version = 4.2


; WORKING DATABASE (SIMPLE)
[sql01]
        host = 192.168.96.21
        port = 1433
        tds version = 7.0


; NOT WORKING DATABASE (MERGE REPLICATION)
[bonnie]
        host = 217.72.103.103
        port = 1433
        tds version = 7.0

Attachment: freetds.log.debug.gz
Description: GNU Zip compressed data

Attachment: freetds.log.ok.gz
Description: GNU Zip compressed data

Thu Jan  8 19:47:59 2004: NOTICE: Server started: Radiator 3.8 on 
arlecchino.uni.it
Thu Jan  8 19:49:34 2004: DEBUG: Packet dump:
*** Received from 192.168.97.197 port 3406 ....
Code:       Access-Request
Identifier: 6
Authentic:        1073587871
Attributes:
        User-Name = "registrazione AT openaccess.it"
        User-Password = "<246>{x<236><18>d<191>3<25><4>c<160>OGt<131>"
        NAS-IP-Address = 217.72.110.16
        NAS-Port = 80
        Called-Station-Id = "650519929"
        Calling-Station-Id = "78359804"
        Service-Type = Framed-User
        Framed-Protocol = PPP
        NAS-Port-Type = Async

Thu Jan  8 19:49:34 2004: DEBUG: Handling request with Handler 'Realm=DEFAULT'
Thu Jan  8 19:49:34 2004: DEBUG: Rewrote user name to registrazione
Thu Jan  8 19:49:34 2004: DEBUG:  Deleting session for 
registrazione AT openaccess.it, 217.72.110.16, 80
Thu Jan  8 19:49:34 2004: DEBUG: do query is: 'DELETE FROM RADONLINE where 
i_NASPort=80 and v_NASIdentifier='217.72.110.16'':

Thu Jan  8 19:49:34 2004: DEBUG: rc is: 1

Thu Jan  8 19:49:34 2004: DEBUG: Query is: 'SELECT v_NASIdentifier, 
i_NASPort, v_acctsessionid  from RADONLINE where 
v_username='registrazione AT openaccess.it'':

Thu Jan  8 19:49:34 2004: DEBUG: Handling with Radius::AuthGROUP
Thu Jan  8 19:49:34 2004: DEBUG: Handling with Radius::AuthSQL
Thu Jan  8 19:49:34 2004: DEBUG: Handling with Radius::AuthSQL: SQL01-realm
Thu Jan  8 19:49:34 2004: DEBUG: Query is: 'select v_password, 
i_session_timeout,v_ip_fisso, v_netmask, v_route_fissa, v_pool_hint, 
i_simultaneous_use from SUBSCRIBERS where v_username='registrazione' and 
v_realm='openaccess.it'':

Thu Jan  8 19:49:34 2004: DEBUG: Radius::AuthSQL looks for match with 
registrazione
Thu Jan  8 19:49:34 2004: DEBUG: Query is: 'select v_password, 
i_session_timeout,v_ip_fisso, v_netmask, v_route_fissa, v_pool_hint, 
i_simultaneous_use from SUBSCRIBERS where v_username='DEFAULT' and 
v_realm='openaccess.it'':

Thu Jan  8 19:49:34 2004: DEBUG: Handling with Radius::AuthGROUP
Thu Jan  8 19:49:34 2004: DEBUG: Handling with Radius::AuthSQL
Thu Jan  8 19:49:34 2004: DEBUG: Handling with Radius::AuthSQL: 
SQL-Registrazione
Thu Jan  8 19:49:34 2004: DEBUG: Query is: 'select i_session_timeout, 
i_simultaneous_use from RESELLERS where v_username='registrazione' and 
v_realm='openaccess.it'':

Thu Jan  8 19:49:34 2004: DEBUG: Radius::AuthSQL looks for match with 
registrazione
Thu Jan  8 19:49:34 2004: DEBUG: Query is: 'SELECT v_NASIdentifier, 
i_NASPort, v_acctsessionid  from RADONLINE where 
v_username='registrazione AT openaccess.it'':

Thu Jan  8 19:49:34 2004: DEBUG: Radius::AuthSQL ACCEPT:
Thu Jan  8 19:49:34 2004: DEBUG: Handling with Radius::AuthDYNADDRESS
Thu Jan  8 19:49:34 2004: DEBUG: Query is: 'select top 1 TIME_STAMP, YIADDR, 
SUBNETMASK, DNSSERVER from RADPOOL where POOL='reserved' and STATE=0 order by 
TIME_STAMP':

Thu Jan  8 19:49:34 2004: DEBUG: do query is: 'update RADPOOL set 
STATE=1,TIME_STAMP=1073587774,EXPIRY=1073591374, USERNAME='registrazione', 
POOL='openaccess.it' where YIADDR='213.233.28.94' and TIME_STAMP =94':

Thu Jan  8 19:49:34 2004: DEBUG: rc is: -1

Thu Jan  8 19:49:34 2004: INFO: Access rejected for registrazione: Too many 
simultaneous address requests
Thu Jan  8 19:49:34 2004: DEBUG: Packet dump:
*** Sending to 192.168.97.197 port 3406 ....
Code:       Access-Reject
Identifier: 6
Authentic:        1073587871
Attributes:
        Session-Timeout = 3600
        Service-Type = Framed-User
        Framed-Protocol = PPP
        Framed-Routing = None
        Framed-MTU = 1500
        Framed-Compression = Van-Jacobson-TCP-IP
        Reply-Message = "Too many simultaneous address requests"


Thu Jan  8 20:05:44 2004: DEBUG: Finished reading configuration file 
'/home/radiator/etc/radius.cfg'
Thu Jan  8 20:05:44 2004: DEBUG: Reading dictionary file 
'/home/radiator/etc//dictionary'
Thu Jan  8 20:05:45 2004: DEBUG: Creating authentication port 0.0.0.0:1812
Thu Jan  8 20:05:45 2004: DEBUG: Creating accounting port 0.0.0.0:1813
Thu Jan  8 20:05:45 2004: NOTICE: Server started: Radiator 3.8 on 
arlecchino.uni.it
Thu Jan  8 20:06:13 2004: DEBUG: Packet dump:
*** Received from 192.168.97.197 port 4122 ....
Code:       Access-Request
Identifier: 0
Authentic:        1073588869
Attributes:
        User-Name = "registrazione AT openaccess.it"
        User-Password = "<198><193>w<13>3 "<147><209><7>Z<201>k<157><195>Y"
        NAS-IP-Address = 217.72.110.16
        NAS-Port = 80
        Called-Station-Id = "650519929"
        Calling-Station-Id = "78359804"
        Service-Type = Framed-User
        Framed-Protocol = PPP
        NAS-Port-Type = Async

Thu Jan  8 20:06:13 2004: DEBUG: Handling request with Handler 'Realm=DEFAULT'
Thu Jan  8 20:06:13 2004: DEBUG: Rewrote user name to registrazione
Thu Jan  8 20:06:13 2004: DEBUG:  Deleting session for 
registrazione AT openaccess.it, 217.72.110.16, 80
Thu Jan  8 20:06:13 2004: DEBUG: do query is: 'DELETE FROM RADONLINE where 
i_NASPort=80 and v_NASIdentifier='217.72.110.16'':

Thu Jan  8 20:06:13 2004: DEBUG: rc is: 139795672

Thu Jan  8 20:06:13 2004: DEBUG: Query is: 'SELECT v_NASIdentifier, 
i_NASPort, v_acctsessionid  from RADONLINE where 
v_username='registrazione AT openaccess.it'':

Thu Jan  8 20:06:13 2004: DEBUG: Handling with Radius::AuthGROUP
Thu Jan  8 20:06:13 2004: DEBUG: Handling with Radius::AuthSQL
Thu Jan  8 20:06:13 2004: DEBUG: Handling with Radius::AuthSQL: SQL01-realm
Thu Jan  8 20:06:13 2004: DEBUG: Query is: 'select v_password, 
i_session_timeout,v_ip_fisso, v_netmask, v_route_fissa, v_pool_hint, 
i_simultaneous_use from SUBSCRIBERS where v_username='registrazione' and 
v_realm='openaccess.it'':

Thu Jan  8 20:06:13 2004: DEBUG: Radius::AuthSQL looks for match with 
registrazione
Thu Jan  8 20:06:13 2004: DEBUG: Query is: 'select v_password, 
i_session_timeout,v_ip_fisso, v_netmask, v_route_fissa, v_pool_hint, 
i_simultaneous_use from SUBSCRIBERS where v_username='DEFAULT' and 
v_realm='openaccess.it'':

Thu Jan  8 20:06:13 2004: DEBUG: Handling with Radius::AuthGROUP
Thu Jan  8 20:06:13 2004: DEBUG: Handling with Radius::AuthSQL
Thu Jan  8 20:06:13 2004: DEBUG: Handling with Radius::AuthSQL: 
SQL-Registrazione
Thu Jan  8 20:06:13 2004: DEBUG: Query is: 'select i_session_timeout, 
i_simultaneous_use from RESELLERS where v_username='registrazione' and 
v_realm='openaccess.it'':

Thu Jan  8 20:06:13 2004: DEBUG: Radius::AuthSQL looks for match with 
registrazione
Thu Jan  8 20:06:13 2004: DEBUG: Query is: 'SELECT v_NASIdentifier, 
i_NASPort, v_acctsessionid  from RADONLINE where 
v_username='registrazione AT openaccess.it'':

Thu Jan  8 20:06:13 2004: DEBUG: Radius::AuthSQL ACCEPT:
Thu Jan  8 20:06:13 2004: DEBUG: Handling with Radius::AuthDYNADDRESS
Thu Jan  8 20:06:13 2004: DEBUG: Query is: 'select top 1 TIME_STAMP, YIADDR, 
SUBNETMASK, DNSSERVER from RADPOOL where POOL='reserved' and STATE=0 order by 
TIME_STAMP':

Thu Jan  8 20:06:13 2004: DEBUG: do query is: 'update RADPOOL set 
STATE=1,TIME_STAMP=1073588773,EXPIRY=1073592373, USERNAME='registrazione', 
POOL='openaccess.it' where YIADDR='192.168.0.4' and TIME_STAMP =0':

Thu Jan  8 20:06:13 2004: DEBUG: rc is: 1

Thu Jan  8 20:06:13 2004: DEBUG: Access accepted for registrazione
Thu Jan  8 20:06:13 2004: DEBUG: Packet dump:
*** Sending to 192.168.97.197 port 4122 ....
Code:       Access-Accept
Identifier: 0
Authentic:        1073588869
Attributes:
        Service-Type = Framed-User
        Framed-Protocol = PPP
        Framed-Routing = None
        Framed-MTU = 1500
        Framed-Compression = Van-Jacobson-TCP-IP
        Framed-IP-Netmask = 255.255.255.0
        Framed-IP-Address = 192.168.0.4