Desktop Client does not update local file if opened in Excel, Word or Powerpoint

[kliess]

Steps to reproduce

1. Create a Microsoft Office file (Word, Excel Powerpoint, doc, docx,
   xls, xlsx, ppt, pptx, ...) and upload it to Owncloud
2. Sync the file with the Owncloud Desktop Client to a Windows PC
3. On the Windows PC: Open the file in the local file system with
   Microsoft Office (Word, Powerpoint or Excel) - without changing anything
4. Change the file on the server during the file is still opened in the
   local file system (from another PC or upload a changed file with the
   same name to the web frontend)
5. Close the file in the local file system (close the Microsoft Office
   program)

Expected behaviour
The desktop client should update the file in the local file system with
the changed version from the server .

Actual behaviour
The desktop client does not change the file in the local file system.
But the activity protocol in the desktop client says that the file is
downloaded.
In reality nothing happens, even when you wait longer. No update happens
if you close the local copy. Also it is not possible to force an update
or any information of a sync conflict.

Client configuration
Client version: 2.2.3 (build 6307)
Client operating system: Windows 10

Server configuration
Operating system: Ubuntu 14.04.5 LTS
Web server: Apache/2.4.7 (Ubuntu)
Database: mysql Ver 14.14 Distrib 5.5.50
PHP version: PHP Version 5.5.9-1ubuntu4.19
ownCloud version (see ownCloud admin page): 9.0.4
Updated from an older ownCloud or fresh install: Updated
ownCloud log (data/owncloud.log): nothing special

Special configurations (external storage, external authentication,
reverse proxy, server-side-encryption): NO

This behaviour was discussed in 2014 - but it is still not solved:
Files in local folders not being updated
https://forum.owncloud.org/viewtopic.php?t=22299

[dragotin]

I just tested this with oC client 2.2.2 running on Windows 10. With Word 2016, the file is properly downloaded after Word was closed.

[dragotin]

Also tested with oC client 2.2.3, works also as expected: As soon as Word was closed, the file was downloaded.
Which MS Office version do you use? Maybe that plays a role?

[kliess]

I tested it now with Office 2016. But it has nothing todo with the MS Office version. The strange thing is that it works sometimes correct and sometimes not. This is the client log (F12) for a not working example with the test file "TestC.docx":

