Syncing stops and "Sync already running in background" is repeated infinitely in log

[nicolas-raoul]

Sometimes sync suddenly stops performing correctly, and only the message SyncInBackground: Sync already running in background appears in the log.

This seems to happen sometimes (but not everytime) when the computer (Windows 10) enters sleep.

[artisticMink]

I can confirm this behavior on MacOS 10.14.02 with master checked out at 146f9bf

The issue comes up seemingly at random. If it comes up however, it will occur on the same file every synchronization attempt. Workarounds are either the deletion of the database file or removal of the specific entry in the files/folders table.

The last log entries with level ALL are as follows:

2019-02-18 10:31:03,097 [Thread Pool Worker] DEBUG DotCMIS.Binding.AtomPub.ObjectService [(null)] - Link: https://foo.bar.baz/servlet/drive-atom/foo/content/img_800x800_3x8bit_T01L01_RGB_tools_b.png?id=6916%3B1.0

2019-02-18 10:31:03,097 [Thread Pool Worker] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms

2019-02-18 10:31:03,221 [Thread Pool Worker] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse

2019-02-18 10:31:03,221 [Thread Pool Worker] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - /Users/foo/foo Test Repositories/Watcher Test/watcher-test-3/img_800x800_3x8bit_T01L01_RGB_tools_b.png

2019-02-18 10:31:03,221 [Thread Pool Worker] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - before SetContentStream

2019-02-18 10:31:13,895 [Thread Pool Worker] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: /Users/foo/foo Test Repositories/Watcher Test

[nicolas-raoul]

@artisticMink Another less extreme workaround is to just restart CmisSync. Does it not work for you?

[artisticMink]

@nicolas-raoul Yes, restarting the application also works. However, the sync after the initial successful sync will again fail.

[artisticMink]

I can reproduce the issue doing the following
Document at remote: /Foo/Bar/Baz.jpg
Document at local: /Foo/Bar/Baz.jpg
Both documents are in sync.

1. The initial sync is successful.
2. I edit my local copy of /Foo/Bar/Baz.jpg
3. I trigger a manual sync which succeeds.
4. I edit my local copy of /Foo/Bar/Baz.jpg
5. The sync will now deadlock.
6. I restart the client
7. The initial sync is successful.
8. I edit my local copy of /Foo/Bar/Baz.jpg
9. The sync will now deadlock.

[artisticMink]

Not setting the Expect HTTP request header solved my connectivity issue on both platforms. Possibly not related to your initial issue, however here's the solution in detail for everyone that arrives via search engine.

https://github.com/aegif/chemistry-dotcmis/blob/6589e79d8d9fc9ebadf646325eaaa24719a92d38/DotCMIS/binding/http.cs

For HttpWebRequest conn set
´conn.ServicePoint.Expect100Continue = false;´

[nicolas-raoul]

Short reproduction, I started CmisSync, then added a file opened its properties dialog in Windows Explorer (which might be a reason of the The process cannot access the file error), then a folder, on the local side. The file got synced but not the folder:

