search

owncloud / client

🖥️ Desktop Syncing Client for ownCloud
GNU General Public License v2.0
1.39k stars 667 forks source link

Windows Desktop App often uses upload/delete instead of move #7838

Closed joholm2 closed 3 years ago

joholm2 commented 4 years ago

Expected behaviour In Windows explorer make any change to a file or folder, within the same sync area, which can be carried out by a move/rename.

eg...

All of these can be accomplished by a simple move operation.

Actual behaviour Sometimes a “move” is used Sometimes files are deleted on the server and re-uploaded. I see no obvious pattern in how it chooses what method to use.

I thought maybe it depended on file size, but even moving a large (500 MB file) into a sub-folder and later back again resulted in a “move” first (Ok) and later a totally unnecessary upload/delete on returning to the original folder.

This is very inefficient and there is no obvious reason for it.

It can also lead to a very bad situation when renaming a folder containing a large quantity of data. In cases where Owncloud chooses the upload/delete route the resulting upload can take hours - all totally unnecessary. Aborting such an upload leads to a further catastrophe with potential loss of data.

Steps to reproduce As described above in Expected behaviour. Check OwnCloud "Activity" in desktop app.

Example here is for creation of a new (empty) folder and repeated renaming (with idle time of a few seconds between each step). Activity log ordering - bottom to top. Annotation 2020-04-04 175051 In this case adding the "_test" suffix results in a Move and removing the "_test" suffix results in an Upload followed by a Delete.

Server configuration Operating system:Ubuntu 18.04

Web server: Apache/2.4.29 (Ubuntu)

Database: mySQL Ver 15.1 Distrib 10.1.43-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

PHP version: 7.2.24 and now 7.3.16-1

ownCloud version: 10.3.2.2 and now 10.4.0.4

Storage backend (external storage): SMB attached drive

Client configuration Client version: 2.6.0 and now 2.6.1

Operating system: Windows 10

michaelstingl commented 4 years ago

@joholm2 thank you very much for your feedback. Please provide a few lines of the client debug log from the time of the incident. (see https://doc.owncloud.org/desktop/2.6/troubleshooting.html#log-files)

joholm2 commented 4 years ago

Hi,

I enabled logging as you said and carried out a short test...

The activity log shows both "Moves" and "Upload/Deletes" - where just Moves should have been used.

Annotation 2020-04-06 005031

I don't yet understand the logging process but appear to have acquired multiple log files; attached here...

Edit... removed numerous log files and will post more specific case below..

michaelstingl commented 4 years ago

I don't yet understand the logging process but appear to have acquired multiple log files; attached here...

Desktop app checks for new changes after 30 second wait period. From every sync run, the log is written to a new file.

joholm2 commented 4 years ago

I don't see any 30 delay in syncing. When I create a "New folder" and rename it as fast as I can, the App always jumps in and uploads "New folder" and then uploads the renamed one and deletes "New folder". Better if it did wait a few moments.

But how ar the log files? Do they show why it does so many unnecessary upload & deletes?

michaelstingl commented 4 years ago

I don't see any 30 delay in syncing. When I create a "New folder" and rename it as fast as I can, the App always jumps in and uploads "New folder" and then uploads the renamed one and deletes "New folder".

Sorry, I didn't explain precise. Local changes get synced immediately. Desktop app always checks for new server-side changes after 30 second wait period.

But how ar the log files? Do they show why it does so many unnecessary upload & deletes?

Didn't check the log files yet.

joholm2 commented 4 years ago

One new log file attached.

Two step test... (what I did)

  1. "Test_document.docx" renamed to ""Test_document_renamed.docx"´
  2. "Test_document_renamed.docx" renamed back to "Test_document.docx"

Result (what Desktop client did) Step 1 was carried out by a rename Step 2 was carried out by an upload/delete.

The log covers the period of Step 2. I have changed the server URL to "https://{server}:{nnnn}" - note port number in the URL.

I notice that a rename is attempted but fails... Line 22: "Can't rename because the etag has changed or the directory is gone" ...and prior to that there are some "404 Not Found" errors.

owncloud_rename_fails.txt

Any help, advice or suggestions would be much appreciated.

joholm2 commented 4 years ago

I collected logs from both client and server during a simple test similar to the one above; in this case just renaming a file (with result upload/delete).

I see the same "Can't rename because the etag has....." in the client log; and on the server there is an equivalent error when trying to access the file to be renamed.... ...."message":"Exception: HTTP\/1.1 404 File with name {filename} could not be located:

One thing I don't understand in the server log is large numbers of pairs of lines...

updateToken","method":"DELETE","url":"{url-to-file}","message":"updating token ddd, last check is now dddddddddd"} ...followed immediately by a "getToken" for the same file... getToken","method":"DELETE","url":"{url-to-file}","message":"token hhhhhhh...really-long-hexadec.....hhhhhhh does not exist"

The method (DELETE in example above) varies between DELETE, PROPFIND and PUT; but the pattern is the same.

Can anyone say whether these getToken responses are normal or an error?

joholm2 commented 4 years ago

Hi,

There doesn't seem to be much in the way or responses or help here.

Is this all I can expect from OwnCloud?

For us It's a very big issue - if there is no help or support what else can we do?

michaelstingl commented 4 years ago

Team is busy with other tasks like 2.6.3 and 2.7.0 release and customer requests, and this problem is nothing that can be solved in the short term.

For professional support with guaranteed response times, you'll find options on the bottom of this page: https://owncloud.org/help/

joholm2 commented 4 years ago

Thanks, but i don't need it to be solved in the short term. I just need some help on the way. Anyone who understands these logs could give me some hints as to what they mean in a couple of minutes.

joholm2 commented 4 years ago

Just to add that we have set up an owncloud docker image server and repeated the tests.

The results are the same, the issue exists even there; so presumably that rules out any server misconfiguration as the cause of the issue.

joholm2 commented 4 years ago

Another test - I installed the latest Windows client on another PC, connected to the same docker image mentioned in my last post and sync'd with the test folder.

a) Same results when moving or renaming folders and files. Most often an upload & delete is used instead of the expected move.

