Rclone copy to FTP: rclone sends a QUIT and never ends itself

realtebo · May 6, 2021, 7:43am

What is the problem you are having with rclone?

rclone itself is doing all well.

I have a specific problem and I need a suggestion.

We are copying a small file (160 KBytes) into an FTP.

But we noticed rclone stay 'waiting' for I don't know what.

2021/05/06 09:33:11 INFO  :
Transferred:      152.272k / 152.272 kBytes, 100%, 2.537 kBytes/s, ETA 0s
Transferred:            0 / 1, 0%
Elapsed time:       1m2.6s
Transferring:
 *                  availabilities.csv:100% /152.272k, 569/s, 0s

2021/05/06 09:34:11 INFO  :
Transferred:      152.272k / 152.272 kBytes, 100%, 1.269 kBytes/s, ETA 0s
Transferred:            0 / 1, 0%
Elapsed time:       2m2.6s
Transferring:
 *                  availabilities.csv:100% /152.272k, 11/s, 0s

...etc...

Rclone stay up ... waiting ... for days ! It never exit.

I tried

--contimeout 1m --timeout 1m --retries 1 --no-check-dest

but nothing changes

What is your rclone version (output from `rclone version`)

rclone v1.55.1

os/type: linux
os/arch: amd64
go/version: go1.16.3
go/linking: static
go/tags: none

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

Distributor ID: Ubuntu
Description: Ubuntu 16.04.1 LTS
Release: 16.04
Codename: xenial

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

FTP

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

rclone copy /home/<user>/mongo_bckp/availabilities.csv customer_ftp:/ --contimeout 1m --timeout 1m --retries 1 --no-check-dest  -vvv

The rclone config contents with secrets removed.

    "customer_ftp": {
        "concurrency": "1",
        "explicit_tls": "true",
        "host": "<redacted>",
        "no_check_certificate": "true",
        "pass": "<redacted>",
        "tls": "false",
        "type": "ftp",
        "user": "<redacted>"
    }

A log from the command with the `-vv` flag

2021/05/06 09:32:08 DEBUG : Creating backend with remote "/home/<user>/mongo_bckp/availabilities.csv"
2021/05/06 09:32:08 DEBUG : Using config file from "/home/<user>/.config/rclone/rclone.conf"
2021/05/06 09:32:08 DEBUG : fs cache: adding new entry for parent of "/home/<user>/mongo_bckp/availabilities.csv", "/home/<user>/mongo_bckp"
2021/05/06 09:32:08 DEBUG : Creating backend with remote "customer_ftp:/"
2021/05/06 09:32:08 DEBUG : ftp://<redacted>:21: Connecting to FTP server
2021/05/06 09:32:11 DEBUG : availabilities.csv: Need to transfer - File not found at Destination
2021/05/06 09:33:11 INFO  :
Transferred:      152.272k / 152.272 kBytes, 100%, 2.537 kBytes/s, ETA 0s
Transferred:            0 / 1, 0%
Elapsed time:       1m2.6s
Transferring:
 *                  availabilities.csv:100% /152.272k, 569/s, 0s

2021/05/06 09:34:11 INFO  :
Transferred:      152.272k / 152.272 kBytes, 100%, 1.269 kBytes/s, ETA 0s
Transferred:            0 / 1, 0%
Elapsed time:       2m2.6s
Transferring:
 *                  availabilities.csv:100% /152.272k, 11/s, 0s

I add here a more exaustive log using --dump body

2021/05/06 09:58:42 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/06 09:58:42 DEBUG : FTP Tx: "AUTH TLS"
2021/05/06 09:58:42 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/06 09:58:42 DEBUG : FTP Tx: "USER <redacted>"
2021/05/06 09:58:42 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/06 09:58:42 DEBUG : FTP Tx: PASS *****
2021/05/06 09:58:44 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/06 09:58:44 DEBUG : FTP Tx: "FEAT"
2021/05/06 09:58:44 DEBUG : FTP Rx: "211-Features:"
2021/05/06 09:58:44 DEBUG : FTP Rx: " AUTH TLS"
2021/05/06 09:58:44 DEBUG : FTP Rx: " CCC"
2021/05/06 09:58:44 DEBUG : FTP Rx: " CLNT"
2021/05/06 09:58:44 DEBUG : FTP Rx: " EPRT"
2021/05/06 09:58:44 DEBUG : FTP Rx: " EPSV"
2021/05/06 09:58:44 DEBUG : FTP Rx: " HOST"
2021/05/06 09:58:44 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/06 09:58:44 DEBUG : FTP Rx: " MDTM"
2021/05/06 09:58:44 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/06 09:58:44 DEBUG : FTP Rx: " MFMT"
2021/05/06 09:58:44 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/06 09:58:44 DEBUG : FTP Rx: " PBSZ"
2021/05/06 09:58:44 DEBUG : FTP Rx: " PROT"
2021/05/06 09:58:44 DEBUG : FTP Rx: " REST STREAM"
2021/05/06 09:58:44 DEBUG : FTP Rx: " SIZE"
2021/05/06 09:58:44 DEBUG : FTP Rx: " SSCN"
2021/05/06 09:58:44 DEBUG : FTP Rx: " TVFS"
2021/05/06 09:58:44 DEBUG : FTP Rx: " UTF8"
2021/05/06 09:58:44 DEBUG : FTP Rx: "211 End"
2021/05/06 09:58:44 DEBUG : FTP Tx: "TYPE I"
2021/05/06 09:58:44 DEBUG : FTP Rx: "200 Type set to I"
2021/05/06 09:58:44 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/06 09:58:44 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/06 09:58:44 DEBUG : FTP Tx: "PBSZ 0"
2021/05/06 09:58:44 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/06 09:58:44 DEBUG : FTP Tx: "PROT P"
2021/05/06 09:58:44 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/06 09:58:44 DEBUG : fs cache: renaming cache item "customer_ftp:/" to be canonical "customer_ftp{klVtY}:/"
2021/05/06 09:58:44 DEBUG : FTP Tx: "EPSV"
2021/05/06 09:58:44 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||56935|)"
2021/05/06 09:58:44 DEBUG : FTP Tx: "MLSD /"
2021/05/06 09:58:44 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/06 09:58:44 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/06 09:58:44 DEBUG : availabilities.csv: Sizes differ (src 155927 vs dst 32768)
2021/05/06 09:58:44 DEBUG : FTP Tx: "EPSV"
2021/05/06 09:58:44 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||53709|)"
2021/05/06 09:58:44 DEBUG : FTP Tx: "STOR /availabilities.csv"
2021/05/06 09:58:44 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /availabilities.csv"
2021/05/06 09:58:44 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/05/06 09:58:44 DEBUG : FTP Tx: "QUIT"

