precondition failed (412) from the server

[moscicki]

Hello,

Under heavier load (with https) I am getting precondition failed (412) from the backend server (both proxy and backends are apache):

proxy server access log:

• - [28/Feb/2014:10:13:50 +0100] "PUT /remote.php/webdav/x27.dat HTTP/1.1" 412 361

backend server access log:

• - [28/Feb/2014:10:13:50 +0100] "PUT /remote.php/webdav/x27.dat HTTP/1.1" 412 361

client log:
02-28 10:13:50:491 void Mirall::CSyncThread::transferCompleted(const Mirall::SyncFileItem&) "x27.dat" 2 "Precondition failed"

[PVince81]

Is that some kind of server timeout ?
Any related errors in owncloud.log or in the Apache's error logs ?

CC @dragotin

[moscicki]

Unfortunately nothing more in the server logs. Could this be a result of aborted db connections? The php timeout is set to 600s so that's certainly not it…

kuba

On Feb 28, 2014, at 6:27 PM, Vincent Petry [email protected] wrote:

Is that some kind of server timeout ?
Any related errors in owncloud.log or in the Apache's error logs ?

CC @dragotin

—
Reply to this email directly or view it on GitHub.

[dragotin]

On update of already existing files, the client sends the ETag it expects to update as a If-Match Header, see http://www.w3.org/Protocols/rfc2616/rfc2616-sec14.html#sec14.24
That is done because we need to avoid that the file has changed between the update phase that compares the etags and the actual PUT request. But this problem should not last but go away in the next sync run.

[moscicki]

OK, that makes sense because I see this primarily when the same user is updating the files from two different clients at the same time.

If that's normal operation mode then I think it should not be made visible to the user as error. Because it will make people think that something is wrong when it is not.
It would be still good to log it though in the debug mode…

kuba

On Mar 5, 2014, at 11:36 AM, dragotin [email protected] wrote:

On update of already existing files, the client sends the ETag it expects to update as a If-Match Header, see http://www.w3.org/Protocols/rfc2616/rfc2616-sec14.html#sec14.24
That is done because we need to avoid that the file has changed between the update phase that compares the etags and the actual PUT request. But this problem should not last but go away in the next sync run.

—
Reply to this email directly or view it on GitHub.

[binarykitchen]

@moscicki Yeah, I agree. I would lower the level to debug for that message. It is not really an error.

[PVince81]

The PR #8488 moves the "precondition failed" log level to DEBUG.

[PVince81]

Hmmm, suddendly I'm having this repeatedly. After some time the sync client gives up so I force resync, but still get precondition failed. This is sync client 1.6.0 beta2 against OC 6.0.3:

{"app":"webdav","message":"Sabre_DAV_Exception_PreconditionFailed: An If-Match header was specified, but none of the specified the ETags matched.","level":4,"time":"2014-05-08T16:01:34+00:00"}

It's my todo list file which I save very often. I'll see if I can debug it as long as I can reproduce the issue.

[PVince81]

It is stuck on preconditon failed. I have only one sync client running now.
I'll see if I can debug on my server.

[PVince81]

I tried changing the local file, but the error doesn't go away.

@dragotin for the rescue ?

[PVince81]

I'll check what etag is in the remote DB and sync client DB.

[PVince81]

Server side:

MariaDB [owncloud]> select * from oc_filecache where name='pomodoro.txt';
+--------+---------+------------------------------------+----------------------------------+--------+--------------+----------+----------+-------+------------+-----------+---------------+------------------+---------------+
| fileid | storage | path                               | path_hash                        | parent | name         | mimetype | mimepart | size  | mtime      | encrypted | etag          | unencrypted_size | storage_mtime |
+--------+---------+------------------------------------+----------------------------------+--------+--------------+----------+----------+-------+------------+-----------+---------------+------------------+---------------+
|    868 |       1 | files/clientsync/work/pomodoro.txt | 5ff1fc6f47b7d5ae5d3560baf96b818d |    802 | pomodoro.txt |       12 |        4 | 13032 | 1399562823 |         1 | 536ba2577b8ca |             9737 |    1399562823 |
+--------+---------+------------------------------------+----------------------------------+--------+--------------+----------+----------+-------+------------+-----------+---------------+------------------+---------------+
1 row in set (0.00 sec)

Client side:

sqlite> select * from metadata where path like '%pomodoro.txt%';
phash            pathlen          path             inode            uid              gid              mode             modtime          type             md5              fileid         
---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------
-23884682555537  17               work/pomodoro.t  1572977          0                0                0                1399562823       0                536ba24fd5d1b    00000868507a979

It seems the etag is not the same (assuming that md5 is the etag on the client side).

I suppose I managed to get stuck in this situation because my laptop lost connectivity before.
Maybe the sync client thought that the last upload didn't succeed and didn't update the local etag ?

[PVince81]

I give up. I just moved the file out of the sync folder, let it delete it from the server, then put it back.
The situation has solved itself.

I think the sync client should probably at some point provide a way to "escape" from this kind of situation.

[moscicki]

Hi,

Just to follow up... what should happen next? Should this be converted into a test-case and should we attempt to fix the client? I think this is clearly a problem that a client should be able to handle a bit better than now...

Regarding storing the local etag I think there is a category of issues related to this, one of which I reported here: owncloud/client#1738

kuba

[dragotin]

I don't see what we can do about the client in this situation. Is anybody able to reproduce this situation and see which etag comes in the reply of a PUT request from the client?

[glannes31]

Hello everybody , i have the case with the last version client , and an OC7 Server .

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.