Closed jochenwezel closed 10 years ago
I can confirm this issue against Server 5.0.10.
Please let me know what information I can give you to further track down this error. I am seeing this regularily on my install.
maybe related: #110
this bug is critical to me since lot of traffic happens due to this issue (>30 GB per month!) my last ISP already kicked me a few weeks ago because I had too much traffic with my internet flat rate. I don't want to retry this procedure again... ;-)
Might be related: I just noticed that my client also decided now to re-download everything (in the menu opening up when clicking on the "tray" icon in my ubuntu 13.04, it wrote "downloading file .. of .., xx of yy MB or something like that - and showing all the 950MB of the one synced folder, so it seems to just re-download everything!) - no idea why, there were no big changes to files recently, no server upgrade (still running 5.0.10), no client upgrade (apart from 1.4, but that was last week already or so and the client has run multiple times since then already).
So I really have no clue at all why the client is redownloading anything. Any logfile I could check (I heard the client now also produces a logfile if not explicitly started with the logging option)? I guess its also no option to restart I the client, not sure if he will exhibit the same behavior, but I will try...
Edit: Restarted the client with logwindow option, and the sync continued to download files I think (at least the Recent changes show something like that). Can provide the logfile on request (don't like to post it publicly with all the document references).
Is it maybe now a good time to think again about introducing proper file checksums instead of the random tags? What was again the argument against using it? High CPU usage? If it can prevent issues such as this, where unmodified files are downloaded multiple times, this argument doesn't hold. Calculating a checksum once can't possibly cost more CPU performance than re-downloading the same things multiple times (and if the argument is for the server side, then the re-downloading possibilities can even be multiplied with more clients!)
Please everybody, can you please post me the result of the following SQL-Statements run on server database:
select count(*) from oc_filecache where etag = '';
select count(*) from oc_filecache;
@RandolfCarter pls. send the full, zipped logfile to freitag at owncloud.com, thanks.
37 without etag, 7790 with.
The 37 are all files within zip files (.../file.zip/...) plus a directory. These are not the files I observed to be redownloaded.
The client seems to do repeated uploading too. Is this related? Same server version, same client version. OS - Gentoo both side. PHP 5.5, Apache 2.4, MariaDB 5.5.
An update, I just added another computer to a folder, which is already synced at a two other hosts. As expected, the new system integrated itself fine. The new system used a blank directory to start its work from.
However, one of the two other systems started to download approximaltely 85% of the files (2.700 files, 1.1 GB) after I booted the system about half an hour later. None of the files have been changed, since the download on the new system.
I have launched a log window during synchronisation, the general pattern seems to be like this:
09-15 15:25:22:087 oc_module: => open called for ownclouds://loremipsum/remote.php/webdav/Documents/file.txt
09-15 15:25:22:087 oc_module: GET request on /remote.php/webdav/Documents/file.txt
09-15 15:25:22:087 oc_module: Sendfile handling request type GET. fd 3
09-15 15:25:22:087 oc_module: -- GET on ownclouds://loremipsum/remote.php/webdav/Documents/file.txt
09-15 15:25:22:204 oc_module: Content encoding ist
If you want the full log untli the end of the sync, please let me know, I have saved it. However, I did not catch the start of the sync. If that is neccessary, please let me know, then I'll change my client systems to permanent logging. As well, if you want to take a peek into the server logs (both oc internal and Apache access log), I have them available for inspection. Just drop me a mail to torben
While trying to investigate #1003, I again got addidional downloads. What I did (Win 7/64 Pro, Client 1.4):
I used Windows Explorer for this.
I'll change my clients now so that they continously create log files. Maybe this gives us some insights.
Are the server logs helpful here, or are the client logs sufficient?
What i had just now:
Several log messages around "stat failed for \/var\/www\/clients\/client1\/web27\/private\/somefile" (Why can't I just copy/past from the log view in the web, this is really irritating...)
At least right now the file in question exists and has the correct permission set.
Again, after a client restart, I got a few dozen files downloaded again without reason. I have zipped together the logs of the individual sync runs the client made, the oc server log and the oc apache access log. Please mail me at torben
http://s.nehmer.net/eSxI6oR2rC
Note, that this is reproducible her. The number of files getting downloaded again and again is increasing (right now he sucks down 629 files wtih 200 MB needlessly).
Another thing to look out, unsure if this is related: Right now I realized (by coincidence) that I had two owncloud.exe instances running (one of it did not show a tray icon, otherwise I'd have noticed it earlier). I cannot say for sure, if this influences things. If it does, you might want to include a check to avoid duplicate program launches.
@torbennehmer We already have a check for double instances. If another instance was running, it did not respond and thus was dead anyway.
@danimo: That check is buggy, see #1004, it is easily possible to launche two instances in case you have different command line. I am unsure how long the multiple instances were running here, though I am fairly certain that most of the problems I experienced were before the second instance came up.
@dragotin Executing your SQL statement doesn't work for me since I use older server version 4.5.7 table oc_filecache doesn't exist if I use table oc_fscache, column etag doesn't exist Please advise what I can do for you to get information as needed.
Hey there folks.
I also have a similar issue where files are synced over and over again even tho they didn't change.
However, in my log, I've found something quite suspicious.
09-16 07:06:27:332 _get_md5: MD5 for [server]/[file]: 5236e6f7dcdd7-gzip
Now, the -gzip at the end is just weird because in my oc_filecache table, the MD5 is just 5236e6f7dcdd7, so it's normal that everytime the client tries to sync this file, it thinks it's a different one. Why would that -gzip be there at the end of the md5?
Please advise what I can do for you to get information as needed.
@jochenwezel back in 4.5 the etag was stored in oc_properties with the propertyname {DAV:}getetag
You need to join the tables while querying. Unfortunately I have no 4.5 instance at hand at the moment - sorry
@jochenwezel please update anyway!
A question: Assuming that the time of one client was 3-4 seconds in the future compared to the other hosts and the OC server: Could that explain the bahavoir?
I am not sure here, I had a clock skew at least for a moment between my MacBook and the OC server (both of which are NTP synced, the server time is valid), once I started to investigate however, the skew vanished and I am quite unsure, how (maybe because I opened the Date & Time settings on the MacBook).
Here are a few exceprts of the log of the sync run (a fresh client start), I grepped for a specific filename in the log. As always, if you need a complete log, please drop me a PM.
09-16 20:28:34:432 csync_ftw: Uniq ID from Database: Word/templates/Torben Nehmer - Einseitig.dot -> 5235c4f5bfad3
09-16 20:28:34:432 csync_walker: file: /Users/torben/Documents/Word/templates/Torben Nehmer - Einseitig.dot
09-16 20:28:34:432 _csync_detect_update: ==> file: Word/templates/Torben Nehmer - Einseitig.dot - hash 18407479296867747143, mtime: 1272913023
09-16 20:28:34:432 _csync_detect_update: Database entry found, compare: 1272913023 <-> 1272913023, md5: 5235c4f5bfad3 <-> 5235c4f5bfad3, inode: 8202737 <-> 8202737
09-16 20:28:34:432 _csync_detect_update: file: Word/templates/Torben Nehmer - Einseitig.dot, instruction: INSTRUCTION_NONE <<=
...
9-16 20:28:35:124 oc_module: owncloud_stat ownclouds://owncloud.nehmer.net/remote.php/webdav/Documents/Word/templates/Torben Nehmer - Einseitig.dot called
09-16 20:28:35:124 csync_walker: file: ownclouds://owncloud.nehmer.net/remote.php/webdav/Documents/Word/templates/Torben Nehmer - Einseitig.dot
09-16 20:28:35:124 _csync_detect_update: ==> file: Word/templates/Torben Nehmer - Einseitig.dot - hash 18407479296867747143, mtime: 1272913023
09-16 20:28:35:124 _csync_detect_update: Database entry found, compare: 1272913023 <-> 1272913023, md5: 5236b9d89d2db <-> 5235c4f5bfad3, inode: 0 <-> 8202737
09-16 20:28:35:124 _csync_detect_update: file: Word/templates/Torben Nehmer - Einseitig.dot, instruction: INSTRUCTION_EVAL <<=
...
09-16 20:29:15:396 _csync_merge_algorithm_visitor: INSTRUCTION_NONE file: Word/templates/Torben Nehmer - Einseitig.dot
...
09-16 20:29:15:505 _csync_merge_algorithm_visitor: INSTRUCTION_SYNC file: Word/templates/Torben Nehmer - Einseitig.dot
...
09-16 20:38:22:947 oc_module: => open called for ownclouds://owncloud.nehmer.net/remote.php/webdav/Documents/Word/templates/Torben Nehmer - Einseitig.dot
09-16 20:38:22:947 oc_module: GET request on /remote.php/webdav/Documents/Word/templates/Torben%20Nehmer%20-%20Einseitig.dot
09-16 20:38:22:948 oc_module: Sendfile handling request type GET. fd 34
09-16 20:38:22:948 oc_module: -- GET on ownclouds://owncloud.nehmer.net/remote.php/webdav/Documents/Word/templates/Torben Nehmer - Einseitig.dot
09-16 20:38:22:957 FolderWatcherPrivate::callback by OS X
09-16 20:38:23:052 oc_module: Content encoding ist <empty> with status 200
09-16 20:38:23:098 oc_module: GET http result 200 (OK)
09-16 20:38:23:098 oc_module: http request all cool, result code 200
09-16 20:38:23:098 oc_module: ** Finished download ownclouds://owncloud.nehmer.net/remote.php/webdav/Documents/Word/templates/Torben Nehmer - Einseitig.dot
09-16 20:38:23:100 oc_module: Get file ID for ownclouds://owncloud.nehmer.net/remote.php/webdav/Documents/Word/templates/Torben Nehmer - Einseitig.dot: 5236b9d89d2db
09-16 20:38:23:100 _get_md5: MD5 for ownclouds://owncloud.nehmer.net/remote.php/webdav/Documents/Word/templates/Torben Nehmer - Einseitig.dot: 5236b9d89d2db
09-16 20:38:23:100 _csync_push_file: FINAL MD5: 5236b9d89d2db
09-16 20:38:23:100 _csync_push_file: PUSHED file: /Users/torben/Documents/Word/templates/Torben Nehmer - Einseitig.dot
...
09-16 20:38:25:542 _merge_file_trees_visitor: PRE UPDATED Word/templates/Torben Nehmer - Einseitig.dot: 5236b9d89d2db
09-16 20:38:25:542 _merge_file_trees_visitor: file: /Users/torben/Documents/Word/templates/Torben Nehmer - Einseitig.dot, instruction: UPDATED (5236b9d89d2db)
...
09-16 20:38:26:632 _insert_metadata_visitor: SQL statement: INSERT INTO metadata_temp
(phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5) VALUES
(-39264776841804473, 44, Word/templates/Torben Nehmer - Einseitig.dot, 8205832, 501, 20, 33188, 1272913023, 0, 5236b9d89d2db);
@DeepDiver1975 @dragotin Coming back to my server instance with V4.5.7, I've adapted your SQL statements as well as possible to me in time - here my results:
select count(*) from oc_properties where propertyname = "{DAV:}getetag"
=> 2621
select count(*) from oc_fscache
=> 1588
Sorry, I don't know how to join both tables correctly - following statement doesn't provide at least 1 row :-/
select * from oc_fscache
inner join (select * from oc_properties where propertyname = "{DAV:}getetag") as etags
on oc_fscache.user = etags.userid and oc_fscache.path = etags.propertypath
If required furthermore, you may provide an optimized sql statement
I want to add that I am dealing with this issue now. I did not use my work laptop for 5 days, accessed a couple files through ipad app, and now today it wants to re-download all of my files.
An update from my side: Since I have found and (a bit misteriously) fixed the clock skew, I didn't have any further problems.
It would be interesting if anybody else has problems with his time sync that could explain this problem. As well I'd be interested in a statement by the OC Gurus how the sync client reacts to system clocks that are not perfectly in sync (note, that my sync was just off a bare four seconds, not that much actually).
@torbennehmer We're thinking of something more clever, along the lines of using lamport clocks. Don't worry, we have not forgotten.
With the recent upgrade of the client to 1.4 on my Linux machine I found that now my Windows laptop will re-sync a lot of the files (possibly all) even though they have not changed. I'm reading through this thread to see if I can provide any extra information but this is causing quite a lot of problems for me and also concerns me that it's possible that I'm losing data.
I'm running 1.4 clients on both Windows 7 and Linux Mint and the 5.0.11 server on a Linux server from a provider. This issue did not start happening until I upgraded the client on my Linux machine.
After almost a week without problems I just experienced the problem again, immediately after taking my MacBook out of sleep after a period without Internet connection. Along with the physical Mac OSX system I also had a Windows 8 VM running. Now what happened was this:
The OC client in the Windows 8 VM recovered almost immediately from the "Could not connect to server" state. It has only a subset of my full clientsync directory synced locally. It immediately began downloading all stuff once again.
In the meantime, the OSX client was still sleeping and therefore did nothing.
Once I noticed this, I immediately compared the system clock of the MacBook with that of my OC server. What I saw earlier was confirmed, the Mac OS System Clock (to which the Windows VM is synchronized via Parallels) was again off by 2 seconds in the future:
galileo:Alex Jacobi torben$ ssh ocserver date; date Sa 21. Sep 20:56:43 CEST 2013 Sa 21 Sep 2013 20:56:45 CEST
Mac OS fixed this within a few seconds after that check above.
The local client recoverd only after the clocks were all synced again. It did as well start to download things again, specifically all stuff which the VM has redownloaded again. It did not redownload the entire sync directory it is using. The files affected were only those which have also been redownloaded by the VM, nothing else.
In addition, there indeed is a potential to data loss: I have had modified one of the files which were redownloaded while the notebook was offline. The Client did not upload it, instead it redownloaded the old version on the server and moved the locally modified file into a conflict file (thank you for that safety net!).
Thus, I'd recommend to everyone to keep an eye on system time synchronization, especially if you have temporary network outages.
So the solution is to just sync ntp times? I ran 'sudo ntpdate ntp.ubuntu.com' on both the 12.04 5.0.10 server and my 12.04 laptop (which has been CONSTANTLY re-downloading every single folder, one by one). So far it appears to be stable but I'm really worried it'll start going again. I went out of my way to delete all desktop client configurations, my account, and start completely from scratch. Having all this sync go out of control because my server was 4 seconds ahead seems very silly. I have a friend using storage as well on Ubuntu 13.04, now that I have updated the ntp time should I be worried about sync issues with her?
It sounds like a downtime issue, my owncloud started the issue only after my laptop had not been used for four days. Once I let mine cycle through and copy over every file again the issue had stopped. During that down time I had accessed two files via my ipad, which should have caused those two files to copy. Any ideas on what would have changed during the four days my laptop had been shut down?
Hm, it appears to not be fixed for me, it's not trying to download a half-gig of files all over again.
What is the recommended way to fix this issue? Downgrade to 1.3?
@drewscm : Be aware that especially laptops disconnected from the net have a time shift. Operating systems automatically resynchronize the time as soon as they come back online, so that drift usually goes by unnoticed. That can even happen if the laptop is shut down if the hardware clock doesent run as it should (which is the norm not the exception). My Macbook requires less then 20-30 seconds (a usual duration for an NTP time sync) for this, but this is by far enough for the OC client to start syncing with wrong timestamps.
@ainola : Be aware, that ntpdate does only a single(!) sync of the local system clock with the NTP time. If your clock drifts heavily, this does not solve the problem. You have to actually run the NTP daemon, which keeps the time in sync permanently by adjusting the speed of the operating systems clock. Note, that this does not change the speed of the hardware clock, that is impossible. If your system gets shut down and starts again the next day, it is quite possible that there is a drift.
I am not sure whether a downgrade would help here, that's for the OC Gurus to tell.
What I'd like anyway is that the OC client waits for perhaps a minute or so after the system boots / resumes from sleep or hibernation to give the clocks time to sync before starting up.
Same problem here. I have the simplest of setups, ownCloud 5.11 on a V-Server (Ubuntu 12.04) and two Windows machines to sync 10 files at most, no more than 50MB at most. Client 1.4.0 keeps syncing and re-syncing those files forever.
Back to 1.3.0 for now.
Result of the command asked by @dragotin :
select count(*) from oc_filecache where etag = ''; 0
select count(*) from oc_filecache; 5738
Updated to 1.4.1 against 5.0.11 and its still re-downloading random blocks of files (6.1 gigs worth right now) on each of my clients. Other users have the same problem with their clients downloading gigs of untouched files over and over again. Nothing has changed and etags are present on every record in oc_filecache. All clocks are synchronized (clients and server) against 5 different ntp servers in my situation. Its happening with both the linux and the OSX clients.
Is there a correct way to disable / block the sync-client server-side? Short of figuring out the URLs ocsync uses and blocking those at the web server? For us, its probably better to just cut it off at the head until the problem can be sorted out. We can't afford the traffic that results from something like this and its going to get people in trouble with their ISPs if they're downloading hundreds of gigs of data every week or so.
I have this issue appearing on my server. (Debian OC 5.0.11 and Debian Client 1.4.1) I have my client sync files overnight and then all of a sudden it re-downloads a random amount of files. (15gb, 4.5gb, 1.3gb)
I would say this has been happening since client 1.3 and server 5.0.4 but i didn't notice the behaviour until 5.0.9
select count(*) from oc_filecache where etag = ''; 0
select count(*) from oc_filecache; 216867
I should add that i haven't been able to recreate this on my windows client or windows server. linux -> linux seems to be causing it for me.
I've already pointed out this earlier: http://mail.kde.org/pipermail/owncloud/2013-July/009799.html As someone is pointing out here, this issue has been there all the way from version 1.3.0, possibly with earlier version too. I've testing version 1.4.1 lately and i can confirm this issue is still there. Even the "Info" button in the sync client lists all my local files as "Download". They all were uploaded to the server! I don't really understand why such an issue isn't on the priority list for the devs of the sync client. Unfortunately, as it is now, the sync client is totally useless in a production environment. @danimo @dragotin
I would also recommend to mark v1.3 the last stable one and to blaim v1.4 as unstable/beta if v1.3 has the same behaviour regarding this issue, then better v1.2 stable and v1.3 also unstable/beta
@jochenwezel consider joining the release team if you wanna mark our releases with tags and do real work.
We still lack useful log files to get to the ground of the problem but you guys complain the night away... Sometimes its hard to keep up motiviation.
Some facts: The logfile snippet of @torbennehmer shows changed etags coming from the server and a resync as a result. That is correct behaviour from client side. We do not know why the server side ETag has changed, maybe the files were changed, somebody did a file cache rescan or there is a problem on the server side. That we have to find out.
@dragotin: So far the situtation from my side is this:
Each and every problem I could trace to (temporary) clock skews. Specifically with my macbook, whose hardware clock looses one or two seconds each day if the system is down. What happens there is that the client detects changes due to the changed system clocks and starts its unnecessary work.
As long as all systems are in sync to NTP time I did not experience the problem any more (not a single case since my last comment here in the thread).
The problem is quite simple: Must users probably will never notice that there actually is a clock skew, as the operating systems seem to do an immediate time resync once they come back online (whether form a network outage or form a full system shutdown). My Macbook usually is off-time for 30-60 seconds. After that, you don't see anything. Mind you, my clocks were usually off between 2 and 4 seconds, something you can't see if you just look at the typical desktop clocks.
If the client starts its work before that resync has been completed, things go downhill.
Also note, that the systems are fully ntp synced, not only by intermittent ntpdate calls but full with a local ntpd running.
Unfortunately, I didn't have the time to explicitly try to reproduce the issue in question by maliciously setting an incorrect system time - my spare time is rather limited and since the problem doesn't manifest here at this time there is no pressure on my part.
Once I get around to it (most probably not before end of October) I'll try to trigger the error once more.
@torbennehmer I would be hugely surprised if this problem would be really related to time. As you see in the logfile, we're comparing ETags rather than times. We switched from time based syncing to ETag based a long time ago. I think it was coincidence that you saw the problem vanishing once you fixed the clocks.
We have to find out why the server has changed ETags.
@dragotin: Ok, now that's strange then ... I'll make sure that ownclouds logging on all clients is active, so that I can give you any information I can get.
Is there a way to trace etag changes on the server side in case the problem is not related to a client?
@dragotin: In addidtion: Can you give me a (very) quick primer on what to grep for in the logfiles to find where the problems might originate from?
@DeepDiver1975 can you help us with server side knowledge here?
@torbennehmer the best would be to have the entire logfile. Can you create a small testcase folder with a couple of files only and create the logs using the --logdir <dir> --logexpire <hours>
options?
Hello @dragotin,
Sorry to seem complaining all the time :-( But we expect a lot from owncloud ;-) You're doing an amazing work, thanks for that!
You can download my log here (I changed the name of the server): https://www.sugarsync.com/pf/D6476655_61894308_901364 . I can send you everything you need, even the server log, but as the adress of the server sometimes appears in the log, I prefer to send it in a personal message. Where can I send it to? The files concerned by a redownload are in the picture attached.
Thank you, and congratulation for your work!
Etienne
@dragotin: I have my clients running in that way already. As for the "smaller" testcase, I have two sync folders, a larger and a smaller, both have been affected in the past. Unfortunately, apart from the timing issue (which you basically ruled out) I have no idea how to trigger the problem. So I am basically waiting for the problem to show up again and then grep the logs for those syncs, that actually triggered the problem. I have increased the backlog time to several days so that I am flexible in case of an actual error. I'll get in check with you as soon as I am seeing any anomalies.
here is an example of what we can find in @etiess logfile:
10-01 15:12:29:286 _csync_detect_update: ==> file: escalade/SAM_7126.JPG - hash 155909457714229693, mtime: 1371060756
10-01 15:12:29:287 _csync_detect_update: Database entry found, compare: 1371060756 <-> 1371060756, md5: 5240001fc4f26 <-> 523fd9d367d29, inode: 0 <-> 7844
10-01 15:12:29:287 _csync_detect_update: file: escalade/SAM_7126.JPG, instruction: INSTRUCTION_EVAL <<=
The interesting thing are the etags in the middle line, it shows that the server side etag is different from the client side etag, which is in the client journal. If the sever ETag has changed and the client one not, it means that the server side file was changed and the local one not which in turn means the server one has to be synced to local.
Again, we need to find out what happened on the server. And here we need @DeepDiver1975 to get us on the track how we can drill that down.
Since the last log, I stopped owncloud (right click, Quit Owncloud). Then I stored the log during one hour: the same files as last time seem to be downloaded again (for example SAM_0376.JPG)
You can find it here: https://www.sugarsync.com/pf/D6476655_61894308_902608
My server is on Ubuntu Server 12.04, and is 5.0.11, in RAID1. And I didn't change anything since last log.
If I can help in any other way, please don't hesitate!
Thanks
@etiess Your last log shows that the downloads run long, so long, that the final database is not written. That means that the new etag coming from the server is not written to the local journal. In that case its clear that its redownloaded. The question is: why didn't it come to the point where the database was written? Did you stop the sync client?
Yes, I stopped the sync client: I've only a slow connection with my server, and I can't afford to download 3.6 GB at 100 kb/s.
2 questions:
Right, we will have to write the etag as soon as the propagation of a file happened. We will fix that soon. Why is it not that way? Historical reasons...
The other point needs to be investigated. That should be reproducable with a new folder with very few files if that is a principal problem.
@etiess your problem is understood with that.
OK, I try to create a reproducable folder with very few files. I created a folder "Photos Test" (the other folder "Photos" was the one with issues: I paused the sync for it). I copied 8 of the files having issues in the redownloading.
When I tried to create a sync pair, then a message appeared: "You are already syncing Photos, which is a parent folder of Photos Test". In fact not. And I dont have the problem if I name it "Photo test" (without 's').
So I called it 'Photo Test', and I deleted the syncing for the folder "Photos". Then I created the sync pair. For the moment, nothing wrong appears.
Then I added some other pictures. Nothing wrong is coming for now.
I'll keep you updated if something bad happens. What if this problem appears only with big folders?
A user shared with me a folder with about 10 10 GB data (approx. 200 files).
I don't know why, but it's often (not always) finding some new files. Download follows - but unnecessarily: files are absolutely identical (byte comparison); the file on server hasn't been touched for months. So the file hasn't changed.
Following suggestions:
Local client: 1.4.0 on Win2008 R2 server (and other win systems, too) Server version: 4.5.7 on Linux