I can succesfuly trasnfer the same exact file using filezilla on my windows machine and on a mac machine.

Note that after QUIT rclone never ends

ncw · May 6, 2021, 8:02pm

Hmm!

Can you kill -QUIT the rclone process when it has got stuck and post the backtrace from it - thanks.

realtebo · May 7, 2021, 7:34am

Also: could be related to this: Rclone corrupt file transfer error with latest rclone version : rclone v1.55.1 · Issue #5304 · rclone/rclone · GitHub ?

realtebo · May 7, 2021, 8:09am

Here the dump

2021/05/07 10:08:34 DEBUG : FTP Tx: "EPSV"
2021/05/07 10:08:34 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||51532|)"
2021/05/07 10:08:34 DEBUG : FTP Tx: "STOR /customer_availabilities.csv"
2021/05/07 10:08:34 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /customer_availabilities.csv"
2021/05/07 10:08:34 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/05/07 10:08:34 DEBUG : FTP Tx: "QUIT"


SIGQUIT: quit
PC=0x4744c0 m=0 sigcode=0

goroutine 0 [idle]:
runtime.epollwait(0x7ffd00000004, 0x7ffd36e4c400, 0x3e700000080, 0x0, 0x3e7, 0x0, 0x0, 0x2c9aaa0, 0x2, 0x0, ...)
        runtime/sys_linux_amd64.s:725 +0x20
runtime.netpoll(0x3b966ed3, 0x0)
        runtime/netpoll_epoll.go:126 +0x92
runtime.findrunnable(0xc000050800, 0x0)
        runtime/proc.go:2879 +0x3ee
runtime.schedule()
        runtime/proc.go:3125 +0x2d7
runtime.park_m(0xc0004ba180)
        runtime/proc.go:3274 +0x9d
runtime.mcall(0x0)
        runtime/asm_amd64.s:327 +0x5b

goroutine 1 [chan receive]:
github.com/rclone/rclone/lib/pacer.(*TokenDispenser).Get(...)
        github.com/rclone/rclone/lib/pacer/tokens.go:24
github.com/rclone/rclone/backend/ftp.(*Fs).getFtpConnection(0xc0004b6fc0, 0x213f5a8, 0xc000042068, 0x1, 0x4f58f4, 0xc00070c4c0)
        github.com/rclone/rclone/backend/ftp/ftp.go:317 +0x225
github.com/rclone/rclone/backend/ftp.(*Fs).getInfo(0xc0004b6fc0, 0x213f5a8, 0xc000042068, 0xc00070c500, 0x1d, 0x50, 0xc0004f29b0, 0x0)
        github.com/rclone/rclone/backend/ftp/ftp.go:725 +0x12d
github.com/rclone/rclone/backend/ftp.(*Object).Remove(0xc00018b400, 0x213f5a8, 0xc000042068, 0xef0a77, 0xc00042c3f0)
        github.com/rclone/rclone/backend/ftp/ftp.go:1072 +0xf1
github.com/rclone/rclone/backend/ftp.(*Object).Update.func1()
        github.com/rclone/rclone/backend/ftp/ftp.go:1041 +0x74
github.com/rclone/rclone/backend/ftp.(*Object).Update(0xc00018b400, 0x213f5a8, 0xc000042068, 0x210d3c0, 0xc000718000, 0x7f343d357b08, 0xc0006b4c60, 0xc000380b20, 0x1, 0x1, ...)
        github.com/rclone/rclone/backend/ftp/ftp.go:1055 +0x347
github.com/rclone/rclone/fs/operations.Copy(0x213f5a8, 0xc000042068, 0x21549d8, 0xc0004b6fc0, 0x2154a48, 0xc00018b400, 0x7ffd36e4d643, 0x1c, 0x21550d8, 0xc0006b4c60, ...)
        github.com/rclone/rclone/fs/operations/operations.go:469 +0x1863
github.com/rclone/rclone/fs/operations.moveOrCopyFile(0x213f5a8, 0xc000042068, 0x21549d8, 0xc0004b6fc0, 0x2155068, 0xc000321710, 0x7ffd36e4d643, 0x1c, 0x7ffd36e4d643, 0x1c, ...)
        github.com/rclone/rclone/fs/operations/operations.go:1808 +0x6af