b) When one sync'd PC does the unwanted upload & delete the second PC does a corresponding download & delete.

This is not good - to say the least!

joholm2 commented 4 years ago

I have to ask again... Is anyone looking into this? Is the cause of the fault known and understood? Are there any more logs we can get or tests we can do to help?

It really is an intolerable fault - I just needed to rename a directory containing 4.37 GB of pictures. Now the Owncloud client is uploading them all again - the time estimate is hovering around 50 minutes.

I've learnt from previous experience that it's best to let it complete it's wasteful upload - in the past, interrupting it has caused even more trouble.

michaelstingl commented 4 years ago

Is anyone looking into this?

Sorry, as mentioned before, nothing planned before 2.6.3 and 2.7.0 release.

ownCloud desktop sync client relies heavily on filesystem events to detect local changes. There are edge cases where the client does not get reliable information. Quite some effort has already been done to detect changes (e.g. checksum comparison), but the remaining cases are really hard to solve. Ensuring the integrity of the data is the higher goal than saving some GB.

I performed a quick test and it detected simple MOVE very reliably. (Using a 2.7 pre-release build on macOS)

Start Docker

docker run --rm -d \
  --name owncloud \
  -p 18080:8080 \
  -e ADMIN_USERNAME=admin \
  -e ADMIN_PASSWORD=admin \
  owncloud/server:latest

Start sync client

% /Applications/testpilotcloud.app/Contents/MacOS/testpilotcloud --logfile ~/tmp/tpc.log --logdebug

Debug log output

You can filter for the folderwatcher

% tail -f -n 1000 tmp/tpc.log | grep "info gui\.folderwatcher"
05-18 00:02:36:944 [ info gui.folderwatcher ]:  Detected changes in paths: QSet("/Users/mstingl_oc/testpilotcloud/Test_document_renamed.docx", "/Users/mstingl_oc/testpilotcloud/Test_document.docx")
05-18 00:02:38:772 [ info gui.folderwatcher ]:  Detected changes in paths: QSet("/Users/mstingl_oc/testpilotcloud/Test_document.docx", "/Users/mstingl_oc/testpilotcloud/Test_document_renamed.docx")
05-18 00:02:41:909 [ info gui.folderwatcher ]:  Detected changes in paths: QSet("/Users/mstingl_oc/testpilotcloud/Test_document_renamed.docx", "/Users/mstingl_oc/testpilotcloud/Test_document.docx")
05-18 00:02:43:484 [ info gui.folderwatcher ]:  Detected changes in paths: QSet("/Users/mstingl_oc/testpilotcloud/Test_document.docx", "/Users/mstingl_oc/testpilotcloud/Test_document_renamed.docx")
05-18 00:03:40:891 [ info gui.folderwatcher ]:  Detected changes in paths: QSet("/Users/mstingl_oc/testpilotcloud/Test_document_renamed.docx", "/Users/mstingl_oc/testpilotcloud/Test_document.docx")

Simple log in sync dir

This log isn't really useful for serious debugging

% tail -f -n 1000 testpilotcloud/.owncloudsync.log | grep Test_document
21:48:51||Test_document.docx -> Test_document_renamed.docx|4|1|1589750679|c39fad53988f3fa4a6e6c2a4b015ac01|6069226|00000011ocbk0cx8s7e9|4||201|0|0|d86b4eaa-c56b-46bc-b92b-d0aed72661d0|
22:01:19||Test_document_renamed.docx -> Test_document.docx|4|1|1589750679|c39fad53988f3fa4a6e6c2a4b015ac01|6069226|00000011ocbk0cx8s7e9|4||201|0|0|df7cbf9a-8548-45c6-a19f-8b9bd7b942f3|
22:01:32||Test_document.docx -> Test_document_renamed.docx|4|1|1589750679|c39fad53988f3fa4a6e6c2a4b015ac01|6069226|00000011ocbk0cx8s7e9|4||201|0|0|975b71f6-84b6-4b91-bb28-7868d7c57ca1|
22:01:59||Test_document_renamed.docx -> Test_document.docx|4|1|1589750679|c39fad53988f3fa4a6e6c2a4b015ac01|6069226|00000011ocbk0cx8s7e9|4||201|0|0|7815c036-2651-4826-88fd-f0c4856f6ed8|
22:02:08||Test_document.docx -> Test_document_renamed.docx|4|1|1589750679|c39fad53988f3fa4a6e6c2a4b015ac01|6069226|00000011ocbk0cx8s7e9|4||201|0|0|a7d31c93-d0c3-454c-ad54-230bf420c8af|
22:03:42||Test_document_renamed.docx -> Test_document.docx|4|1|1589750679|c39fad53988f3fa4a6e6c2a4b015ac01|6069226|00000011ocbk0cx8s7e9|4||201|0|0|523fbd88-2dad-4485-986c-e7b8989f2c5a|

