locked
Sync Framework 2.1 keeps downloading the same records RRS feed

  • Question

  • I have an application using Sync Framework with the central database running under SQL/Server 2008 and multiple remote clients connecting using SQL Express 2008. I have some basic conflict resolution in place but from time to time the database ends up in a state where the same records keep getting downloaded, on this occasion 12 records in one table when the scope contains around 80 other tables that are all fine. Doing some debugging ApplyChangeFailed for either the local or remote provider not being called when this happens.

    The following are parts of a detailed trace log where I'd previously performed a few sync operations and each time I kept getting 12 records downloaded in the sync stats. This shows a record that was downloaded again when it hadn't changed:

    INFO   , HorseApp, 1, 04/09/2013 04:08:40:264,    ----- Table "HorseOrganisationStatus" -----
    VERBOSE, HorseApp, 1, 04/09/2013 04:08:40:267,       Executing Command: [HorseOrganisationStatus_selectchanges]
    VERBOSE, HorseApp, 1, 04/09/2013 04:08:40:268,          Parameter: @sync_min_timestamp Value: 22924264
    VERBOSE, HorseApp, 1, 04/09/2013 04:08:40:268,          Parameter: @sync_scope_local_id Value: 32
    VERBOSE, HorseApp, 1, 04/09/2013 04:08:40:268,          Parameter: @sync_scope_restore_count Value: 0
    VERBOSE, HorseApp, 1, 04/09/2013 04:08:40:268,          Parameter: @sync_update_peer_key Value: 206

    Update for row with PK: HorseID = 4837, OrganisationTypeID = A, OrgStatusTypeID = NV, StatusDate = 9/12/2011 12:00:00 AM on HORSE
    UV: 149,24396862 CV: 75,30820708

    On the server the following data was in the tracking table for that row:

    HorseID OrganisationTypeID OrgStatusTypeID StatusDate update_scope_local_id scope_update_peer_key scope_update_peer_timestamp local_update_peer_key local_update_peer_timestamp create_scope_local_id scope_create_peer_key scope_create_peer_timestamp local_create_peer_key local_create_peer_timestamp sync_row_is_tombstone restore_timestamp last_change_datetime
    4837    A                  NV              1901-01-01 NULL                  0                     21610358                     0                    0x00000000014A297E          NULL                  NULL                  NULL                        0                     21305446                    0                     NULL              NULL
    4837    A                  NV              2011-12-09 32                    149                   24396862                     0                    0x00000000015E0858          32                    75                    30820708                    0                     22622234                    0                     NULL              2013-02-21 15:41:17.920
    

    And this is the tracking data that was on the client:

    HorseID OrganisationTypeID OrgStatusTypeID StatusDate update_scope_local_id scope_update_peer_key scope_update_peer_timestamp local_update_peer_key local_update_peer_timestamp create_scope_local_id scope_create_peer_key scope_create_peer_timestamp local_create_peer_key local_create_peer_timestamp sync_row_is_tombstone restore_timestamp last_change_datetime
    4837    A                  NV              1901-01-01 32                    4                     21637502                    3                     0x000000000173AF5F          NULL                  NULL                  NULL                        3                     21975493                    0   22334694          2013-01-03        14:41:27.830
    4837    A                  NV              2011-12-09 32                    78                    30820708                    2                     0x000000000173AF60          32                    78                    30820708                    2                     23491691                    0   23491774          2013-02-07        12:24:18.480
    


    Considering I didn't get any apply change failed events or other errors that I could see in the trace log I wondered if anyone could suggest possible reasons or further steps I can take to track the problem down?

    Tuesday, April 9, 2013 5:22 AM