github.com/rclone/rclone/fs/operations.CopyFile(...)
        github.com/rclone/rclone/fs/operations/operations.go:1826
github.com/rclone/rclone/cmd/copy.glob..func1.1(0xc00000dde8, 0xc000042068)
        github.com/rclone/rclone/cmd/copy/copy.go:87 +0xef
github.com/rclone/rclone/cmd.Run(0xc0001c0101, 0x2d150a0, 0xc0004abd30)
        github.com/rclone/rclone/cmd/cmd.go:256 +0xed
github.com/rclone/rclone/cmd/copy.glob..func1(0x2d150a0, 0xc0001c3480, 0x2, 0x4)
        github.com/rclone/rclone/cmd/copy/copy.go:83 +0x12a
github.com/spf13/cobra.(*Command).execute(0x2d150a0, 0xc0001c3440, 0x4, 0x4, 0x2d150a0, 0xc0001c3440)
        github.com/spf13/cobra@v1.1.1/command.go:854 +0x2c2
github.com/spf13/cobra.(*Command).ExecuteC(0x2d10f00, 0x0, 0x0, 0xc00005c778)
        github.com/spf13/cobra@v1.1.1/command.go:958 +0x375
github.com/spf13/cobra.(*Command).Execute(...)
        github.com/spf13/cobra@v1.1.1/command.go:895
github.com/rclone/rclone/cmd.Main()
        github.com/rclone/rclone/cmd/cmd.go:555 +0xad
main.main()
        github.com/rclone/rclone/rclone.go:14 +0x25

goroutine 7 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000e3180)
        go.opencensus.io@v0.22.6/stats/view/worker.go:276 +0xcd
created by go.opencensus.io/stats/view.init.0
        go.opencensus.io@v0.22.6/stats/view/worker.go:34 +0x68

goroutine 34 [chan receive]:
github.com/rclone/rclone/backend/local.(*fadvise).worker(0xc0001c3b40)
        github.com/rclone/rclone/backend/local/fadvise_unix.go:114 +0x5a
created by github.com/rclone/rclone/backend/local.newFadvise
        github.com/rclone/rclone/backend/local/fadvise_unix.go:74 +0xff

goroutine 35 [select]:
github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0xc000718000)
        github.com/rclone/rclone/fs/accounting/accounting.go:212 +0x109
created by github.com/rclone/rclone/fs/accounting.newAccountSizeName
        github.com/rclone/rclone/fs/accounting/accounting.go:110 +0x449

goroutine 21 [select]:
github.com/rclone/rclone/cmd.StartStats.func2(0xc0001bb8c0, 0xc0004b8300)
        github.com/rclone/rclone/cmd/cmd.go:365 +0x10d
created by github.com/rclone/rclone/cmd.StartStats
        github.com/rclone/rclone/cmd/cmd.go:361 +0xb1

rax    0xfffffffffffffffc
rbx    0x3e7
rcx    0x4744c0
rdx    0x80
rdi    0x4
rsi    0x7ffd36e4c400
rbp    0x7ffd36e4ca00
rsp    0x7ffd36e4c3b0
r8     0x0
r9     0x1
r10    0x3e7
r11    0x246
r12    0x0
r13    0xa
r14    0x1
r15    0x1
rip    0x4744c0
rflags 0x246
cs     0x33
fs     0x0
gs     0x0

ncw · May 7, 2021, 9:53am

realtebo:

github.com/rclone/rclone/lib/pacer.(*TokenDispenser).Get(...)
        github.com/rclone/rclone/lib/pacer/tokens.go:24
github.com/rclone/rclone/backend/ftp.(*Fs).getFtpConnection(0xc0004b6fc0, 0x213f5a8, 0xc000042068, 0x1, 0x4f58f4, 0xc00070c4c0)
        github.com/rclone/rclone/backend/ftp/ftp.go:317 +0x225

This is deadlocked in the getting a token code.

This is caused by concurrency = 1 in your config file.

Can you raise that?

realtebo · May 7, 2021, 7:27pm

Thanks for your help.

I removed concurrency = 1 (I supposed it was here to force only one file at time)

But still some problem.

rclone do not stay infinitely blocked as before

But still the transfer don't works

Here dump-bodies

