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

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

Hmm!

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

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

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

This is deadlocked in the getting a token code.

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

Can you raise that?

1 Like

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 ?!?!

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.

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%.

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.

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.

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.

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.

Nice one :slight_smile:

:frowning: Is this a timeout?

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

1 Like