search

nextcloud / desktop

💻 Desktop sync client for Nextcloud
https://nextcloud.com/install/#install-clients
GNU General Public License v2.0
2.98k stars 784 forks source link

[Bug]: Sync fails at some point + sync doesn't continue with further files #5779

Open JochenHWezel opened 1 year ago

JochenHWezel commented 1 year ago

⚠️ Before submitting, please verify the following: ⚠️

Bug description

After syncing several files, the sync stopped at some point (sync hangs for several hours). Forcefully restarting sync process or app hasn't solved the issue. Taskmanager shows no relevant network traffic.

Currently, the sync status look as follows: image

Steps to reproduce

unknown

Expected behavior

  1. Sync should either complete successfully or show an error somewhere
  2. The current file should be displayed somewhere (e.g. in tooltip, but tooltip isn't displayed this time)
  3. There should be a timeout for the current step/process/file of approx. 5 min.
  4. MOST IMPORTANT: The sync process should continue at least with the following 2317 files if the 1st one can't be synced.

Which files are affected by this bug

unknown / not displayed by nextcloud client app

Operating system

Windows

Which version of the operating system you are running.

Windows 11

Package

Appimage

Nextcloud Server version

26.0.2

Nextcloud Desktop Client version

3.4.1 (windows)

Is this bug present after an update or on a fresh install?

Updated from a minor version (ex. 3.4.2 to 3.4.4)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

Are you using an external user-backend?

Nextcloud Server logs

{"reqId":"A7BoPtdgLEdqUJBzZJYY","level":3,"time":"2023-06-04T11:27:55+00:00","remoteAddr":"192.168.32.111","user":"lwezel","app":"no app in context","method":"PUT","url":"/cloud/remote.php/dav/files/lwezel/Photos_L+J/Uploads%20Handy%20Lea/20210809_141516.jpg","message":"Did expect one result but found none when executing: query \"SELECT * FROM `*PREFIX*files_versions` WHERE (`file_id` = :dcValue1) AND (`timestamp` = :dcValue2)\"; ","userAgent":"Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)","version":"26.0.1.1","exception":{"Exception":"OCP\\AppFramework\\Db\\DoesNotExistException","Message":"Did expect one result but found none when executing: query \"SELECT * FROM `*PREFIX*files_versions` WHERE (`file_id` = :dcValue1) AND (`timestamp` = :dcValue2)\"; ","Code":0,"Trace":[{"file":"/var/www/html/cloud/lib/public/AppFramework/Db/QBMapper.php","line":361,"function":"findOneQuery","class":"OCP\\AppFramework\\Db\\QBMapper","type":"->"},{"file":"/var/www/html/cloud/apps/files_versions/lib/Db/VersionsMapper.php","line":78,"function":"findEntity","class":"OCP\\AppFramework\\Db\\QBMapper","type":"->"},{"file":"/var/www/html/cloud/apps/files_versions/lib/Listener/FileEventsListener.php","line":242,"function":"findVersionForFileId","class":"OCA\\Files_Versions\\Db\\VersionsMapper","type":"->"},{"file":"/var/www/html/cloud/apps/files_versions/lib/Listener/FileEventsListener.php","line":106,"function":"post_write_hook","class":"OCA\\Files_Versions\\Listener\\FileEventsListener","type":"->"},{"file":"/var/www/html/cloud/lib/private/EventDispatcher/ServiceEventListener.php","line":86,"function":"handle","class":"OCA\\Files_Versions\\Listener\\FileEventsListener","type":"->"},{"file":"/var/www/html/cloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php","line":251,"function":"__invoke","class":"OC\\EventDispatcher\\ServiceEventListener","type":"->"},{"file":"/var/www/html/cloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php","line":73,"function":"callListeners","class":"Symfony\\Component\\EventDispatcher\\EventDispatcher","type":"->"},{"file":"/var/www/html/cloud/lib/private/EventDispatcher/EventDispatcher.php","line":87,"function":"dispatch","class":"Symfony\\Component\\EventDispatcher\\EventDispatcher","type":"->"},{"file":"/var/www/html/cloud/lib/private/EventDispatcher/EventDispatcher.php","line":99,"function":"dispatch","class":"OC\\EventDispatcher\\EventDispatcher","type":"->"},{"file":"/var/www/html/cloud/lib/private/Files/Node/HookConnector.php","line":118,"function":"dispatchTyped","class":"OC\\EventDispatcher\\EventDispatcher","type":"->"},{"file":"/var/www/html/cloud/lib/private/legacy/OC_Hook.php","line":105,"function":"postWrite","class":"OC\\Files\\Node\\HookConnector","type":"->"},{"file":"/var/www/html/cloud/apps/dav/lib/Connector/Sabre/File.php","line":471,"function":"emit","class":"OC_Hook","type":"::"},{"file":"/var/www/html/cloud/apps/dav/lib/Connector/Sabre/File.php","line":398,"function":"emitPostHooks","class":"OCA\\DAV\\Connector\\Sabre\\File","type":"->"},{"file":"/var/www/html/cloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1137,"function":"put","class":"OCA\\DAV\\Connector\\Sabre\\File","type":"->"},{"file":"/var/www/html/cloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php","line":492,"function":"updateFile","class":"Sabre\\DAV\\Server","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/html/cloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"httpPut","class":"Sabre\\DAV\\CorePlugin","type":"->"},{"file":"/var/www/html/cloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":472,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/cloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":253,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/cloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":321,"function":"start","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/cloud/apps/dav/lib/Server.php","line":366,"function":"exec","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/cloud/apps/dav/appinfo/v2/remote.php","line":35,"function":"exec","class":"OCA\\DAV\\Server","type":"->"},{"file":"/var/www/html/cloud/remote.php","line":172,"args":["/var/www/html/cloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/var/www/html/cloud/lib/public/AppFramework/Db/QBMapper.php","Line":284,"CustomMessage":"--"}}

Additional info

NOTE on Nextcloud server log

The above log shows it's last log item before the problem started. There are now newer entries for the relevant user!

NextCloud client log

2023-06-07 12:34:21:037 [ info nextcloud.sync.networkjob C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\abstractnetworkjob.cpp:361 ]: OCC::PropfindJob created for "https://cloud.server1.de/cloud" + "/" "OCC::ConnectionValidator" 2023-06-07 12:34:21:037 [ debug nextcloud.sync.connectionvalidator C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\connectionvalidator.cpp:175 ] [ OCC::ConnectionValidator::checkAuthentication ]: # Check whether authenticated propfind works. 2023-06-07 12:34:21:037 [ info nextcloud.sync.accessmanager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\accessmanager.cpp:78 ]: 6 "PROPFIND" "https://cloud.server2.de/cloud/remote.php/dav/files/userA/" has X-Request-ID "38ea6e4f-e0e4-4142-a979-d58e74394843" 2023-06-07 12:34:21:053 [ debug nextcloud.sync.cookiejar C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\cookiejar.cpp:90 ] [ OCC::CookieJar::cookiesForUrl ]: QUrl("https://cloud.server2.de/cloud/remote.php/dav/files/userA/") requests: (QNetworkCookie("nc_sameSiteCookielax=true; secure; HttpOnly; expires=Fri, 31-Dec-2100 23:59:59 GMT; domain=cloud.server2.de; path=/cloud"), QNetworkCookie("nc_sameSiteCookiestrict=true; secure; HttpOnly; expires=Fri, 31-Dec-2100 23:59:59 GMT; domain=cloud.server2.de; path=/cloud"), QNetworkCookie("oc_sessionPassphrase=E5C%2F4x4DDzKaLTf3x8y1LGwy8%2FMniik0u7FeYM0THZ2Jjr7bwRNFWN7P%2Brb2Nkoxzb6C9dF%2FlLf5O7GemnSkLQeYCATLjfZ0K4jMtRBZWEJ79ofO11Ul7sMWQfEgSM8x; secure; HttpOnly; domain=cloud.server2.de; path=/cloud"), QNetworkCookie("och0mq586my5=lt9cdn43dhds6dbk02r0o7q52a; secure; HttpOnly; domain=cloud.server2.de; path=/cloud")) 2023-06-07 12:34:21:053 [ info nextcloud.sync.networkjob C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\abstractnetworkjob.cpp:361 ]: OCC::PropfindJob created for "https://cloud.server2.de/cloud" + "/" "OCC::ConnectionValidator" 2023-06-07 12:34:21:256 [ info nextcloud.sync.credentials.webflow C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\creds\webflowcredentials.cpp:425 ]: request finished 2023-06-07 12:34:21:256 [ info nextcloud.sync.networkjob.propfind C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\networkjobs.cpp:617 ]: PROPFIND of QUrl("https://cloud.server2.de/cloud/remote.php/dav/files/userA/") FINISHED WITH STATUS "OK" 2023-06-07 12:34:21:256 [ debug nextcloud.sync.networkjob C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\abstractnetworkjob.cpp:298 ] [ OCC::AbstractNetworkJob::slotFinished ]: Network job OCC::PropfindJob finished for "/" 2023-06-07 12:34:21:506 [ info nextcloud.sync.credentials.webflow C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\creds\webflowcredentials.cpp:425 ]: request finished 2023-06-07 12:34:21:506 [ info nextcloud.sync.networkjob.propfind C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\networkjobs.cpp:617 ]: PROPFIND of QUrl("https://cloud.server1.de/cloud/remote.php/dav/files/user123/") FINISHED WITH STATUS "OK" 2023-06-07 12:34:21:506 [ debug nextcloud.sync.networkjob C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\abstractnetworkjob.cpp:298 ] [ OCC::AbstractNetworkJob::slotFinished ]: Network job OCC::PropfindJob finished for "/" 2023-06-07 12:34:31:996 [ info nextcloud.gui.folder.manager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\folderman.cpp:867 ]: Etag poll timer timeout 2023-06-07 12:34:31:996 [ info nextcloud.gui.folder.manager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\folderman.cpp:871 ]: Folders to sync: 2 2023-06-07 12:34:31:996 [ info nextcloud.gui.folder.manager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\folderman.cpp:881 ]: Number of folders that don't use push notifications: 2 2023-06-07 12:34:31:996 [ info nextcloud.gui.folder.manager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\folderman.cpp:898 ]: Run etag job on folder OCC::Folder(0x18900307ff0) 2023-06-07 12:34:31:996 [ info nextcloud.gui.folder.manager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\folderman.cpp:898 ]: Run etag job on folder OCC::Folder(0x18900452150) 2023-06-07 12:34:31:996 [ info nextcloud.gui.folder.manager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\folderman.cpp:904 ]: Can not run etag job: Sync is running 2023-06-07 12:34:32:011 [ info nextcloud.gui.folder C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\folder.cpp:331 ]: Trying to check "https://cloud.server1.de/cloud/remote.php/dav/files/user123/" for changes via ETag check. (time since last sync: 35 s) 2023-06-07 12:34:32:028 [ debug nextcloud.gui.folder.manager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\folderman.cpp:696 ] [ OCC::FolderMan::slotRunOneEtagJob ]: Scheduling "https://cloud.server1.de/cloud/remote.php/dav/files/user123/" to check remote ETag 2023-06-07 12:34:32:028 [ info nextcloud.sync.accessmanager C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\accessmanager.cpp:78 ]: 6 "PROPFIND" "https://cloud.server1.de/cloud/remote.php/dav/files/user123/" has X-Request-ID "504eae8e-1b41-4af6-bc8e-ac1d75c1ef48" 2023-06-07 12:34:32:028 [ debug nextcloud.sync.cookiejar C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\cookiejar.cpp:90 ] [ OCC::CookieJar::cookiesForUrl ]: QUrl("https://cloud.server1.de/cloud/remote.php/dav/files/user123/") requests: (QNetworkCookie("nc_sameSiteCookielax=true; secure; HttpOnly; expires=Fri, 31-Dec-2100 23:59:59 GMT; domain=cloud.server1.de; path=/cloud"), QNetworkCookie("nc_sameSiteCookiestrict=true; secure; HttpOnly; expires=Fri, 31-Dec-2100 23:59:59 GMT; domain=cloud.server1.de; path=/cloud"), QNetworkCookie("oc_sessionPassphrase=m5qqXEthmzkZ%2Fvy1ipgW2tAYqdvAlJvgEhQdDGXXFsB73xk5Ge6OR6CGlQej9nKCobQXkBSLKKYTTKM5dW1grZ4T8wKK%2BQCN0%2FLzU3XT%2B9i5JruiZqaLgMDPGmdrOOa%2B; secure; HttpOnly; domain=cloud.server1.de; path=/cloud"), QNetworkCookie("oc3hogip89v8=62rs1g5qg4jqb384aplbf6tdsl; secure; HttpOnly; domain=cloud.server1.de; path=/cloud")) 2023-06-07 12:34:32:028 [ info nextcloud.sync.networkjob C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\abstractnetworkjob.cpp:361 ]: OCC::RequestEtagJob created for "https://cloud.server1.de/cloud" + "/" "OCC::Folder" 2023-06-07 12:34:32:219 [ info nextcloud.sync.credentials.webflow C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\gui\creds\webflowcredentials.cpp:425 ]: request finished 2023-06-07 12:34:32:219 [ info nextcloud.sync.networkjob.etag C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\networkjobs.cpp:109 ]: Request Etag of QUrl("https://cloud.server1.de/cloud/remote.php/dav/files/user123/") FINISHED WITH STATUS "OK" 2023-06-07 12:34:32:219 [ debug nextcloud.sync.networkjob C:\Users\sysadmin\AppData\Local\Temp\2\windows-8634\client-building\desktop\src\libsync\abstractnetworkjob.cpp:298 ] [ OCC::AbstractNetworkJob::slotFinished ]: Network job OCC::RequestEtagJob finished for "/"

Server's Apache access log

192.168.1.15 - userA [06/Jun/2023:23:51:02 +0000] "GET /cloud/ocs/v2.php/apps/notifications/api/v2/notifications?format=json HTTP/1.0" 200 2310 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:51:36 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:52:38 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:53:40 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:54:42 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:55:44 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:56:01 +0000] "GET /cloud/ocs/v2.php/apps/user_status/api/v1/user_status?format=json HTTP/1.0" 200 2386 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:56:02 +0000] "GET /cloud/ocs/v2.php/apps/notifications/api/v2/notifications?format=json HTTP/1.0" 200 2310 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:56:46 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:57:48 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:58:50 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)" 192.168.1.15 - userA [06/Jun/2023:23:59:52 +0000] "PROPFIND /cloud/remote.php/dav/files/userA/ HTTP/1.0" 207 2607 "-" "Mozilla/5.0 (Windows) mirall/3.4.1stable-Win64 (build 20211221) (Nextcloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64)"

JochenHWezel commented 1 year ago

nextcloud-client-log.zip

JochenHWezel commented 1 year ago

Found issue

I found and solved the issue: there were 2 files in my file system with an invalid datetime in last-file-change-attribute (I don't know why the files haven't got a valid datetime timestamp, but maybe one of the cameras created a photo file with an empty or too early datetime.)

Solution for me

After re-saving these 2 files, both files got a valid timestamp.

Finally

Bugfix request for solution for next users with same problem

I'd suggest to implement a check on datetime field of every file in sync process. If there is an invalid datetime field, the user should

  1. get a warning message box popup (or something similar) explaining that file XY has got an invalid time stamp can therefore cannot be synced
  2. get the same warning in log file
  3. meanwhile, the sync process should continue to sync all remaining files with proper datetime information