2021/05/07 21:28:03 NOTICE: --dump-bodies is obsolete - please use --dump bodies instead
2021/05/07 21:28:03 DEBUG : Using config file from "/home/username/.config/rclone/rclone.conf"
2021/05/07 21:28:03 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "copy" "/home/username/mongo_bckp/customer_availabilities.csv" "customer_ftp:/" "-vv" "--dump-bodies"]
2021/05/07 21:28:03 DEBUG : Creating backend with remote "/home/username/mongo_bckp/customer_availabilities.csv"
2021/05/07 21:28:03 DEBUG : fs cache: adding new entry for parent of "/home/username/mongo_bckp/customer_availabilities.csv", "/home/username/mongo_bckp"
2021/05/07 21:28:03 DEBUG : Creating backend with remote "customer_ftp:/"
2021/05/07 21:28:03 DEBUG : ftp://domain.com:21: Connecting to FTP server
2021/05/07 21:28:03 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/07 21:28:03 DEBUG : FTP Tx: "AUTH TLS"
2021/05/07 21:28:03 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/07 21:28:03 DEBUG : FTP Tx: "USER <redacted>"
2021/05/07 21:28:03 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/07 21:28:03 DEBUG : FTP Tx: PASS *****
2021/05/07 21:28:06 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/07 21:28:06 DEBUG : FTP Tx: "FEAT"
2021/05/07 21:28:06 DEBUG : FTP Rx: "211-Features:"
2021/05/07 21:28:06 DEBUG : FTP Rx: " AUTH TLS"
2021/05/07 21:28:06 DEBUG : FTP Rx: " CCC"
2021/05/07 21:28:06 DEBUG : FTP Rx: " CLNT"
2021/05/07 21:28:06 DEBUG : FTP Rx: " EPRT"
2021/05/07 21:28:06 DEBUG : FTP Rx: " EPSV"
2021/05/07 21:28:06 DEBUG : FTP Rx: " HOST"
2021/05/07 21:28:06 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/07 21:28:06 DEBUG : FTP Rx: " MDTM"
2021/05/07 21:28:06 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/07 21:28:06 DEBUG : FTP Rx: " MFMT"
2021/05/07 21:28:06 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/07 21:28:06 DEBUG : FTP Rx: " PBSZ"
2021/05/07 21:28:06 DEBUG : FTP Rx: " PROT"
2021/05/07 21:28:06 DEBUG : FTP Rx: " REST STREAM"
2021/05/07 21:28:06 DEBUG : FTP Rx: " SIZE"
2021/05/07 21:28:06 DEBUG : FTP Rx: " SSCN"
2021/05/07 21:28:06 DEBUG : FTP Rx: " TVFS"
2021/05/07 21:28:06 DEBUG : FTP Rx: " UTF8"
2021/05/07 21:28:06 DEBUG : FTP Rx: "211 End"
2021/05/07 21:28:06 DEBUG : FTP Tx: "TYPE I"
2021/05/07 21:28:06 DEBUG : FTP Rx: "200 Type set to I"
2021/05/07 21:28:06 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/07 21:28:06 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/07 21:28:06 DEBUG : FTP Tx: "PBSZ 0"
2021/05/07 21:28:06 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/07 21:28:06 DEBUG : FTP Tx: "PROT P"
2021/05/07 21:28:06 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/07 21:28:06 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:06 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||62114|)"
2021/05/07 21:28:06 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:06 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:06 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:06 DEBUG : customer_availabilities.csv: Need to transfer - File not found at Destination
2021/05/07 21:28:06 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:06 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||55957|)"
2021/05/07 21:28:06 DEBUG : FTP Tx: "STOR /customer_availabilities.csv"
2021/05/07 21:28:06 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /customer_availabilities.csv"
2021/05/07 21:28:06 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/05/07 21:28:06 DEBUG : FTP Tx: "QUIT"
2021/05/07 21:28:07 DEBUG : ftp://domain.com:21: Connecting to FTP server
2021/05/07 21:28:07 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/07 21:28:07 DEBUG : FTP Tx: "AUTH TLS"
2021/05/07 21:28:07 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/07 21:28:07 DEBUG : FTP Tx: "USER <redacted>"
2021/05/07 21:28:07 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/07 21:28:07 DEBUG : FTP Tx: PASS *****
2021/05/07 21:28:09 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/07 21:28:09 DEBUG : FTP Tx: "FEAT"
2021/05/07 21:28:09 DEBUG : FTP Rx: "211-Features:"
2021/05/07 21:28:09 DEBUG : FTP Rx: " AUTH TLS"
2021/05/07 21:28:09 DEBUG : FTP Rx: " CCC"
2021/05/07 21:28:09 DEBUG : FTP Rx: " CLNT"
2021/05/07 21:28:09 DEBUG : FTP Rx: " EPRT"
2021/05/07 21:28:09 DEBUG : FTP Rx: " EPSV"
2021/05/07 21:28:09 DEBUG : FTP Rx: " HOST"
2021/05/07 21:28:09 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/07 21:28:09 DEBUG : FTP Rx: " MDTM"
2021/05/07 21:28:09 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/07 21:28:09 DEBUG : FTP Rx: " MFMT"
2021/05/07 21:28:09 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/07 21:28:09 DEBUG : FTP Rx: " PBSZ"
2021/05/07 21:28:09 DEBUG : FTP Rx: " PROT"
2021/05/07 21:28:09 DEBUG : FTP Rx: " REST STREAM"
2021/05/07 21:28:09 DEBUG : FTP Rx: " SIZE"
2021/05/07 21:28:09 DEBUG : FTP Rx: " SSCN"
2021/05/07 21:28:09 DEBUG : FTP Rx: " TVFS"
2021/05/07 21:28:09 DEBUG : FTP Rx: " UTF8"
2021/05/07 21:28:09 DEBUG : FTP Rx: "211 End"
2021/05/07 21:28:09 DEBUG : FTP Tx: "TYPE I"
2021/05/07 21:28:09 DEBUG : FTP Rx: "200 Type set to I"
2021/05/07 21:28:09 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/07 21:28:09 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/07 21:28:09 DEBUG : FTP Tx: "PBSZ 0"
2021/05/07 21:28:09 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/07 21:28:09 DEBUG : FTP Tx: "PROT P"
2021/05/07 21:28:09 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/07 21:28:09 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:09 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||51497|)"
2021/05/07 21:28:09 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:09 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:09 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:09 DEBUG : FTP Tx: "DELE /customer_availabilities.csv"
2021/05/07 21:28:09 DEBUG : FTP Rx: "250 DELE command successful"
2021/05/07 21:28:09 DEBUG : customer_availabilities.csv: Removed after failed upload: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:09 ERROR : customer_availabilities.csv: Failed to copy: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:09 ERROR : Attempt 1/3 failed with 1 errors and: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:09 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:09 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||60811|)"
2021/05/07 21:28:09 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:09 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:09 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:09 DEBUG : customer_availabilities.csv: Need to transfer - File not found at Destination
2021/05/07 21:28:09 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:09 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||63628|)"
2021/05/07 21:28:09 DEBUG : FTP Tx: "STOR /customer_availabilities.csv"
2021/05/07 21:28:09 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /customer_availabilities.csv"
2021/05/07 21:28:09 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/05/07 21:28:09 DEBUG : FTP Tx: "QUIT"
2021/05/07 21:28:10 DEBUG : ftp://domain.com:21: Connecting to FTP server
2021/05/07 21:28:11 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/07 21:28:11 DEBUG : FTP Tx: "AUTH TLS"
2021/05/07 21:28:11 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/07 21:28:11 DEBUG : FTP Tx: "USER <redacted>"
2021/05/07 21:28:11 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/07 21:28:11 DEBUG : FTP Tx: PASS *****
2021/05/07 21:28:14 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/07 21:28:14 DEBUG : FTP Tx: "FEAT"
2021/05/07 21:28:14 DEBUG : FTP Rx: "211-Features:"
2021/05/07 21:28:14 DEBUG : FTP Rx: " AUTH TLS"
2021/05/07 21:28:14 DEBUG : FTP Rx: " CCC"
2021/05/07 21:28:14 DEBUG : FTP Rx: " CLNT"
2021/05/07 21:28:14 DEBUG : FTP Rx: " EPRT"
2021/05/07 21:28:14 DEBUG : FTP Rx: " EPSV"
2021/05/07 21:28:14 DEBUG : FTP Rx: " HOST"
2021/05/07 21:28:14 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/07 21:28:14 DEBUG : FTP Rx: " MDTM"
2021/05/07 21:28:14 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/07 21:28:14 DEBUG : FTP Rx: " MFMT"
2021/05/07 21:28:14 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/07 21:28:14 DEBUG : FTP Rx: " PBSZ"
2021/05/07 21:28:14 DEBUG : FTP Rx: " PROT"
2021/05/07 21:28:14 DEBUG : FTP Rx: " REST STREAM"
2021/05/07 21:28:14 DEBUG : FTP Rx: " SIZE"
2021/05/07 21:28:14 DEBUG : FTP Rx: " SSCN"
2021/05/07 21:28:14 DEBUG : FTP Rx: " TVFS"
2021/05/07 21:28:14 DEBUG : FTP Rx: " UTF8"
2021/05/07 21:28:14 DEBUG : FTP Rx: "211 End"
2021/05/07 21:28:14 DEBUG : FTP Tx: "TYPE I"
2021/05/07 21:28:14 DEBUG : FTP Rx: "200 Type set to I"
2021/05/07 21:28:14 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/07 21:28:14 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/07 21:28:14 DEBUG : FTP Tx: "PBSZ 0"
2021/05/07 21:28:14 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/07 21:28:14 DEBUG : FTP Tx: "PROT P"
2021/05/07 21:28:14 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/07 21:28:14 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:14 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||58715|)"
2021/05/07 21:28:14 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:14 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:14 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:14 DEBUG : FTP Tx: "DELE /customer_availabilities.csv"
2021/05/07 21:28:14 DEBUG : FTP Rx: "250 DELE command successful"
2021/05/07 21:28:14 DEBUG : customer_availabilities.csv: Removed after failed upload: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:14 ERROR : customer_availabilities.csv: Failed to copy: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:14 ERROR : Attempt 2/3 failed with 1 errors and: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:14 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:14 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||56450|)"
2021/05/07 21:28:14 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:14 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:14 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:14 DEBUG : customer_availabilities.csv: Need to transfer - File not found at Destination
2021/05/07 21:28:14 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:14 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||65529|)"
2021/05/07 21:28:14 DEBUG : FTP Tx: "STOR /customer_availabilities.csv"
2021/05/07 21:28:14 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /customer_availabilities.csv"
2021/05/07 21:28:14 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/05/07 21:28:14 DEBUG : FTP Tx: "QUIT"
2021/05/07 21:28:15 DEBUG : ftp://domain.com:21: Connecting to FTP server
2021/05/07 21:28:15 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/07 21:28:15 DEBUG : FTP Tx: "AUTH TLS"
2021/05/07 21:28:15 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/07 21:28:15 DEBUG : FTP Tx: "USER <redacted>"
2021/05/07 21:28:15 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/07 21:28:15 DEBUG : FTP Tx: PASS *****
2021/05/07 21:28:17 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/07 21:28:17 DEBUG : FTP Tx: "FEAT"
2021/05/07 21:28:17 DEBUG : FTP Rx: "211-Features:"
2021/05/07 21:28:17 DEBUG : FTP Rx: " AUTH TLS"
2021/05/07 21:28:17 DEBUG : FTP Rx: " CCC"
2021/05/07 21:28:17 DEBUG : FTP Rx: " CLNT"
2021/05/07 21:28:17 DEBUG : FTP Rx: " EPRT"
2021/05/07 21:28:17 DEBUG : FTP Rx: " EPSV"
2021/05/07 21:28:17 DEBUG : FTP Rx: " HOST"
2021/05/07 21:28:17 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/07 21:28:17 DEBUG : FTP Rx: " MDTM"
2021/05/07 21:28:17 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/07 21:28:17 DEBUG : FTP Rx: " MFMT"
2021/05/07 21:28:17 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/07 21:28:17 DEBUG : FTP Rx: " PBSZ"
2021/05/07 21:28:17 DEBUG : FTP Rx: " PROT"
2021/05/07 21:28:17 DEBUG : FTP Rx: " REST STREAM"
2021/05/07 21:28:17 DEBUG : FTP Rx: " SIZE"
2021/05/07 21:28:17 DEBUG : FTP Rx: " SSCN"
2021/05/07 21:28:17 DEBUG : FTP Rx: " TVFS"
2021/05/07 21:28:17 DEBUG : FTP Rx: " UTF8"
2021/05/07 21:28:17 DEBUG : FTP Rx: "211 End"
2021/05/07 21:28:17 DEBUG : FTP Tx: "TYPE I"
2021/05/07 21:28:17 DEBUG : FTP Rx: "200 Type set to I"
2021/05/07 21:28:17 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/07 21:28:17 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/07 21:28:17 DEBUG : FTP Tx: "PBSZ 0"
2021/05/07 21:28:17 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/07 21:28:17 DEBUG : FTP Tx: "PROT P"
2021/05/07 21:28:17 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/07 21:28:17 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:17 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||59044|)"
2021/05/07 21:28:17 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:17 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:17 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:17 DEBUG : FTP Tx: "DELE /customer_availabilities.csv"
2021/05/07 21:28:17 DEBUG : FTP Rx: "250 DELE command successful"
2021/05/07 21:28:17 DEBUG : customer_availabilities.csv: Removed after failed upload: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:17 ERROR : customer_availabilities.csv: Failed to copy: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:17 ERROR : Attempt 3/3 failed with 1 errors and: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:17 INFO  :
Transferred:      456.814k / 456.814 kBytes, 100%, 39.626 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Elapsed time:        14.2s

