[1.5.2/1.5.3/1.5.4] Sync Failure due to Precondition Failed

[ser72]

Notes
3 separate users have reported that files fail to sync due to Precondition Failed.
Users have been on 1.5.2,1.5.3,1.5.4 clients

Unable to reproduce locally, however, these users seem to see the same files fail constantly. One reports the only way to get the file to sync is to remove it from the folder, then replace it into the folder.

logs
The client logs have no indication of an error. One user's client logs can be found:
s3/Support/customer-tickets-history/Precondition

That user sees the following in the server:

"app":"webdav","message":"Exception: Sabre_DAV_Exception_PreconditionFailed: An If-Match header was specified, but none of the specified the ETags matched.","level":4,"time":"2014-04-02T12:51:47+09:00"}

All users state they were the only ones syncing at the time and that the files exhibiting the error were NOT being modified on the server by anyone else.

@dragotin @danimo

[dragotin]

I asked to check if there are empty etags in the server db.

CC @ogoffart

[ser72]

@dragotin As I thought, I did ask for that information from the first user having the issue. They never responded with the information and then the issue went away and they closed the case. They reopened it a week later stating the issue was back, but still haven't received that data.

Requested data from the current user.

[ogoffart]

"Precondition failed" error happens if the etag sent by the client on upload differ from the one in the server. This may happen for two reason:

1. Another client did change the file at the same moment (between update and propagate)
2. The etag stored in the client database is different from the one on the server, and we read from the DB in the uppate phase and not from the server.

The case 1 is totaly normal and an error is expected, and should resolve by itself on next sync.

The case 2 is more problematic and is not supposed to happen. Maybe the etag of a file changed on the server but the etag of the parent folders did not change recursively? maybe there is something else corrupted in the database.

Perhaps, in this case, the client should clear all the parent folder's etag to avoid reading from db on next sync.

[ogoffart]

maybe something to look at in 1.7

[caseyamcl]

This seems to be the same issue as: owncloud/core#7479

Or, at least the same behavior.

[dragotin]

Yes, sounds like a good idea to clear the parents etags after the precondition failed problem appeared three times. Moved to 1.6.1 milestone.

[ser72]

@dragotin Etags are all populated. There are no NULL's in the database

[ser72]

@dragotin @danimo @PVince81

Another user has the same issue. Logs on S3/Support/customer-tickets-history/Precondition
If you search Precondition you will see over 400 instances in the logs of this.

[PVince81]

I had an issue before that happened because my sync client (1.6.0 beta2) was interrupted by a Wifi failure after it had uploaded a file. It seems that the file itself got its etag properly saved in the DB but the sync client didn't have the correct local etag.
So when trying to sync again, the sync client would always say "Precondition failed" because the remote etag never matched.

My workaround was to move the broken file out of the sync folder, let it sync, then move it back again.

[PVince81]

Note: the explanation above is only what I think might have happened, I didn't check the logs to confirm this.

[dragotin]

@PVince81 could you investigate the following: if a file is uploaded, it needs to update the etag in the db, how "atomar" is that done? Is it possible that if two clients upload the same file at the same time that a concurrency situation can happen where we end up with a wrong etag that is passed back to the client?

[PVince81]

I imagine it could happen that between the time when the DB is updated and the etag is returned, another client could read out that new etag before the first request has returned.

I'll check whether the etag is saved in the DB before or after the file operations (chunk assembling / part file renaming). In my case it was a small text file, but I had encryption enabled which might slow it down a bit.

I don't think it's possible to do it in an atomic way, unless we use a DB transaction that gets close only at the very last moment when the response has been sent (CC @icewind1991)

[ser72]

It is reported that the issue still exists in 1.6.1:

Upgraded my (linux) owncloud client to 1.6.1,
$ owncloud -h
ownCloud version 1.6.1
File synchronisation desktop utility.

opened a spreadsheet, saved it twice and the second time I see this in
the log. Let me know if you need the complete log. (fyi, both the
owncloud server and my desktop use the same ntp server, so timestamps
should be identical).