2019-03-22 13:17:50,944 [1] INFO  CmisSync.Console.CmisSyncConsole [(null)] - Starting. Version: 2.13.1.0
2019-03-22 13:17:50,994 [1] INFO  CmisSync.Lib.RepoBase [(null)] - Repo Synchronized folder for unit tests - Set poll interval to 5000ms
2019-03-22 13:17:50,996 [1] INFO  CmisSync.Lib.Sync.CmisRepo [(null)] - Synchronized folder for unit tests
2019-03-22 13:17:56,005 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: IsSyncing(): True
2019-03-22 13:17:56,016 [5] INFO  CmisSync.Lib.RepoBase [(null)] -  Sync Started: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:17:56,027 [5] INFO  CmisSync.Auth.Authentication [(null)] - Your password is not obfuscated.
2019-03-22 13:17:56,100 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:17:58,512 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:17:58,901 [5] INFO  CmisSync.Auth.Authentication [(null)] - VendorName: Alfresco
2019-03-22 13:17:58,901 [5] INFO  CmisSync.Auth.Authentication [(null)] - ProductName: Alfresco Community
2019-03-22 13:17:58,901 [5] INFO  CmisSync.Auth.Authentication [(null)] - ProductVersion: 4.2.0 (r54676-b4795)
2019-03-22 13:17:58,901 [5] INFO  CmisSync.Auth.Authentication [(null)] - CmisVersionSupported: 1.1
2019-03-22 13:17:58,901 [5] INFO  CmisSync.Auth.Authentication [(null)] - Name: 
2019-03-22 13:17:58,901 [5] INFO  CmisSync.Auth.Authentication [(null)] - Description: 
2019-03-22 13:17:58,901 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Created CMIS session: DotCMIS.Client.Impl.Session
2019-03-22 13:17:58,901 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - ChangeLog capability: True
2019-03-22 13:17:58,901 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Get folder tree support: True
2019-03-22 13:17:58,901 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Get descendants support: True
2019-03-22 13:17:58,901 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Chunked Up/Download disabled
2019-03-22 13:17:58,913 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:17:59,369 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:17:59,450 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:17:59,477 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:17:59,598 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - First sync, apply local changes then invoke a full crawl sync
2019-03-22 13:17:59,614 [5] INFO  CmisSync.Lib.Database.Database [(null)] - Checking whether database C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\configuration\Synchronized folder for unit tests.cmissync exists
2019-03-22 13:18:00,509 [5] INFO  CmisSync.Lib.Database.Database [(null)] - Database created
2019-03-22 13:18:00,527 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - 1 local changes to apply.
2019-03-22 13:18:00,540 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:00,579 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() triggered exception: System.Net.WebException: The remote server returned an error: (404) Not Found.
   at System.Net.HttpWebRequest.GetResponse()
   at DotCMIS.Binding.Impl.HttpUtils.Invoke(UrlBuilder url, String method, String contentType, Output writer, BindingSession session, Nullable`1 offset, Nullable`1 length, IDictionary`2 headers, Boolean outputErrors) in C:\Users\nico\src\CmisSync\Extras\OpenDataSpaceDotCMIS\DotCMIS\binding\http.cs:line 282
2019-03-22 13:18:00,581 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:00,621 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() triggered exception: System.Net.WebException: The remote server returned an error: (404) Not Found.
   at System.Net.HttpWebRequest.GetResponse()
   at DotCMIS.Binding.Impl.HttpUtils.Invoke(UrlBuilder url, String method, String contentType, Output writer, BindingSession session, Nullable`1 offset, Nullable`1 length, IDictionary`2 headers, Boolean outputErrors) in C:\Users\nico\src\CmisSync\Extras\OpenDataSpaceDotCMIS\DotCMIS\binding\http.cs:line 282