2021/05/07 21:28:17 DEBUG : 3 go routines active
2021/05/07 21:28:17 Failed to copy: update stor: 450 Transfer aborted. Link to file server lost

I tried adding --ftp-disable-mlsd but nothing changes

I triead also adding --ftp-disable-epsv but nothing changes

I tried --no-check-dest but nothing changes

But WHY rclone is deleting file ?!?!

ncw · May 7, 2021, 8:00pm

This is the underlying problem.

Not sure what is causing that.

The server is proftpd isn't it which shouldn't be a problem - we test against that daily.

I wonder if it is the TLS causing the problem.

Can you try without?

Rclone deletes the partial file because the transfer failed.

littlemd · May 27, 2021, 9:36am

I have the exact same issue as OP

Using FTP without TLS works without any problems, so it looks like it is something TLS related. As soon as I enable TLS it will start the transfer of the first few files (specified with the ftp-concurrency parameter), but the transfer goes to 100% and freezes. It's like rclone cannot "finish" the transfer.

Edit:
After rclone transfered 24/30 files it stopped again at 100%.

ncw · May 27, 2021, 4:55pm

That is good to know.

Can you try the latest beta and see if that fixes it - there were some ftp backend changes in there

Also did you turn off session resumption

I think this may be related to this issue FTPS (FTP with implicit TLS) issues in rclone-v1.55.0-windows-amd64 · Issue #5210 · rclone/rclone · GitHub which should be fixed in 1.55.1 but maybe something went wrong with the backport.