>07-01 11:53:41:072 Transaction Start "checkConnect"
>07-01 11:53:41:237 Columns in the current journal: ("phash", "pathlen",
>"path", "inode", "uid", "gid", "mode", "modtime", "type", "md5", "fileid")
>07-01 11:53:41:256 Using QNAM/HTTP parallel code path
>07-01 11:53:41:261 * csync thread started
>07-01 11:53:41:657 Folder in overallStatus Message:
>Mirall::Folder(0xe6f7b0) with name "ownCloud"
>07-01 11:53:41:657 Sync state changed for folder "ownCloud" : "Sync
>Running"
>07-01 11:53:41:658 SocketApi: Broadcasting to 0 listeners: "UPDATE_VIEW"
>07-01 11:53:41:677 void Mirall::AbstractNetworkJob::setTimeout(qint64)
>300000
>07-01 11:53:41:678 !!! Mirall::PUTFileJob created for QUrl(
>"<URL>" ) querying "<FILE>"
>07-01 11:53:43:969 void Mirall::AbstractNetworkJob::slotFinished() 299
>"Error downloading
><FILE>
>- server replied: Precondition failed"
>07-01 11:53:43:970 void
>Mirall::PropagateUploadFileQNAM::slotPutFinished() QUrl(
>"<FILE>" ) FINISHED WITH STATUS 299
>"Error downloading
><FILE>
>- server replied: Precondition failed" QVariant(int, 412)
>QVariant(QString, "Precondition failed")
>07-01 11:53:43:971 "<?xml version="1.0" encoding="utf-8"?>
><d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
> <s:exception>Sabre_DAV_Exception_PreconditionFailed</s:exception>
> <s:message>An If-Match header was specified, but none of the specified
>the ETags matched.</s:message>
> <s:sabredav-version>1.7.6</s:sabredav-version>
> <s:header>If-Match</s:header>
></d:error>
>"
>07-01 11:53:43:976 "UPDATE metadata SET md5='_invalid_' WHERE ?
>LIKE(path||'/%') AND type == 2" "RCC
><FILE>
>07-01 11:53:43:977 void Mirall::SyncEngine::slotJobCompleted(const
>Mirall::SyncFileItem&) <FILE> 3 "Error downloading
><FILE>
>- server replied: Precondition failed (An If-Match header was specified,
>but none of the specified the ETags matched.)"
>07-01 11:53:44:015 Transaction Start "All Finished."
>07-01 11:53:44:140 CSync run took 9914
>07-01 11:53:44:142 -> CSync Finished slot with error false warn count 0
>07-01 11:53:44:142 Processing result list and logging took 0
>Milliseconds.

[dragotin]

@ogoffart can you have a look?

[ogoffart]

Was there two instance of the client open?
That error is normal and should happen if the file was modified on the server during the sync.

[dragotin]

@ser72 is this still a problem?

[PVince81]

@ser72 is that file smaller than 10 MB ? (no chunking involved)
Was it an "overwrite file" case ?
Does the file disappear from the server ? (and land in the trashbin)
If yes, go to owncloud/core#9302

[ogoffart]

Closing: The original issue was fixed in 1.6.1.
If there is a similar issue please open a new (detailed) bug report.

[ser72]

@ogoffart @dragotin @PVince81
It is reported that this is reproducible:

• No other users were modifying or had the file open
• Other users were syncing the folder as it is a shared folder
• No the file does not get moved to the trash bin
• Yes the file that error are almost always smaller than 10 MB - generally
  people are using own cloud for microsoft word/excel docs
• The only way people seem to be able to make it sync is to delete the
  file completely from the sync'ed folder and then move it back into it
• Yes once a file fails it is never able to be synced, it must be deleted
  from the sync folder and then recreated there

[PVince81]

As discovered recently, this is very likely to be related to the upload abort bug here: owncloud/core#9302

where it basically deletes the original file instead of the part file...

[PVince81]

I can also confirm about having to move out the file and put it back in to fix the issue. This is exactly what I had on my private owncloud.

[dragotin]

The files in question, are they new and need to be uploaded to the server? Or are that updates?

[PVince81]

@ser72 and I looked at logs and it seems like they were existing files to be overwritten.
Analysis seemed to show that the problem was indeed due to owncloud/core#9302

A patch was applied, now waiting for results.

[dragotin]

ok, so no need for me to investigate further?! Thanks @PVince81

[PVince81]

Not for now, thanks @dragotin 😄

[PVince81]

@ser72 has there been any news regarding this issue ? Or is it solved finally ? 😄
Assuming that the files were moved out and moved in again to "solve" the problem for these particular broken files.

[ser72]

@PVince81 : So far so good.

[FreeMinded]

Hi all, I just ran into this issue! Using ownCloud 7.0.2 with client 1.7. So it is still there.

[ogoffart]

@FreeMinded But the files were modified in the same time on the server? Was it after upgrading? Did the client recover properly?

[FreeMinded]

@ogoffart I was testing upload and syncing through several channels (client for windows, upload as logged user and upload through public link). There were intentionally changes done on the server and local file at the same time. I was expecting to get a sync conflict. But the client produced the output mentioned above. It didn't recover. At least not within a decent time frame and I had te delete the file and upload it again. No upgrading was involved.