none
Problem with SyncDirectionOrder.Download the second time a synchronisation is run RRS feed

  • Question

  • We have two replicas, the local replica provider is a FileSyncProvider and the remote replica provider uses a custom implementation of FullEnumerationSimpleSyncProvider.

    The following problem occurs (custom log snippets shown to help show more detail):

    1. Add a file to the local replica

     

    [22/10/2010 14:31:31] Adding file(s)...
    [22/10/2010 14:31:36] Item: watermark.bmp is added
    [22/10/2010 14:31:36] Item(s) added.

     

    2. Perform a SyncDirectionOrder.Upload synchronisation

     

    [22/10/2010 14:31:39] Synchronization (UPLOAD) started
    [22/10/2010 14:31:39] Logging the contents of the local metadata store:
    [22/10/2010 14:31:39] The remote metadata store does not currently exist
    [22/10/2010 14:31:39] Creating metadata file
    [22/10/2010 14:31:39] Enumerating files on the server (NONE)
    [22/10/2010 14:31:40] Finished enumerating files on the server
    [22/10/2010 14:31:40] FileSyncProvider is detecting changes in local replica
    [22/10/2010 14:31:41] FileSyncProvider has finished detecting changes
    [22/10/2010 14:31:41] 	Directories found: 0
    [22/10/2010 14:31:41] 	Files found: 1
    [22/10/2010 14:31:41] 	Size of files found: 199525 bytes
    [22/10/2010 14:31:41] 
    [22/10/2010 14:31:41] INSERTING a local item into the remote store (watermark.bmp)
    [22/10/2010 14:31:41] Filename: watermark.bmp (194.84 KB)
    [22/10/2010 14:31:41] Uploading new file watermark.bmp
    [22/10/2010 14:31:42] Uploaded new file
    [22/10/2010 14:31:43] InsertItem() took 00:00:01
    [22/10/2010 14:31:43] Local item has been uploaded to the remote store
    [22/10/2010 14:31:43] 
    [22/10/2010 14:31:43] Synchronisation orchestrator is applying changes to the remote provider [Progress: 1/1]
    [22/10/2010 14:31:43] Synchronisation orchestrator is applying changes to the remote provider [Progress: 1/1]
    [22/10/2010 14:31:43] Synchronisation session has ended
    [22/10/2010 14:31:43] SyncStartTime: 22/10/2010 14:31:39
    [22/10/2010 14:31:43] SyncEndTime: 22/10/2010 14:31:43
    [22/10/2010 14:31:43] DownloadChangesApplied: 0
    [22/10/2010 14:31:43] DownloadChangesFailed: 0
    [22/10/2010 14:31:43] DownloadChangesTotal: 0
    [22/10/2010 14:31:43] UploadChangesApplied: 1
    [22/10/2010 14:31:43] UploadChangesFailed: 0
    [22/10/2010 14:31:43] UploadChangesTotal: 1
    [22/10/2010 14:31:43] Synchronization complete. Success = True
    [22/10/2010 14:31:43] BytesUploadedThisSynchronisationSession: 194.84 KB
    [22/10/2010 14:31:43] NumberOfRecoverableErrorsReported: 0

     

    3. Delete the file in the local replica

     

    [22/10/2010 14:32:00] Deleting item(s)...
    [22/10/2010 14:32:01] Item: watermark.bmp is deleted
    [22/10/2010 14:32:01] Items(s) deleted.

     

    4. Perform a SyncDirectionOrder.Download synchronisation

     

    Synchronization (DOWNLOAD) started
    [22/10/2010 14:32:03] Logging the contents of the local metadata store:
    [22/10/2010 14:32:03] 	RelativePathWithFileName: watermark.bmp
    [22/10/2010 14:32:03] 		CreationTime: 22/10/2010 14:31:36
    [22/10/2010 14:32:03] 		FileSize: 199525
    [22/10/2010 14:32:03] 		GlobalItemId: Actx9dT5B/AJyayBs77FSKBTg0V/v/Iq(1 203 113 245 212 249 7 240 9 201 172 129 179 190 197 72 160 83 131 69 127 191 242 42 )
    [22/10/2010 14:32:03] 		LastLocalModification: 
    [22/10/2010 14:32:03] 		LastWriteTime: 22/10/2010 14:31:36
    [22/10/2010 14:32:03] Logging the contents of the remote metadata store:
    [22/10/2010 14:32:03] 	RelativePathWithFileName: watermark.bmp
    [22/10/2010 14:32:03] 		CreationTime: 
    [22/10/2010 14:32:03] 		FileSize: 199525
    [22/10/2010 14:32:03] 		GlobalItemId: Actx9dT5B/AJyayBs77FSKBTg0V/v/Iq(1 203 113 245 212 249 7 240 9 201 172 129 179 190 197 72 160 83 131 69 127 191 242 42 )
    [22/10/2010 14:32:03] 		LastLocalModification: 01/01/1601 00:00:00
    [22/10/2010 14:32:03] 		LastWriteTime: 
    [22/10/2010 14:32:03] Opening existing metadata file
    [22/10/2010 14:32:03] Enumerating files on the server
    [22/10/2010 14:32:04] 	Filename: watermark.bmp Timestamp: 22/10/2010 14:31:42 File size in bytes: 199525
    [22/10/2010 14:32:04] Finished enumerating files on the server
    [22/10/2010 14:32:04] 
    [22/10/2010 14:32:04] Synchronisation orchestrator is detecting changes from the remote provider [Progress: 0/0]
    [22/10/2010 14:32:04] FileSyncProvider is detecting changes in local replica
    [22/10/2010 14:32:04] FileSyncProvider has finished detecting changes
    [22/10/2010 14:32:04] 	Directories found: 0
    [22/10/2010 14:32:04] 	Files found: 0
    [22/10/2010 14:32:04] 	Size of files found: 0 bytes
    [22/10/2010 14:32:04] 
    [22/10/2010 14:32:05] Downloading file from remote server
    [22/10/2010 14:32:06] FileSyncProvider is applying a change
    [22/10/2010 14:32:06] ChangeType: Create
    [22/10/2010 14:32:06] NewFileData.CreationTime: 22/10/2010 14:31
    [22/10/2010 14:32:06] NewFileData.LastAccessTime: 01/01/1700 00:00
    [22/10/2010 14:32:06] NewFileData.LastWriteTime: 22/10/2010 14:31
    [22/10/2010 14:32:06] NewFileData.Size: 199525
    [22/10/2010 14:32:06] SkipChange: False
    [22/10/2010 14:32:06] FileSyncProvider has applied a change
    [22/10/2010 14:32:06] Applied create for file watermark.bmp
    [22/10/2010 14:32:06] NewFilePath=watermark.bmp  OldFilePath=null  ChangeType=Create
    [22/10/2010 14:32:06] Synchronisation orchestrator is applying changes to the local provider [Progress: 1/1]
    [22/10/2010 14:32:06] Synchronisation orchestrator is applying changes to the local provider [Progress: 1/1]
    [22/10/2010 14:32:06] Synchronisation session has ended
    [22/10/2010 14:32:06] SyncStartTime: 22/10/2010 14:32:03
    [22/10/2010 14:32:06] SyncEndTime: 22/10/2010 14:32:06
    [22/10/2010 14:32:06] DownloadChangesApplied: 1
    [22/10/2010 14:32:06] DownloadChangesFailed: 0
    [22/10/2010 14:32:06] DownloadChangesTotal: 1
    [22/10/2010 14:32:06] UploadChangesApplied: 0
    [22/10/2010 14:32:06] UploadChangesFailed: 0
    [22/10/2010 14:32:06] UploadChangesTotal: 0
    [22/10/2010 14:32:06] Synchronization complete. Success = True
    [22/10/2010 14:32:06] BytesUploadedThisSynchronisationSession: 0 bytes
    [22/10/2010 14:32:06] NumberOfRecoverableErrorsReported: 0

     

    5. The file is restored from the remote replica to the local replica

    6. Delete the file in the local replica

     

    [22/10/2010 14:32:09] Deleting item(s)...
    [22/10/2010 14:32:09] Item: watermark.bmp is deleted

     

    7.  Perform a SyncDirectionOrder.Download synchronisation

    [22/10/2010 14:32:13] Synchronization (DOWNLOAD) started
    [22/10/2010 14:32:13] Logging the contents of the local metadata store:
    [22/10/2010 14:32:13] 	RelativePathWithFileName: watermark.bmp
    [22/10/2010 14:32:13] 		CreationTime: 22/10/2010 14:31:36
    [22/10/2010 14:32:13] 		FileSize: 199525
    [22/10/2010 14:32:13] 		GlobalItemId: Actx9dT5B/AJyayBs77FSKBTg0V/v/Iq(1 203 113 245 212 249 7 240 9 201 172 129 179 190 197 72 160 83 131 69 127 191 242 42 )
    [22/10/2010 14:32:13] 		LastLocalModification: 
    [22/10/2010 14:32:13] 		LastWriteTime: 22/10/2010 14:31:36
    [22/10/2010 14:32:13] Logging the contents of the remote metadata store:
    [22/10/2010 14:32:13] 	RelativePathWithFileName: watermark.bmp
    [22/10/2010 14:32:13] 		CreationTime: 
    [22/10/2010 14:32:13] 		FileSize: 199525
    [22/10/2010 14:32:13] 		GlobalItemId: Actx9dT5B/AJyayBs77FSKBTg0V/v/Iq(1 203 113 245 212 249 7 240 9 201 172 129 179 190 197 72 160 83 131 69 127 191 242 42 )
    [22/10/2010 14:32:13] 		LastLocalModification: 01/01/1601 00:00:00
    [22/10/2010 14:32:13] 		LastWriteTime: 
    [22/10/2010 14:32:13] Opening existing metadata file
    [22/10/2010 14:32:13] Enumerating files on the server
    [22/10/2010 14:32:14] 	Filename: watermark.bmp Timestamp (year adjusted): 22/10/2010 14:31:42 File size in bytes: 199525
    [22/10/2010 14:32:14] Finished enumerating files on the server
    [22/10/2010 14:32:14] 
    [22/10/2010 14:32:14] Synchronisation orchestrator is detecting changes from the remote provider [Progress: 0/0]
    [22/10/2010 14:32:14] FileSyncProvider is detecting changes in the local replica
    [22/10/2010 14:32:14] FileSyncProvider has finished detecting changes
    [22/10/2010 14:32:14] 	Directories found: 0
    [22/10/2010 14:32:14] 	Files found: 0
    [22/10/2010 14:32:14] 	Size of files found: 0 bytes
    [22/10/2010 14:32:14] 
    [22/10/2010 14:32:14] Synchronisation orchestrator is applying changes to the local provider [Progress: 0/0]
    [22/10/2010 14:32:14] Synchronisation session has ended
    [22/10/2010 14:32:14] SyncStartTime: 22/10/2010 14:32:13
    [22/10/2010 14:32:14] SyncEndTime: 22/10/2010 14:32:14
    [22/10/2010 14:32:14] DownloadChangesApplied: 0
    [22/10/2010 14:32:14] DownloadChangesFailed: 0
    [22/10/2010 14:32:14] DownloadChangesTotal: 0
    [22/10/2010 14:32:14] UploadChangesApplied: 0
    [22/10/2010 14:32:14] UploadChangesFailed: 0
    [22/10/2010 14:32:14] UploadChangesTotal: 0
    [22/10/2010 14:32:14] Synchronization complete. Success = True
    [22/10/2010 14:32:14] BytesUploadedThisSynchronisationSession: 0 bytes
    [22/10/2010 14:32:14] NumberOfRecoverableErrorsReported: 0

     

    8. The file is not restored to the FileSyncProvider replica

    Additional information:

    • The ConflictResolutionPolicy and CollisionConflictResolutionPolicy are both set to CollisionConflictResolutionPolicy.SourceWins for both providers
    • This is being testing on Windows 7 Ultimate x64 with an NTFS filesystem
    • Sync Framework 2.1
    • The timezone of the machine is set to UTC

    What else could I check to help diagnose the issue? The real problem is that I don't know why the Sync Framework restored the deleted file the first time, but not the second time.
    • Edited by tjrobinson Friday, October 22, 2010 2:46 PM Fixed dodgy formatting
    Friday, October 22, 2010 2:44 PM