ivandeex · June 4, 2021, 7:30pm

I see this problem with hetzner storage box.
tl;dr The bug was introduced between rclone 1.53 and 1.55

config section:

[stobox-ftp]
type = ftp
host = XXX.your-storagebox.de
user = XXX
pass = XXX
explicit_tls = true

[stobox-sftp]
type = sftp
host = XXX.your-storagebox.de
user = XXX
pass = XXX

SFTP works fine:

rclone copy ./file_60mb.bin stobox-sftp:

FTP with explicit TLS fails for me:

rclone copy ./file_60mb.bin stobox-ftp:

I did not try pure FTP for security. According to reports above it should work fine.

Failure log with verbose dump:

2021/06/04 21:53:42 DEBUG : rclone: Version "v1.56.0-DEV" starting with parameters ["rclone" "copy" "-P" "60m" "stobox:" "--dump" "headers,bodies,auth" "-vv"]
2021/06/04 21:53:42 DEBUG : Creating backend with remote "60m"
2021/06/04 21:53:42 DEBUG : Using config file from "/home/XXX/.rclone.conf"
2021/06/04 21:53:42 DEBUG : fs cache: adding new entry for parent of "60m", "/home/XXX"
2021/06/04 21:53:42 DEBUG : Creating backend with remote "stobox:"
2021/06/04 21:53:42 DEBUG : ftp://XXX.your-storagebox.de:21: Connecting to FTP server
2021/06/04 21:53:42 DEBUG : FTP Rx: "220 ProFTPD Server (Hetzner Backup) [XXX]"
2021/06/04 21:53:42 DEBUG : FTP Tx: "AUTH TLS"
2021/06/04 21:53:42 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/06/04 21:53:42 DEBUG : FTP Tx: "USER XXX"
2021/06/04 21:53:42 DEBUG : FTP Rx: "331 Password required for XXX"
2021/06/04 21:53:42 DEBUG : FTP Tx: "PASS XXX"
2021/06/04 21:53:42 DEBUG : FTP Rx: "230 User XXX logged in"
2021/06/04 21:53:42 DEBUG : FTP Tx: "FEAT"
2021/06/04 21:53:42 DEBUG : FTP Rx: "211-Features:"
2021/06/04 21:53:42 DEBUG : FTP Rx: " AUTH TLS"
2021/06/04 21:53:42 DEBUG : FTP Rx: " CCC"
2021/06/04 21:53:42 DEBUG : FTP Rx: " CLNT"
2021/06/04 21:53:42 DEBUG : FTP Rx: " EPRT"
2021/06/04 21:53:42 DEBUG : FTP Rx: " EPSV"
2021/06/04 21:53:42 DEBUG : FTP Rx: " HOST"
2021/06/04 21:53:42 DEBUG : FTP Rx: " LANG ko-KR.UTF-8;ko-KR;it-IT.UTF-8;it-IT;es-ES.UTF-8;es-ES;bg-BG.UTF-8;bg-BG;ru-RU.UTF-8;ru-RU;zh-TW.UTF-8;zh-TW;zh-CN.UTF-8;zh-CN;ja-JP;fr-FR.UTF-8;fr-FR;en-US.UTF-8;en-US*"
2021/06/04 21:53:42 DEBUG : FTP Rx: " MDTM"
2021/06/04 21:53:42 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/06/04 21:53:42 DEBUG : FTP Rx: " MFMT"
2021/06/04 21:53:42 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/06/04 21:53:42 DEBUG : FTP Rx: " PBSZ"
2021/06/04 21:53:42 DEBUG : FTP Rx: " PROT"
2021/06/04 21:53:42 DEBUG : FTP Rx: " RANG STREAM"
2021/06/04 21:53:42 DEBUG : FTP Rx: " REST STREAM"
2021/06/04 21:53:42 DEBUG : FTP Rx: " SIZE"
2021/06/04 21:53:42 DEBUG : FTP Rx: " SSCN"
2021/06/04 21:53:42 DEBUG : FTP Rx: " TVFS"
2021/06/04 21:53:42 DEBUG : FTP Rx: " UTF8"
2021/06/04 21:53:42 DEBUG : FTP Rx: "211 End"
2021/06/04 21:53:42 DEBUG : FTP Tx: "TYPE I"
2021/06/04 21:53:42 DEBUG : FTP Rx: "200 Type set to I"
2021/06/04 21:53:42 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/06/04 21:53:42 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/06/04 21:53:42 DEBUG : FTP Tx: "PBSZ 0"
2021/06/04 21:53:42 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/06/04 21:53:42 DEBUG : FTP Tx: "PROT P"
2021/06/04 21:53:42 DEBUG : FTP Rx: "200 Protection set to Private"
2021-06-04 21:53:42 DEBUG : FTP Tx: "EPSV"
2021-06-04 21:53:42 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||49152|)"
2021-06-04 21:53:42 DEBUG : FTP Tx: "MLSD ."
2021-06-04 21:53:42 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021-06-04 21:53:42 DEBUG : FTP Rx: "226 Transfer complete"
2021-06-04 21:53:42 DEBUG : 60m: Need to transfer - File not found at Destination
2021-06-04 21:53:42 DEBUG : FTP Tx: "EPSV"
2021-06-04 21:53:42 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||53461|)"
2021-06-04 21:53:42 DEBUG : FTP Tx: "MLSD ."
2021-06-04 21:53:42 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021-06-04 21:53:42 DEBUG : FTP Rx: "226 Transfer complete"
2021-06-04 21:53:42 DEBUG : FTP Tx: "EPSV"
2021-06-04 21:53:42 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||57526|)"
2021-06-04 21:53:42 DEBUG : FTP Tx: "MLSD ."
2021-06-04 21:53:42 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021-06-04 21:53:42 DEBUG : FTP Rx: "226 Transfer complete"
2021-06-04 21:53:42 DEBUG : FTP Tx: "EPSV"
2021-06-04 21:53:42 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||64179|)"
2021-06-04 21:53:42 DEBUG : FTP Tx: "STOR 60m"
2021-06-04 21:53:42 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for 60m"
2021-06-04 21:53:44 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021-06-04 21:53:44 DEBUG : FTP Tx: "QUIT"