09-21 07:53:11:730 0x4da7660 OCC::Folder::slotRunEtagJob: * Trying to check "https://myserver.org/owncloud/remote.php/webdav/" for changes via ETag check. (time since last sync: 177 s)
09-21 07:53:11:740 0x4da7660 OCC::FolderMan::slotRunOneEtagJob: Scheduling "https://myserver.org/owncloud/remote.php/webdav/" to check remote ETag
09-21 07:53:11:741 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for "https://myserver.org/owncloud" + "/" "OCC::Folder"
09-21 07:53:12:181 0x4da7660 OCC::Folder::etagRetreived: * Compare etag with previous etag: last: ""d060e94dfe87533b68613d9fbb1bbfd7"" , received: ""67b2bca794976ac745b7ad18b014ea3f"" -> CHANGED
09-21 07:53:12:181 0x4da7660 OCC::FolderMan::slotScheduleSync: Schedule folder  "1"  to sync!
09-21 07:53:12:181 0x4da7660 OCC::SocketApi::slotUpdateFolderView: Not sending UPDATE_VIEW for "1" because status() is 1
09-21 07:53:12:181 0x4da7660 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "https://myserver.org/owncloud/remote.php/webdav/" :  "Not yet Started"
09-21 07:53:12:181 0x4da7660 OCC::ActivityListModel::startFetchJob: void OCC::ActivityListModel::startFetchJob(OCC::AccountState*) Start fetching activities for  "user2@myserver.org"
09-21 07:53:12:181 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::JsonApiJob created for "https://myserver.org/owncloud" + "ocs/v1.php/cloud/activity" "OCC::ActivityListModel"
09-21 07:53:12:181 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::JsonApiJob created for "https://myserver.org/owncloud" + "ocs/v2.php/apps/notifications/api/v1/notifications" "OCC::ServerNotificationHandler"
09-21 07:53:12:181 0x4da7660 OCC::FolderMan::startScheduledSyncSoon: Scheduling a sync in 2 seconds
09-21 07:53:14:181 0x4da7660 OCC::FolderMan::slotStartScheduledFolderSync: XX slotScheduleFolderSync: folderQueue size:  1
09-21 07:53:14:181 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud"
09-21 07:53:14:181 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "UPDATE_VIEW:C:\Users\user1\ownCloud"
09-21 07:53:14:181 0x4da7660 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "https://myserver.org/owncloud/remote.php/webdav/" :  "SyncPrepare"
09-21 07:53:14:181 0x4da7660 OCC::Folder::startSync: *** Start syncing  "https://myserver.org/owncloud/remote.php/webdav/"  - client version 2.2.3 (build 6307)
09-21 07:53:14:181 0x4da7660 OCC::Folder::setIgnoredFiles: ==== adding system ignore list to csync: "C:/Program Files (x86)/ownCloud/sync-exclude.lst"
09-21 07:53:14:181 0x4da7660 OCC::FolderMan::slotFolderSyncStarted: >===================================== sync started for  "https://myserver.org/owncloud/remote.php/webdav/"
09-21 07:53:14:181 0x4da7660 OCC::SyncEngine::startSync: There are 4456185856 bytes available at "C:/Users/user1/ownCloud/" and at least 50000000 are required
09-21 07:53:14:181 0x4da7660 OCC::SyncEngine::startSync: =====sync with existing DB
09-21 07:53:14:181 0x4da7660 OCC::SyncEngine::startSync: =====Using Qt 5.4.0
09-21 07:53:14:181 0x4da7660 OCC::SyncEngine::startSync: =====Using SSL library version OpenSSL 1.0.2h  3 May 2016
09-21 07:53:14:181 0x4da7660 OCC::SyncEngine::startSync: void OCC::SyncEngine::startSync() ====Using Selective Sync
09-21 07:53:14:181 0x4da7660 OCC::SyncEngine::startSync: #### Discovery start #################################################### >>
09-21 07:53:14:197 0x4da7660 OCC::SyncEngine::startSync: =====Server "9.0.4.1" "rootEtagChangesNotOnlySubFolderEtags=1"
09-21 07:53:14:197 0x4da7660 OCC::SyncEngine::startSync: void OCC::SyncEngine::startSync() "/"  QUrl( "https://myserver.org/owncloud/remote.php/webdav/" ) 
09-21 07:53:14:197 0x73ba2e0 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x9ecb190)  Calling into main thread...
09-21 07:53:14:197 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::LsColJob created for "https://myserver.org/owncloud" + "" "OCC::DiscoverySingleDirectoryJob"
09-21 07:53:14:341 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:53:14:342 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:53:14:343 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test3.docx"
09-21 07:53:14:344 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test3.docx"
09-21 07:53:14:344 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel-1.xlsx"
09-21 07:53:14:344 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel-1.xlsx"
09-21 07:53:14:344 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test1.docx"
09-21 07:53:14:344 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test1.docx"
09-21 07:53:14:353 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test2.docx"
09-21 07:53:14:353 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test2.docx"
09-21 07:53:14:353 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel.xlsx"
09-21 07:53:14:353 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel.xlsx"
09-21 07:53:14:353 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel (2).xlsx"
09-21 07:53:14:353 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel (2).xlsx"
09-21 07:53:14:353 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\~$TestC.docx"
09-21 07:53:14:353 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:IGNORE:C:\Users\user1\ownCloud\Top1\SubTop1\~$TestC.docx"
09-21 07:53:14:556 0x4da7660 OCC::DiscoveryMainThread::singleDirectoryJobFirstDirectoryPermissionsSlot: Permissions for root dir: "RDNVCK"
09-21 07:53:14:556 0x4da7660 OCC::DiscoveryMainThread::singleDirectoryJobResultSlot: void OCC::DiscoveryMainThread::singleDirectoryJobResultSlot(const QList<OCC::FileStatPointer>&) Have 17 results for  ""
09-21 07:53:14:556 0x73ba2e0 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x9ecb190)  ...Returned from main thread
09-21 07:53:14:556 0x73ba2e0 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x9ecb190) Top1 Calling into main thread...
09-21 07:53:14:572 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::LsColJob created for "https://myserver.org/owncloud" + "/Top1" "OCC::DiscoverySingleDirectoryJob"
09-21 07:53:14:869 0x4da7660 OCC::DiscoveryMainThread::singleDirectoryJobResultSlot: void OCC::DiscoveryMainThread::singleDirectoryJobResultSlot(const QList<OCC::FileStatPointer>&) Have 6 results for  "/Top1"
09-21 07:53:14:869 0x73ba2e0 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x9ecb190) Top1 ...Returned from main thread
09-21 07:53:14:869 0x73ba2e0 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x9ecb190) Top1/SubTop1 Calling into main thread...
09-21 07:53:14:869 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::LsColJob created for "https://myserver.org/owncloud" + "/Top1/SubTop1" "OCC::DiscoverySingleDirectoryJob"
09-21 07:53:15:322 0x4da7660 OCC::DiscoveryMainThread::singleDirectoryJobResultSlot: void OCC::DiscoveryMainThread::singleDirectoryJobResultSlot(const QList<OCC::FileStatPointer>&) Have 7 results for  "/Top1/SubTop1"
09-21 07:53:15:322 0x73ba2e0 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x9ecb190) Top1/SubTop1 ...Returned from main thread
09-21 07:53:15:322 0x73ba2e0 OCC::DiscoveryJob::remote_vio_closedir_hook: static void OCC::DiscoveryJob::remote_vio_closedir_hook(csync_vio_handle_t*, void*) OCC::DiscoveryJob(0x9ecb190) "/Top1/SubTop1"
09-21 07:53:15:322 0x73ba2e0 OCC::DiscoveryJob::remote_vio_closedir_hook: static void OCC::DiscoveryJob::remote_vio_closedir_hook(csync_vio_handle_t*, void*) OCC::DiscoveryJob(0x9ecb190) "/Top1"
09-21 07:53:15:322 0x73ba2e0 OCC::DiscoveryJob::remote_vio_closedir_hook: static void OCC::DiscoveryJob::remote_vio_closedir_hook(csync_vio_handle_t*, void*) OCC::DiscoveryJob(0x9ecb190) ""
09-21 07:53:15:342 0x4da7660 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Discovery end ####################################################  1145
09-21 07:53:15:348 0x4da7660 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Reconcile end ####################################################  1152
09-21 07:53:15:348 0x4da7660 OCC::SyncEngine::slotDiscoveryJobFinished: Permissions of the root folder:  "RDNVCK"
09-21 07:53:15:348 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC+SWM:C:\Users\user1\ownCloud\Top1"
09-21 07:53:15:348 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC+SWM:C:\Users\user1\ownCloud\Top1\SubTop1"
09-21 07:53:15:353 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:53:15:353 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud\Top1\SubTop1\~$TestC.docx"
09-21 07:53:15:353 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "post treewalk" and starting new transaction
09-21 07:53:15:353 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "post stale entry removal" and starting new transaction
09-21 07:53:15:353 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC:C:\Users\user1\ownCloud\"
09-21 07:53:15:353 0x4da7660 OCC::OwncloudPropagator::start: Using QNAM/HTTP parallel code path
09-21 07:53:15:353 0x4da7660 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Post-Reconcile end ####################################################  1170
09-21 07:53:15:369 0x4da7660 OCC::Folder::slotSyncStarted: #### Propagation start #################################################### >>
09-21 07:53:15:369 0x4da7660 OCC::SocketApi::slotUpdateFolderView: Not sending UPDATE_VIEW for "1" because status() is 3
09-21 07:53:15:384 0x4da7660 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "https://myserver.org/owncloud/remote.php/webdav/" :  "Sync Running"
09-21 07:53:15:384 0x4da7660 OCC::PropagateDownloadFileQNAM::start: virtual void OCC::PropagateDownloadFileQNAM::start() "Top1/SubTop1/TestC.docx" 0
09-21 07:53:15:384 0x4da7660 OCC::OwncloudPropagator::localFileNameClash: CaseClashCheck for  "C:/Users/user1/ownCloud/Top1/SubTop1/TestC.docx"
09-21 07:53:15:384 0x4da7660 OCC::SyncJournalDb::setDownloadInfo: "INSERT OR REPLACE INTO downloadinfo (path, tmpfile, etag, errorcount) VALUES ( ?1 , ?2, ?3, ?4 )" "Top1/SubTop1/TestC.docx" "Top1/SubTop1/.TestC.docx.~44c8" "2d653f0abbcecc2d2c04325c43068cda" 0
09-21 07:53:15:384 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "download file start" and starting new transaction
09-21 07:53:15:416 0x4da7660 OCC::GETFileJob::start: virtual void OCC::GETFileJob::start() OCC::BandwidthManager(0x78396b0) false false
09-21 07:53:15:416 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::GETFileJob created for "https://myserver.org/owncloud" + "/Top1/SubTop1/TestC.docx" ""
09-21 07:53:15:431 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/Top1/SubTop1/.TestC.docx.~44c8"
09-21 07:53:15:431 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-wal"
09-21 07:53:15:431 0x4da7660 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "Top1/SubTop1/~$TestC.docx" INSTRUCTION_IGNORE 6 "Die Datei ist in der Ignorierliste geführt."
09-21 07:53:15:431 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:IGNORE:C:\Users\user1\ownCloud\Top1\SubTop1\~$TestC.docx"
09-21 07:53:15:541 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\.TestC.docx.~44c8"
09-21 07:53:15:543 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:IGNORE:C:\Users\user1\ownCloud\Top1\SubTop1\.TestC.docx.~44c8"
09-21 07:53:15:650 0x4da7660 OCC::PropagateDownloadFileQNAM::slotGetFinished: void OCC::PropagateDownloadFileQNAM::slotGetFinished()  QUrl( "https://myserver.org/owncloud/remote.php/webdav/Top1/SubTop1/TestC.docx" )  FINISHED WITH STATUS 0 "" 0 4084 4084 0 "" "4084"
09-21 07:53:15:650 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/Top1/SubTop1/.TestC.docx.~44c8"
09-21 07:53:15:650 0x4da7660 OCC::OwncloudPropagator::localFileNameClash: CaseClashCheck for  "C:/Users/user1/ownCloud/Top1/SubTop1/TestC.docx"
09-21 07:53:15:666 0x4da7660 OCC::FileSystem::uncheckedRenameReplace: FAIL: renaming temp file to final failed:  "Zugriff verweigert
"
09-21 07:53:15:666 0x4da7660 OCC::PropagateDownloadFileQNAM::downloadFinished: void OCC::PropagateDownloadFileQNAM::downloadFinished() "Rename failed: C:/Users/user1/ownCloud/Top1/SubTop1/.TestC.docx.~44c8 => C:/Users/user1/ownCloud/Top1/SubTop1/TestC.docx"
09-21 07:53:15:666 0x4da7660 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "Top1/SubTop1/TestC.docx" INSTRUCTION_SYNC 3 "Zugriff verweigert
"
09-21 07:53:15:666 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:53:15:666 0x4da7660 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "Top1/SubTop1" INSTRUCTION_SYNC 4 ""
09-21 07:53:15:666 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1"
09-21 07:53:15:681 0x4da7660 OCC::SyncJournalFileRecord::SyncJournalFileRecord: OCC::SyncJournalFileRecord::SyncJournalFileRecord(const OCC::SyncFileItem&, const QString&) "C:/Users/user1/ownCloud/Top1" Retrieved inode  85080 (previous item inode:  0 )
09-21 07:53:15:681 0x4da7660 OCC::SyncJournalDb::setFileRecord: "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm, filesize, ignoredChildrenRemote, contentChecksum, contentChecksumTypeId) VALUES (?1 , ?2, ?3 , ?4 , ?5 , ?6 , ?7,  ?8 , ?9 , ?10, ?11, ?12, ?13, ?14, ?15, ?16);" 5534610839700273652 4 "Top1" 85080 "1474437187" "2" "57e2204330303" "00019668ocg75vbca45t" "SRDNVCK" 0 0 "" "" 0
09-21 07:53:15:681 0x4da7660 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "Top1" INSTRUCTION_SYNC 4 ""
09-21 07:53:15:681 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1"
09-21 07:53:15:681 0x4da7660 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "" INSTRUCTION_NONE 4 ""
09-21 07:53:15:681 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud"
09-21 07:53:15:697 0x4da7660 OCC::SyncJournalDb::walCheckpoint: void OCC::SyncJournalDb::walCheckpoint() took 0 msec
09-21 07:53:15:697 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "All Finished." 
09-21 07:53:15:697 0x4da7660 OCC::SyncJournalDb::close: void OCC::SyncJournalDb::close() "C:/Users/user1/ownCloud/.csync_journal.db"
09-21 07:53:15:697 0x4da7660 OCC::SyncJournalDb::commitTransaction: No database Transaction to commit
09-21 07:53:15:697 0x4da7660 OCC::SyncEngine::finalize: CSync run took  1511
09-21 07:53:15:697 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud\"
09-21 07:53:15:697 0x4da7660 OCC::BandwidthManager::~BandwidthManager: virtual OCC::BandwidthManager::~BandwidthManager()
09-21 07:53:15:697 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-wal"
09-21 07:53:15:697 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db"
09-21 07:53:15:697 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-shm"
09-21 07:53:15:697 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-wal"
09-21 07:53:15:697 0x4da7660 OCC::Folder::slotSyncFinished:  - client version 2.2.3 (build 6307)  Qt 5.4.0  SSL  OpenSSL 1.0.2h  3 May 2016
09-21 07:53:15:712 0x4da7660 OCC::Folder::slotSyncFinished: -> SyncEngine finished without problem.
09-21 07:53:15:712 0x4da7660 OCC::Folder::bubbleUpSyncResult: Processing result list and logging took  0  Milliseconds.
09-21 07:53:15:712 0x4da7660 OCC::Folder::bubbleUpSyncResult: OO folder slotSyncFinished: result:  3
09-21 07:53:15:712 0x4da7660 OCC::SyncJournalDb::checkConnect: sqlite3 version "3.13.0"
09-21 07:53:15:712 0x4da7660 OCC::defaultJournalMode: Detected filesystem "NTFS" for "C:/Users/user1/ownCloud/.csync_journal.db"
09-21 07:53:15:712 0x4da7660 OCC::SyncJournalDb::checkConnect: sqlite3 journal_mode= "wal"
09-21 07:53:15:712 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "checkConnect" and starting new transaction
09-21 07:53:15:712 0x4da7660 OCC::SyncJournalDb::tableColumns: Columns in the current journal:  ("phash", "pathlen", "path", "inode", "uid", "gid", "mode", "modtime", "type", "md5", "fileid", "remotePerm", "filesize", "ignoredChildrenRemote", "contentChecksum", "contentChecksumTypeId")
09-21 07:53:15:712 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "update database structure: add inode index" and starting new transaction
09-21 07:53:15:712 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "update database structure: add path index" and starting new transaction
09-21 07:53:15:712 0x4da7660 OCC::SyncJournalDb::tableColumns: Columns in the current journal:  ("path", "lastTryEtag", "lastTryModtime", "retrycount", "errorstring", "lastTryTime", "ignoreDuration", "renameTarget")
09-21 07:53:15:712 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "checkConnect End" 
09-21 07:53:15:712 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud"
09-21 07:53:15:712 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "UPDATE_VIEW:C:\Users\user1\ownCloud"
09-21 07:53:15:728 0x4da7660 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "https://myserver.org/owncloud/remote.php/webdav/" :  "Success"
09-21 07:53:15:733 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.owncloudsync.log"
09-21 07:53:15:734 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-wal"
09-21 07:53:15:735 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-shm"
09-21 07:53:15:792 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test3.docx"
09-21 07:53:15:794 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test3.docx"
09-21 07:53:15:795 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test2.docx"
09-21 07:53:15:796 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test2.docx"
09-21 07:53:15:799 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test1.docx"
09-21 07:53:15:800 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test1.docx"
09-21 07:53:15:801 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel.xlsx"
09-21 07:53:15:802 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel.xlsx"
09-21 07:53:15:805 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel-1.xlsx"
09-21 07:53:15:806 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel-1.xlsx"
09-21 07:53:15:806 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel (2).xlsx"
09-21 07:53:15:807 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel (2).xlsx"
09-21 07:53:15:811 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\.TestC.docx.~44c8"
09-21 07:53:15:811 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:IGNORE:C:\Users\user1\ownCloud\Top1\SubTop1\.TestC.docx.~44c8"
09-21 07:53:15:815 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:53:15:816 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:53:15:818 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\~$TestC.docx"
09-21 07:53:15:819 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:IGNORE:C:\Users\user1\ownCloud\Top1\SubTop1\~$TestC.docx"
09-21 07:53:15:929 0x4da7660 OCC::FolderMan::slotFolderSyncFinished: <===================================== sync finished for  "https://myserver.org/owncloud/remote.php/webdav/"
09-21 07:54:06:401 0x4da7660 OCC::ConnectionValidator::checkAuthentication: # Check whether authenticated propfind works.
09-21 07:54:06:403 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::PropfindJob created for "https://myserver.org/owncloud" + "/" "OCC::ConnectionValidator"
09-21 07:54:11:744 0x4da7660 OCC::Folder::slotRunEtagJob: * Trying to check "https://myserver.org/owncloud/remote.php/webdav/" for changes via ETag check. (time since last sync: 56 s)
09-21 07:54:11:744 0x4da7660 OCC::FolderMan::slotRunOneEtagJob: Scheduling "https://myserver.org/owncloud/remote.php/webdav/" to check remote ETag
09-21 07:54:11:744 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for "https://myserver.org/owncloud" + "/" "OCC::Folder"
09-21 07:54:41:745 0x4da7660 OCC::Folder::slotRunEtagJob: * Trying to check "https://myserver.org/owncloud/remote.php/webdav/" for changes via ETag check. (time since last sync: 86 s)
09-21 07:54:41:750 0x4da7660 OCC::FolderMan::slotRunOneEtagJob: Scheduling "https://myserver.org/owncloud/remote.php/webdav/" to check remote ETag
09-21 07:54:41:751 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for "https://myserver.org/owncloud" + "/" "OCC::Folder"
09-21 07:54:54:009 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/Top1/SubTop1/~$TestC.docx"
09-21 07:55:11:760 0x4da7660 OCC::Folder::slotRunEtagJob: * Trying to check "https://myserver.org/owncloud/remote.php/webdav/" for changes via ETag check. (time since last sync: 116 s)
09-21 07:55:11:760 0x4da7660 OCC::FolderMan::slotRunOneEtagJob: Scheduling "https://myserver.org/owncloud/remote.php/webdav/" to check remote ETag
09-21 07:55:11:760 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for "https://myserver.org/owncloud" + "/" "OCC::Folder"
09-21 07:55:11:838 0x4da7660 OCC::FolderMan::slotScheduleSync: Schedule folder  "1"  to sync!
09-21 07:55:11:838 0x4da7660 OCC::SocketApi::slotUpdateFolderView: Not sending UPDATE_VIEW for "1" because status() is 1
09-21 07:55:11:838 0x4da7660 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "https://myserver.org/owncloud/remote.php/webdav/" :  "Not yet Started"
09-21 07:55:11:838 0x4da7660 OCC::ActivityListModel::startFetchJob: void OCC::ActivityListModel::startFetchJob(OCC::AccountState*) Start fetching activities for  "user2@myserver.org"
09-21 07:55:11:838 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::JsonApiJob created for "https://myserver.org/owncloud" + "ocs/v1.php/cloud/activity" "OCC::ActivityListModel"
09-21 07:55:11:853 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::JsonApiJob created for "https://myserver.org/owncloud" + "ocs/v2.php/apps/notifications/api/v1/notifications" "OCC::ServerNotificationHandler"
09-21 07:55:11:853 0x4da7660 OCC::FolderMan::startScheduledSyncSoon: Scheduling a sync in 2 seconds
09-21 07:55:13:853 0x4da7660 OCC::FolderMan::slotStartScheduledFolderSync: XX slotScheduleFolderSync: folderQueue size:  1
09-21 07:55:13:853 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud"
09-21 07:55:13:853 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "UPDATE_VIEW:C:\Users\user1\ownCloud"
09-21 07:55:13:853 0x4da7660 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "https://myserver.org/owncloud/remote.php/webdav/" :  "SyncPrepare"
09-21 07:55:13:853 0x4da7660 OCC::Folder::startSync: *** Start syncing  "https://myserver.org/owncloud/remote.php/webdav/"  - client version 2.2.3 (build 6307)
09-21 07:55:13:853 0x4da7660 OCC::Folder::setIgnoredFiles: ==== adding system ignore list to csync: "C:/Program Files (x86)/ownCloud/sync-exclude.lst"
09-21 07:55:13:853 0x4da7660 OCC::FolderMan::slotFolderSyncStarted: >===================================== sync started for  "https://myserver.org/owncloud/remote.php/webdav/"
09-21 07:55:13:869 0x4da7660 OCC::SyncEngine::startSync: There are 4455747584 bytes available at "C:/Users/user1/ownCloud/" and at least 50000000 are required
09-21 07:55:13:869 0x4da7660 OCC::SyncEngine::startSync: =====sync with existing DB
09-21 07:55:13:869 0x4da7660 OCC::SyncEngine::startSync: =====Using Qt 5.4.0
09-21 07:55:13:869 0x4da7660 OCC::SyncEngine::startSync: =====Using SSL library version OpenSSL 1.0.2h  3 May 2016
09-21 07:55:13:869 0x4da7660 OCC::SyncEngine::startSync: void OCC::SyncEngine::startSync() ====Using Selective Sync
09-21 07:55:13:869 0x4da7660 OCC::SyncEngine::startSync: #### Discovery start #################################################### >>
09-21 07:55:13:869 0x4da7660 OCC::SyncEngine::startSync: =====Server "9.0.4.1" "rootEtagChangesNotOnlySubFolderEtags=1"
09-21 07:55:13:869 0x4da7660 OCC::SyncEngine::startSync: void OCC::SyncEngine::startSync() "/"  QUrl( "https://myserver.org/owncloud/remote.php/webdav/" ) 
09-21 07:55:13:869 0x73ba2e0 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x7308228)  Calling into main thread...
09-21 07:55:13:891 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::LsColJob created for "https://myserver.org/owncloud" + "" "OCC::DiscoverySingleDirectoryJob"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\.TestC.docx.~44c8"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:IGNORE:C:\Users\user1\ownCloud\Top1\SubTop1\.TestC.docx.~44c8"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel (2).xlsx"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel (2).xlsx"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel.xlsx"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel.xlsx"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel-1.xlsx"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel-1.xlsx"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test1.docx"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test1.docx"
09-21 07:55:14:073 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test2.docx"
09-21 07:55:14:088 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test2.docx"
09-21 07:55:14:091 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test3.docx"
09-21 07:55:14:092 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test3.docx"
09-21 07:55:14:092 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:55:14:092 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:55:14:213 0x4da7660 OCC::DiscoveryMainThread::singleDirectoryJobFirstDirectoryPermissionsSlot: Permissions for root dir: "RDNVCK"
09-21 07:55:14:213 0x4da7660 OCC::DiscoveryMainThread::singleDirectoryJobResultSlot: void OCC::DiscoveryMainThread::singleDirectoryJobResultSlot(const QList<OCC::FileStatPointer>&) Have 17 results for  ""
09-21 07:55:14:213 0x73ba2e0 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x7308228)  ...Returned from main thread
09-21 07:55:14:213 0x73ba2e0 OCC::DiscoveryJob::remote_vio_closedir_hook: static void OCC::DiscoveryJob::remote_vio_closedir_hook(csync_vio_handle_t*, void*) OCC::DiscoveryJob(0x7308228) ""
09-21 07:55:14:213 0x4da7660 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Discovery end ####################################################  354
09-21 07:55:14:228 0x4da7660 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Reconcile end ####################################################  356
09-21 07:55:14:228 0x4da7660 OCC::SyncEngine::slotDiscoveryJobFinished: Permissions of the root folder:  "RDNVCK"
09-21 07:55:14:228 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:IGNORE:C:\Users\user1\ownCloud\Top1\SubTop1\~$TestC.docx"
09-21 07:55:14:228 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "post treewalk" and starting new transaction
09-21 07:55:14:228 0x4da7660 OCC::deleteBatch: Removing stale  downloadinfo  entries:  "Top1/SubTop1/TestC.docx"
09-21 07:55:14:228 0x4da7660 OCC::SyncEngine::deleteStaleDownloadInfos: Deleting stale temporary file:  "C:/Users/user1/ownCloud/Top1/SubTop1/.TestC.docx.~44c8"
09-21 07:55:14:228 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "post stale entry removal" and starting new transaction
09-21 07:55:14:228 0x4da7660 OCC::OwncloudPropagator::start: Using QNAM/HTTP parallel code path
09-21 07:55:14:228 0x4da7660 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Post-Reconcile end ####################################################  367
09-21 07:55:14:228 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/Top1/SubTop1/.TestC.docx.~44c8"
09-21 07:55:14:228 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-wal"
09-21 07:55:14:228 0x4da7660 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "" INSTRUCTION_NONE 4 ""
09-21 07:55:14:244 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud"
09-21 07:55:14:244 0x4da7660 OCC::SyncJournalDb::walCheckpoint: void OCC::SyncJournalDb::walCheckpoint() took 0 msec
09-21 07:55:14:244 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "All Finished." 
09-21 07:55:14:244 0x4da7660 OCC::SyncJournalDb::close: void OCC::SyncJournalDb::close() "C:/Users/user1/ownCloud/.csync_journal.db"
09-21 07:55:14:244 0x4da7660 OCC::SyncJournalDb::commitTransaction: No database Transaction to commit
09-21 07:55:14:244 0x4da7660 OCC::SyncEngine::finalize: CSync run took  384
09-21 07:55:14:244 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud\"
09-21 07:55:14:244 0x4da7660 OCC::BandwidthManager::~BandwidthManager: virtual OCC::BandwidthManager::~BandwidthManager()
09-21 07:55:14:259 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db"
09-21 07:55:14:259 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-shm"
09-21 07:55:14:259 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-wal"
09-21 07:55:14:259 0x4da7660 OCC::Folder::slotSyncFinished:  - client version 2.2.3 (build 6307)  Qt 5.4.0  SSL  OpenSSL 1.0.2h  3 May 2016
09-21 07:55:14:259 0x4da7660 OCC::Folder::slotSyncFinished: -> SyncEngine finished without problem.
09-21 07:55:14:259 0x4da7660 OCC::Folder::bubbleUpSyncResult: Processing result list and logging took  0  Milliseconds.
09-21 07:55:14:259 0x4da7660 OCC::Folder::bubbleUpSyncResult: OO folder slotSyncFinished: result:  2
09-21 07:55:14:259 0x4da7660 OCC::SyncJournalDb::checkConnect: sqlite3 version "3.13.0"
09-21 07:55:14:259 0x4da7660 OCC::defaultJournalMode: Detected filesystem "NTFS" for "C:/Users/user1/ownCloud/.csync_journal.db"
09-21 07:55:14:259 0x4da7660 OCC::SyncJournalDb::checkConnect: sqlite3 journal_mode= "wal"
09-21 07:55:14:259 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "checkConnect" and starting new transaction
09-21 07:55:14:259 0x4da7660 OCC::SyncJournalDb::tableColumns: Columns in the current journal:  ("phash", "pathlen", "path", "inode", "uid", "gid", "mode", "modtime", "type", "md5", "fileid", "remotePerm", "filesize", "ignoredChildrenRemote", "contentChecksum", "contentChecksumTypeId")
09-21 07:55:14:259 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "update database structure: add inode index" and starting new transaction
09-21 07:55:14:259 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "update database structure: add path index" and starting new transaction
09-21 07:55:14:259 0x4da7660 OCC::SyncJournalDb::tableColumns: Columns in the current journal:  ("path", "lastTryEtag", "lastTryModtime", "retrycount", "errorstring", "lastTryTime", "ignoreDuration", "renameTarget")
09-21 07:55:14:259 0x4da7660 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "checkConnect End" 
09-21 07:55:14:259 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\user1\ownCloud"
09-21 07:55:14:259 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "UPDATE_VIEW:C:\Users\user1\ownCloud"
09-21 07:55:14:275 0x4da7660 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "https://myserver.org/owncloud/remote.php/webdav/" :  "Success"
09-21 07:55:14:283 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.owncloudsync.log"
09-21 07:55:14:283 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-wal"
09-21 07:55:14:284 0x4da7660 OCC::FolderWatcher::pathIsIgnored: * Ignoring file "C:/Users/user1/ownCloud/.csync_journal.db-shm"
09-21 07:55:14:378 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel (2).xlsx"
09-21 07:55:14:379 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel (2).xlsx"
09-21 07:55:14:380 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel.xlsx"
09-21 07:55:14:381 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel.xlsx"
09-21 07:55:14:384 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test excel-1.xlsx"
09-21 07:55:14:384 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test excel-1.xlsx"
09-21 07:55:14:385 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test1.docx"
09-21 07:55:14:386 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test1.docx"
09-21 07:55:14:389 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test2.docx"
09-21 07:55:14:390 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test2.docx"
09-21 07:55:14:391 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\test3.docx"
09-21 07:55:14:392 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\test3.docx"
09-21 07:55:14:395 0x4da7660 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString&, QIODevice*) "C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:55:14:396 0x4da7660 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK+SWM:C:\Users\user1\ownCloud\Top1\SubTop1\TestC.docx"
09-21 07:55:14:476 0x4da7660 OCC::FolderMan::slotFolderSyncFinished: <===================================== sync finished for  "https://myserver.org/owncloud/remote.php/webdav/"
09-21 07:55:28:504 0x4da7660 OCC::ActivityListModel::startFetchJob: void OCC::ActivityListModel::startFetchJob(OCC::AccountState*) Start fetching activities for  "user2@myserver.org"
09-21 07:55:28:507 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::JsonApiJob created for "https://myserver.org/owncloud" + "ocs/v1.php/cloud/activity" "OCC::ActivityListModel"
09-21 07:55:28:509 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::JsonApiJob created for "https://myserver.org/owncloud" + "ocs/v2.php/apps/notifications/api/v1/notifications" "OCC::ServerNotificationHandler"
09-21 07:56:11:791 0x4da7660 OCC::Folder::slotRunEtagJob: * Trying to check "https://myserver.org/owncloud/remote.php/webdav/" for changes via ETag check. (time since last sync: 57 s)
09-21 07:56:11:791 0x4da7660 OCC::FolderMan::slotRunOneEtagJob: Scheduling "https://myserver.org/owncloud/remote.php/webdav/" to check remote ETag
09-21 07:56:11:791 0x4da7660 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for "https://myserver.org/owncloud" + "/" "OCC::Folder"

