Rclone + ftp gives ECONNABORTED - Connection aborted after file has transfered

What is the problem you are having with rclone?

I get a "425 Error while transfering data: ECONNABORTED - Connection aborted" whenever I am trying to do an rclone move or copy to a FileZilla FTP server. It seems to happen after a file has been transfered, looks like it's happening on closing the FTP action.

The FileZilla FTP server is running on a Windows 10 machine, no firewall active, running plain FTP. Rclone itself is running from a QNAP NAS. The FileZilla Server logs give a similar result, just a "Connection Aborted" message without any hints on why this might be. See a snippet of the FileZilla Server log below:

<Date> Info [Type] Message
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Response] 229 Entering Extended Passive Mode (|||51423|)
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Trace] session::on_socket_event(): source = data listen, flag = 2, error = 0, state = -1
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Trace] session::on_socket_event(): source = data, flag = 8, error = 0, state = 2
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Command] REST 1048313856
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Response] 350 Restarting at 1048313856
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Trace] session::on_socket_event(): source = data listen, flag = 2, error = 0, state = -1
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Trace] session::on_socket_event(): source = data listen, flag = 2, error = 0, state = -1
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Trace] session::on_socket_event(): source = data, flag = 8, error = 0, state = 2
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Trace] session::on_socket_event(): source = data, flag = 8, error = 0, state = 2
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Command] REST 524156928
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Command] REST 1572470784
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Response] 350 Restarting at 524156928
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Response] 350 Restarting at 1572470784
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Command] RETR dailycapture/single_file/ladybug_21144740_20221010_111531-000000.pgr
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler/TVFS/local_filesys [Trace] open_file(E:\diskjuggler\single_file\ladybug_21144740_20221010_111531-000000.pgr): fd = 2460, res = 0
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Trace] CHANNEL state is being dumped:
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Trace] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53ea28
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Trace] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53e8f0
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:30:40> FTP Session 125 10.10.11.250 diskjuggler [Response] 150 Starting data transfer.
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Command] RETR dailycapture/single_file/ladybug_21144740_20221010_111531-000000.pgr
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Command] RETR dailycapture/single_file/ladybug_21144740_20221010_111531-000000.pgr
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler/TVFS/local_filesys [Trace] open_file(E:\diskjuggler\single_file\ladybug_21144740_20221010_111531-000000.pgr): fd = 2020, res = 0
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler/TVFS/local_filesys [Trace] open_file(E:\diskjuggler\single_file\ladybug_21144740_20221010_111531-000000.pgr): fd = 3396, res = 0
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Trace] CHANNEL state is being dumped:
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Trace] CHANNEL state is being dumped:
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Trace] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b540138
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Trace] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53bc08
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Trace] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b540000
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Trace] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53bad0
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:30:40> FTP Session 126 10.10.11.250 diskjuggler [Response] 150 Starting data transfer.
<26/10/2022 17:30:40> FTP Session 124 10.10.11.250 diskjuggler [Response] 150 Starting data transfer.
<26/10/2022 17:32:35> FTP Session 120 10.10.11.250 diskjuggler [Trace] data_socket_->shutdown() = 0
<26/10/2022 17:32:35> FTP Session 120 10.10.11.250 diskjuggler [Response] 425 Error while transfering data: ECONNABORTED - Connection aborted
<26/10/2022 17:32:35> FTP Session 120 10.10.11.250 diskjuggler [Trace] session::close_data_connection(): there_was_a_transfer_going_on = 1
<26/10/2022 17:32:35> FTP Session 120 10.10.11.250 diskjuggler [Trace] Removed done events: 0
<26/10/2022 17:32:35> FTP Session 120 10.10.11.250 diskjuggler/Done Event [Trace] CHANNEL state is being dumped:
<26/10/2022 17:32:35> FTP Session 120 10.10.11.250 diskjuggler/Done Event [Trace] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53d318
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:32:35> FTP Session 120 10.10.11.250 diskjuggler/Done Event [Trace] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53d1e0
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:32:35> FTP Server [Status] Session 120 ended gracefully.
<26/10/2022 17:32:35> FTP Session 120 10.10.11.250 [Trace] Session 0x1f46b53be00 with ID 120 destroyed.
<26/10/2022 17:32:35> FTP Session 126 10.10.11.250 diskjuggler [Trace] data_socket_->shutdown() = 0
<26/10/2022 17:32:35> FTP Session 124 10.10.11.250 diskjuggler [Trace] data_socket_->shutdown() = 0
<26/10/2022 17:32:35> FTP Session 126 10.10.11.250 diskjuggler [Response] 425 Error while transfering data: ECONNABORTED - Connection aborted
<26/10/2022 17:32:35> FTP Session 124 10.10.11.250 diskjuggler [Response] 425 Error while transfering data: ECONNABORTED - Connection aborted
<26/10/2022 17:32:35> FTP Session 126 10.10.11.250 diskjuggler [Trace] session::close_data_connection(): there_was_a_transfer_going_on = 1
<26/10/2022 17:32:35> FTP Session 124 10.10.11.250 diskjuggler [Trace] session::close_data_connection(): there_was_a_transfer_going_on = 1
<26/10/2022 17:32:35> FTP Session 126 10.10.11.250 diskjuggler [Trace] Removed done events: 0
<26/10/2022 17:32:35> FTP Session 124 10.10.11.250 diskjuggler [Trace] Removed done events: 0
<26/10/2022 17:32:35> FTP Session 126 10.10.11.250 diskjuggler/Done Event [Trace] CHANNEL state is being dumped:
<26/10/2022 17:32:35> FTP Session 124 10.10.11.250 diskjuggler/Done Event [Trace] CHANNEL state is being dumped:
<26/10/2022 17:32:35> FTP Session 126 10.10.11.250 diskjuggler/Done Event [Trace] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b540138
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:32:35> FTP Session 124 10.10.11.250 diskjuggler/Done Event [Trace] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53bc08
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:32:35> FTP Session 126 10.10.11.250 diskjuggler/Done Event [Trace] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b540000
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:32:35> FTP Session 124 10.10.11.250 diskjuggler/Done Event [Trace] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53bad0
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler [Trace] data_socket_->shutdown() = 0
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler [Response] 425 Error while transfering data: ECONNABORTED - Connection aborted
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler [Trace] session::close_data_connection(): there_was_a_transfer_going_on = 1
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler [Trace] Removed done events: 0
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler/Done Event [Trace] CHANNEL state is being dumped:
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler/Done Event [Trace] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53ea28
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler/Done Event [Trace] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    variant_adder_           = <2>
    variant_consumer_        = <2>
    buffer_                  = 0x1f46b53e8f0
    adder_                   = 0x0
    consumer_                = 0x0
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler [Command] QUIT
<26/10/2022 17:32:35> FTP Session 125 10.10.11.250 diskjuggler [Response] 221 Goodbye.

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