Final error message:

Failed to copy: update stor: 450 Transfer aborted. Link to file server lost

Failing rclone versions: 1.55.1, git master

However rclone version 1.52.3 works fine.

I did not try other versions in between.
Will do git bisect later.

ivandeex · June 5, 2021, 12:40pm

Bisection pointed me to the first patch introducing support for FTP's explicit_tls in rclone. In fact 1.52.3 did not recognize the explicit_tls parameter, ignored it and accessed FTP by plain protocol. Thus, the explicit_tls mode always had the problem in question.

Surfing through the github threads related to the FTP TLS bugs, I stumbled upon this comment: Failing data connection with STARTTLS (Explicit TLS): tls session not reused · Issue #49 · secsy/goftp · GitHub

I then made a patch adding tls session cache in the ftp backend: Commits · ivandeex/rclone · GitHub
Running rclone with tls cache enabled fixed the upload to hetzner storage for me. This is nice because FTP+TLS gives me the 80MB/s upload speed while workaround with SFTP capped at 40MB/s, both being securely encryped.

FWIW Please try rclone beta with the patch from Release v1.55.1-ftp02 · ivandeex/rclone · GitHub
Note that I don't fully understand all security implications of tls session cache or how big it should be, so by default it's disabled. To enable it and fix the 450 problem, you should enable it manually via command line flag --ftp-tls-cache-size=64, or add the line tls_cache_size = 64 in the ftp section of rclone.conf