Docker log

% docker logs --follow owncloud | grep Test_document
creating sqlite db
[Sun May 17 21:23:29.850702 2020] [mpm_prefork:notice] [pid 181] AH00163: Apache/2.4.41 (Ubuntu) configured -- resuming normal operations
[Sun May 17 21:23:29.850779 2020] [core:notice] [pid 181] AH00094: Command line: '/usr/sbin/apache2 -f /etc/apache2/apache2.conf -D FOREGROUND'
172.17.0.1 - admin [17/May/2020:21:48:51 +0000] "MOVE /remote.php/dav/files/admin/Test_document.docx HTTP/1.1" 201 651 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"
172.17.0.1 - admin [17/May/2020:22:01:18 +0000] "PROPFIND /remote.php/dav/files/admin/Test_document_renamed.docx HTTP/1.1" 207 971 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"
172.17.0.1 - admin [17/May/2020:22:01:19 +0000] "MOVE /remote.php/dav/files/admin/Test_document_renamed.docx HTTP/1.1" 201 651 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"
172.17.0.1 - admin [17/May/2020:22:01:32 +0000] "MOVE /remote.php/dav/files/admin/Test_document.docx HTTP/1.1" 201 651 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"
172.17.0.1 - admin [17/May/2020:22:01:59 +0000] "PROPFIND /remote.php/dav/files/admin/Test_document_renamed.docx HTTP/1.1" 207 971 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"
172.17.0.1 - admin [17/May/2020:22:01:59 +0000] "MOVE /remote.php/dav/files/admin/Test_document_renamed.docx HTTP/1.1" 201 651 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"
172.17.0.1 - admin [17/May/2020:22:02:08 +0000] "MOVE /remote.php/dav/files/admin/Test_document.docx HTTP/1.1" 201 651 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"
172.17.0.1 - admin [17/May/2020:22:03:42 +0000] "PROPFIND /remote.php/dav/files/admin/Test_document_renamed.docx HTTP/1.1" 207 971 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"
172.17.0.1 - admin [17/May/2020:22:03:42 +0000] "MOVE /remote.php/dav/files/admin/Test_document_renamed.docx HTTP/1.1" 201 651 "-" "Mozilla/5.0 (Macintosh) mirall/2.7.0daily20200516 (ownCloud Testpilot Edition, osx-19.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)"

Interesting in your log owncloud_rename_fails.txt

04-10 17:24:42:771 [ info sync.discovery ]: Processing "Data/TestFolder/Test_document_rename.docx" | valid: true/false/true | mtime: 1586126680/0/1586126680 | size: 0/0/0 | etag: "97a541031ff61287f051818cd564d844"//"97a541031ff61287f051818cd564d844" | checksum: "SHA1:da39a3ee5e6b4b0d3255bfef95601890afd80709"//"SHA1:da39a3ee5e6b4b0d3255bfef95601890afd80709" | perm: WDNVR//WDNVR | fileid: "00107897ocyhh4g4hc51"//"00107897ocyhh4g4hc51" | inode: 122593/0/ | type: 0/3/0

I'd say your log file is worth another look from more knowledgable experts. I totally understand the inconvenience for you, and I wish the team finds ways to improve here in the future, but there is nothing critical or urgent about it.

joholm2 commented 4 years ago

Hi Michael,

Thanks, we really appreciate your reply.

It's a shame you tested on macOS - we are using Windows so I don't know how closely they match.

Interesting you mention SMB storage. Are you referring to the PC files or the sever file system?

On the PCs we have mainly files on the single hard disk, but one is on a Micro-SD card in a "built in" slot.

On the sever we have a separate Raid storage unit mounted via SMB.

In our setup using Docker we have sync'd only local HD storage on the PC and presumably Docker uses purely local storage on the sever. Since the Docker setup shows the same problems it's hard to draw any conclusions.

michaelstingl commented 4 years ago

Since the Docker setup shows the same problems it's hard to draw any conclusions.

Strange, in my Docker tests, I wasn't able to reproduce. I'll need to have another look when time allows…

joholm2 commented 4 years ago

Thanks, as I mentioned you used a new client on macOS and we have 2.6.1 client on Windows10 - so not directly comparable.

joholm2 commented 4 years ago

It's now 3 weeks since I renamed a directory containing about 5 GB of files on my windows PC, and OwnCloud client decided to re-upload the whole lot rather than just rename/move the directory on the server.

I use a program called FreeFileSync to keep a local backup up to date and run that sporadically - often every few weeks. So almost 3 weeks after the "rename" I ran FreeFileSync and watched to see what it did with the directory.

With no problem at all it saw it as a "move" and simply moved it on the backup drive.

So if FreeFileSync can figure it out correctly after 3 weeks it can't be that hard for OwnCloud client after just a few seconds.

Maybe some developer here can take a look at the FreeFileSync code.

