panic during copy

[buengese]

What is the problem you are having with rclone?

I've noticed some panic errors caught by pacer when looking at the log of an rclone copy from onedrive to ulozto. I'm not sure where the originate. I'll try to reproduce this.

2024/09/16 10:22:06 DEBUG : Too many requests. Trying again in 1268 seconds.
2024/09/16 10:22:06 DEBUG : pacer: low level retry 1/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/16 10:22:06 DEBUG : pacer: Rate limited, increasing sleep to 21m8s
2024/09/16 10:22:06 DEBUG : Too many requests. Trying again in 1413 seconds.
2024/09/16 10:22:06 DEBUG : pacer: low level retry 1/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/16 10:22:06 DEBUG : pacer: Rate limited, increasing sleep to 23m33s

What is your rclone version (output from rclone version)

rclone v1.68.0
- os/version: ubuntu 22.04 (64 bit)
- os/kernel: 6.5.0-1027-oracle (aarch64)
- os/type: linux
- os/arch: arm64 (ARMv8 compatible)
- go/version: go1.23.1
- go/linking: static
- go/tags: none

Which OS you are using and how many bits (e.g. Windows 7, 64 bit)

Ubuntu 22.04 aarch64

Which cloud storage system are you using? (e.g. Google Drive)

OneDrive and uloz.to

The command you were trying to run (e.g. rclone copy /tmp remote:tmp)

rclone copy onedrive:/path/to/dir/ uloz:/path/to/dir/ --progress -vv

How to use GitHub

• Please use the 👍 reaction to show that you are affected by the same issue.
• Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
• Subscribe to receive notifications on status change and new comments.

[Animosity022]

If I had to bet, OneDrive as the throttling there is real and running defaults, I'd imagine that was doing it.

[ncw]

I didn't think we caught panics anywhere, but we must be... Or something is...

[ncw]

Grepping the rclone source for recover(), I don't think a plain rclone copy can catch panics

Neither onedrive or ulozto use any external modules.

If it was run via the rc then yes it could.

@buengese are you using a patched rclone? Struggling to understand what is going on here!

[buengese]

Nope, this rclone version is neither patched nor was it running via rc. I've also not been able to reproduce that.

A detail I forgot in the initial post ist that both the onedrive and ulozto backend very wrapped by a crypt backend.

The exact command being run was:
rclone copy onedrive-crypt:<redacted> uloz-crypt:<redacted> --transfers 8 --retries 10 --low-level-retries 10 -vv --log-file=/log/rclone-copy-1726176156.log

[ncw]

The only places we recover panics are here

$ git grep "recover()" | grep -v test
backend/qingstor/qingstor.go:		if r := recover(); r != nil {
cmd/cmount/mount.go:			if r := recover(); r != nil {
cmd/serve/dlna/dlna_util.go:			err := recover()
fs/rc/jobs/job.go:		if r := recover(); r != nil {
librclone/librclone/librclone.go:		if r := recover(); r != nil {
vfs/dir.go:		_ = recover()

For a plain rclone copy onedrive-crypt:<redacted> uloz-crypt:<redacted> I don't think any of those should be running...

So maybe in a dependency....

Unless you can reproduce it I don't think we'll track it down like this!

[buengese]

I've seen the error yet again in a new transfer. Once again deep into a large transfer, always twice in a row and in very much seems to be related to the rate limiting. Still now clue where its coming from. I guess I'm going to retry that transfer with a debugger attached.

2024/09/21 01:11:00 DEBUG : Too many requests. Trying again in 61 seconds.
2024/09/21 01:11:00 DEBUG : pacer: low level retry 1/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 01:11:00 DEBUG : pacer: Rate limited, increasing sleep to 1m1s
2024/09/21 01:11:00 DEBUG : Too many requests. Trying again in 78 seconds.
2024/09/21 01:11:00 DEBUG : pacer: low level retry 2/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 01:11:00 DEBUG : pacer: Rate limited, increasing sleep to 1m18s
...
2024/09/21 01:21:00 DEBUG : Too many requests. Trying again in 101 seconds.
2024/09/21 01:21:00 DEBUG : pacer: low level retry 1/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 01:21:00 DEBUG : pacer: Rate limited, increasing sleep to 1m41s
2024/09/21 01:21:00 DEBUG : Too many requests. Trying again in 103 seconds.
2024/09/21 01:21:00 DEBUG : pacer: low level retry 2/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 01:21:00 DEBUG : pacer: Rate limited, increasing sleep to 1m43s
...
2024/09/21 01:33:30 DEBUG : Too many requests. Trying again in 111 seconds.
2024/09/21 01:33:30 DEBUG : pacer: low level retry 1/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 01:33:30 DEBUG : pacer: Rate limited, increasing sleep to 1m51s
2024/09/21 01:33:30 DEBUG : pacer: Reducing sleep to 1m23.25s
2024/09/21 01:33:30 DEBUG : Too many requests. Trying again in 96 seconds.
2024/09/21 01:33:30 DEBUG : pacer: low level retry 2/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 01:33:30 DEBUG : pacer: Rate limited, increasing sleep to 1m36s
2024/09/21 01:33:30 DEBUG : pacer: Reducing sleep to 1m12s
...
2024/09/21 01:44:00 DEBUG : Too many requests. Trying again in 102 seconds.
2024/09/21 01:44:00 DEBUG : pacer: low level retry 1/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 01:44:00 DEBUG : pacer: Rate limited, increasing sleep to 1m42s
2024/09/21 01:44:00 DEBUG : Couldn't decode error response: EOF
2024/09/21 01:44:00 DEBUG : pacer: Reducing sleep to 1m16.5s
2024/09/21 01:44:00 DEBUG : Too many requests. Trying again in 102 seconds.
2024/09/21 01:44:00 DEBUG : pacer: low level retry 2/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 01:44:00 DEBUG : pacer: Rate limited, increasing sleep to 1m42s
...
2024/09/21 02:15:00 DEBUG : Too many requests. Trying again in 74 seconds.
2024/09/21 02:15:00 DEBUG : pacer: low level retry 1/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 02:15:00 DEBUG : pacer: Rate limited, increasing sleep to 1m14s
2024/09/21 02:15:00 DEBUG : Couldn't decode error response: EOF
2024/09/21 02:15:00 DEBUG : pacer: Reducing sleep to 55.5s
2024/09/21 02:15:00 DEBUG : Too many requests. Trying again in 78 seconds.
2024/09/21 02:15:00 DEBUG : pacer: low level retry 2/10 (error %!v(PANIC=Error method: runtime error: invalid memory address or nil pointer dereference))
2024/09/21 02:15:00 DEBUG : pacer: Rate limited, increasing sleep to 1m18s