All replies

  • Hi -

    Restoring the file the first time was incorrect. Look at the metadata you are reporting in Step 4) These two numbers should have been the same because there were no changes on the remote side. The bug probably is that when you uploaded the file for the first time to the remote server - you are not correctly setting the metadata on the file correctly. When you are called to Apply changes for a file - you need to copy the file correctly and then ensure that the metadata ( size of file/creation time/last modified time) that is stored in the metadata file is also correct.

    [22/10/2010 14:32:03] Logging the contents of the local metadata store:
    [22/10/2010 14:32:03] RelativePathWithFileName: watermark.bmp
    [22/10/2010 14:32:03] CreationTime: 22/10/2010 14:31:36
    [22/10/2010 14:32:03] FileSize: 199525
    [22/10/2010 14:32:03] GlobalItemId: Actx9dT5B/AJyayBs77FSKBTg0V/v/Iq(1 203 113 245 212 249 7 240 9 201 172 129 179 190 197 72 160 83 131 69 127 191 242 42 )
    [22/10/2010 14:32:03] LastLocalModification:
    [22/10/2010 14:32:03] LastWriteTime: 22/10/2010 14:31:36
    [22/10/2010 14:32:03] Logging the contents of the remote metadata store:
    [22/10/2010 14:32:03] RelativePathWithFileName: watermark.bmp
    [22/10/2010 14:32:03] CreationTime:
    [22/10/2010 14:32:03] FileSize: 199525
    [22/10/2010 14:32:03] GlobalItemId: Actx9dT5B/AJyayBs77FSKBTg0V/v/Iq(1 203 113 245 212 249 7 240 9 201 172 129 179 190 197 72 160 83 131 69 127 191 242 42 )
    [22/10/2010 14:32:03] LastLocalModification: 01/01/1601 00:00:00
    [22/10/2010 14:32:03] LastWriteTime:

    Thanks
    Deepa


    Deepa ( Microsoft Sync Framework)
    Friday, October 22, 2010 8:10 PM
    Answerer
  • It looks like the first time you download, a conflict is detected - an update on the remote side, and a delete on the local side. In the delete-update conflict, the Source is chosen as the winner, and so the update is applied, restoring the file.

    In the second download, there is no conflict - you have already downloaded the update, so there is no new change to download since the last time, so no changes are applied, and the local file stays deleted.

    Friday, October 22, 2010 8:13 PM
    Moderator
  • Thanks for your help. I am assuming that in the scenario above, after step 2, the LastLocalModification column in the remote metadata store should be the same as the LastWriteTime?

    At the moment it is always 0 (the equivalent of 01/01/1601 00:00:00). However, I have been unable to find a way of doing this. In fact, even using the Synchronizing Files to Windows Azure Storage sample I am seeing the same value of 0 being stored in the remote metadata store after a simple upload.

    Here is an example (i.e. exact values vary but the structure is the same) of the ItemFieldDictionary returned as an out parameter of the call to InsertItem():

    And an example of the IEnumerable<ItemFieldDictionary> returned by EnumerateItems():

    Assuming this is where the remote metadata store derives the LastLocalModification value from, is there something wrong with what I'm returning?

    • Edited by tjrobinson Monday, October 25, 2010 11:55 AM Added more detail and images
    Monday, October 25, 2010 11:45 AM
  • Thanks, that's an interesting idea and not something I had considered. I've managed to add additional logging when an ItemConflict occurs by using the SyncCallbacks property of the FileSyncProvider (as described under the Handling Conflicts section of this MSDN How To and this sample code).

    I now have the following additional information which matches what you suggested was happening during step 4:

    [25/10/2010 15:02:22] Event: FileSyncProvider_ItemConflicting
    [25/10/2010 15:02:23] DestinationChange.ChangeKind: Deleted
    [25/10/2010 15:02:23] DestinationChange.ItemId: 01cb7453d97ac380470f30266251dd43a74c492847af2ce0
    [25/10/2010 15:02:23] SourceChange.ChangeKind: Update
    [25/10/2010 15:02:24] SourceChange.ItemId: 01cb7453d97ac380470f30266251dd43a74c492847af2ce0

    I'm assuming this is all caused by the difference in timestamps that Deepa originally mentioned? 

    • Edited by tjrobinson Monday, October 25, 2010 3:09 PM Updated with new information
    Monday, October 25, 2010 12:00 PM
  • Yes, it looks like a conflict is detected due to the difference in timestamps, when ideally there shouldn't be any conflict detected at all. Hopefully you have enough info from Deepa to fix whatever is causing the wrong metadata to be stored.
    Monday, October 25, 2010 7:43 PM
    Moderator
  • Hi, unfortunately whilst I now understand the problem I am no closer to finding a way of fixing it. Please see my reply to Deepa's message above (the one with screenshots).

    Monday, October 25, 2010 8:41 PM
  • It might help to deep dive into the metadata file itself.  You can do that by changing the extension of your metadata file to .sdf (sql ce compact database file), and then opening it in visual studio or the Sql Management Studio.  If you do that, you can see what is happening to your metadata file at every step in your program - that might give you some insight on how to fix it.

    Wednesday, October 27, 2010 9:20 PM
  • Hi, I have already been examining the metadata file itself. It's the only way I managed to work out why my download direction synchronisation was causing an update/delete conflict. Because it's awkward to open the metadata file at each stage of the process, I'm actually using System.Data.SqlServerCe to read the file and display details in my log file. I will try and post some of the code at some point as it may be useful to others.
    Thursday, October 28, 2010 8:03 AM