joholm2 commented 3 years ago

Hi,

We've been waiting now over 7 months and so far no useful help or solution.

We really need to be able to sort out our photo collection without Owncloud continuously up & down-loading gigabytes of files every time we move or rename a folder.

If Owncloud can't function properly we'll need to move on to something which can.

joholm2 commented 3 years ago

Today on Windows 10 the ownCloud App updated to 2.1.1

I made a quick test of the synchronisation to my test area in a completely standard Docker/ownCloud.

Moving a sub-folder containing files from one folder to another (in the same sync folder) resulted in a move on the sever. Good - although it beats my why the log shows both folder move and then individual file moves - surely carrying out a proper move of a folder means all the files are included anyway.

But next - move the sub-folder onward to another folder (still within same sync area). This time all the files are upload as if new to the server and the originals are deleted. Bad!

Third try. move te sub-folder back to te starting folder - another upload/delete session - completely unnecessary.

I made several more moves in Windows but no sign of any move operations in the sync log - always uploads and deletes.

So there is no improvement this new version of the Windows app.

This is a critical issue - when will it be fixed?

joholm2 commented 3 years ago

I have just completed a switch from Owncloud to Nextcloud.

Same server Same Linux (Ubunti) Same data storage device Same client PC

Tested renaming and moving of folders and files and Nextcloud gets it right every time.

Goodbye Owncloud !!!

sfadschm commented 3 years ago

Hi all, as there has not been any action for some time, I decided to add my two cents here.

This behavior is still an issue and I think it is an important one that affects a core functionality of OwnCloud.

The unreliable detection of move/rename operations is a significant efficiency reduction. While I understand the raised point that data consistency is more important than sparing bandwidth, the issue also affects consistency. Take the following example case:

  1. Move a folder with some file on client A to a different folder (such that reuploading gets triggered).
  2. Abort the reupload process by shutting down (or whatever other way).
  3. Open OwnCloud on a second synced client.

Depending on the sync status when shutting down client 1, the delete operation of the old folder will be processed by the server or not. This can result in the moved files being reuploaded by client 2 to the old location and hence duplicate data.

On another note, the reupload process also destroys the moved files history (because they get deleted and recreated).

IMO, these are two major problems (inconsistent data, corrupted file history, along with unnecessary syncing times) for OwnClouds core functionality that should be addressed, even if they are complicated to resolve. However, moving files around is working perfectly nice with other clients (e.g. Dropbox, Seafile) so detection based on OS behavior should be possible in principle.

