Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Thousands of PROPFIND requests even the client was fully synced, results in redownloading all files #6543

Closed
windaishi opened this issue Dec 21, 2013 · 10 comments

Comments

@windaishi
Copy link
Contributor

Circumstances

I synced about 178 GB of data in 58,015 files in 5,170 directories.
The client has finished the upload completely and all files are available online via webinterface.

Expected behaviour

When restarting the client, it should take only some second or minutes until the client is ready. It should not redownload the existing files.

Actual behaviour

It takes a couple of minutes until the local files were scanned. Then the client sends thousands of PROPFIND request to the webserver, one for each directory causing heavy load on the webserver. When finished (after about an hour) the clients starts to download all files, all 178GB of data

Steps to reproduce

  1. Sync all files
  2. Restart client

(Worked several times on my system)

Server configuration

Operating system: Windows Server 2003

Web server: Apache/2.2.26

Database: MySQL 5.5.25

PHP version: 5.4.22

ownCloud version: ownCloud 6.0.0a (stable)

Updated from an older ownCloud or fresh install: Fresh Install

List of activated app:
Activity
Calendar
Contacts
Deleted files
Documents
First Run Wizard
Full Text Search
ownCloud dependencies info
PDF Viewer
Pictures
Share Files
Text Editor
Updater
Versions

The content of config/config.php: (Without the database password and passwordsalt)

Are you using external storage, if yes which one: No

Client configuration

Browser: N/A

Operating system: Windows 7 x64

Sync Client: 1.5

Logs

Web access log