All replies

  • can you fire a trace again or profiler and see if the value for @sync_min_timestamp Value: 22924264 actually changes.
    Tuesday, April 9, 2013 5:56 AM
  • Hi June, I've performed another sync and it did stay the same at 22924264.

    Wednesday, April 10, 2013 6:12 AM
  • hard to tell what's wrong without a full trace or database to try to reproduce the issue.

    have you by any chance used a  backup copy of a provisioned database and restored it on a client?

    Wednesday, April 10, 2013 11:03 AM
  • Hi June, yes that's the way I distribute it to the clients. The installation contains a provisioned backup that I restore and then do a PerformPostRestoreFixup. Is there something else I need to do or a preferred way to go about that? Some machines are on slow Internet connections and the database contains a lot of historical information that is only rarely updated so I think many of the machines would struggle to do a full provision over the Internet.
    Thursday, April 11, 2013 12:26 AM
  • that's the only other thing i could think of. but if youre doing the PerformPostRestoreFixup, then it should be good.

    is it specific just to this table or same client or its random?

    Thursday, April 11, 2013 1:04 AM
  • Hi June, I've just fired up a seperate test machine that I keep updated the same way as client machines. It hadn't been updated for several weeks but after the initial sync it is in the same state with only this table and the same timestamp being used as above. I do recall seeing it in the past on a different table but that was at any earlier stage of development where I wasn't handling some conflicts properly so I'd assumed that had caused it and didn't keep a note of the tables involved.

    This is a table that links two tables and adds a status date where originally every column was in the primary key. I discovered early on that isn't supported so added a column called 'DummyForSync' that is a bit field that I just leave null. I have the same situation in several other tables and there is one other table identical in structure to this one that is working fine at the moment, although I seem to recall last time I had the problem it was on a similar table but that may have just been coincidence.

    Due to the size of the verbose trace log I was searching for "error" but since scrolling have found related errors further down the log that may explain things, I've had to truncate this a bit but hopefully this covers the relevant parts:

    INFO   , HorseApp.vshost, 8, 04/11/2013 03:25:22:226,    ----- Updates for Table "HorseOrganisationStatus" -----
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:264,    Executing Command: [HorseOrganisationStatus_bulkupdate]
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:266,       Parameter: @sync_min_timestamp Value: 25037523
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:267,       Parameter: @sync_scope_local_id Value: 32
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:268,       Parameter: @changeTable Value: HorseOrganisationStatus
    INFO   , HorseApp.vshost, 8, 04/11/2013 03:25:22:274, Applied 0 of 14 rows with bulk command BulkUpdateCommand
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:275,    Failed to update row with PK using bulk apply: HorseID="619" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="8/08/2010 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:277,    Failed to update row with PK using bulk apply: HorseID="2407" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="30/09/2012 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:278,    Failed to update row with PK using bulk apply: HorseID="2433" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="22/08/2010 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:280,    Failed to update row with PK using bulk apply: HorseID="2773" OrganisationTypeID="A" OrgStatusTypeID="NV" StatusDate="1/01/1901 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:283,    Failed to update row with PK using bulk apply: HorseID="2938" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="10/12/2012 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:285,    Failed to update row with PK using bulk apply: HorseID="4117" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="8/08/2010 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:286,    Failed to update row with PK using bulk apply: HorseID="4837" OrganisationTypeID="A" OrgStatusTypeID="NV" StatusDate="9/12/2011 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:287,    Failed to update row with PK using bulk apply: HorseID="4876" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="5/02/2013 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:288,    Failed to update row with PK using bulk apply: HorseID="5039" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="22/07/2012 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:289,    Failed to update row with PK using bulk apply: HorseID="5784" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="1/01/1901 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:290,    Failed to update row with PK using bulk apply: HorseID="6493" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="10/06/2012 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:292,    Failed to update row with PK using bulk apply: HorseID="6511" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="20/04/2008 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:294,    Failed to update row with PK using bulk apply: HorseID="6783" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="25/11/2012 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:295,    Failed to update row with PK using bulk apply: HorseID="7727" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="7/10/2012 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:300,
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:302,    RowId: horseorganisationstatus-619-A-EN-8/08/2010 12:00:00 AM UV: 4,23523899 CV: 78,30820606 IsTomb: False
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:312,    Updating row with PK: HorseID="619" OrganisationTypeID="A" OrgStatusTypeID="EN" StatusDate="8/08/2010 12:00:00 AM"  on AERA
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:320,    Executing Command: [HorseOrganisationStatus_update]
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:321,       Parameter: @P_1 Value: 619
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:322,       Parameter: @P_2 Len: 1 Value: A
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:324,       Parameter: @P_3 Len: 2 Value: EN
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:325,       Parameter: @P_4 Value: 8/08/2010 12:00:00 AM
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:327,       Parameter: @P_5 Value: NULL
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:328,       Parameter: @sync_force_write Value: 0
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:329,       Parameter: @sync_min_timestamp Value: 25037523
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:330,       Parameter: @sync_row_count Value: 0
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:332,    Rows affected: 0
    INFO   , HorseApp.vshost, 8, 04/11/2013 03:25:22:333, Optimistic change application failed
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:337,    Executing Command: [HorseOrganisationStatus_selectrow]
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:339,       Parameter: @P_1 Value: 619
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:340,       Parameter: @P_2 Len: 1 Value: A
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:342,       Parameter: @P_3 Len: 2 Value: EN
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:343,       Parameter: @P_4 Value: 8/08/2010 12:00:00 AM
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:345,       Parameter: @sync_scope_local_id Value: 32
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:346,       Parameter: @sync_scope_restore_count Value: 3
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:350,
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:351,    RowId: horseorganisationstatus-619-A-EN-8/08/2010 12:00:00 AM UV: 78,30820606 CV: 78,30820606 IsTomb: False
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:353,             Checking for conflict.
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:355,             Remote peer contains local change. Returning RemoteSupersedes.
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:357,    Executing Command: [HorseOrganisationStatus_update]
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:358,       Parameter: @P_1 Value: 619
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:360,       Parameter: @P_2 Len: 1 Value: A
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:361,       Parameter: @P_3 Len: 2 Value: EN
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:363,       Parameter: @P_4 Value: 8/08/2010 12:00:00 AM
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:364,       Parameter: @P_5 Value: NULL
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:366,       Parameter: @sync_force_write Value: 0
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:367,       Parameter: @sync_min_timestamp Value: 24354403
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:368,       Parameter: @sync_row_count Value: 0
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:370,    Rows affected: 0
    VERBOSE, HorseApp.vshost, 8, 04/11/2013 03:25:22:373,    Local UV: 78,30820606 CV: 78,30820606 IsTomb: False

    The thing I can't explain now is why when I have an ApplyChangeFailed on both the local and remote provider it's not getting called. Those rows are contained in both databases but because the handler isn't called I don't get change to set RetryWithForceWrite when a duplicate occurs.

    Thursday, April 11, 2013 4:17 AM
  • can you pick one of the rows and do the update yourself. or even just do a select on the destination if it actually finds that record. let's try to isolate first why its not being able to update. the conflict not firing is another issue.

    e.g., select * from HorseOrganisationStatus where HorseID="619" and OrganisationTypeID="A"  and OrgStatusTypeID="EN" and StatusDate="8/08/2010 12:00:00 AM" 

    Thursday, April 11, 2013 4:37 AM
  • I hadn't noticed the difference between the client and the server but if I run the query

    select * from HorseOrganisationStatus where HorseID = 619 and OrganisationTypeID='A'

    and StatusDate = '8/08/2010 12:00:00 AM'

    The server has the following data:

    HorseID	OrganisationTypeID	OrgStatusTypeID	StatusDate	DummyForSync
    619	A	EN	2010-08-08	NULL

    And the client has the following:

    HorseID	OrganisationTypeID	OrgStatusTypeID	StatusDate	DummyForSync
    619	A	NV	2010-08-08	NULL

    So the the following query as you have above returns a row OK on the server database:

    select * from HorseOrganisationStatus where HorseID=619 
    and OrganisationTypeID='A' 
    and StatusDate = '8/08/2010 12:00:00 AM'
    All columns apart from DummyForSync are part of a unique primary key and for that particular HorseID the only other row has a StatusDate of 1901-01-01 so I can't see why they'd be an insert / update issue. OrgStatusTypeID has a constraint check to another table, but that contains EN / NV on both sides and there are plenty of other records with those two values. No other tables have constraints that rely on this table.
    Thursday, April 11, 2013 7:46 AM
  • the thing that i notice in your data is that the datetime column status date has a time component based on the trace. but the data you posted for the tracking table doesnt have one or you just excluded the time yourself?

    maybe we should take this offline.

    but if you can do sql profiler, capture the actual update statement and run it yourself and see what happens.

    Thursday, April 11, 2013 7:58 AM
  • Hi June, the StatusDate column has the data type defined as date in the main table schema and just checking the tracking table it's defined the same way. I assume the trace must output the 12:00:00 AM time regardless while a standard SQL query doesn't doesn't include the time component for date columns. The where clause works either way with or without the 12:00:00 AM component. I didn't alter the SQL query results and that was what I saw under SQL management studio.

    I'll be away tomorrow but will try the SQL Profiler the next day and see capture what it shows, and thanks for your assistance.

    Thursday, April 11, 2013 12:51 PM
  • Hi June, the trace results are below along with the results returned.

    declare @p3 dbo.HorseOrganisationStatus_BulkType
    insert into @p3 values(619,N'A',N'EN','2010-08-08 00:00:00',NULL,23523899,4,30820606,78)
    -- other inserts here
    exec [HorseOrganisationStatus_bulkupdate] @sync_min_timestamp=25042178,@sync_scope_local_id=32,@changeTable=@p3
    
    -- HorseID	OrganisationTypeID	OrgStatusTypeID	StatusDate
    -- 619	A	EN	2010-08-08
    
    declare @p8 int
    set @p8=0
    exec [HorseOrganisationStatus_update] @P_1=619,@P_2='A',@P_3='EN',@P_4='2010-08-08',@P_5=NULL,@sync_force_write=0,@sync_min_timestamp=25042178,@sync_row_count=@p8 output
    
    -- (0 row(s) affected)
    
    select @p8
    -- returns 0
    
    exec [HorseOrganisationStatus_selectrow] @P_1=619,@P_2='A',@P_3='EN',@P_4='2010-08-08',@sync_scope_local_id=32,@sync_scope_restore_count=3
    
    -- HorseID	OrganisationTypeID	OrgStatusTypeID	StatusDate	DummyForSync	sync_row_is_tombstone	sync_row_timestamp	sync_update_peer_timestamp	sync_update_peer_key	sync_create_peer_timestamp	sync_create_peer_key
    -- 619	A	EN	2010-08-08	NULL	0	0x0000000001739E63	30820606	78	30820606	78
    
    declare @p8 int
    set @p8=0
    exec [HorseOrganisationStatus_update] @P_1=619,@P_2='A',@P_3='EN',@P_4='2010-08-08',@P_5=NULL,@sync_force_write=0,@sync_min_timestamp=24354403,@sync_row_count=@p8 output
    -- (0 row(s) affected)
    
    select @p8
    
    -- returns 0
    


    Monday, April 15, 2013 5:01 AM
  • and this didn't fire a conflict? 

    _selectrow is normally called when there's a conflict.

    if you have a small sample db and a snippet of your sync code, fire me an email at junetidlethoughts at hotmail dot com and i'll have a look. 

    hard troubleshooting it without being able to reproduce the issue.

    Monday, April 15, 2013 12:54 PM
  • Did you ever resolve this?  I'm having a similar issue (or same?), the @sync_min_timestamp value is not changing in my 3 distant sites.
    Thursday, May 14, 2015 5:04 PM