One thing I do not understand: If I open the file "TestC.docx" in the local file system Word generates a temp file with the name "$TestC.docx". After I Update the file on the server Owncloud deletes the file "$TestC.docx" and generates a new file ".TestC.docx.~44c8". When I close the "TestC.docx" the file ".TestC.docx.~44c8" is deleted and the file "TestC.docx" is unchanged.

[ckamm]

@kliess @dragotin What I see happening is this:

• "~TestC.docx" is Word's temporary file. The client ignores that completely. It never touches or deletes it.
• The client sees the change on the server and downloads the server's version to ".TestC.docx.~44c8".
• It can't rename the file to "TestC.docx" because it's locked by Word (Error: "Zugriff verweigert")
• Presumably this makes the file get added to the lock-watcher - but unfortunately we have no log message about that. I'll add one to help with debugging this in the future.
• In the second sync "TestC.docx" doesn't get mentioned as needing sync - that's really surprising! @kliess It looks like you cut a bunch of lines from the log, could you include all lines mentioning TestC.docx or send the full log to me at mail at ckamm dot de?
• Also, the temporary download file gets removed during stale download file deletion - that's a side effect of reconcile not marking it as needing to be downloaded.

[brodya]

I have the same problem.
Forum topic https://central.owncloud.org/t/the-client-is-not-synchronized-access-denied/2640
This occurs when the file "TestC.docx" is read-only, so the temporary file ".TestC.docx.~44c8" also has the attribute "read only". Therefore, the client can not change it. If the temporary file ".TestC.docx.~44c8" to remove the attribute "Read-only", then everything works. So you should never set the attribute for temporary files.