192.168.2.21 - - [21/Dec/2013:16:29:56 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/205/1/.cp/icons/full/elcl16 HTTP/1.1" 207 1103
192.168.2.21 - - [21/Dec/2013:16:29:56 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/205/1/.cp/icons/full/dlcl16 HTTP/1.1" 207 1968
192.168.2.21 - - [21/Dec/2013:16:29:57 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/205/1/.cp/icons/full/cview16 HTTP/1.1" 207 1110
192.168.2.21 - - [21/Dec/2013:16:29:57 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/205/1/.cp/icons/full/clcl16 HTTP/1.1" 207 1968
192.168.2.21 - - [21/Dec/2013:16:29:57 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/204 HTTP/1.1" 207 1139
192.168.2.21 - - [21/Dec/2013:16:29:57 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/204/1 HTTP/1.1" 207 1145
192.168.2.21 - - [21/Dec/2013:16:29:58 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/204/1/.cp HTTP/1.1" 207 1155
192.168.2.21 - - [21/Dec/2013:16:29:58 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/204/1/.cp/icons HTTP/1.1" 207 1678
192.168.2.21 - - [21/Dec/2013:16:29:58 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/204/1/.cp/icons/obj16 HTTP/1.1" 207 1098
192.168.2.21 - - [21/Dec/2013:16:29:59 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/204/1/.cp/icons/elcl16 HTTP/1.1" 207 3271
192.168.2.21 - - [21/Dec/2013:16:29:59 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202 HTTP/1.1" 207 1139
192.168.2.21 - - [21/Dec/2013:16:29:59 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1 HTTP/1.1" 207 1145
192.168.2.21 - - [21/Dec/2013:16:29:59 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp HTTP/1.1" 207 1155
192.168.2.21 - - [21/Dec/2013:16:30:00 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons HTTP/1.1" 207 1166
192.168.2.21 - - [21/Dec/2013:16:30:00 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full HTTP/1.1" 207 4794
192.168.2.21 - - [21/Dec/2013:16:30:00 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full/wizban HTTP/1.1" 207 1980
192.168.2.21 - - [21/Dec/2013:16:30:01 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full/progress HTTP/1.1" 207 2438
192.168.2.21 - - [21/Dec/2013:16:30:01 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full/obj16 HTTP/1.1" 207 2839
192.168.2.21 - - [21/Dec/2013:16:30:02 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full/eview16 HTTP/1.1" 207 1551
192.168.2.21 - - [21/Dec/2013:16:30:02 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full/etool16 HTTP/1.1" 207 8113
192.168.2.21 - - [21/Dec/2013:16:30:02 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full/elcl16 HTTP/1.1" 207 5040
192.168.2.21 - - [21/Dec/2013:16:30:03 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full/dtool16 HTTP/1.1" 207 3294
192.168.2.21 - - [21/Dec/2013:16:30:03 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/202/1/.cp/icons/full/dlcl16 HTTP/1.1" 207 3300
192.168.2.21 - - [21/Dec/2013:16:30:04 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200 HTTP/1.1" 207 1139
192.168.2.21 - - [21/Dec/2013:16:30:04 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1 HTTP/1.1" 207 1145
192.168.2.21 - - [21/Dec/2013:16:30:04 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1/.cp HTTP/1.1" 207 1155
192.168.2.21 - - [21/Dec/2013:16:30:05 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1/.cp/icons HTTP/1.1" 207 1166
192.168.2.21 - - [21/Dec/2013:16:30:05 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1/.cp/icons/full HTTP/1.1" 207 3240
192.168.2.21 - - [21/Dec/2013:16:30:05 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1/.cp/icons/full/wizban HTTP/1.1" 207 1109
192.168.2.21 - - [21/Dec/2013:16:30:05 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1/.cp/icons/full/obj HTTP/1.1" 207 1111
192.168.2.21 - - [21/Dec/2013:16:30:06 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1/.cp/icons/full/eview16 HTTP/1.1" 207 1549
192.168.2.21 - - [21/Dec/2013:16:30:06 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1/.cp/icons/full/elcl16 HTTP/1.1" 207 8568
192.168.2.21 - - [21/Dec/2013:16:30:07 +0100] "PROPFIND /remote.php/webdav/Ablage/eclipse/configuration/org.eclipse.osgi/bundles/200/1/.cp/icons/full/dlcl16 HTTP/1.1" 207 5938

ownCloud log (data/owncloud.log)

Fatal   core    Unable to parse OCS content     2013-12-21T15:29:02+00:00
Fatal   core    Unable to parse OCS content     2013-12-21T15:28:14+00:00
Warning     core    Authentication cookie rejected for user admin   2013-12-21T14:52:26+00:00
Warning core    Authentication cookie rejected for user admin   2013-12-21T00:21:00+00:00
Warning core    Authentication cookie rejected for user admin   2013-12-21T00:20:50+00:00
Warning PHP file_get_contents(E:\ownCloud/admin/files/entwicklung/projekte/tstools/htdocs/include/fun.inc.php): failed to open stream: No such file or directory at D:\www\owncloud\lib\private\files\storage\mappedlocal.php#153   2013-12-20T22:42:35+00:00
Warning PHP filemtime(): stat failed for E:\ownCloud/admin/files/entwicklung/projekte/tstools/htdocs/include/fun.inc.php at D:\www\owncloud\lib\private\files\storage\mappedlocal.php#135   2013-12-20T22:42:35+00:00
Warning PHP call_user_func() expects parameter 1 to be a valid callback, first array member is not a valid class name or object at D:\www\owncloud\lib\private\backgroundjob\legacy\queuedjob.php#16    2013-12-20T22:20:35+00:00
Warning PHP call_user_func() expects parameter 1 to be a valid callback, first array member is not a valid class name or object at D:\www\owncloud\lib\private\backgroundjob\legacy\queuedjob.php#16    2013-12-20T22:20:35+00:00
Warning PHP call_user_func() expects parameter 1 to be a valid callback, first array member is not a valid class name or object at D:\www\owncloud\lib\private\backgroundjob\legacy\queuedjob.php#16    2013-12-20T22:20:32+00:00
Warning PHP call_user_func() expects parameter 1 to be a valid callback, first array member is not a valid class name or object at D:\www\owncloud\lib\private\backgroundjob\legacy\queuedjob.php#16    2013-12-20T22:20:32+00:00
Warning PHP call_user_func() expects parameter 1 to be a valid callback, first array member is not a valid class name or object at D:\www\owncloud\lib\private\backgroundjob\legacy\queuedjob.php#16    2013-12-20T22:20:32+00:00
Warning PHP call_user_func() expects parameter 1 to be a valid callback, first array member is not a valid class name or object at D:\www\owncloud\lib\private\backgroundjob\legacy\queuedjob.php#16    2013-12-20T22:11:12+00:00
@blackm
Copy link

blackm commented Dec 22, 2013

I see the similar behaviour.

My server is Debian 7 (@raspberrypi; owncloud 6.0.0) and with Debian 7 Client (owncloud 1.5) and Max OSX Client (owncloud 1.5).

I see also PROPFIND requests for every directory but I don't see re-downloading. Before updating from client 1.4 and server 4.5 there was only one PROPFIND request for folder I sync with owncloud.

I left one client switch on for two days but the PROPFIND requests stayed constant (I assumed after one complete cycle everything will be back to normal.

The "annoying" thing is indeed the high server load and that other files are not synced while owncloud client is "waiting for next sync run to start" (that's what the mouse over help displays for the tray icon) by sending the PROFIND requests.

@PVince81
Copy link
Contributor

PVince81 commented Jan 8, 2014

CC @dragotin @DeepDiver1975

From my understanding, the desktop sync client should only do a PROPFIND on the base folder to check its etag to find out whether there were changes. No idea why it would decide to explore the whole tree unless there are etag discrepancies.

@k3a
Copy link

k3a commented Feb 24, 2014

I am also seeing lots of PROPFIND on green "finished" own cloud mac os client but it is probably not redownloading. Each PROPFIND causes lots of MySQL queries though. I think it started doing that after I restored my client HDD from backup. But all files are on the client, complete, with writable permissions.

Any way to stop it doing it?

owncloud 6.0.1 (stable), latest Mac client.

@mpscy
Copy link

mpscy commented May 31, 2014

Any news on this issue? Experiencing similar problems with OC 6.0.3 + Encryption App and latest Mac client

@willyaranda
Copy link

I have the same problem on Mac with latest client (1.6.1) and latest 7.0 beta 1. I get flooded of PROPFIND, returning all of them a 207.
It is done each 30 seconds!!

@willyaranda
Copy link

Just for reference: https://github.com/owncloud/mirall/blob/master/doc/conffile.rst (check remotePollInterval variable) and https://github.com/owncloud/mirall/blob/master/src/mirall/mirallconfigfile.cpp#L38, they are both set at a default of 30000 ms (30 seconds), which I think they are the culprit of this.

I have changed my owncloud to 600000 ms (10 minutes and see if that works)

@willyaranda
Copy link

I think mirall does not check correctly the file:

07-03 20:24:14:620 application.cpp:344 "################## ownCloud es_ES () 1.6.1"
07-03 20:24:14:620 application.cpp:531 void Mirall::Application::setupTranslations() Using "es" translation
07-03 20:24:14:651 folderman.cpp:136 * Setup folders from  ""
07-03 20:24:14:651 folderman.cpp:250   ` -> setting up: "GIFs"
07-03 20:24:14:651 folderman.cpp:268     -> file path:  "/Users/willyaranda/Library/Application Support/ownCloud/folders/GIFs"
07-03 20:24:14:651 folder.cpp:165 Checked local path ok
07-03 20:24:14:651 folder.cpp:84 setting remote poll timer interval to 30000 msec

@willyaranda
Copy link

Ok, got it working (I needed to read the documentation of QSettings and blah blah):

By default, remotePollInterval is 30 seconds.

If you want to change it, just go to the file specified in https://github.com/owncloud/mirall/blob/master/doc/conffile.rst and add a remotePollInterval under the [OwnCloud] line, like this:

[ownCloud]
authType=http
http_user=willyaranda
remotePollInterval=600000
url=https://cloud.pijusmagnificus.com
user=willyaranda

So now, it is asking for changes each 10 minutes instead of 30 seconds, which is way better for downstream :)

@willyaranda
Copy link

But I still got the root asked each 30 seconds…

95.122.208.94 - willyaranda [03/Jul/2014:20:57:09 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 493 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
95.122.208.94 - willyaranda [03/Jul/2014:20:57:39 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 493 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
95.122.208.94 - willyaranda [03/Jul/2014:20:58:09 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 493 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
95.122.208.94 - willyaranda [03/Jul/2014:20:58:39 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 493 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
95.122.208.94 - willyaranda [03/Jul/2014:20:59:09 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 493 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"

@guruz
Copy link
Contributor

guruz commented Jan 23, 2015

Closing this, the upcoming 1.8 client has improvements on when to start a sync.

@guruz guruz closed this as completed Jan 23, 2015
@lock lock bot locked as resolved and limited conversation to collaborators Aug 14, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

7 participants