2019-03-22 13:18:00,629 [5] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Uploading file absent on repository: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc
2019-03-22 13:18:00,677 [5] DEBUG CmisSync.Lib.Cmis.MimeType [(null)] - Filename to MIME: file.doc->application/msword
2019-03-22 13:18:00,679 [5] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Uploading: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc as /Sites/test/documentLibrary/???????????/external-tests/file.doc
2019-03-22 13:18:00,683 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:00,716 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:00,836 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:01,008 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:02,697 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:02,765 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:02,829 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:02,839 [5] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Uploaded: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc
2019-03-22 13:18:02,843 [5] DEBUG CmisSync.Lib.Database.Database [(null)] - Starting database file addition for file: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc
2019-03-22 13:18:03,213 [5] DEBUG CmisSync.Lib.Database.Database [(null)] - Completed database file addition for file: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc
2019-03-22 13:18:03,220 [5] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Added file to database: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc
2019-03-22 13:18:03,220 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Finished applying local changes.
2019-03-22 13:18:03,225 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:05,703 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:05,751 [5] DEBUG CmisSync.Lib.Cmis.CmisUtils [(null)] - Server:Alfresco Community token: 45085351
2019-03-22 13:18:05,753 [5] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Crawl remote folder /Sites/test/documentLibrary/???????????/external-tests
2019-03-22 13:18:05,766 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:05,900 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:05,925 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:06,009 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:06,201 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:06,207 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:06,242 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:06,268 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:06,440 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:06,463 [5] DEBUG CmisSync.Lib.SyncItem [(null)] - File.Exists(C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc) = True
2019-03-22 13:18:06,468 [5] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Crawl local files in the local folder C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:06,469 [5] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Crawl local folder C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:06,521 [5] INFO  CmisSync.Lib.Database.Database [(null)] - Database ChangeLog token set to: 45085351
2019-03-22 13:18:06,521 [5] INFO  CmisSync.Lib.RepoBase [(null)] - Sync Complete: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data , success=True
2019-03-22 13:18:11,010 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: IsSyncing(): True
2019-03-22 13:18:11,010 [5] INFO  CmisSync.Lib.RepoBase [(null)] -  Sync Started: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:11,011 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:11,432 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:11,434 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:11,463 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:11,472 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - 0 local changes to apply.
2019-03-22 13:18:11,472 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Invoke a remote change log sync
2019-03-22 13:18:11,472 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:13,583 [5] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:13,626 [5] DEBUG CmisSync.Lib.Cmis.CmisUtils [(null)] - Server:Alfresco Community token: 45085351
2019-03-22 13:18:13,626 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - No changes to sync, tokens on server and client are equal: "45085351"
2019-03-22 13:18:13,626 [5] INFO  CmisSync.Lib.RepoBase [(null)] - Sync Complete: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data , success=True
2019-03-22 13:18:16,011 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: IsSyncing(): True
2019-03-22 13:18:16,011 [4] INFO  CmisSync.Lib.RepoBase [(null)] -  Sync Started: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:16,012 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:16,054 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:16,057 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:16,078 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:16,083 [4] ERROR CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - The process cannot access the file 'C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc' because it is being used by another process.
2019-03-22 13:18:16,085 [4] INFO  CmisSync.Lib.RepoBase [(null)] - Sync Error: CmisSync.Lib.Cmis.BaseException, The process cannot access the file 'C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc' because it is being used by another process.
2019-03-22 13:18:16,087 [4] INFO  CmisSync.Lib.RepoBase [(null)] - Sync Complete: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data , success=False
2019-03-22 13:18:21,012 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: IsSyncing(): True
2019-03-22 13:18:21,012 [4] INFO  CmisSync.Lib.RepoBase [(null)] -  Sync Started: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:21,013 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:21,572 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:21,573 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:21,622 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:21,625 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - 1 local changes to apply.
2019-03-22 13:18:21,625 [4] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Uploading file update on repository: file.doc
2019-03-22 13:18:21,631 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:21,680 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:21,681 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:21,710 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:21,719 [4] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Updating: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc
2019-03-22 13:18:21,723 [4] DEBUG DotCMIS.Binding.AtomPub.ObjectService [(null)] - Link: https://avenue.aegif.jp:11222/alfresco/api/-default-/public/cmis/versions/1.1/atom/content/file.doc?id=0c195dd9-73c8-4f09-9ef8-b481829578df%3B1.0
2019-03-22 13:18:21,723 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:21,820 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:21,821 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - before SetContentStream
2019-03-22 13:18:21,847 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:21,988 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:21,989 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:22,070 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:22,071 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - after SetContentStream
2019-03-22 13:18:22,082 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:22,152 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:22,697 [4] INFO  CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Updated: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data\file.doc
2019-03-22 13:18:22,697 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Finished applying local changes.
2019-03-22 13:18:22,699 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - Invoke a remote change log sync
2019-03-22 13:18:22,699 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:24,847 [4] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:24,893 [4] DEBUG CmisSync.Lib.Cmis.CmisUtils [(null)] - Server:Alfresco Community token: 45085351
2019-03-22 13:18:24,893 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - No changes to sync, tokens on server and client are equal: "45085351"
2019-03-22 13:18:24,893 [4] INFO  CmisSync.Lib.RepoBase [(null)] - Sync Complete: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data , success=True
2019-03-22 13:18:26,013 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: IsSyncing(): True
2019-03-22 13:18:26,013 [7] INFO  CmisSync.Lib.RepoBase [(null)] -  Sync Started: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:26,014 [7] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:26,486 [7] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:26,493 [7] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - About to call conn.GetResponse() with HttpWebRequest.Timeout=3600000ms and HttpWebRequest.ReadWriteTimeout=21600000ms
2019-03-22 13:18:26,533 [7] DEBUG DotCMIS.Binding.Impl.HttpUtils [(null)] - conn.GetResponse() result: System.Net.HttpWebResponse
2019-03-22 13:18:26,537 [7] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - 0 local changes to apply.
2019-03-22 13:18:31,014 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:36,022 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:41,024 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:46,025 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:51,026 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:18:56,028 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:01,029 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:06,030 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:11,035 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:16,038 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:21,039 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:26,040 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:31,040 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:36,041 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:41,042 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:46,043 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:51,044 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:19:56,047 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:20:01,050 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:20:06,052 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:20:11,052 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:20:16,053 [5] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:20:21,054 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:20:26,055 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data
2019-03-22 13:20:31,056 [4] DEBUG CmisSync.Lib.Sync.CmisRepo+SynchronizedFolder [(null)] - SyncInBackground: Sync already running in background: C:\Users\nico\AppData\Local\Temp\CmisSync_test_3pv0ingb.s1t\data

Maybe the The process cannot access the file error prevented a sync loop from returning correctly?