[kliess]

Now I know how to reproduce this issue: It occurs only if the file is inside a shared subfolder. To reproduce the issue please use the following steps:

1. Create two users: wi1 and wi2
2. Under wi1 in owncloud: create a folder "TestF" with a subfolder "TestFSub", put a file "TestF.docx" in folder "TestF" and the file "TestFSub.docx" in subfolder "TestFSub"
3. Share the top-folder "TestF" with user "wi2"
4. Open in the local file system under "wi2" the file "TestF.docx"
5. Change "TestF.docx" as wi1 on the server
6. Close in the local file system under "wi2" the file "TestF.docx"
7. The file "TestF.docx" will be updated correct - everything is fine until now.

BUT:

1. Open in the local file system under "wi2" the file "TestFsub.docx" (this is the file inside the subfolder)
2. Change "TestFsub.docx" as wi1 on the server
3. Close in the local file system under "wi2" the file "TestFsub.docx"
4. The file "TestFsub.docx" will NOT be updated!!!

[ckamm]

@brodya Are you saying you believe this fails because the read-only temporary .TestC.docx.~44c8 cannot be renamed to TestC.docx? I'll test that.

EDIT: Tested: If it was a problem that the download temporary was read-only, we'd have trouble updating files inside read-only shares on Windows in general. That's not the case. Changes inside read-only shares are propagated properly.

