How to handle pcloud rate limit

Help and Support
1

What is the problem you are having with rclone?

I am using rclone to access a pcloud backend and I seem top be hitting some rate limit on which rclone seems to be giving up too soon.

Run the command 'rclone version' and share the full output of the command.

rclone v1.58.1
- os/version: debian 10.12 (64 bit)
- os/kernel: 5.4.174-2-pve (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.17.9
- go/linking: static
- go/tags: none

Note that the log is from v1.57.0, i.e. I have upgraded since I the problem occurred but the problem persists.

Which cloud storage system are you using? (eg Google Drive)

pcloud

The command you were trying to run (eg rclone copy /tmp remote:tmp)

sudo rclone serve sftp pcloud:Backup/  --user ******* --pass ***************
--log-file=/zfs/NAS/config/rclone.log -vv`

The rclone config contents with secrets removed.

[pcloud]
type = pcloud
token = {"access_token":"**************************************************************","token_type":"bearer","expiry":"0001-01-01T00:00:00Z"}

A log from the command with the -vv flag

2022/06/14 13:11:44 DEBUG : /Testfolder/failingfile: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2022/06/14 13:11:44 DEBUG : Testfolder/failingfile: Open: flags=O_RDONLY
2022/06/14 13:11:44 DEBUG : Testfolder/failingfile: >Open: fd=Testfolder/failingfile (r), err=<nil>
2022/06/14 13:11:44 DEBUG : /Testfolder/failingfile: >OpenFile: fd=Testfolder/failingfile (r), err=<nil>
2022/06/14 13:11:44 DEBUG : /Testfolder2/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2022/06/14 13:11:44 DEBUG : Testfolder2/file1: Open: flags=O_RDONLY
2022/06/14 13:11:44 DEBUG : Testfolder2/file1: >Open: fd=Testfolder2/file1 (r), err=<nil>
2022/06/14 13:11:44 DEBUG : /Testfolder2/file1: >OpenFile: fd=Testfolder2/file1 (r), err=<nil>
2022/06/14 13:11:44 DEBUG : /Testfolder3/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2022/06/14 13:11:44 DEBUG : Testfolder3/file1: Open: flags=O_RDONLY
2022/06/14 13:11:44 DEBUG : Testfolder3/file1: >Open: fd=Testfolder3/file1 (r), err=<nil>
2022/06/14 13:11:44 DEBUG : /Testfolder3/file1: >OpenFile: fd=Testfolder3/file1 (r), err=<nil>
2022/06/14 13:11:44 DEBUG : Testfolder3/file1: ChunkedReader.openRange at 0 length 134217728
2022/06/14 13:11:44 DEBUG : Testfolder2/file1: ChunkedReader.openRange at 0 length 134217728
2022/06/14 13:11:44 DEBUG : Testfolder/failingfile: ChunkedReader.openRange at 0 length 134217728
2022/06/14 13:11:44 DEBUG : Testfolder4/file1: ChunkedReader.openRange at 0 length 134217728
2022/06/14 13:11:45 DEBUG : pacer: low level retry 1/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2022/06/14 13:11:45 DEBUG : Couldn't parse Date: from server p-lux3.pcloud.com: "Tue, 14 Jun 2022 11:11:44 +0000": parsing time "Tue, 14 Jun 2022 11:11:44 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 14 Jun 2022 11:11:44 +0000" as " "
2022/06/14 13:11:45 DEBUG : pacer: Reducing sleep to 15ms
2022/06/14 13:11:45 DEBUG : Testfolder2/file1: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Testfolder2/file1: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Testfolder2/file1: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Testfolder2/file1: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Testfolder2/file1: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Couldn't parse Date: from server p-lux3.pcloud.com: "Tue, 14 Jun 2022 11:11:44 +0000": parsing time "Tue, 14 Jun 2022 11:11:44 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 14 Jun 2022 11:11:44 +0000" as " "
2022/06/14 13:11:45 DEBUG : pacer: Reducing sleep to 11.25ms
2022/06/14 13:11:45 DEBUG : Testfolder4/file1: ChunkedReader.Read at 0 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Tue, 14 Jun 2022 11:11:45 +0000": parsing time "Tue, 14 Jun 2022 11:11:45 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 14 Jun 2022 11:11:45 +0000" as " "
2022/06/14 13:11:45 DEBUG : pacer: Reducing sleep to 10ms
2022/06/14 13:11:45 DEBUG : Testfolder3/file1: ChunkedReader.Read at 0 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Testfolder3/file1: waiting for in-sequence read to 65536 for 20ms
2022/06/14 13:11:45 DEBUG : Testfolder3/file1: ChunkedReader.Read at 32768 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Testfolder3/file1: ChunkedReader.Read at 65536 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:45 DEBUG : Testfolder3/file1: aborting in-sequence read wait, off=65536
2022/06/14 13:11:45 DEBUG : pacer: low level retry 2/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2022/06/14 13:11:46 DEBUG : pacer: low level retry 3/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:46 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/06/14 13:11:46 DEBUG : pacer: low level retry 4/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:46 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/06/14 13:11:47 DEBUG : pacer: low level retry 5/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:47 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/06/14 13:11:47 DEBUG : pacer: low level retry 6/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:47 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/06/14 13:11:48 DEBUG : pacer: low level retry 7/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:48 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/06/14 13:11:48 DEBUG : pacer: low level retry 8/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:48 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/06/14 13:11:49 DEBUG : pacer: low level retry 9/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:49 DEBUG : pacer: Rate limited, increasing sleep to 2s
2022/06/14 13:11:50 DEBUG : pacer: low level retry 10/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))

2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 65536 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: waiting for in-sequence read to 65536 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 32768 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 65536 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 196608 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 98304 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 98304 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 131072 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 163840 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 196608 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 294912 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 229376 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 294912 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 262144 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 360448 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 327680 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 393216 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 294912 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 425984 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 360448 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 327680 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 360448 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 458752 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 393216 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 425984 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 360448 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 393216 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 458752 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 425984 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 458752 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 458752 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 458752 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 131072 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 163840 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 196608 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 229376 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 589824 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 491520 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 524288 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 557056 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 688128 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 589824 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 720896 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 622592 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 753664 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 655360 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 786432 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 688128 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 819200 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 720896 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: waiting for in-sequence read to 851968 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 753664 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 786432 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 819200 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 851968 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 262144 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: waiting for in-sequence read to 327680 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 294912 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 655360 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 688128 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 720896 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 753664 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 786432 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 819200 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 851968 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 884736 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder4/file1: ChunkedReader.Read at 327680 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 917504 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 753664 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 950272 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 983040 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 851968 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 884736 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 917504 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 917504 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 950272 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 983040 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 851968 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 884736 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 884736 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 917504 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 950272 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 983040 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 851968 for 20ms
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 884736 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 917504 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder3/file1: ChunkedReader.Read at 950272 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/14 13:11:50 DEBUG : Testfolder2/file1: waiting for in-sequence read to 950272 for 20ms
2022/06/14 13:11:52 DEBUG : pacer: Reducing sleep to 1.5s
2022/06/14 13:11:54 DEBUG : pacer: Reducing sleep to 1.125s
2022/06/14 13:11:54 ERROR : serve sftp 127.0.0.1:36282->127.0.0.1:2022: Failed to serve SFTP: completed with error: unexpected EOF
2022/06/14 13:12:13 INFO  :
Transferred:   	   91.687 MiB / 91.687 MiB, 100%, 3 B/s, ETA 0s
Transferred:           85 / 85, 100%
Elapsed time:    2h38m0.5s

2022/06/14 13:13:13 INFO  :
Transferred:   	   91.687 MiB / 91.687 MiB, 100%, 3 B/s, ETA 0s
Transferred:           85 / 85, 100%
Elapsed time:    2h39m0.5s

I included an empty line at the place where I believe the problem occurred, but I'm leaving the remaining logs just in case.

From what I can tell, I'm hitting some rate limit on pcloud's side but I'm not sure what it is. I also see that rclone is trying again ten times, gradually backing off. My hope would be that if it just waited longer, the connection might be reestablished, but I didn't find a setting to control that.

I have also contacted pcloud support, but I suspect they'll just tell me to respect their rate limit. On the other hand, they state in their api documentation about this kind of error:

5xxx Errors of this type are the ones that we work very hard to never happen. Nevertheless they are still possible. These type of errors generally mean that we can not satisfy the request at this time (e.g. a server is unavailable) but it is very likely that the API server will be able to satisfy the request at a later stage.

so that this may simply be a problem on their side.

2

You can control the number of those retries with --low-level-retries

You can experiment with --tpslimit to keep rclone under the rate limit.

1 Like
3

OK, thanks, this is interesting. So I will try experimenting with --low-level-retries and --tpslimit. But I'm not sure in which direction I should go with --low-level-retries. My intuition was to increase the number or retries, but in the documentation it says

This shouldn't need to be changed from the default in normal operations. However, if you get a lot of low level retries you may wish to reduce the value so rclone moves on to a high level retry (see the --retries flag) quicker.

So it seems that decreasing the number of retries might make more sense. Do I understand correctly, that "moving to a high level retry quicker" means that instead of retrying ten times to get a particular chunk of the file, it will throw away whatever it already has of the file and request the file anew?

Or what exactly does rclone do when it reaches the max low level retries? - In my log above it looks like it's simply giving up on reading that file (/Testfolder/failingfile). It doesn't seem to retry, which leads the program (duplicacy) trying to download the file to throw me an error and give up on all downloads (despite the fact that other downloads (Testfolder2/file1, Testfolder3/file1, Testfolder4/file1 still seem to be working fine...), Or is it rcloud that says that it failed serving the file? But the error I get from duplicacy is not unexpected EOF but Internal error, no servers available. Try again later. (5002),

So, basically, I'm a bit confused about how to read the log. For example, I don't quite understand this part:

2022/06/14 13:11:45 DEBUG : pacer: low level retry 1/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/14 13:11:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2022/06/14 13:11:45 DEBUG : Couldn't parse Date: from server p-lux3.pcloud.com: "Tue, 14 Jun 2022 11:11:44 +0000": parsing time "Tue, 14 Jun 2022 11:11:44 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 14 Jun 2022 11:11:44 +0000" as " "
2022/06/14 13:11:45 DEBUG : pacer: Reducing sleep to 15ms

What I see is that it increases the sleep time to 20 ms because it was told to slow down but almost immediately after, it reduces the sleep time again to 15 ms, then to 11,25 ms and then 10 ms. But then it gets another 5002 error so that it changes back to 20 ms backoff.

I think the problem might be that I can't tell apart the different file downloading processes that are going on "simultaneously" so that I'm not sure why /Testfolder/failingfile fails when other downloads still are in progress and seem to be doing fine.

As for --tpslimit, what might be a value to try here? I couldn't find any figures on rate-limits in the pcloud's API docu...

4

I would say increase them.

The high level retries are for when doing a sync - rclone will retry the entire sync. For a mount you don't have that option and rclone will just give up at the end of low level retries.

This is direct from pcloud.

The 20ms delay is caused by getting an error. For non errors, the timeout will gradually be reduced so it looks like you've got some transfers working just fine (which are reducing the timeouts) and some that aren't.

Cloud providers rarely document their rate limits. Currently rclone is operating with about 100 transactions/second with pcloud. You could try --tpslimit 10 to limit it to 10 per second which probably won't noticeably slow things down. If it does you can increase the number and if it doesn't work, decrease the number.

1 Like
5

Hi tophee,

Not an expert in pcloud nor serve sftp, but I would first try to make a SIMPLE and SLOW setup where there are no issues (except performance) and then gradually increase/double one parameter at the time from there until you start to see errors or many low level retries.

I would also simplify the command initially and test on a testfolder with a few files.

In your situation I might start with something like this:

rclone copy pcloud:testfolder ./testfolder --ignore-times --checkers=1 --transfers=1 --tpslimit=0.25 -vv

And then gradually move towards:

 rclone serve sftp pcloud:Backup/ --transfers=X --tpslimit=Y ...
1 Like
6

OK, trying that now and we'll see. Last night I tried increasing --low-level-retries to 12, but it didn't change anything so I'm starting to thing that this is either a rate limit for transactions or number of parallel downloads or something, also because other downloads seem to continue just fine, despite the errors for one file. Thanks, @Ole for pointing me to --transfers=1, I'm using that now, if only to avoid confusion about which log messages are related with which transfer.

7

So, I tried this command: sudo rclone serve sftp pcloud:Backup/ --user ********* --pass ******--log-file=/zfs/NAS/config/rclone4.log --ignore-times --transfers=1 --tpslimit=10 -vv and it still failed (I have marked the lines I assume are relevant, because they seem to relate to the file that couldn't be read):

=> 2022/06/15 19:39:54 DEBUG : /testfolder/failedfile: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
=> 2022/06/15 19:39:54 DEBUG : testfolder/failedfile: Open: flags=O_RDONLY
=> 2022/06/15 19:39:54 DEBUG : testfolder/failedfile: >Open: fd=testfolder/failedfile (r), err=<nil>
=> 2022/06/15 19:39:54 DEBUG : /testfolder/failedfile: >OpenFile: fd=testfolder/failedfile (r), err=<nil>
2022/06/15 19:39:54 DEBUG : testfolder1/file1: waiting for in-sequence read to 196608 for 20ms
2022/06/15 19:39:54 DEBUG : testfolder1/file1: waiting for in-sequence read to 131072 for 20ms
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 98304 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 131072 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: waiting for in-sequence read to 196608 for 20ms
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 163840 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 196608 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: waiting for in-sequence read to 262144 for 20ms
2022/06/15 19:39:54 DEBUG : testfolder3/file3: ChunkedReader.openRange at 0 length 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 229376 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 262144 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: waiting for in-sequence read to 458752 for 20ms
2022/06/15 19:39:54 DEBUG : testfolder2/file2: ChunkedReader.openRange at 0 length 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 294912 length 32768 chunkOffset 0 chunkSize 134217728
=> 2022/06/15 19:39:54 DEBUG : testfolder/failedfile: ChunkedReader.openRange at 0 length 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 327680 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 360448 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 393216 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 425984 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:54 DEBUG : testfolder1/file1: ChunkedReader.Read at 458752 length 32768 chunkOffset 0 chunkSize 134217728
=> 2022/06/15 19:39:55 DEBUG : pacer: low level retry 1/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
=> 2022/06/15 19:39:55 DEBUG : pacer: Rate limited, increasing sleep to 20ms
=> 2022/06/15 19:39:55 DEBUG : pacer: Reducing sleep to 15ms
2022/06/15 19:39:55 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:39:55 +0000": parsing time "Wed, 15 Jun 2022 17:39:55 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:39:55 +0000" as " "
2022/06/15 19:39:55 DEBUG : pacer: Reducing sleep to 11.25ms
2022/06/15 19:39:55 DEBUG : testfolder2/file2: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder2/file2: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder2/file2: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
=> 2022/06/15 19:39:55 DEBUG : pacer: low level retry 2/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/15 19:39:55 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2022/06/15 19:39:55 DEBUG : testfolder2/file2: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : Couldn't parse Date: from server p-lux1.pcloud.com: "Wed, 15 Jun 2022 17:39:55 +0000": parsing time "Wed, 15 Jun 2022 17:39:55 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:39:55 +0000" as " "
2022/06/15 19:39:55 DEBUG : pacer: Reducing sleep to 16.875ms
2022/06/15 19:39:55 DEBUG : testfolder3/file3: ChunkedReader.Read at 0 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder2/file2: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: waiting for in-sequence read to 589824 for 20ms
2022/06/15 19:39:55 DEBUG : testfolder3/file3: ChunkedReader.Read at 32768 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 491520 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 524288 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 557056 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 589824 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: waiting for in-sequence read to 753664 for 20ms
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 622592 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: waiting for in-sequence read to 786432 for 20ms
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 655360 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: waiting for in-sequence read to 819200 for 20ms
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 688128 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: waiting for in-sequence read to 819200 for 20ms
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 720896 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: waiting for in-sequence read to 819200 for 20ms
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 753664 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:55 DEBUG : testfolder1/file1: waiting for in-sequence read to 819200 for 20ms
2022/06/15 19:39:55 DEBUG : testfolder1/file1: ChunkedReader.Read at 786432 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:56 DEBUG : testfolder1/file1: ChunkedReader.Read at 819200 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:39:56 DEBUG : testfolder3/file3: ChunkedReader.Read at 65536 length 32768 chunkOffset 0 chunkSize 134217728
=> 2022/06/15 19:39:57 DEBUG : pacer: low level retry 3/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
=> 2022/06/15 19:39:57 DEBUG : pacer: Rate limited, increasing sleep to 33.75ms
=> 2022/06/15 19:39:58 DEBUG : pacer: low level retry 4/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
=> 2022/06/15 19:39:58 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms
=> 2022/06/15 19:39:58 DEBUG : pacer: low level retry 5/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
=> 2022/06/15 19:39:58 DEBUG : pacer: Rate limited, increasing sleep to 135ms
=> 2022/06/15 19:39:59 DEBUG : pacer: low level retry 6/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
=> 2022/06/15 19:39:59 DEBUG : pacer: Rate limited, increasing sleep to 270ms
=> 2022/06/15 19:39:59 DEBUG : pacer: low level retry 7/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
=> 2022/06/15 19:39:59 DEBUG : pacer: Rate limited, increasing sleep to 540ms
=> 2022/06/15 19:40:00 DEBUG : pacer: low level retry 8/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
=> 2022/06/15 19:40:00 DEBUG : pacer: Rate limited, increasing sleep to 1.08s
=> 2022/06/15 19:40:00 DEBUG : pacer: low level retry 9/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
=> 2022/06/15 19:40:00 DEBUG : pacer: Rate limited, increasing sleep to 2s
=> 2022/06/15 19:40:01 DEBUG : pacer: low level retry 10/10 (error pcloud error: Internal error, no servers available. Try again later. (5002))
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 98304 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder2/file2: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder1/file1: waiting for in-sequence read to 851968 for 20ms
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 131072 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder2/file2: waiting for in-sequence read to 163840 for 20ms
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 163840 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder2/file2: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder1/file1: aborting in-sequence read wait, off=851968
2022/06/15 19:40:01 DEBUG : testfolder1/file1: failed to wait for in-sequence read to 851968
2022/06/15 19:40:01 DEBUG : testfolder1/file1: ReadFileHandle.Read attempt to read beyond end of file: 851968 > 830992
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 196608 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder3/file3: waiting for in-sequence read to 327680 for 20ms
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 229376 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder3/file3: waiting for in-sequence read to 327680 for 20ms
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 262144 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder3/file3: waiting for in-sequence read to 327680 for 20ms
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 294912 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 327680 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 360448 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder3/file3: ChunkedReader.Read at 393216 length 32768 chunkOffset 0 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder3/file3: aborting in-sequence read wait, off=327680
2022/06/15 19:40:01 DEBUG : testfolder2/file2: waiting for in-sequence read to 688128 for 20ms
2022/06/15 19:40:01 DEBUG : testfolder2/file2: waiting for in-sequence read to 524288 for 20ms
2022/06/15 19:40:01 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=688128
2022/06/15 19:40:01 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=524288
2022/06/15 19:40:01 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 688128
2022/06/15 19:40:01 DEBUG : testfolder2/file2: ReadFileHandle.seek from 491520 to 688128 (fs.RangeSeeker)
2022/06/15 19:40:01 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 520192 to 688128 length -1
2022/06/15 19:40:01 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 688128 chunkSize 134217728
2022/06/15 19:40:01 DEBUG : testfolder2/file2: ChunkedReader.openRange at 688128 length 134217728
2022/06/15 19:40:03 DEBUG : pacer: Reducing sleep to 1.5s
2022/06/15 19:40:05 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:05 +0000": parsing time "Wed, 15 Jun 2022 17:40:05 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:05 +0000" as " "
2022/06/15 19:40:05 DEBUG : pacer: Reducing sleep to 1.125s
2022/06/15 19:40:05 DEBUG : testfolder2/file2: ChunkedReader.Read at 692224 length 8192 chunkOffset 688128 chunkSize 134217728
2022/06/15 19:40:05 DEBUG : testfolder2/file2: ChunkedReader.Read at 700416 length 16384 chunkOffset 688128 chunkSize 134217728
2022/06/15 19:40:05 DEBUG : testfolder2/file2: ChunkedReader.Read at 716800 length 32768 chunkOffset 688128 chunkSize 134217728
2022/06/15 19:40:05 DEBUG : testfolder2/file2: waiting for in-sequence read to 753664 for 20ms
2022/06/15 19:40:05 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 524288
2022/06/15 19:40:05 DEBUG : testfolder2/file2: ReadFileHandle.seek from 720896 to 524288 (fs.RangeSeeker)
2022/06/15 19:40:05 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 749568 to 524288 length -1
2022/06/15 19:40:05 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 524288 chunkSize 134217728
2022/06/15 19:40:05 DEBUG : testfolder2/file2: ChunkedReader.openRange at 524288 length 134217728
2022/06/15 19:40:06 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:06 +0000": parsing time "Wed, 15 Jun 2022 17:40:06 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:06 +0000" as " "
2022/06/15 19:40:06 DEBUG : pacer: Reducing sleep to 843.75ms
2022/06/15 19:40:06 DEBUG : testfolder2/file2: ChunkedReader.Read at 528384 length 8192 chunkOffset 524288 chunkSize 134217728
2022/06/15 19:40:06 DEBUG : testfolder2/file2: ChunkedReader.Read at 536576 length 16384 chunkOffset 524288 chunkSize 134217728
2022/06/15 19:40:06 DEBUG : testfolder2/file2: ChunkedReader.Read at 552960 length 32768 chunkOffset 524288 chunkSize 134217728
2022/06/15 19:40:07 DEBUG : testfolder2/file2: waiting for in-sequence read to 622592 for 20ms
2022/06/15 19:40:07 DEBUG : testfolder2/file2: waiting for in-sequence read to 655360 for 20ms
2022/06/15 19:40:07 DEBUG : testfolder2/file2: waiting for in-sequence read to 720896 for 20ms
2022/06/15 19:40:07 DEBUG : testfolder2/file2: ChunkedReader.Read at 585728 length 65536 chunkOffset 524288 chunkSize 134217728
2022/06/15 19:40:07 DEBUG : testfolder2/file2: ReadFileHandle.seek from 589824 to 491520 (fs.RangeSeeker)
2022/06/15 19:40:07 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 651264 to 491520 length -1
2022/06/15 19:40:07 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 491520 chunkSize 134217728
2022/06/15 19:40:07 DEBUG : testfolder2/file2: ChunkedReader.openRange at 491520 length 134217728
2022/06/15 19:40:08 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:07 +0000": parsing time "Wed, 15 Jun 2022 17:40:07 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:07 +0000" as " "
2022/06/15 19:40:08 DEBUG : pacer: Reducing sleep to 632.8125ms
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at 495616 length 8192 chunkOffset 491520 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at 503808 length 16384 chunkOffset 491520 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at 520192 length 32768 chunkOffset 491520 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: waiting for in-sequence read to 589824 for 20ms
2022/06/15 19:40:08 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=753664
2022/06/15 19:40:08 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 753664
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ReadFileHandle.seek from 524288 to 753664 (fs.RangeSeeker)
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 552960 to 753664 length -1
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 753664 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.openRange at 753664 length 134217728
2022/06/15 19:40:08 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:08 +0000": parsing time "Wed, 15 Jun 2022 17:40:08 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:08 +0000" as " "
2022/06/15 19:40:08 DEBUG : pacer: Reducing sleep to 474.609375ms
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at 757760 length 8192 chunkOffset 753664 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at 765952 length 16384 chunkOffset 753664 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at 782336 length 32768 chunkOffset 753664 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at 815104 length 65536 chunkOffset 753664 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=720896
2022/06/15 19:40:08 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=622592
2022/06/15 19:40:08 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=655360
2022/06/15 19:40:08 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 655360
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ReadFileHandle.seek from 819200 to 655360 (fs.RangeSeeker)
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 880640 to 655360 length -1
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 655360 chunkSize 134217728
2022/06/15 19:40:08 DEBUG : testfolder2/file2: ChunkedReader.openRange at 655360 length 134217728
2022/06/15 19:40:09 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:09 +0000": parsing time "Wed, 15 Jun 2022 17:40:09 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:09 +0000" as " "
2022/06/15 19:40:09 DEBUG : pacer: Reducing sleep to 355.957031ms
2022/06/15 19:40:09 DEBUG : testfolder2/file2: ChunkedReader.Read at 659456 length 8192 chunkOffset 655360 chunkSize 134217728
2022/06/15 19:40:09 DEBUG : testfolder2/file2: ChunkedReader.Read at 667648 length 16384 chunkOffset 655360 chunkSize 134217728
2022/06/15 19:40:09 DEBUG : testfolder2/file2: ChunkedReader.Read at 684032 length 32768 chunkOffset 655360 chunkSize 134217728
2022/06/15 19:40:09 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 622592
2022/06/15 19:40:09 DEBUG : testfolder2/file2: ReadFileHandle.seek from 688128 to 622592 (fs.RangeSeeker)
2022/06/15 19:40:09 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 716800 to 622592 length -1
2022/06/15 19:40:09 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 622592 chunkSize 134217728
2022/06/15 19:40:09 DEBUG : testfolder2/file2: ChunkedReader.openRange at 622592 length 134217728
2022/06/15 19:40:10 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:09 +0000": parsing time "Wed, 15 Jun 2022 17:40:09 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:09 +0000" as " "
2022/06/15 19:40:10 DEBUG : pacer: Reducing sleep to 266.967773ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 626688 length 8192 chunkOffset 622592 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 634880 length 16384 chunkOffset 622592 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 651264 length 32768 chunkOffset 622592 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 720896
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ReadFileHandle.seek from 655360 to 720896 (fs.RangeSeeker)
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 684032 to 720896 length -1
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 720896 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.openRange at 720896 length 134217728
2022/06/15 19:40:10 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:10 +0000": parsing time "Wed, 15 Jun 2022 17:40:10 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:10 +0000" as " "
2022/06/15 19:40:10 DEBUG : pacer: Reducing sleep to 200.225829ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 724992 length 8192 chunkOffset 720896 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 733184 length 16384 chunkOffset 720896 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 749568 length 32768 chunkOffset 720896 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 819200 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 851968 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 589824 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=589824
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 884736 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 917504 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 950272 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 983040 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder3/file3: waiting for in-sequence read to 425984 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 819200 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 851968 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 589824
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ReadFileHandle.seek from 753664 to 589824 (fs.RangeSeeker)
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 782336 to 589824 length -1
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 589824 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.openRange at 589824 length 134217728
2022/06/15 19:40:10 DEBUG : testfolder3/file3: aborting in-sequence read wait, off=425984
2022/06/15 19:40:10 DEBUG : testfolder3/file3: failed to wait for in-sequence read to 425984
2022/06/15 19:40:10 DEBUG : testfolder3/file3: ReadFileHandle.Read attempt to read beyond end of file: 425984 > 415270
2022/06/15 19:40:10 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:10 +0000": parsing time "Wed, 15 Jun 2022 17:40:10 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:10 +0000" as " "
2022/06/15 19:40:10 DEBUG : pacer: Reducing sleep to 150.169371ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 593920 length 8192 chunkOffset 589824 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 602112 length 16384 chunkOffset 589824 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 618496 length 32768 chunkOffset 589824 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 983040 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: waiting for in-sequence read to 819200 for 20ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=851968
2022/06/15 19:40:10 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=884736
2022/06/15 19:40:10 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=917504
2022/06/15 19:40:10 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=950272
2022/06/15 19:40:10 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=983040
2022/06/15 19:40:10 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 851968
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ReadFileHandle.seek from 622592 to 851968 (fs.RangeSeeker)
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 651264 to 851968 length -1
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 851968 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.openRange at 851968 length 134217728
2022/06/15 19:40:10 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:10 +0000": parsing time "Wed, 15 Jun 2022 17:40:10 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:10 +0000" as " "
2022/06/15 19:40:10 DEBUG : pacer: Reducing sleep to 112.627028ms
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 856064 length 8192 chunkOffset 851968 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 864256 length 16384 chunkOffset 851968 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 880640 length 32768 chunkOffset 851968 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 913408 length 65536 chunkOffset 851968 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at 978944 length 131072 chunkOffset 851968 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: aborting in-sequence read wait, off=819200
2022/06/15 19:40:10 DEBUG : testfolder2/file2: failed to wait for in-sequence read to 819200
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ReadFileHandle.seek from 1015808 to 819200 (fs.RangeSeeker)
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.RangeSeek from 1110016 to 819200 length -1
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.Read at -1 length 4096 chunkOffset 819200 chunkSize 134217728
2022/06/15 19:40:10 DEBUG : testfolder2/file2: ChunkedReader.openRange at 819200 length 134217728
2022/06/15 19:40:11 DEBUG : Couldn't parse Date: from server p-lux2.pcloud.com: "Wed, 15 Jun 2022 17:40:11 +0000": parsing time "Wed, 15 Jun 2022 17:40:11 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 15 Jun 2022 17:40:11 +0000" as " "
2022/06/15 19:40:11 DEBUG : pacer: Reducing sleep to 84.470271ms
2022/06/15 19:40:11 DEBUG : testfolder2/file2: ChunkedReader.Read at 823296 length 8192 chunkOffset 819200 chunkSize 134217728
2022/06/15 19:40:11 DEBUG : testfolder2/file2: ChunkedReader.Read at 831488 length 16384 chunkOffset 819200 chunkSize 134217728
2022/06/15 19:40:11 DEBUG : testfolder2/file2: ChunkedReader.Read at 847872 length 32768 chunkOffset 819200 chunkSize 134217728
2022/06/15 19:40:11 DEBUG : pacer: Reducing sleep to 63.352703ms
2022/06/15 19:40:11 ERROR : serve sftp 127.0.0.1:48102->127.0.0.1:2022: Failed to serve SFTP: completed with error: unexpected EOF
2022/06/15 19:40:30 INFO  :
Transferred:   	  213.224 MiB / 213.224 MiB, 100%, 3 B/s, ETA 0s
Transferred:          193 / 193, 100%
Elapsed time:     7h0m3.1s

2022/06/15 19:41:30 INFO  :
Transferred:   	  213.224 MiB / 213.224 MiB, 100%, 3 B/s, ETA 0s
Transferred:          193 / 193, 100%
Elapsed time:     7h1m3.1s

I don't quite understand why there is still so much other processes going on. With --transfers=1 I was expecting the log being about one file at a time until that file has been transferred completely, so that the last file mentioned in the logs would be the failing one. But okay, I guess I'm going to try --tpslimit=1 and see what happens.

8

So, I tried sudo rclone serve sftp pcloud:Backup/ --user ****** --pass ******* --log-file=/zfs/NAS/config/rclone5.log --ignore-times --transfers=1 --tpslimit=1 -vv but I'm still getting the same errors.

I will now add --checkers=1 to that command. If that also fails (and my feeling is that it will, but mostly because I don't understand what it does), the only way seems to be to increase --tpslimit --low-level-retries...

An update on what pcloud is saying: Their first and second answers were even less helpful than I anticipated:

No. 1:

We had a minor issue for some of our users only, which was handled as soon as possible by our team. Everything should be fine now. If needed restart your device

No. 2

We don't have an official integration with rclone. As a result, we cannot guarantee that pCloud Drive will work seamlessly.

Last thing I heard from them (after asking for information on rate limits) was:

Your case is forwarded to the respective department and we'll get back to you when more details are provided.

According to my experience, this kind of message usually means "Your ticket has been closed", but let's wait another while (never give up hope).

9

You want to decrease --tpslimit - but that is my recommendation, keep decreasing it (cut it in half) until it works.

10

Sorry, I miswrote (corrected it now). I meant increase --low-level-retries, not --tpslimit. Or do you still mean I should decrease --tpslimit below 1?

11

I'd decrease tpslimit. Don't you have it at 10 at the moment? Try 5? It can be a floating point number so 0.1 for 1 transaction every 10 seconds. That is really slow though!

12

Last two tries try, I was already down to --tpslimit=1, one with --checkers=1 and one without. Both failed. So I guess I'll try --checkers=0.1 and if that doesn't work I'll try increasing --low-level-retries.

1 Like
13

I wonder is this means anything: whenever I start rclone serve (after killing all rclone processes), I get two rclone processes. Is that expected?

$ ps -ef | grep rclone
christo+ 12517 17310  0 11:01 pts/4    00:00:00 grep rclone
$ sudo rclone serve sftp pcloud:Backup/  --user ****** --pass ****** --log-file=/zfs/NAS/config/rclone5.log --ignore-times --transfers=1 --tpslimit=1 --checkers=1 -vv  &
[1] 15799
$ ps -ef | grep rclone
christo+  6279 17310  0 18:24 pts/4    00:00:00 grep rclone
root     15799 17310  0 11:02 pts/4    00:00:00 sudo rclone serve sftp pcloud:Backup/ --user ****** --pass ****** --log-file=/zfs/NAS/config/rclone5.log --ignore-times --transfers=1 --tpslimit=1 --checkers=1 -vv
root     15800 15799  3 11:02 pts/4    00:13:24 rclone serve sftp pcloud:Backup/ --user ****** --pass ******** --log-file=/zfs/NAS/config/rclone5.log --ignore-times --transfers=1 --tpslimit=1 --checkers=1 -vv
$
14

The first is actually a sudo process running the second rclone as root.

15

Oh, I didn't know that sudo had its own process. But now that you say it, it makes sense.

It seems like --tpslimit=0.1 with --low-level-retries=15 works (at least it didn't fail as early as previous tries). The download speed was at around 15 kbps, though. I'm trying --tpslimit=0.5 now...

Is there anyway how I can hot-change the rclone settings without killing the process? (so that the app accessing the storage via rclone doesn't have to re-start the entire download?)

Another thing I noticed is that the failure only seems to occur when the main activity is downloading files. It never fails on upload or directory listings etc. So the number of transactions per second doesn't seem to be the problem (my internet connection has the same speed up and down). Is that correct?

16

No, but a simple copy command lets you test --tpslimit (and other settings) during downloads without needing the sftp server or another app to pull data. This command can be run repeatedly:

You may also want to check --bwlimit=UP,DOWN instead of --tpslimit, if you suspect it is sufficient to limit the download speed.

1 Like
17

Note: https://www.pcloud.com/ doesn't respond at the moment, there may be more general issues.

18

Progress, of a sort!

In theory you can set this using the remote control interface Remote Control / API however I just looked at the code and setting it doesn't actually change the limiter as it is set when rclone starts only...

The other thing you could try is using --bwlimit to limit bandwidth used instead of --tpslimit. Since we don't know exactly what limits are being used at the cloud provider then this involves some guesswork.

You might need a combination of the two.

1 Like
19

Oh, I didn't understand why you wrote rclone copy and assumed it was just a "typo". Now I get it.

I haven't seen any downtime of pcloud.com today.

OMG, this is getting complex. I really hope that pcloud will provide me with some details about the rate limits...

But since it seems to be common for storage providers to be obscure about their rate limits, I wonder, whether there is some potential for rclone to automate part of this process of optimizing the parameters? (I am aware of the --tpslimit-burst option which seems to add some flexibility to --tpslimit, but at this point, adding it to my command would only increase the complexity and make it more even more difficult to tell what the actual source of failure is).

20

If you want rclone to deal with this, then set --low-level-retries high enough so that the temporary rate limit expires and rclone carries on after the rate limit expires. That is how it is supposed to work. It might be that rclone should back off a bit more than it does at the moment.

Whether that will work in this case I don't know, but try setting --low-level-retries 100 say and see what happens.