Please let me know if it helped you. Maybe it deserves submitting a patch for the mainline rclone.

ivandeex · June 6, 2021, 8:27am

I tested the TLS session cache a little more with hetzner storage box using a 4GB file. While uploads seem to be fixed, downloads are broken. In the middle of download rclone resets the stream back, then downloads again and again, forever.
Please don't use the above beta for real data. I don't have much time to continue with the patch. My real storage will use SFTP.

ncw · June 7, 2021, 5:05pm

Nice one

Is this a timeout?

ivandeex · June 7, 2021, 8:57pm

I don't know. Feels broken. I stopped this experiment and reverted to SFTP.

Kaziq · July 17, 2021, 10:39am

Hi, I have the exact same problem. I try to transfer a directory of small files, but files over certain size aren't transferred, no matter how many times I try.
The largest file sent successfully is 6.11 kB,
The smallest file with error is 17.3 kB,
so the threshold is somewhere in between,

ivandeex, the links to the patch in your post do not work (404), so I don't know how to try it.
Tried the latest beta (1.56.0-beta.5589), but the patch doesn't seem to be merged yet (doesn't recognize the --ftp-tls-cache-size=64 flag).

ivandeex · July 17, 2021, 11:50am

I din't submit the patch and removed the beta build. Will investigate further.

ivandeex · July 17, 2021, 1:11pm

Currently you can try this dev build

of this dev branch

ivandeex · July 17, 2021, 7:52pm

I was able to correctly download a 2g file from hetzner storage box via ftp+explicit tls, handwaving harmless error messages about close timeouts, though the speed (9 Mib/s) sucks vs sftp (30 Mib/s) or pure ftp (100 Mib/s). note: rclone and storage box live in two germany hetzner datacenters.

config:

type = ftp
host = u123456.your-storagebox.de
user = u123456
pass = s123456
encoding = Slash,Asterisk,Ctl,Dot
explicit_tls = true
no_check_certificate = true
close_timeout = 0
data_close_timeout = 1m

build:

The key problem with hetzner storage box (ProFTPd v1.3.something on FreeBSD) likely stems from incorrect use of timeouts by rclone and the jlaffaye/ftp library. Timeout related bugs reveal with large files both in plain and in tls modes.

problematic spots in code:

github.com

ivandeex/rclone/blob/ci-ftp/backend/ftp/ftp.go#L1026

    
      
          	return
          }
          
          
// Close the FTP reader and return the connection to the pool
          func (f *ftpReadCloser) Close() error {
          	var err error
          	errchan := make(chan error, 1)
          	go func() {
          		errchan <- f.rc.Close()
          	}()
          	// Wait for Close for up to 60 seconds by default
          	timer := time.NewTimer(time.Duration(f.f.opt.CloseTimeout))
          	select {
          	case err = <-errchan:
          		timer.Stop()
          	case <-timer.C:
          		// if timer fired assume no error but connection dead
          		fs.Errorf(f.f, "Timeout when waiting for connection Close")
          		f.f.putFtpConnection(nil, nil)
          		return nil
          	}

github.com

ivandeex/rclone/blob/ci-ftp/fs/fshttp/dialer.go#L121

    
      
          
          
// Read bytes doing idle timeouts
          func (c *timeoutConn) Read(b []byte) (n int, err error) {
          	// Ideally we would LimitBandwidth(len(b)) here and replace tokens we didn't use
          	n, err = c.Conn.Read(b)
          	accounting.TokenBucket.LimitBandwidth(accounting.TokenBucketSlotTransportRx, n)
          	// Don't nudge if no bytes or an error
          	if n == 0 || err != nil {
          		return
          	}
          	// Nudge the deadline on successful Read or Write
          	err = c.nudgeDeadline()
          	return n, err
          }
          
          
// Write bytes doing idle timeouts
          func (c *timeoutConn) Write(b []byte) (n int, err error) {
          	accounting.TokenBucket.LimitBandwidth(accounting.TokenBucketSlotTransportTx, len(b))
          	n, err = c.Conn.Write(b)
          	// Don't nudge if no bytes or an error
          	if n == 0 || err != nil {

cc @ncw

Kaziq · July 18, 2021, 8:50am

Thank you, but it doesn't help in my case. Still the same behaviour. I tried increasing the cache size to 256, but still the same.

I think I will switch to SFTP in the end, because it supports modtime and hashes. But have to resolve other problems I have with it first.

Kaziq · July 19, 2021, 3:44pm

Looks like I cannot use SFTP, and have to stick to FTPS.
In the previous test I forgot to set disable_tls13. After set to true, the transfer works, but now I'm getting some weird FTP error, that is most likely unrelated to rclone (but perhaps someone knows what may be causing it?):

2021/07/19 16:40:46 DEBUG : FTP Tx: "MFMT 20060918115312 /test_rclone/current/Test.zip"
2021/07/19 16:40:46 DEBUG : FTP Rx: "501 /test_rclone/current/Test.zip: Operation not permitted"
2021/07/19 16:40:46 ERROR : Test.zip: Failed to copy: SetModTime: 501 /test_rclone/current/Test.zip: Operation not permitted

The server is ProFTPD with RPi OS, and NTFS drive attached.
I tried setting writing_mdtm to true, as the description says "Use MDTM to set modification time (non-standard)" (which is strange, because according to Wikipedia, MDTM is used to read modification time, not set it). But enabling it didn't change anything, and rclone still used MFMT.