Client just deleted local files, even though they also exist on the server

[sagamusix]

Expected behaviour

The client should never delete files for no good reason.

Actual behaviour

I had a tough time synchronizing big ownCloud folders (which is already being discussed e.g. in #5017), often resulting in 503s and timeouts during the sync and thus restarting the sync process.
After some days the folder was mostly synchornized at last, as I could observe on the web interface.
However, all of a sudden the client decided that it should delete the local folder, even though it was still present on the server as well! I got a message telling me that there is a big folder that won't be synchronized by default, I chose to synchronize everything but by that time the local files were already gone...

Steps to reproduce

I'm not really sure.

Client configuration

Client version: Version 2.5.0-nightly20180110 (build 8967).

Operating system: Windows 7 x64

OS language: German

Installation path of client: Default

[ogoffart]

Start the client with --logdebug --logfile C:\log.txt To start the client will full debug output into a file.

Select the folder in the settings dialog and press the secret "Ctrl+F6" shortcut which will redo a sync with full remote discovery. Does the deleted file re-appear?

Go in the log and search for filename of files that are deleted and send us the lines around that.

My suspission is that the server did not report the files for some reason, doing CTRL+F6 should force the client to read everything again from the server.
Either we will see the file reaparing, or we will see in the log why the client thinks the files are not there.

[sagamusix]

After copying the files back to their original location, the bug didn't happen anymore, even after a enforcing a full remote discovery.

[guruz]

@sagamusix Which exact server version are you using?
Can you grep your server access log for the respective path?

[sagamusix]

10.0.4, but probably 10.0.3 at that time. I have pruned my logs since they grew to more than 6GB, so I'm afraid they are gone now.

[guruz]

@sagamusix But you don't know if in this special case the server sent something unexpected, right?
The 503s you spoke about were on previous occasions?

[sagamusix]

As far as I can tell, yes, there was no direct connection between the two.

[sagamusix]

Coincidentally, this just happened again today. This time, it was even worse, though, because it deleted a hardlink (which it would normally not touch at all), and apparently, as a consequence, even deleted the contents of the linked-to folder. I cannot imagine how that is even possible.

[sagamusix]

I'd be much less frustrated now if ownCloud at least (optionally) uses the recycle bin to delete local files. I do have other backups, but the recycle bin would be just much more convenient, in particular since I use ownCloud with a single client and in theory the server should never delete files for me.

[ckamm]

@sagamusix Can you look for the .owncloudsync.log log entry for the file that was deleted? This is pretty hard to debug without a full client log (and I realize getting one is very hard for rare problems like this) and the log entry there might at least provide some pointers.

[ckamm]

I've looked at this as much as I could with the given data in #6282 but don't know what's going on.

[sagamusix]

@ckamm I will send you some logs via mail.

[ckamm]

@sagamusix Thank you for the logs!

Initial impressions follow:

Setup:

• A sync folder A, some data somewhere else called B/data
• A/link is a directory link to B/data, so A/link/foo and B/data/foo point to the same file

Trigger:

• During the sync of A, link has an _invalid_ etag (unclear whether parents also had that etag)
• Because of that it's missing in the remote tree and gets assigned a REMOVE instruction with Down direction.
• The folder and all its contents get deleted. That means B/data/foo gets deleted.

Bugs:

• The recursive folder deletion follows the directory link and deletes the shared contents (note: windows!)
• Mysterious _invalid_ etags

Log snippet from sync run of A:

#=#=#=# Syncrun started 2018-02-05T17:47:02Z
#=#=#=#=# Propagation starts 2018-02-05T17:48:08Z (last step: 66717 msec, total: 66717 msec)
#=#=#=# Syncrun finished 2018-02-05T17:48:14Z (last step: 5587 msec, total: 72305 msec)
#=#=#=# Syncrun started 2018-02-05T17:48:27Z
#=#=#=#=# Propagation starts 2018-02-05T17:48:53Z (last step: 25894 msec, total: 25894 msec)
||link|INST_REMOVE|Down|1468444962|_invalid_|0|01199898oc79c8z0bi2n|4||0|0|0||||
#=#=#=# Syncrun finished 2018-02-05T17:49:34Z (last step: 40429 msec, total: 66323 msec)

[ckamm]

@sagamusix I've looked at documentation and apparently you can only have hardlinks for files. Is this a symbolic link or a junction? Both should be detectable by looking for reparse points - our current check of !fi.isSymLink() seems to not cut it on Windows.

[ckamm]

Looking at Qt, I see https://bugreports.qt.io/browse/QTBUG-45344 and that https://codereview.qt-project.org/#/c/113019/ was abandoned. So isSymLink() will be true for symlinks but false for junctions.

[ckamm]

In my tests I was unable to reproduce the concrete situation. The discovery correctly detects the junction and refuses to sync it (like other symlink-like things). Deleting the parent directory on the remote didn't lead to a local deletion. However the PR #6349 nevertheless makes the recursive-deletion code safer by worrying about junctions.

[sagamusix]

I don't remember exactly if it was a symbolic link or junction, but my best guess would be that it was a symbolic link. After I re-created them, they get ignored again, as it happened in the past.

[ckamm]

@sagamusix Yes, both symbolic links and junctions should be ignored. The contents behind a symbolic link should never be deleted, and with the upcoming patch the contents behind junctions will be safe too.

[ckamm]

There've been some fixes for 2.4.1 that might have addressed the problem. Since we couldn't reproduce we don't know for sure. The patch to never delete files behind junctions also went into 2.4.1.

[ckamm]

@ogoffart How about we add a safety-fixup check, where we find all _invalid_ etags before discovery and ensure that their parent folders are also marked as invalid? By checking this supposed invariant, situations like this would never be allowed to happen.

[ogoffart]

How about we add a safety-fixup check, where we find all invalid etags before discovery and ensure that their parent folders are also marked as invalid?

This can happen if the file/folder is deleted on the server. but the deletion of the file did not work because it was still in use (or had a ignored file)

[ckamm]

Other cases:

• Folders excluded due to selective sync are marked with invalid etags
• During PropagateLocalMkdir, and that persists if the sync is aborted before the directory contents are done syncing.

[guruz]

Moving to 2.4.2

[ckamm]

@ogoffart I think we should disentangle the two use cases of _invalid_ to make this more robust. In my opinion these are

• A marker for rediscovery. If we want to ensure the next sync will rediscover a particular remote subtree we mark it and all its parents. This is always transient and should go away as soon as the rediscovery was done. It's also an error for a subfolder to be marked without the parent being marked as well.
• A marker for hiding. For items that should be hidden if we pull from the db instead of doing actual discovery. Only for selective sync, I think.

If we did this, we could validate whether there are any invariant-breaking markers occasionally and thereby avoid problems like the one that popped up here.

[ckamm]

We don't know the concrete issue and mitigations won't be in time for 2.5.0, changing milestone

[ogoffart]

Is this issue still a problem?
I guess the 2.6 new discovery does not suffer from these problem, does it?

[sagamusix]

I don't think I have recently experienced this specific issue. I have been on 2.5 for a while now - I believe. For some reason the UI does not show the version number anymore?

[guruz]

For some reason the UI does not show the version number anymore?

It's in the about dialog now, accessible from the tray icon.

[ckamm]

Definitely reopen if you see it happen again. (also reminder to enable permanent rotating file logging!)

[sagamusix]

Yup, I have that enabled now, but back when I captured the log this option didn't exist. :)

[BigMuscle85]

Today, I noticed weird behaviour similar to this one.
Suddenly notification "Following files will be deleted..." appeared and it deleted some local files/folder although I did not touch them at all. They still exist on the server, but local copy has gone and does not resynchronize back. Sync log just contains these folders with action "Deleted".

Client version ownCloud 2.5.4, Win10 x64.
Deleting user data is very critical bug!

[sagamusix]

Since it's unlikely that this has something to do with the bug that I was experiencing over a year ago, can you please create a separate issue and provide as much information there as possible?