Race condition while uploading with two clients to webdav server

Help and Support
1

At first the activity panel of my nextcloud server:

2020-07-28 01_01_43
2020-07-28 01_01_43927×349 7.14 KB

As you can see the file has been uploaded and several hours later it was deleted and uploaded again.

Now the logs of the two uploading clients:

client A

Command:

rclone sync /mnt/user/Movie owncube:movie --create-empty-src-dirs --ignore-checksum --bwlimit 3M --checkers 2 --transfers 1 -v --stats 10s

Logs:

2020/07/27 21:05:40 INFO  : 
Transferred:   	  107.889G / 40.939 TBytes, 0%, 2.923 MBytes/s, ETA 24w1d13h34s
Checks:               112 / 112, 100%
Transferred:            6 / 3074, 0%
Elapsed time:  10h29m56.8s
Transferring:
 * AB/A.mkv:  0% /26.450G, 0/s, -

...

2020/07/27 23:45:50 INFO  : 
Transferred:   	  134.340G / 40.939 TBytes, 0%, 2.902 MBytes/s, ETA 24w2d16h7m35s
Checks:               112 / 112, 100%
Transferred:            6 / 3074, 0%
Elapsed time:   13h10m6.8s
Transferring:
 * AB/A.mkv:100% /26.450G, 993.676k/s, 0s

2020/07/27 23:46:00 INFO  : 
Transferred:   	  134.356G / 40.964 TBytes, 0%, 2.902 MBytes/s, ETA 24w2d19h5m26s
Checks:               112 / 112, 100%
Transferred:            6 / 3074, 0%
Elapsed time:  13h10m16.8s
Transferring:
 * AB/A.mkv:  0% /26.450G, 3.311M/s, 2h16m14s

(upload is still running)

client B

Command:

rclone copy /mnt/user/movie owncube:movie --create-empty-src-dirs --ignore-checksum --bwlimit 3M --checkers 2 --transfers 1 -v --stats 10s

Logs:

2020/07/27 19:25:16 INFO  : 
Transferred:   	   52.024G / 36.759 TBytes, 0%, 2.833 MBytes/s, ETA 22w3d6h38m33s
Checks:               124 / 124, 100%
Transferred:            2 / 2887, 0%
Elapsed time:   5h13m27.2s
Transferring:
 * AB/A.mkv:  0% /26.450G, 0/s, -

...

2020/07/27 21:58:26 INFO  : 
Transferred:   	   78.475G / 36.759 TBytes, 0%, 2.870 MBytes/s, ETA 22w1d2h31m1s
Checks:               124 / 124, 100%
Transferred:            2 / 2887, 0%
Elapsed time:   7h46m37.2s
Transferring:
 * AB/A.mkv:100% /26.450G, 1.926M/s, 0s

2020/07/27 21:58:28 INFO  : AB/A.mkv: Copied (new)
2020/07/27 21:58:28 INFO  : AB/A.mkv: Copied (new)

Overview

2020/07/27 19:25:16 Client B starts uploading A.mkv
2020/07/27 21:05:40 Client A starts uploading A.mkv
2020/07/27 21:58:28 Client B successfully uploaded A.mkv
2020/07/27 23:45:50 Client A deletes existing A.mkv (no log entry)
2020/07/27 23:45:50 Client A successfully uploaded A.mkv
2020/07/27 23:45:50 Client A starts uploading A.mkv

As its still running I do not know what happens next. I will update this bug report tomorrow.

But for now there are already open questions:

1.) Why has Client A started to upload A.mkv although it's already uploading through Client B. Isn't there a "uploaded lock" built in Nextcloud to avoid such situations?

2.) Why isn't there a log entry for the file deletion?

3.) After Client A has overwritten the existing A.mkv, why does it start a second upload?

2

Ok, Client A hangs in an infinite loop of deleting and uploading A.mkv and its deleting all other files that Client B is uploading, too:

2020-07-28 13_53_41
2020-07-28 13_53_41943×658 9.13 KB

I will kill all rclone processs and use "-vv" to get more detailed logs.

3

Ok "--v" does not help. The logs do not contain any delete entries?!

This time I searched for a specific file that was uploaded and deleted multiple times. Client A uploaded this file once. After that no new entry regarding this file was logged. Client B uploaded it three times by now and will continue (infinite loop).

Another strange thing is that it started a second upload although I limited it to "--transfers 1".

2020-07-29 18_22_17
2020-07-29 18_22_17643×600 220 KB

My next try is to let the clients upload different files, so they do not interfere each other.

4

Each sync directory needs to have one owner otherwise bad stuff can happen.

However you can use rclone copy simultaneously - because it doesn't do the delete step. It still might ulpload things twice though.

That is a good idea.

5

Client A is the "master". Thats the reason why it uses sync and not copy.

because it doesn't do the delete step

1.) But don't you think there is a bug as the delete step isn't logged?
2.) And shouldn't Nextcloud return an error if a second client tries to upload the same file?

EDIT:
Regarding 2.) suprisingly not. I uploaded the same file through two different nextclient webclient tabs and it uploads both. BUT there is a little difference. It did not delete/recreate the file. Instead it "changed" it:

2020-07-29 20_44_43

Because of that I checked the http headers. First upload:

MOVE /remote.php/dav/uploads/marc/web-file-upload-36476897654213-1596051498340/.file HTTP/1.1
Host: example.com
Destination: https://example.com/remote.php/dav/files/marc/Share/test.mp4
...
HTTP/1.1 201 Created

Second (parallel) upload:

MOVE /remote.php/dav/uploads/marc/web-file-upload-36476897654213-1596051492210/.file HTTP/1.1
Host: example.com
Destination: https://example.com/remote.php/dav/files/marc/Share/test.mp4
...
HTTP/1.1 204 No Content

Maybe rclone does not know how to react if the answer is "204 No Content"?

6

If rclone deletes a file there should be an INFO level log, unless there was an ERROR uploading the file - rclone tries to delete errored files after they have been uploaded. If you run with -vv you may be able to work out what is going on.

It is possible nexcloud is doing something odd when it is receiving two uploads for the same file simultaneously also.

The WebDAV protocol doesn't forbid it and rclone doesn't use locks.

Rclone isn't expecting a reply from the MOVE so it shouldn't care what code is returned as long as it is 2xx

7

Ok, now I added --max-age to Client A and --min-age to Client B so they both do not interfere and there were still deletions. After checking the logs I found out that my script on Client B was called every day although its still running. This means rclone copy was executed multiple times on the same folder. Of course its not really clever to call rclone twice, but why does it delete the uploaded file although copy-mode shouldn't do that?

Is it possible to log the http requests of rclone or do you have an idea whats happening here?

8

Use -vv --dump requests to log the HTTP requests of rclone.

I don't know what is happening here, but running two rclone's at once on the same destination can cause problems.

9

I assume you mean on this if you are copying and you'd overwrite the destination if you have a file that is 'newer' or meets your upload criteria. If you are running multiple rclones, that might do it as is just depends on if the source is changing and becomes newer and while the 1 is copying, 2 may overwrite it. Having more than 2, the problem gets tougher to pinpoint.

10

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.