[ckamm]

@kliess It's odd that it only happens inside "TestFSub". The whole TestF folder is shared, right? Does it matter whether it's shared read-write or read-only?

And you did test this outside of shared folders?

Unfortunately I don't have MS Word around to test. @dragotin do you still have a test setup?

[kliess]

I tested the shared folders aspect:

Outside of shared folders it is the same situation, it has nothing to do with shared folders, it depends only on the question if it is a subfolder or not. The simplest steps to reproduce are now:

1. create a folder "TestG" with a subfolder "TestGSub", put a file "TestG.docx" in folder "TestG" and the file "TestGSub.docx" in subfolder "TestGSub"
2. Open in the local file system under the same user the file "TestG.docx" with MSOffice
3. Change "TestG.docx" direct on the server via file upload
4. Close in the local file system the file "TestG.docx"
   The file "TestG.docx" will be updated correct - everything is fine until now.

BUT:

1. Open in the local file system the file "TestGsub.docx" (this is the file inside the subfolder) with MSOffice
2. Change "TestGsub.docx" on the server via file upload
3. Close in the local file system the file "TestGsub.docx"
4. The file "TestGsub.docx" will NOT be updated!!!

And I tested the read-write and read-only aspect:

First I tested it with read-write shares (see last posting). If you use read-only shares it is worse: Both Files will not be updated, the message is "Zugriff verweigert" (Access denied) even if I close Office. This happens:

1. MS Office opens the file "TestF.docx" read only (as expected)
2. MS Office does not generate a temporary file like "~$TestF.docx" (as expected)
3. When I change the file on the server as "wi1" the desktop clients downloads the new version as ".TestF.docx.~24b6" (as expected)
4. The logs says "Zugriff verweigert" (Access denied) in relation to TestF.docx (more or less expected)
5. When i close MS Office the log still says "Zugriff verweigert" (Access denied) in relation to TestF.docx and the file ".TestF.docx.~24b6" will not be deleted and the file "TestF.docx" is marked with a white cross on a red circle in the file explorer (not expected)
6. even when I wait this situation does not change, the same situation is with the subfolder file

But one thing is interesting: If I delete the file ".TestF.docx.~24b6" in the local file system the next synchronization updates the file "TestF.docx" correctly.

[dragotin]

I tested again exactly how you described above. Same result - it worked here. After a short while the file was properly updated, after I closed word.

There must be another difference between your and my setup. Do you have any special file system permissions?

[kliess]

There are no special permissions. I have tested this with multiple Windows 10 clients and different server versions - the behavior is absolute consistent on all tested machines.

[kliess]

to make sure that is has nothing todo with my server installations I made a test on https://demo.owncloud.org/ - it is the same