- os/version: unknown
- os/kernel: 5.10.60-qnap (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.18.6
- go/linking: static
- go/tags: none

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

Self-hosted FTP server on local network running in plain FTP mode. FileZilla Server on Windows 10.

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

rclone copy pinky:dailycapture/single_file /share/CACHEDEV2_DATA/20221026 --check-first --transfers 16 --checkers 16 --progress --log-file /tmp/rclone_20221026.log```


#### The rclone config contents with secrets removed.  
<!--  You should use 3 backticks to begin and end your paste to make it readable.   -->

[pinky]
type = ftp
host = 10.10.11.104
user = diskjuggler
pass = thunderboltsoflightningveryveryfrightening




#### A log from the command with the `-vv` flag  
```2022/10/26 17:19:35 DEBUG : rclone: Version "v1.59.2" starting with parameters ["rclone" "copy" "pinky:dailycapture/single_file" "/share/CACHEDEV2_DATA/20221026" "-vv" "--check-first" "--transfers" "16" "--checkers" "16" "-vv"]
2022/10/26 17:19:35 DEBUG : Creating backend with remote "pinky:dailycapture/single_file"
2022/10/26 17:19:35 DEBUG : Using config file from "/share/homes/frank/.config/rclone/rclone.conf"
2022/10/26 17:19:35 DEBUG : ftp://10.10.11.104:21/dailycapture/single_file: Connecting to FTP server

2022/10/26 17:19:35 DEBUG : Creating backend with remote "/share/CACHEDEV2_DATA/20221026"

2022/10/26 17:19:35 INFO : Local file system at /share/CACHEDEV2_DATA/20221026: Running all checks before starting transfers

2022/10/26 17:19:35 DEBUG : Local file system at /share/CACHEDEV2_DATA/20221026: Waiting for checks to finish

2022/10/26 17:19:35 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Sizes differ (src 2096505344 vs dst 1999156625)

2022/10/26 17:19:35 INFO : Local file system at /share/CACHEDEV2_DATA/20221026: Checks finished, now starting transfers

2022/10/26 17:19:35 DEBUG : Local file system at /share/CACHEDEV2_DATA/20221026: Waiting for transfers to finish

2022/10/26 17:19:35 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Starting multi-thread copy with 4 parts of size 499.875Mi

2022/10/26 17:19:35 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 (1572470784-2096505344) size 499.758Mi starting

2022/10/26 17:19:35 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 (524156928-1048313856) size 499.875Mi starting

2022/10/26 17:19:35 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 (1048313856-1572470784) size 499.875Mi starting

2022/10/26 17:19:35 DEBUG : ftp://10.10.11.104:21/dailycapture/single_file: Connecting to FTP server

2022/10/26 17:19:35 DEBUG : ftp://10.10.11.104:21/dailycapture/single_file: Connecting to FTP server

2022/10/26 17:19:35 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi starting

2022/10/26 17:19:35 DEBUG : ftp://10.10.11.104:21/dailycapture/single_file: Connecting to FTP server

2022/10/26 17:19:45 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 (1572470784-2096505344) size 499.758Mi finished

2022/10/26 17:19:52 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi finished

2022/10/26 17:19:52 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 failed: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:19:53 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 failed: context canceled

2022/10/26 17:19:53 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 failed: context canceled

2022/10/26 17:19:53 ERROR : ladybug_21144740_20221010_111531-000000.pgr: Failed to copy: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:19:53 ERROR : Attempt 1/3 failed with 1 errors and: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:19:53 INFO : Local file system at /share/CACHEDEV2_DATA/20221026: Running all checks before starting transfers

2022/10/26 17:19:53 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Modification times differ by 389h56m1.113490757s: 2022-10-10 09:23:51.819 +0000 UTC, 2022-10-26 17:19:52.932490757 +0200 CEST

2022/10/26 17:19:53 DEBUG : Local file system at /share/CACHEDEV2_DATA/20221026: Waiting for checks to finish

2022/10/26 17:19:53 INFO : Local file system at /share/CACHEDEV2_DATA/20221026: Checks finished, now starting transfers

2022/10/26 17:19:53 DEBUG : Local file system at /share/CACHEDEV2_DATA/20221026: Waiting for transfers to finish

2022/10/26 17:19:53 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Starting multi-thread copy with 4 parts of size 499.875Mi

2022/10/26 17:19:53 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 (1572470784-2096505344) size 499.758Mi starting

2022/10/26 17:19:53 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 (524156928-1048313856) size 499.875Mi starting

2022/10/26 17:19:53 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 (1048313856-1572470784) size 499.875Mi starting

2022/10/26 17:19:53 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi starting

2022/10/26 17:19:53 DEBUG : ftp://10.10.11.104:21/dailycapture/single_file: Connecting to FTP server

2022/10/26 17:20:07 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi finished

2022/10/26 17:20:07 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 failed: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 failed: context canceled

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 failed: context canceled

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 failed: context canceled

2022/10/26 17:20:08 ERROR : ladybug_21144740_20221010_111531-000000.pgr: Failed to copy: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:20:08 ERROR : Attempt 2/3 failed with 1 errors and: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:20:08 INFO : Local file system at /share/CACHEDEV2_DATA/20221026: Running all checks before starting transfers

2022/10/26 17:20:08 DEBUG : Local file system at /share/CACHEDEV2_DATA/20221026: Waiting for checks to finish

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Sizes differ (src 2096505344 vs dst 1983036162)

2022/10/26 17:20:08 INFO : Local file system at /share/CACHEDEV2_DATA/20221026: Checks finished, now starting transfers

2022/10/26 17:20:08 DEBUG : Local file system at /share/CACHEDEV2_DATA/20221026: Waiting for transfers to finish

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Starting multi-thread copy with 4 parts of size 499.875Mi

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi starting

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 (524156928-1048313856) size 499.875Mi starting

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 (1572470784-2096505344) size 499.758Mi starting

2022/10/26 17:20:08 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 (1048313856-1572470784) size 499.875Mi starting

2022/10/26 17:20:08 DEBUG : ftp://10.10.11.104:21/dailycapture/single_file: Connecting to FTP server

2022/10/26 17:20:24 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 (524156928-1048313856) size 499.875Mi finished

2022/10/26 17:20:24 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 failed: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:20:24 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 failed: context canceled

2022/10/26 17:20:24 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 failed: context canceled

2022/10/26 17:20:24 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 failed: context canceled

2022/10/26 17:20:24 ERROR : ladybug_21144740_20221010_111531-000000.pgr: Failed to copy: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:20:24 ERROR : Attempt 3/3 failed with 1 errors and: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 17:20:24 INFO :

Transferred: 5.270 GiB / 5.270 GiB, 100%, 111.417 MiB/s, ETA 0s

Errors: 1 (retrying may help)

Checks: 3 / 3, 100%

Elapsed time: 48.9s

2022/10/26 17:20:24 DEBUG : 3 go routines active

2022/10/26 17:20:24 DEBUG : ftp://10.10.11.104:21/dailycapture/single_file: closing 3 unused connections

2022/10/26 17:20:24 Failed to copy: 1 error occurred:

* 425 Error while transfering data: ECONNABORTED - Connection aborted```

hello and welcome ot the forum,

things to try

--- update to latest stable and try again.
https://rclone.org/commands/rclone_selfupdate/

--- test using another ftp client, such as filezilla client.

--- test running rclone on the same machine running filezilla server.
you can copy the rclone.conf from the qnas to the winbox.

Thank you for the pointers.

  1. I tried the latest rclone, same result.
  2. I tried with another FTP client (Cyberduck), same result.
  3. I tried rclone (latest version) on the same machine as the FileZilla server, same result. See the logs below for that run:
2022/10/26 19:03:59 DEBUG : rclone: Version "v1.60.0" starting with parameters ["C:\\Users\\Jorrith\\Downloads\\rclone-v1.60.0-windows-amd64\\rclone-v1.60.0-windows-amd64\\rclone.exe" "copy" "pinky:dailycapture/single_file" "c:\\20221026" "-vv" "--check-first" "--transfers" "16" "--checkers" "16"]
2022/10/26 19:03:59 DEBUG : Creating backend with remote "pinky:dailycapture/single_file"
2022/10/26 19:03:59 DEBUG : Using config file from "C:\\Users\\Jorrith\\AppData\\Roaming\\rclone\\rclone.conf"
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52145")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : Creating backend with remote "c:\\20221026"
2022/10/26 19:03:59 DEBUG : fs cache: renaming cache item "c:\\20221026" to be canonical "//?/c:/20221026"
2022/10/26 19:03:59 INFO  : Local file system at //?/c:/20221026: Running all checks before starting transfers
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52147")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : Local file system at //?/c:/20221026: Waiting for checks to finish
2022/10/26 19:03:59 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Modification times differ by 391h38m55.5188557s: 2022-10-10 09:23:51.819 +0000 UTC, 2022-10-26 19:02:47.3378557 +0200 CEST
2022/10/26 19:03:59 INFO  : Local file system at //?/c:/20221026: Checks finished, now starting transfers
2022/10/26 19:03:59 DEBUG : Local file system at //?/c:/20221026: Waiting for transfers to finish
2022/10/26 19:03:59 INFO  : Writing sparse files: use --local-no-sparse or --multi-thread-streams 0 to disable
2022/10/26 19:03:59 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Starting multi-thread copy with 4 parts of size 499.875Mi
2022/10/26 19:03:59 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 (524156928-1048313856) size 499.875Mi starting
2022/10/26 19:03:59 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 (1048313856-1572470784) size 499.875Mi starting
2022/10/26 19:03:59 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi starting
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:03:59 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 (1572470784-2096505344) size 499.758Mi starting
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52149")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52154")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52156")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52158")
2022/10/26 19:03:59 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:01 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 (524156928-1048313856) size 499.875Mi finished
2022/10/26 19:04:01 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 failed: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:01 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 failed: context canceled
2022/10/26 19:04:01 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 failed: context canceled
2022/10/26 19:04:01 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 failed: context canceled
2022/10/26 19:04:01 ERROR : ladybug_21144740_20221010_111531-000000.pgr: Failed to copy: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:01 ERROR : Attempt 1/3 failed with 1 errors and: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:01 INFO  : Local file system at //?/c:/20221026: Running all checks before starting transfers
2022/10/26 19:04:01 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:04:01 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:04:01 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:01 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52161")
2022/10/26 19:04:01 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:01 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Sizes differ (src 2096505344 vs dst 2015048149)
2022/10/26 19:04:01 DEBUG : Local file system at //?/c:/20221026: Waiting for checks to finish
2022/10/26 19:04:01 INFO  : Local file system at //?/c:/20221026: Checks finished, now starting transfers
2022/10/26 19:04:01 DEBUG : Local file system at //?/c:/20221026: Waiting for transfers to finish
2022/10/26 19:04:05 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Starting multi-thread copy with 4 parts of size 499.875Mi
2022/10/26 19:04:05 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 (1572470784-2096505344) size 499.758Mi starting
2022/10/26 19:04:05 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi starting
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:04:05 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 (524156928-1048313856) size 499.875Mi starting
2022/10/26 19:04:05 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 (1048313856-1572470784) size 499.875Mi starting
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52164")
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52168")
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52171")
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52173")
2022/10/26 19:04:05 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:07 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi finished
2022/10/26 19:04:07 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 failed: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:07 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 failed: context canceled
2022/10/26 19:04:07 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 failed: context canceled
2022/10/26 19:04:07 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 failed: context canceled
2022/10/26 19:04:07 ERROR : ladybug_21144740_20221010_111531-000000.pgr: Failed to copy: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:07 ERROR : Attempt 2/3 failed with 1 errors and: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:07 INFO  : Local file system at //?/c:/20221026: Running all checks before starting transfers
2022/10/26 19:04:07 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52175")
2022/10/26 19:04:07 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:07 DEBUG : Local file system at //?/c:/20221026: Waiting for checks to finish
2022/10/26 19:04:07 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Sizes differ (src 2096505344 vs dst 2096238425)
2022/10/26 19:04:07 INFO  : Local file system at //?/c:/20221026: Checks finished, now starting transfers
2022/10/26 19:04:07 DEBUG : Local file system at //?/c:/20221026: Waiting for transfers to finish
2022/10/26 19:04:11 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: Starting multi-thread copy with 4 parts of size 499.875Mi
2022/10/26 19:04:11 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 (1572470784-2096505344) size 499.758Mi starting
2022/10/26 19:04:11 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi starting
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:04:11 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 (524156928-1048313856) size 499.875Mi starting
2022/10/26 19:04:11 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 (1048313856-1572470784) size 499.875Mi starting
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52177")
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: Connecting to FTP server
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:21")
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52182")
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52184")
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: dial("tcp","127.0.0.1:52186")
2022/10/26 19:04:11 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: > dial: conn=*fshttp.timeoutConn, err=<nil>
2022/10/26 19:04:13 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 4/4 (1572470784-2096505344) size 499.758Mi finished
2022/10/26 19:04:13 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 (0-524156928) size 499.875Mi finished
2022/10/26 19:04:13 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 1/4 failed: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:13 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 2/4 failed: context canceled
2022/10/26 19:04:13 DEBUG : ladybug_21144740_20221010_111531-000000.pgr: multi-thread copy: stream 3/4 failed: context canceled
2022/10/26 19:04:13 ERROR : ladybug_21144740_20221010_111531-000000.pgr: Failed to copy: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:13 ERROR : Attempt 3/3 failed with 1 errors and: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

2022/10/26 19:04:13 INFO  :
Transferred:        5.476 GiB / 5.476 GiB, 100%, 349.510 MiB/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:                 3 / 3, 100%
Elapsed time:        14.0s

2022/10/26 19:04:13 DEBUG : 3 go routines active
2022/10/26 19:04:13 DEBUG : ftp://127.0.0.1:21/dailycapture/single_file: closing 1 unused connections
2022/10/26 19:04:13 Failed to copy: 1 error occurred:
        * 425 Error while transfering data: ECONNABORTED - Connection aborted

PS C:\Users\Jorrith\Downloads\rclone-v1.60.0-windows-amd64\rclone-v1.60.0-windows-amd64>

So it's probably not an rclone issue, but more something on the FileZilla side. But I'm baffled as to how or why, and no clear pointers on where to look.

this is not a rclone issue but might be able to use rclone to debug the issue

is the ftp server running as passive or active, rclone only works with passive

plain? is that using plain text, not using tls?
have you tried to force tls?

could be a timeout issue with the ftp server
maybe tweak --ftp-concurrency, --ftp-close-timeout, --ftp-shut-timeout

for the log file, might try
--dump headers, --dump bodies, --dump auth

as a test, run rclone as a ftp or sftp server
for example, rclone serve ftp pinky:

Thanks, I'll give those pointers a go!

And indeed, we're (intentionally) not using TLS because it's on an internal network and there is a lot of data we want to transfer.

We tested this a few more times, also with different FTP servers (FileZilla, IIS, Xlightftpd), and with FTP it always gives these errors. So that'd hint at this being a problem in rclone / the used FTP library after all.

We noticed that the latest rclone also supports SMB, so we moved to that and it was working correctly from the get-go.

Nice to hear that. Is the speed good with SMB?

About the same as on FTP (106MB/s on a 1gbit connection)

1 Like

Can't get much better than that on a 1 Gbit/s link! :slight_smile:

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