@joholm2 Can you confirm that this still works reliably with NextCloud? There seem to be similar open issues in the tracker (e.g, https://github.com/nextcloud/desktop/issues/2132).

joholm2 commented 3 years ago

Hi,

Yes, we can confirm that move and rename work reliably (for us) with Nextcloud.

Since we switched from Owncloud to Nextcloud we have had no such problems at all.

We can rename folders containing gigabytes of data and/or large numbers of files without fear that they are re-uploaded (and re-downloaded to other clients).

One noticeable thing is that upon renaming (or moving) a folder, the NextCloud Windows client dialog shows that is runs through every underlying folder & file. The counter shows progress and it doesn't normally take long (eg 2 or 3 seconds for a hundred files). We have also double checked that it is not "secretly" uploading he files during that slight delay.

So the Windows "dynamic log" which pops up when you left-click the NextCloud icon shows a rename operation for each and every file within the renamed/moved folder - which seems a bit unnecessary. But the web interface "Activity" log show simple "You renamed to

. I checked the case #2132 you mentioned and confirm we don't see that problem at all. I see that issue was reported on server 19.0.0 and we actually started and 20.0.02 (now on 20.0.7). Good luck - it would be interesting to hear how things work out... Regards David Bloomfield +46705315381 Johannisholm Adventure AB +4625060000 http://joholm.se info@joholm.se ------ Original Message ------ From: "Alex Schmitz" To: "owncloud/client" Cc: "joholm2" ; "Mention" Sent: 2021-02-18 08:58:35 Subject: Re: [owncloud/client] Windows Desktop App often uses upload/delete instead of move (#7838) Hi all, as there has not been any action for some time, I decided to add my two cents here. This behavior is still an issue and I think it is an important one that affects a core functionality of OwnCloud. The unreliable detection of move/rename operations is a significant efficiency reduction. While I understand the raised point that data consistency is more important than sparing bandwidth, the issue also affects consistency. Take the following example case: Move a folder with some file on client A to a different folder (such that reuploading gets triggered). Abort the reupload process by shutting down (or whatever other way). Open OwnCloud on a second synced client. Depending on the sync status when shutting down client 1, the delete operation of the old folder will be processed by the server or not. This can result in the moved files being reuploaded by client 2 to the old location and hence duplicate data. On another note, the reupload process also destroys the moved files history (because they get deleted and recreated). IMO, these are two major problems (inconsistent data, corrupted file history, along with unnecessary syncing times) for OwnClouds core functionality that should be addressed, even if they are complicated to resolve. However, moving files around is working perfectly nice with other clients (e.g. Dropbox, Seafile) so detection based on OS behavior should be possible in principle. @joholm2 Can you confirm that this still works reliably with NextCloud? There seem to be similar open issues in the tracker (e.g, nextcloud/desktop#2132 ). — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub , or unsubscribe .
gabi18 commented 3 years ago

@joholm2 Could you please confirm that for the last tests the ownCloud client was updated to 2.7.1.. Which ownCloud server version was installed?

joholm2 commented 3 years ago

@joholm2 Could you please confirm that for the last tests the ownCloud client was updated to 2.7.1.. Which ownCloud server version was installed?

Yes. I see there is a typo in my comment Nov 2020 where it says 2.1.1. In earlier posts i had already mentioned using 2.6.1, so the November version was undoubtedly 2.7.1.

Owncloud server was always kept up to date, so was whatever was current in November 2020.

gabi18 commented 3 years ago

Thank you for the quick response!

sfadschm commented 3 years ago

Just to add to this: I last experienced the issue yesterday, running client 2.7.6 and server 10.6.0.5.

I also tried playing around with the various ways of moving files in Windows Explorer, but couldn't find any way to work around the issue. Namely, neither using the context menu Cut -> Paste nor the shortcut Strg+X + Strg+V nor simple drag and drop is working consistently. It also does not seem to matter whether the move operation takes place inside the same Explorer window or across two windows.

joholm2 commented 3 years ago

Don't forget the simple renaming of a folder containing sub-folders and files. There is less scope for variation in how that is done. Med vänlig hälsning David Bloomfield Johannisholm Adventure AB 0705315381

On 22 February 2021 14:30:16 CET, Alex Schmitz notifications@github.com wrote: Just to add to this: I last experienced the issue yesterday, running client 2.7.6 and server 10.6.0.5.

I also tried playing around with the various ways of moving files in Windows Explorer, but couldn't find any way to work around the issue. Namely, neither using the context menu Cut -> Paste nor the shortcut Strg+X + Strg+V nor simple drag and drop is working consistently. It also does not seem to matter whether the move operation takes place inside the same Explorer window or across two windows.

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/owncloud/client/issues/7838#issuecomment-783374639

gabi18 commented 3 years ago

@sfadschm Thank you for the info. It would be very helpful to get client log files at time the issue occurs. If it's possible for you, please provide those logs. Yesterday logs probably got deleted, it's default to delete logs older than 4 hours (can be changed in client 'Settings' 'Log Settings'). See also https://doc.owncloud.org/desktop/2.7/troubleshooting.html#log-files.

sfadschm commented 3 years ago

@gabi18 Thanks for taking a look!

I just triggered the issue intentionally, the correspoding log is attached (if thats not the correct one, let me know). Action:

Moved folder _current/Nanoplatelets/Singletary to Research/CsPbBr3 NPLs - Kovalenko/Data/_Single Platelets/Singletary inside the same tracked folder (Promotion) via drag&drop.

I also attached the clients activity window output. Let me know if there is anything I can provide to help.

Windows Client Move Failure.zip

gabi18 commented 3 years ago

Thank you very much!

sfadschm commented 3 years ago

Please find attached a log from another (unintended) try today, where the move operation was actually successfully detected.

The folder was moved the same way as yesterday, and origin/target location are also identical. The moved folder itself contains fewer, but bigger files.

Windows Client Move Success.zip

gabi18 commented 3 years ago

Thanks again for your feedback. It's very useful to have also 'success' logs provided.

From yesterdays log-files we already could see that there are similar lines about "Can't rename..." and error "404 Not Found" like in initial report. Compared that with the success log will help us a lot to solve the issue.

TheOneRing commented 3 years ago

When we discover that a file disappeared and a new file appears, we compare the checksum, if they match we assume a move. Under certain conditions we need to make the file on the server, the original file for which we detected a move, has not changed in the meantime.

This check fails in the original error log

04-10 17:24:43:126 [ info sync.networkjob.etag ]:   Request Etag of QUrl("https://{server}:{nnnn}/owncloud/remote.php/dav/files/davblo/Data/TestFolder/Test_document_rename.docx") FINISHED WITH STATUS "ContentNotFoundError Server replied \"404 Not Found\" to \"PROPFIND https://{server}:{nnnn}/owncloud/remote.php/dav/files/davblo/Data/TestFolder/Test_document_rename.docx\""
04-10 17:24:43:126 [ info sync.discovery ]: Can't rename because the etag has changed or the directory is gone "Data/TestFolder/Test_document_rename.docx"

As the error message already says, we cant find the move origin on the server. In that case we can only upload the new file, with the old file gone there is nothing to move on the server.

If the error still occurs, I need recent logs of a fail, ideally with http logs enabled. The original issue might be related to the smb external storage use on the server but we would need to find out why the file was not discovered on the server.

TheOneRing commented 3 years ago

I just saw the recent logs in https://github.com/owncloud/client/issues/7838#issuecomment-783432477 What server config are you using, is an external storage involved?

sfadschm commented 3 years ago

I just saw the recent logs in #7838 (comment) What server config are you using, is an external storage involved?

In my case, no external storage is involved. Just a simple OwnCloud installation on a vServer running Ubuntu. If any config files or such can help, let me know.

sfadschm commented 3 years ago

As the error message already says, we cant find the move origin on the server. In that case we can only upload the new file, with the old file gone there is nothing to move on the server.

The original issue might be related to the smb external storage use on the server but we would need to find out why the file was not discovered on the server.

Does that mean that the file/folder somehow got deleted on the server side before the etag check was run? That would be strange, I think. In the sync logs, the delete operation of the old path is always displayed after the moved files were uploaded to the new path.

If the error still occurs, I need recent logs of a fail, ideally with http logs enabled.

By http logs, do you mean the server side logs?

joholm2 commented 3 years ago

HI,

External storage? Yes and no.

In our main server we have SMB raid drives - (now working fine with NextCloud)

In the simple Docker setup we tested there was only local storage.

Both behaved the same way.

------ Original Message ------ From: "Hannah von Reth" notifications@github.com To: "owncloud/client" client@noreply.github.com Cc: "joholm2" info@joholm.se; "Mention" mention@noreply.github.com Sent: 2021-02-24 15:43:42 Subject: Re: [owncloud/client] Windows Desktop App often uses upload/delete instead of move (#7838)

I just saw the recent logs in #7838 (comment) https://github.com/owncloud/client/issues/7838#issuecomment-783432477 What server config are you using, is an external storage involved?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/owncloud/client/issues/7838#issuecomment-785124132, or unsubscribe https://github.com/notifications/unsubscribe-auth/AOT5L3NK3J3OBI7J7BKLOZTTAUGB5ANCNFSM4L6SI5VQ.

joholm2 commented 3 years ago

Hi,

A question about your comment below.

If the original file is not found on he server - why does OwnCloud subsequently go on and delete it?

There is always a distinct upload to the server followed by a delete on the server.

Delete a file that it cannot find? That doesn't make sense.

------ Original Message ------ From: "Hannah von Reth" notifications@github.com To: "owncloud/client" client@noreply.github.com Cc: "joholm2" info@joholm.se; "Mention" mention@noreply.github.com Sent: 2021-02-24 15:41:14 Subject: Re: [owncloud/client] Windows Desktop App often uses upload/delete instead of move (#7838)

When we discover that a file disappeared and a new file appears, we compare the checksum, if they match we assume a move. Under certain conditions we need to make the file on the server, the original file for which we detected a move, has not changed in the meantime.

This check fails in the original error log

04-10 17:24:43:126 [ info sync.networkjob.etag ]: Request Etag of QUrl("https://{server}:{nnnn}/owncloud/remote.php/dav/files/davblo/Data/TestFolder/Test_document_rename.docx") FINISHED WITH STATUS "ContentNotFoundError Server replied \"404 Not Found\" to \"PROPFIND https://{server}:{nnnn}/owncloud/remote.php/dav/files/davblo/Data/TestFolder/Test_document_rename.docx\"" 04-10 17:24:43:126 [ info sync.discovery ]: Can't rename because the etag has changed or the directory is gone "Data/TestFolder/Test_document_rename.docx"

As the error message already says, we cant find the move origin on the server. In that case we can only upload the new file, with the old file gone there is nothing to move on the server.

If the error still occurs, I need recent logs of a fail, ideally with http logs enabled. The original issue might be related to the smb external storage use on the server but we would need to find out why the file was not discovered on the server.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/owncloud/client/issues/7838#issuecomment-785122446, or unsubscribe https://github.com/notifications/unsubscribe-auth/AOT5L3I3QX7PM3IOUFKXAC3TAUFYVANCNFSM4L6SI5VQ.

sfadschm commented 3 years ago

@joholm2 Thats what I wanted to ask @TheOneRing. I think I missunderstood her point, but to me the clients sync log seems to implicate that files are first uploaded, then deleted from the old location.

From the log files, I see

02-22 15:37:09:996 [ info sync.discovery ]: Discovered "_current/Nanoplatelets/Singletary" CSyncEnums::CSYNC_INSTRUCTION_REMOVE OCC::SyncFileItem::Up CSyncEnums::ItemTypeDirectory
02-22 15:37:10:065 [ info sync.discovery ]: Discovered "Research/CsPbBr3 NPLs - Kovalenko/Data/_Single Platelets/Singletary" CSyncEnums::CSYNC_INSTRUCTION_NEW OCC::SyncFileItem::Up CSyncEnums::ItemTypeDirectory

So a CSYNC_INSTRUCTION_REMOVE and CSYNC_INSTRUCTION_NEW are discovered for the moved folder itself. However afterwards, the etag of the folder itself does not seem to be checked. Instead several etags of sub-folder/-files are checked and at some point, some files generate the 404 error, e.g.:

02-22 15:37:10:066 [ info sync.accessmanager ]: 6 "PROPFIND" "https://OWNCLOUD_URL/remote.php/dav/files/alex/_current/Nanoplatelets/Singletary/Data" has X-Request-ID "5b1a24f8-a4e8-4bc0-8779-8a8c6ad92689"
02-22 15:37:10:066 [ info sync.networkjob ]:    OCC::RequestEtagJob created for "https://OWNCLOUD_URL" + "_current/Nanoplatelets/Singletary/Data" "OCC::ProcessDirectoryJob"

02-22 15:37:10:164 [ warning sync.networkjob ]: QNetworkReply::ContentNotFoundError "Server hat \"404 Not Found\" auf \"PROPFIND https://OWNCLOUD_URL/remote.php/dav/files/alex/_current/Nanoplatelets/Singletary/Data\" geantwortet" QVariant(int, 404)
02-22 15:37:10:165 [ info sync.networkjob.etag ]:   Request Etag of QUrl("https://OWNCLOUD_URL/remote.php/dav/files/alex/_current/Nanoplatelets/Singletary/Data") FINISHED WITH STATUS "ContentNotFoundError Server hat \"404 Not Found\" auf \"PROPFIND https://OWNCLOUD_URL/remote.php/dav/files/alex/_current/Nanoplatelets/Singletary/Data\" geantwortet"
02-22 15:37:10:165 [ info sync.discovery ]: Can't rename because the etag has changed or the directory is gone "_current/Nanoplatelets/Singletary/Data"

Please correct me if I missed a log entry here, but I can't seem to find the etag check for the moved folder itself (Singletary).

joholm2 commented 3 years ago

Concerning sub-folders etc - all very important; but when debugging it seems most sensible to begin with the simplest of all possible situations to avoid extraneous variable.

eg. start by choosing on file and rename it. Wait for sync to finish then rename it again. Even there I found erratic behaviour. If that seems to work ok, then progress to doing the same with an empty folder, If that seems to work the progress to a renaming a folder containing one file.

If all of those work then go back to a single file and try drag and drop from one folder to another. etc etc.

Either you see the problem at the start and get the simplest of logs or you find where the problem starts to occur.

sfadschm commented 3 years ago

Concerning sub-folders etc - all very important; but when debugging it seems most sensible to begin with the simplest of all possible situations to avoid extraneous variable.

eg. start by choosing on file and rename it. Wait for sync to finish then rename it again. Even there I found erratic behaviour. If that seems to work ok, then progress to doing the same with an empty folder, If that seems to work the progress to a renaming a folder containing one file.

If all of those work then go back to a single file and try drag and drop from one folder to another. etc etc.

Either you see the problem at the start and get the simplest of logs or you find where the problem starts to occur.

Seems reasonable. I will play around a little :)

sfadschm commented 3 years ago

Well that was easier than expected. I never realized this was a problem with single files, too. @gabi18, @TheOneRing please find attached the log files (HTTP enabled) for a very simple test case:

  1. Create "Neues Textdokument.txt" in tracked folder.
  2. Add sample text to file.
  3. Rename file to "Testfile.txt"
  4. Repeatedly rename file to "Testfile X.txt" (X = 2, ..., 16). Between each rename, I waited until the action was completed.
  5. Move testfile in and out of subfolder a few times.

Hope this can get us on the road.

Simple Test Rename File.zip

Thanks @joholm2 for the idea. Sometimes one can't see the forest for all the trees...

joholm2 commented 3 years ago

I see rename "Testfile 9" to "Testfile 10"

02-24 23:01:24:483 [ warning sync.networkjob ]: QNetworkReply::ContentNotFoundError "Server hat \"404 Not Found\" auf \"PROPFIND https://--- SENSITIVE INFORMATION ---/remote.php/dav/files/alex/Promotion/_current/Testfile 9.txt\" geantwortet" QVariant(int, 404) 02-24 23:01:24:483 [ info sync.networkjob.etag ]: Request Etag of QUrl("https://--- SENSITIVE INFORMATION ---/remote.php/dav/files/alex/Promotion/_current/Testfile 9.txt") FINISHED WITH STATUS "ContentNotFoundError Server hat \"404 Not Found\" auf \"PROPFIND https://--- SENSITIVE INFORMATION ---/remote.php/dav/files/alex/Promotion/_current/Testfile 9.txt\" geantwortet" 02-24 23:01:24:483 [ info sync.discovery ]: Can't rename because the etag has changed or the directory is gone "Promotion/_current/Testfile 9.txt"

joholm2 commented 3 years ago

Then a while later....

Line 520: 02-24 23:01:25:453 [ info sync.networkjob.delete ]: DELETE of QUrl("https://--- SENSITIVE INFORMATION ---/remote.php/dav/files/alex/Projekte/Promotion/_current/Testfile 9.txt") FINISHED WITH STATUS "OK"

... it successfully deletes the file it couldn't find!

sfadschm commented 3 years ago

Yep, might be right direction to look. But lets see what the team says. I know way to little about OCs internal processes to conclude the underlying issues here (e.g., PROPFIND might have other information available which makes it think the file is already gone).

Btw., thank you very much for keeping up with the issue!

jnweiger commented 3 years ago

Using the idea from @joholm2 and the examples from @sfadschm I was able to create a 100% reliable reproducer with a 2.7.6 client on Ubuntu 20.04.

#! /bin/sh
#
# reproduce a similar situation as discussed in https://github.com/owncloud/client/issues/7838
# Differences are
# - here it is done on Linux
# - we don't see a 404 from the server, and 'etag has changed'
# - instead we see 'Not a move, ' messages.
#
# Requires:
# sudo apt-get install docker.io netcat testpilotcloud-client

docker run --rm --name repr-7838 -d -p 7788:8080 owncloud/server:10.6.0
sleep 5 # wait docker startup

dir=/tmp/repr-7838
rm -rf $dir

env HOME=$dir testpilotcloud --showsettings --logdebug --logfile $dir/client.log &
sleep 5

test -z "$UID" && UID=$(id -u)
send() { echo "$@" | netcat -U -w 1 /run/user/$UID/testpilotcloud/socket; }
settext() { send "ASYNC_SET_WIDGET_PROPERTY:42|{\"objectName\":\"#$1\", \"property\":\"text\",\"value\":\"$2\"}"; }
click() { sleep 1; send "ASYNC_INVOKE_WIDGET_METHOD:42|{\"objectName\":\"#$1\", \"method\":\"click\"}"; sleep 1; }

send VERSION
settext leUrl http://localhost:7788
click __qt__passive_wizardbutton1
settext leUsername admin
settext lePassword admin
click __qt__passive_wizardbutton1
click __qt__passive_wizardbutton1
click __qt__passive_wizardbutton1
click __qt__passive_wizardbutton1

checksync() { sleep 1; grep 'Not a move' $dir/client.log; }

for r in 0 1 2 3 4 5 6 7 8 9 10; do
  for i in 0 1 2 3 4 5 6 7 8 9 10; do
    echo $r.$i
    mv $dir/testpilotcloud/Photos/Portugal.jpg $dir/testpilotcloud/Portugal.jpg
    checksync && break
    mv $dir/testpilotcloud/Portugal.jpg $dir/testpilotcloud/Photos/Portugal.jpg
    checksync && break
  done
  checksync && break
done

echo "Review the client debug log at $dir/client.log"
echo ""
echo "Press ENTER to kill server and client. CTRL-C to keep them."; read a
killall testpilotcloud
docker kill repr-7838

Wait ca 20 sec. until the client UI is fully initialized, and the shell starts counting loop numbers. Then you may click to the activity page and watch the client's sync protocol. It should show repeated move operations, ca. one per second. The timing intentionally provokes race conditions. After ca 10 to 20 iterations, delete+create should occur instead, and the script stops.

I've seen two new types of errors in the logs:

02-25 03:21:34:562 [ info sync.discovery ]:     Processing "Photos/Portugal.jpg" | valid: false/true/db | mtime: 0/1614219677/0 | size: 0/243733/0 | etag: ""//"" | checksum: ""//"" | perm: 0x7f161e4cdd58//0x7f161e4cdd58 | fileid: ""//"" | inode: 0/657847/ | type: CSyncEnums::ItemTypeSkip/CSyncEnums::ItemTypeFile/CSyncEnums::ItemTypeFile
02-25 03:21:34:562 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 657847
02-25 03:21:34:562 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        SQL exec "SELECT path, inode, modtime, type, md5, fileid, remotePerm, filesize,  ignoredChildrenRemote, contentchecksumtype.name || ':' || contentChecksum FROM metadata  LEFT JOIN checksumtype as contentchecksumtype ON metadata.contentChecksumTypeId == contentchecksumtype.id WHERE inode=?1"
02-25 03:21:34:562 [ info sync.discovery ]:     Not a move, no item in db with inode 657847
02-25 03:21:34:562 [ info sync.discovery ]:     Discovered "Photos/Portugal.jpg" CSyncEnums::CSYNC_INSTRUCTION_NEW OCC::SyncFileItem::Up CSyncEnums::ItemTypeFile

and 

02-25 03:18:53:592 [ info sync.discovery ]:     Processing "Portugal.jpg" | valid: false/true/false | mtime: 0/1614219503/0 | size: 0/243733/0 | etag: ""//"" | checksum: ""//"" | perm: 0x7f72fcb4bd58//0x7f72fcb4bd58 | fileid: ""//"" | inode: 0/657848/ | type: CSyncEnums::ItemTypeSkip/CSyncEnums::ItemTypeFile/CSyncEnums::ItemTypeFile
02-25 03:18:53:592 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 657848
02-25 03:18:53:592 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        SQL exec "SELECT path, inode, modtime, type, md5, fileid, remotePerm, filesize,  ignoredChildrenRemote, contentchecksumtype.name || ':' || contentChecksum FROM metadata  LEFT JOIN checksumtype as contentchecksumtype ON metadata.contentChecksumTypeId == contentchecksumtype.id WHERE inode=?1"
02-25 03:18:53:592 [ info sync.discovery ]:     Not a move, base file still exists at "Photos/Portugal.jpg"
02-25 03:18:53:592 [ info sync.discovery ]:     Discovered "Portugal.jpg" CSyncEnums::CSYNC_INSTRUCTION_NEW OCC::SyncFileItem::Up CSyncEnums::ItemTypeFile

If you remove the && break clauses from the loops, then you should see move operations again after a while, followed by another round of delete+create, and so on ...

sfadschm commented 3 years ago

@jnweiger Quite interesting. If I conclude correctly, on Linux, inodesare used instead of etags to detect file changes? If so it seeme to me that the core issue is rather the communication between client and server (or the server response, so to say) and not so much the client itself, as the client seems to try to propagate a move operation correctly, but gets stopped by the server response.

sfadschm commented 3 years ago

Forgot to add the server logs for my example, here they are: owncloud.log

They document the 404 exceptions.

From scanning the logs again it seems to me that the etag request and answer are quite offset on a time axis. In between serveral other operations are processed. Could it be a poosible cause that the file on the serverside actually gets moved/deleted even before the server processed the etag request?

gabi18 commented 3 years ago

@joholm2, @sfadschm Thanks a lot for all the useful input!