SFTP Errors - cannot upload multiple files

guyarad · July 29, 2021, 7:47am

What is the problem you are having with rclone?

I'm trying to upload a folder to an SFTP remote. I've been using rclone successfully with other SFTPs but not this one. Using FileZilla upload works just fine. In this case, using rclone uploads only some of the files, and complains about permissions. I tried removing some checks, but didn't work.
I have tried looking through the forums but couldn't find anything relevant. Thank you in advance for your help!

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

v1.56.0

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

MacOS Catalina 10.15.7 on MacBook Pro 2019, 8 core i9, 32GB RAM

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

From my local drive to an SFTP

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

Remote server, IP, and folders were renamed due to the sensitivity of the information. The chain folder contains 7 small files (less than 1MB each).

./rclone --low-level-retries 1 --retries 1 --ignore-size --no-check-dest -vv copy ~/Downloads/2021-07-28/chain REMOTE:/REMOTE_PATH/testing

The rclone config contents with secrets removed.

[REMOTE]
type = sftp
host = SFTP_HOST
user = SFTP_USER
port = 22
pass = ***
set_modtime = false
md5sum_command = none
sha1sum_command = none

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

File names were modified due to the sensitivity of the names.

2021/07/29 10:44:27 DEBUG : rclone: Version "v1.56.0" starting with parameters ["rclone" "--low-level-retries" "1" "--retries" "1" "--ignore-size" "--no-check-dest" "-vv" "copy" "/Users/guyarad/Downloads/2021-07-28/chain" "REMOTE:/REMOTE_PATH/testing"]
2021/07/29 10:44:27 DEBUG : Creating backend with remote "/Users/guyarad/Downloads/2021-07-28/chain"
2021/07/29 10:44:27 DEBUG : Using config file from "/Users/guyarad/.config/rclone/rclone.conf"
2021/07/29 10:44:27 DEBUG : Creating backend with remote "REMOTE:/REMOTE_PATH/testing"
2021/07/29 10:44:28 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:61856->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/07/29 10:44:29 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: Waiting for checks to finish
2021/07/29 10:44:29 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: Waiting for transfers to finish
2021/07/29 10:44:31 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:61857->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/07/29 10:44:33 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:61858->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/07/29 10:44:34 ERROR : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: Discarding closed SSH connection: ssh: disconnect, reason 11:
2021/07/29 10:44:35 DEBUG : file_4.csv.gz: Removed after failed upload: permission denied
2021/07/29 10:44:35 ERROR : file_4.csv.gz: Failed to copy: Update Close failed: permission denied
2021/07/29 10:44:36 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:61861->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/07/29 10:44:37 INFO  : file_2.csv.gz: Copied (new)
2021/07/29 10:44:37 DEBUG : file_3.csv.gz: Removed after failed upload: connection lost
2021/07/29 10:44:37 ERROR : file_3.csv.gz: Failed to copy: Update ReadFrom failed: connection lost
2021/07/29 10:44:37 DEBUG : file_1.csv.gz: Removed after failed upload: file does not exist
2021/07/29 10:44:37 ERROR : file_1.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/07/29 10:44:38 INFO  : file_5.csv.gz: Copied (new)
2021/07/29 10:44:38 DEBUG : file_6.csv.gz: Failed to remove: file does not exist
2021/07/29 10:44:38 ERROR : file_6.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/07/29 10:44:42 INFO  : file_7.csv.gz: Copied (new)
2021/07/29 10:44:42 ERROR : Attempt 1/1 failed with 4 errors and: Update ReadFrom failed: file does not exist
2021/07/29 10:44:42 INFO  :
Transferred:   	    2.289Mi / 2.289 MiByte, 100%, 180.106 KiByte/s, ETA 0s
Errors:                 4 (retrying may help)
Transferred:            3 / 3, 100%
Elapsed time:        15.3s

2021/07/29 10:44:42 DEBUG : 32 go routines active
2021/07/29 10:44:42 Failed to copy with 4 errors: last error was: Update ReadFrom failed: file does not exist

Right after the above command, I ran lsl against the same folder:

2021/07/29 10:45:48 DEBUG : rclone: Version "v1.56.0" starting with parameters ["rclone" "-vv" "lsl" "REMOTE:/REMOTE_PATH/testing"]
2021/07/29 10:45:48 DEBUG : Creating backend with remote "REMOTE:/REMOTE_PATH/testing"
2021/07/29 10:45:48 DEBUG : Using config file from "/Users/guyarad/.config/rclone/rclone.conf"
2021/07/29 10:45:52 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:61884->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
   236924 2021-07-29 10:44:00.000000000 file_2.csv.gz
   167635 2021-07-29 10:44:00.000000000 file_5.csv.gz
   205226 2021-07-29 10:44:00.000000000 file_7.csv.gz
2021/07/29 10:45:53 DEBUG : 13 go routines active

ncw · July 29, 2021, 3:05pm

It might be worth checking out

https://rclone.org/sftp/#sftp-disable-concurrent-reads

Do you know what kind of server it is? Can you tell us anything about it?

guyarad · July 30, 2021, 2:24pm

Thanks for your response @ncw
I see these new entries in the logs:

2021/07/30 17:18:54 DEBUG : REMOTE: detected overridden config - adding "{1vybe}" suffix to name
...
2021/07/30 17:18:57 ERROR : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: Ignoring disable_concurrent_reads after library reversion - see #5197

Still the same behavior...
The only thing I know about the server is from the logs, unfortunately: SSH-2.0-9.99 sshlib

ncw · July 31, 2021, 10:54am

The first message is harmless

The second is a spurious message which shouldn't be there! I'll remove that now.

Does the sftp server immediately remove the files or change their permissions?

Rclone likes to check the files have been uploaded properly.

Can you run this beta with the -vv --dump headers flags - it should print more verbose stuff about the sftp connection - hopefully that will help!

v1.56.0-beta.5608.97ade36d8.fix-sftp-debug on branch fix-sftp-debug (uploaded in 15-30 mins)

guyarad · August 1, 2021, 7:09am

Thanks again!
Seems like a very similar behavior. I actually did 2 runs - the first run with the new version actually transferred all the 7 files. The second run yielded the following log (I don't see much more debug information):

2021/08/01 09:56:44 DEBUG : rclone: Version "v1.56.0" starting with parameters ["rclone" "--low-level-retries" "1" "--retries" "1" "-vv" "--dump" "headers" "copy" "/Users/guyarad/Downloads/2021-07-28/chain" "REMOTE:/REMOTE_PATH/testing"]
2021/08/01 09:56:44 DEBUG : Creating backend with remote "/Users/guyarad/Downloads/2021-07-28/chain"
2021/08/01 09:56:44 DEBUG : Using config file from "/Users/guyarad/.config/rclone/rclone.conf"
2021/08/01 09:56:44 DEBUG : Creating backend with remote "REMOTE:/REMOTE_PATH/testing"
2021/08/01 09:56:45 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:56210->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/01 09:56:47 DEBUG : file_3.csv.gz: Modification times differ by 91h45m1.434s: 2021-07-28 14:08:58.566 +0300 IDT, 2021-08-01 09:54:00 +0300 IDT
2021/08/01 09:56:47 DEBUG : file_1.csv.gz: Modification times differ by 91h44m46.09s: 2021-07-28 14:09:13.91 +0300 IDT, 2021-08-01 09:54:00 +0300 IDT
2021/08/01 09:56:47 DEBUG : file_4.csv.gz: Modification times differ by 91h44m45.268s: 2021-07-28 14:09:14.732 +0300 IDT, 2021-08-01 09:54:00 +0300 IDT
2021/08/01 09:56:47 DEBUG : file_2.csv.gz: Modification times differ by 91h44m50.334s: 2021-07-28 14:09:09.666 +0300 IDT, 2021-08-01 09:54:00 +0300 IDT
2021/08/01 09:56:47 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: Waiting for checks to finish
2021/08/01 09:56:47 DEBUG : file_5.csv.gz: Modification times differ by 91h44m56.408s: 2021-07-28 14:09:03.592 +0300 IDT, 2021-08-01 09:54:00 +0300 IDT
2021/08/01 09:56:47 DEBUG : file_6.csv.gz: Modification times differ by 91h44m55.216s: 2021-07-28 14:09:04.784 +0300 IDT, 2021-08-01 09:54:00 +0300 IDT
2021/08/01 09:56:47 DEBUG : file_7.csv.gz: Modification times differ by 91h44m58.041s: 2021-07-28 14:09:01.959 +0300 IDT, 2021-08-01 09:54:00 +0300 IDT
2021/08/01 09:56:47 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: Waiting for transfers to finish
2021/08/01 09:56:48 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:56212->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/01 09:56:48 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:56213->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/01 09:56:48 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: New connection 192.168.0.136:56214->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/01 09:56:49 INFO  : file_3.csv.gz: Copied (replaced existing)
2021/08/01 09:56:51 DEBUG : file_2.csv.gz: Removed after failed upload: file does not exist
2021/08/01 09:56:51 ERROR : file_2.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/01 09:56:51 ERROR : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/testing: Discarding closed SSH connection: ssh: disconnect, reason 11: 
2021/08/01 09:56:51 DEBUG : file_5.csv.gz: Removed after failed upload: connection lost
2021/08/01 09:56:51 ERROR : file_5.csv.gz: Failed to copy: Update ReadFrom failed: connection lost
2021/08/01 09:56:52 DEBUG : file_4.csv.gz: Removed after failed upload: permission denied
2021/08/01 09:56:52 ERROR : file_4.csv.gz: Failed to copy: Update Close failed: permission denied
2021/08/01 09:56:52 INFO  : file_1.csv.gz: Copied (replaced existing)
2021/08/01 09:56:53 DEBUG : file_6.csv.gz: Removed after failed upload: file does not exist
2021/08/01 09:56:53 ERROR : file_6.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/01 09:56:54 INFO  : file_7.csv.gz: Copied (replaced existing)
2021/08/01 09:56:54 ERROR : Attempt 1/1 failed with 4 errors and: Update ReadFrom failed: file does not exist
2021/08/01 09:56:54 INFO  : 
Transferred:   	    2.289Mi / 2.289 MiByte, 100%, 334.963 KiByte/s, ETA 0s
Errors:                 4 (retrying may help)
Checks:                 7 / 7, 100%
Transferred:            3 / 3, 100%
Elapsed time:        10.4s

2021/08/01 09:56:54 DEBUG : 32 go routines active
2021/08/01 09:56:54 Failed to copy with 4 errors: last error was: Update ReadFrom failed: file does not exist

ncw · August 1, 2021, 4:53pm

YOu should have seen some logs like

2021/08/01 17:52:24 DEBUG : sftp://ncw@example.com:22/: > ReadDir: "/home/ncw"
2021/08/01 17:52:26 DEBUG : sftp://ncw@example.com:22/: < ReadDir: []fs.FileInfo{(*sftp.fileInfo)(0xc000780410), (*sftp.fileInfo)(0xc000780460), (*sftp.f

Are you sure you used the right version?

guyarad · August 2, 2021, 6:11am

This is what I used

╭─guyarad@guyarad-mac ~/Downloads/rclone-v1.56.0-beta.5608.97ade36d8.fix-sftp-debug-osx-amd64   21-08-01 17:40:56
╰─$ rclone --low-level-retries 1 --retries 1 -vv --dump headers copy ~/Downloads/2021-07-28/chain REMOTE:/REMOTE_PATH/testing

Ole · August 2, 2021, 8:00am

Please try this from the same folder (and shell) as you performed the above rclone copy:

    rclone version -vv

What does it show?

ivandeex · August 2, 2021, 8:44am

Make sure you run ./rclone, not rclone from path.

guyarad · August 2, 2021, 10:00am

Well, silly me!
@ivandeex was correct - thanks!
Here's the updated output - in this run RCLONE managed to copy 5 of the 7 files (when no files existed on the remote folder):

2021/08/02 12:47:02 DEBUG : rclone: Version "v1.56.0-beta.5608.97ade36d8.fix-sftp-debug" starting with parameters ["./rclone" "--low-level-retries" "1" "--retries" "1" "-vv" "--dump" "headers" "copy" "/Users/guyarad/Downloads/2021-07-28/chain" "REMOTE:/REMOTE_PATH/FOLDER1/testing"]
2021/08/02 12:47:02 DEBUG : Creating backend with remote "/Users/guyarad/Downloads/2021-07-28/chain"
2021/08/02 12:47:02 DEBUG : Using config file from "/Users/guyarad/.config/rclone/rclone.conf"
2021/08/02 12:47:02 DEBUG : Creating backend with remote "REMOTE:/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:04 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:55660->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 12:47:05 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Getwd
2021/08/02 12:47:05 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Getwd: "/REMOTE_PATH", err=<nil>
2021/08/02 12:47:05 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:05 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00047c040)}, err=<nil>
2021/08/02 12:47:05 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:05 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0001260c0)}, err=<nil>
2021/08/02 12:47:05 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > ReadDir: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:06 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < ReadDir: []fs.FileInfo(nil), err=<nil>
2021/08/02 12:47:06 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for checks to finish
2021/08/02 12:47:06 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for transfers to finish
2021/08/02 12:47:06 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:06 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000126180)}, err=<nil>
2021/08/02 12:47:06 DEBUG : file_3.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/02 12:47:06 DEBUG : file_3.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc00090c090), path:"/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 12:47:08 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:55662->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 12:47:08 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:08 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00047c640)}, err=<nil>
2021/08/02 12:47:08 DEBUG : file_4.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/02 12:47:08 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:09 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0000aba80)}, err=<nil>
2021/08/02 12:47:09 DEBUG : file_2.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/02 12:47:09 DEBUG : file_4.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc00090c090), path:"/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz", handle:"\x00\x00\x00\x01", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 12:47:09 DEBUG : file_2.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000ac4090), path:"/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 12:47:09 ERROR : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Discarding closed SSH connection: ssh: disconnect, reason 11: 
2021/08/02 12:47:09 DEBUG : file_3.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/02 12:47:10 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:55663->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 12:47:11 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:11 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:55664->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 12:47:11 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00071c700)}, err=<nil>
2021/08/02 12:47:11 DEBUG : file_1.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/02 12:47:11 DEBUG : file_1.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000710480), path:"/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 12:47:11 DEBUG : file_4.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/02 12:47:12 DEBUG : file_3.csv.gz: < Remove file: err=<nil>
2021/08/02 12:47:12 DEBUG : file_3.csv.gz: Removed after failed upload: permission denied
2021/08/02 12:47:12 ERROR : file_3.csv.gz: Failed to copy: Update Close failed: permission denied
2021/08/02 12:47:12 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:12 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/02 12:47:12 DEBUG : file_4.csv.gz: < Remove file: err=<nil>
2021/08/02 12:47:12 DEBUG : file_4.csv.gz: Removed after failed upload: connection lost
2021/08/02 12:47:12 ERROR : file_4.csv.gz: Failed to copy: Update ReadFrom failed: connection lost
2021/08/02 12:47:12 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_2.csv.gz", size:236924, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763494430, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00047c040)}, err=<nil>
2021/08/02 12:47:12 INFO  : file_2.csv.gz: Copied (new)
2021/08/02 12:47:14 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00047c0c0)}, err=<nil>
2021/08/02 12:47:14 DEBUG : file_5.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/02 12:47:14 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:14 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00081a000)}, err=<nil>
2021/08/02 12:47:14 DEBUG : file_7.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/02 12:47:14 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 12:47:14 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00047c140)}, err=<nil>
2021/08/02 12:47:14 DEBUG : file_6.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/02 12:47:14 DEBUG : file_5.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc00090c240), path:"/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 12:47:14 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/02 12:47:15 DEBUG : file_7.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000710480), path:"/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 12:47:15 DEBUG : file_6.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000ac4090), path:"/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 12:47:16 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/02 12:47:16 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_7.csv.gz", size:205226, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763494434, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00081a480)}, err=<nil>
2021/08/02 12:47:16 INFO  : file_7.csv.gz: Copied (new)
2021/08/02 12:47:16 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/02 12:47:16 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_1.csv.gz", size:695848, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763494433, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0002d56c0)}, err=<nil>
2021/08/02 12:47:16 INFO  : file_1.csv.gz: Copied (new)
2021/08/02 12:47:17 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_6.csv.gz", size:166610, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763494434, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0002d58c0)}, err=<nil>
2021/08/02 12:47:17 INFO  : file_6.csv.gz: Copied (new)
2021/08/02 12:47:17 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/02 12:47:18 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_5.csv.gz", size:167635, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763494435, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00081a4c0)}, err=<nil>
2021/08/02 12:47:18 INFO  : file_5.csv.gz: Copied (new)
2021/08/02 12:47:18 ERROR : Attempt 1/1 failed with 2 errors and: Update ReadFrom failed: connection lost
2021/08/02 12:47:18 INFO  : 
Transferred:   	    2.289Mi / 2.289 MiByte, 100%, 213.056 KiByte/s, ETA 0s
Errors:                 2 (retrying may help)
Transferred:            5 / 5, 100%
Elapsed time:        16.0s

2021/08/02 12:47:18 DEBUG : 32 go routines active
2021/08/02 12:47:18 Failed to copy with 2 errors: last error was: Update ReadFrom failed: connection lost

Ole · August 2, 2021, 10:21am

I am not an SFTP expert, but the errors look somewhat sporadic to me.

I wonder what happens if you repeat the exact same command 3 times in a row.

You can do this by adding the --ignore-times flag, that will make rclone upload all the files each time.

Does the 3 executions give the same result? (the same files failing in the same way)

guyarad · August 2, 2021, 10:32am

The behavior is indeed sporadic and inconsistent. it could upload none or all (all is very rare), and retries don't really help (that's why I removed those, to avoid log clutter).

As I mentioned earlier, using other client, like FileZilla, works fine.

guyarad · August 2, 2021, 10:39am

Another weird thing that's happening - subsequent runs might result in file deletion as well. For example, I ran same command again, adding --ignore-times and it resulted in 2 files uploaded and the other 3 files completely removed:

2021/08/02 13:36:31 DEBUG : rclone: Version "v1.56.0-beta.5608.97ade36d8.fix-sftp-debug" starting with parameters ["./rclone" "--low-level-retries" "1" "--ignore-times" "--retries" "1" "-vv" "--dump" "headers" "copy" "/Users/guyarad/Downloads/2021-07-28/chain" "REMOTE:/REMOTE_PATH/FOLDER1/testing"]
2021/08/02 13:36:31 DEBUG : Creating backend with remote "/Users/guyarad/Downloads/2021-07-28/chain"
2021/08/02 13:36:31 DEBUG : Using config file from "/Users/guyarad/.config/rclone/rclone.conf"
2021/08/02 13:36:31 DEBUG : Creating backend with remote "REMOTE:/REMOTE_PATH/FOLDER1/testing"
2021/08/02 13:36:33 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:56193->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 13:36:34 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Getwd
2021/08/02 13:36:34 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Getwd: "/REMOTE_PATH", err=<nil>
2021/08/02 13:36:34 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 13:36:34 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000b14000)}, err=<nil>
2021/08/02 13:36:34 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 13:36:34 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0007200c0)}, err=<nil>
2021/08/02 13:36:34 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > ReadDir: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 13:36:35 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < ReadDir: []fs.FileInfo{(*sftp.fileInfo)(0xc0006fc000), (*sftp.fileInfo)(0xc0006fc050), (*sftp.fileInfo)(0xc0006fc0a0), (*sftp.fileInfo)(0xc0006fc0f0), (*sftp.fileInfo)(0xc0006fc140)}, err=<nil>
2021/08/02 13:36:35 DEBUG : file_1.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/02 13:36:35 DEBUG : file_5.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/02 13:36:35 DEBUG : file_7.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/02 13:36:35 DEBUG : file_2.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/02 13:36:35 DEBUG : file_6.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/02 13:36:35 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for checks to finish
2021/08/02 13:36:35 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for transfers to finish
2021/08/02 13:36:35 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 13:36:35 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000720200)}, err=<nil>
2021/08/02 13:36:35 DEBUG : file_3.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/02 13:36:35 DEBUG : file_3.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc0001bd170), path:"/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 13:36:36 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:56197->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 13:36:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:56199->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 13:36:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:56198->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 13:36:37 DEBUG : file_1.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/02 13:36:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/02 13:36:37 DEBUG : file_5.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/02 13:36:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00064e000)}, err=<nil>
2021/08/02 13:36:37 DEBUG : file_4.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/02 13:36:37 DEBUG : file_1.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc00039f170), path:"/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 13:36:37 DEBUG : file_5.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000ba0090), path:"/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 13:36:39 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/02 13:36:40 DEBUG : file_4.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc0001bd170), path:"/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz", handle:"\x00\x00\x00\x01", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 13:36:40 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_5.csv.gz", size:167635, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763497398, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0004d7280)}, err=<nil>
2021/08/02 13:36:40 INFO  : file_5.csv.gz: Copied (replaced existing)
2021/08/02 13:36:40 DEBUG : file_7.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/02 13:36:40 DEBUG : file_3.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/02 13:36:40 ERROR : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Discarding closed SSH connection: ssh: disconnect, reason 11: 
2021/08/02 13:36:40 DEBUG : file_4.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/02 13:36:41 DEBUG : file_4.csv.gz: < Remove file: err=&errors.errorString{s:"file does not exist"}
2021/08/02 13:36:41 DEBUG : file_4.csv.gz: Failed to remove: file does not exist
2021/08/02 13:36:41 ERROR : file_4.csv.gz: Failed to copy: Update ReadFrom failed: connection lost
2021/08/02 13:36:41 DEBUG : file_2.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/02 13:36:41 DEBUG : file_2.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000b1c120), path:"/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 13:36:41 DEBUG : file_3.csv.gz: < Remove file: err=<nil>
2021/08/02 13:36:41 DEBUG : file_3.csv.gz: Removed after failed upload: permission denied
2021/08/02 13:36:41 ERROR : file_3.csv.gz: Failed to copy: Update Close failed: permission denied
2021/08/02 13:36:41 DEBUG : file_6.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/02 13:36:43 DEBUG : file_6.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000b1c120), path:"/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz", handle:"\x00\x00\x00\x01", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 13:36:43 DEBUG : file_7.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc00039f170), path:"/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz", handle:"\x00\x00\x00\x01", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/02 13:36:43 DEBUG : file_2.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/02 13:36:43 ERROR : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Discarding closed SSH connection: ssh: disconnect, reason 11: 
2021/08/02 13:36:43 DEBUG : file_6.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/02 13:36:43 DEBUG : file_6.csv.gz: < Remove file: err=0x7
2021/08/02 13:36:43 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Connection failed, closing: connection lost
2021/08/02 13:36:43 DEBUG : file_6.csv.gz: Failed to remove: connection lost
2021/08/02 13:36:43 ERROR : file_6.csv.gz: Failed to copy: Update ReadFrom failed: connection lost
2021/08/02 13:36:44 DEBUG : file_2.csv.gz: < Remove file: err=<nil>
2021/08/02 13:36:44 DEBUG : file_2.csv.gz: Removed after failed upload: permission denied
2021/08/02 13:36:44 ERROR : file_2.csv.gz: Failed to copy: Update Close failed: permission denied
2021/08/02 13:36:45 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:56201->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 13:36:45 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:56202->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/02 13:36:45 DEBUG : file_1.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/02 13:36:45 DEBUG : file_7.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/02 13:36:46 DEBUG : file_1.csv.gz: < Remove file: err=<nil>
2021/08/02 13:36:46 DEBUG : file_1.csv.gz: Removed after failed upload: permission denied
2021/08/02 13:36:46 ERROR : file_1.csv.gz: Failed to copy: Update Close failed: permission denied
2021/08/02 13:36:46 DEBUG : file_7.csv.gz: < Remove file: err=<nil>
2021/08/02 13:36:46 DEBUG : file_7.csv.gz: Removed after failed upload: connection lost
2021/08/02 13:36:46 ERROR : file_7.csv.gz: Failed to copy: Update ReadFrom failed: connection lost
2021/08/02 13:36:46 ERROR : Attempt 1/1 failed with 6 errors and: Update ReadFrom failed: connection lost
2021/08/02 13:36:46 INFO  : 
Transferred:   	    2.289Mi / 2.289 MiByte, 100%, 234.092 KiByte/s, ETA 0s
Errors:                 6 (retrying may help)
Checks:                 5 / 5, 100%
Transferred:            1 / 1, 100%
Elapsed time:        14.6s

2021/08/02 13:36:46 DEBUG : 32 go routines active
2021/08/02 13:36:46 Failed to copy with 6 errors: last error was: Update ReadFrom failed: connection lost

Ole · August 2, 2021, 10:49am

It could be a network or a race/concurrency issue.

What happens if you remove --low-level-retries 1 and add --checkers 1 --transfers 1 instead?

guyarad · August 3, 2021, 10:11pm

@Ole
I don't think it's network related. As I said, with FileZilla upload works perfectly (and fast) with simultaneous connections. These are the new logs with modified args:

2021/08/04 01:02:06 DEBUG : rclone: Version "v1.56.0-beta.5608.97ade36d8.fix-sftp-debug" starting with parameters ["./rclone" "--ignore-times" "-vv" "--dump" "headers" "--checkers" "1" "--transfers" "1" "copy" "/Users/guyarad/Downloads/2021-07-28/chain" "REMOTE:/REMOTE_PATH/FOLDER1/testing"]
2021/08/04 01:02:06 DEBUG : Creating backend with remote "/Users/guyarad/Downloads/2021-07-28/chain"
2021/08/04 01:02:06 DEBUG : Using config file from "/Users/guyarad/.config/rclone/rclone.conf"
2021/08/04 01:02:06 DEBUG : Creating backend with remote "REMOTE:/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:08 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: New connection 192.168.0.136:57118->111.2.3.4:22 to "SSH-2.0-9.99 sshlib"
2021/08/04 01:02:09 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Getwd
2021/08/04 01:02:09 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Getwd: "/REMOTE_PATH", err=<nil>
2021/08/04 01:02:09 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:09 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000718000)}, err=<nil>
2021/08/04 01:02:09 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:09 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000838080)}, err=<nil>
2021/08/04 01:02:09 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > ReadDir: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:10 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < ReadDir: []fs.FileInfo(nil), err=<nil>
2021/08/04 01:02:10 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for checks to finish
2021/08/04 01:02:10 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for transfers to finish
2021/08/04 01:02:10 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:10 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000718040)}, err=<nil>
2021/08/04 01:02:10 DEBUG : file_3.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/04 01:02:11 DEBUG : file_3.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:16 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/04 01:02:17 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_3.csv.gz", size:266120, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624932, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0007a2240)}, err=<nil>
2021/08/04 01:02:17 INFO  : file_3.csv.gz: Copied (new)
2021/08/04 01:02:17 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:18 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0007a2280)}, err=<nil>
2021/08/04 01:02:18 DEBUG : file_2.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/04 01:02:18 DEBUG : file_2.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:21 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/04 01:02:21 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_2.csv.gz", size:236924, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624937, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00025f780)}, err=<nil>
2021/08/04 01:02:21 INFO  : file_2.csv.gz: Copied (new)
2021/08/04 01:02:21 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:21 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00025f900)}, err=<nil>
2021/08/04 01:02:21 DEBUG : file_4.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/04 01:02:22 DEBUG : file_4.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:27 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/04 01:02:27 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_4.csv.gz", size:662156, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624943, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0008384c0)}, err=<nil>
2021/08/04 01:02:27 INFO  : file_4.csv.gz: Copied (new)
2021/08/04 01:02:27 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:28 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000838500)}, err=<nil>
2021/08/04 01:02:28 DEBUG : file_1.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/04 01:02:28 DEBUG : file_1.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:30 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/04 01:02:31 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_1.csv.gz", size:695848, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624947, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0004d4800)}, err=<nil>
2021/08/04 01:02:31 INFO  : file_1.csv.gz: Copied (new)
2021/08/04 01:02:31 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:31 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0004d4880)}, err=<nil>
2021/08/04 01:02:31 DEBUG : file_5.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/04 01:02:32 DEBUG : file_5.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz", handle:"\x00\x00\x00\x00", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:32 DEBUG : file_5.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/04 01:02:32 DEBUG : file_5.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:32 DEBUG : file_5.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:32 ERROR : file_5.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:32 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:33 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0007a2180)}, err=<nil>
2021/08/04 01:02:33 DEBUG : file_6.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/04 01:02:33 DEBUG : file_6.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz", handle:"\x00\x00\x00\x01", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:33 DEBUG : file_6.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/04 01:02:34 DEBUG : file_6.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:34 DEBUG : file_6.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:34 ERROR : file_6.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:34 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:35 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc00025f040)}, err=<nil>
2021/08/04 01:02:35 DEBUG : file_7.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/04 01:02:35 DEBUG : file_7.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz", handle:"\x00\x00\x00\x02", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:36 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/04 01:02:36 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_7.csv.gz", size:205226, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624952, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000690100)}, err=<nil>
2021/08/04 01:02:36 INFO  : file_7.csv.gz: Copied (new)
2021/08/04 01:02:36 ERROR : Attempt 1/3 failed with 2 errors and: Update ReadFrom failed: file does not exist
2021/08/04 01:02:36 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:36 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000690200)}, err=<nil>
2021/08/04 01:02:36 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > ReadDir: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < ReadDir: []fs.FileInfo{(*sftp.fileInfo)(0xc000a8e190), (*sftp.fileInfo)(0xc000a8e1e0), (*sftp.fileInfo)(0xc000a8e230), (*sftp.fileInfo)(0xc000a8e280), (*sftp.fileInfo)(0xc000a8e2d0)}, err=<nil>
2021/08/04 01:02:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for checks to finish
2021/08/04 01:02:37 DEBUG : file_3.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:37 DEBUG : file_2.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:37 DEBUG : file_4.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:37 DEBUG : file_1.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:37 DEBUG : file_7.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for transfers to finish
2021/08/04 01:02:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:37 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000690240)}, err=<nil>
2021/08/04 01:02:37 DEBUG : file_5.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/04 01:02:38 DEBUG : file_5.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz", handle:"\x00\x00\x00\x02", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:38 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/04 01:02:39 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_5.csv.gz", size:167635, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624955, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000690340)}, err=<nil>
2021/08/04 01:02:39 INFO  : file_5.csv.gz: Copied (new)
2021/08/04 01:02:39 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:39 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000690380)}, err=<nil>
2021/08/04 01:02:39 DEBUG : file_6.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/04 01:02:39 DEBUG : file_6.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz", handle:"\x00\x00\x00\x02", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:40 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/04 01:02:40 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_6.csv.gz", size:166610, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624956, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0004d4e40)}, err=<nil>
2021/08/04 01:02:40 INFO  : file_6.csv.gz: Copied (new)
2021/08/04 01:02:40 DEBUG : file_3.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/04 01:02:40 DEBUG : file_3.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz", handle:"\x00\x00\x00\x02", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:41 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/04 01:02:42 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_3.csv.gz", size:266120, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624957, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0007a2880)}, err=<nil>
2021/08/04 01:02:42 INFO  : file_3.csv.gz: Copied (replaced existing)
2021/08/04 01:02:42 DEBUG : file_2.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/04 01:02:42 DEBUG : file_2.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz", handle:"\x00\x00\x00\x02", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:42 DEBUG : file_2.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/04 01:02:43 DEBUG : file_2.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:43 DEBUG : file_2.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:43 ERROR : file_2.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:43 DEBUG : file_4.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/04 01:02:43 DEBUG : file_4.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz", handle:"\x00\x00\x00\x03", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:43 DEBUG : file_4.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/04 01:02:44 DEBUG : file_4.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:44 DEBUG : file_4.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:44 ERROR : file_4.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:44 DEBUG : file_1.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/04 01:02:44 DEBUG : file_1.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz", handle:"\x00\x00\x00\x04", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:45 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/04 01:02:45 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_1.csv.gz", size:695848, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624961, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0007224c0)}, err=<nil>
2021/08/04 01:02:45 INFO  : file_1.csv.gz: Copied (replaced existing)
2021/08/04 01:02:45 DEBUG : file_7.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/04 01:02:46 DEBUG : file_7.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz", handle:"\x00\x00\x00\x04", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:47 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat file: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/04 01:02:47 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat file: &sftp.fileInfo{name:"file_7.csv.gz", size:205226, mode:0x1ff, mtime:time.Time{wall:0x0, ext:63763624963, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0007225c0)}, err=<nil>
2021/08/04 01:02:47 INFO  : file_7.csv.gz: Copied (replaced existing)
2021/08/04 01:02:47 ERROR : Attempt 2/3 failed with 2 errors and: Update ReadFrom failed: file does not exist
2021/08/04 01:02:47 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:47 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0008384c0)}, err=<nil>
2021/08/04 01:02:47 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > ReadDir: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:48 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < ReadDir: []fs.FileInfo{(*sftp.fileInfo)(0xc00025b360), (*sftp.fileInfo)(0xc00025b450), (*sftp.fileInfo)(0xc00025b4a0), (*sftp.fileInfo)(0xc00025b4f0), (*sftp.fileInfo)(0xc00025b540)}, err=<nil>
2021/08/04 01:02:48 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for checks to finish
2021/08/04 01:02:48 DEBUG : file_3.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:48 DEBUG : file_1.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:48 DEBUG : file_5.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:48 DEBUG : file_6.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:48 DEBUG : file_7.csv.gz: Transferring unconditionally as --ignore-times is in use
2021/08/04 01:02:48 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: Waiting for transfers to finish
2021/08/04 01:02:48 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:48 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc0004d5600)}, err=<nil>
2021/08/04 01:02:48 DEBUG : file_2.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/04 01:02:49 DEBUG : file_2.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz", handle:"\x00\x00\x00\x04", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:49 DEBUG : file_2.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_2.csv.gz"
2021/08/04 01:02:50 DEBUG : file_2.csv.gz: < Remove file: err=&errors.errorString{s:"file does not exist"}
2021/08/04 01:02:50 DEBUG : file_2.csv.gz: Failed to remove: file does not exist
2021/08/04 01:02:50 ERROR : file_2.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:50 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: > Stat dirExists: "/REMOTE_PATH/FOLDER1/testing"
2021/08/04 01:02:50 DEBUG : sftp://SFTP_USER@SFTP_HOST:22//REMOTE_PATH/FOLDER1/testing: < Stat dirExists: &sftp.fileInfo{name:"testing", size:0, mode:0x800001c9, mtime:time.Time{wall:0x0, ext:63763091760, loc:(*time.Location)(0x6a81860)}, sys:(*sftp.FileStat)(0xc000722900)}, err=<nil>
2021/08/04 01:02:50 DEBUG : file_4.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/04 01:02:50 DEBUG : file_4.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz", handle:"\x00\x00\x00\x05", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:51 DEBUG : file_4.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_4.csv.gz"
2021/08/04 01:02:52 DEBUG : file_4.csv.gz: < Remove file: err=&errors.errorString{s:"file does not exist"}
2021/08/04 01:02:52 DEBUG : file_4.csv.gz: Failed to remove: file does not exist
2021/08/04 01:02:52 ERROR : file_4.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:52 DEBUG : file_3.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/04 01:02:52 DEBUG : file_3.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz", handle:"\x00\x00\x00\x06", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:52 DEBUG : file_3.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_3.csv.gz"
2021/08/04 01:02:54 DEBUG : file_3.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:54 DEBUG : file_3.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:54 ERROR : file_3.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:54 DEBUG : file_1.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/04 01:02:54 DEBUG : file_1.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz", handle:"\x00\x00\x00\a", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:54 DEBUG : file_1.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_1.csv.gz"
2021/08/04 01:02:55 DEBUG : file_1.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:55 DEBUG : file_1.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:55 ERROR : file_1.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:55 DEBUG : file_5.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/04 01:02:55 DEBUG : file_5.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz", handle:"\x00\x00\x00\b", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:55 DEBUG : file_5.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_5.csv.gz"
2021/08/04 01:02:56 DEBUG : file_5.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:56 DEBUG : file_5.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:56 ERROR : file_5.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:56 DEBUG : file_6.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/04 01:02:56 DEBUG : file_6.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz", handle:"\x00\x00\x00\t", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:56 DEBUG : file_6.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_6.csv.gz"
2021/08/04 01:02:57 DEBUG : file_6.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:57 DEBUG : file_6.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:57 ERROR : file_6.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:57 DEBUG : file_7.csv.gz: > OpenFile write: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/04 01:02:57 DEBUG : file_7.csv.gz: < OpenFile write: &sftp.File{c:(*sftp.Client)(0xc000836120), path:"/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz", handle:"\x00\x00\x00\n", mu:sync.Mutex{state:0, sema:0x0}, offset:0}, err=<nil>
2021/08/04 01:02:57 DEBUG : file_7.csv.gz: > Remove file: "/REMOTE_PATH/FOLDER1/testing/file_7.csv.gz"
2021/08/04 01:02:57 DEBUG : file_7.csv.gz: < Remove file: err=<nil>
2021/08/04 01:02:57 DEBUG : file_7.csv.gz: Removed after failed upload: file does not exist
2021/08/04 01:02:57 ERROR : file_7.csv.gz: Failed to copy: Update ReadFrom failed: file does not exist
2021/08/04 01:02:57 ERROR : Attempt 3/3 failed with 7 errors and: Update ReadFrom failed: file does not exist
2021/08/04 01:02:57 INFO  : 
Transferred:   	    6.868Mi / 6.868 MiByte, 100%, 196.431 KiByte/s, ETA 0s
Errors:                 7 (retrying may help)
Checks:                10 / 10, 100%
Transferred:           10 / 10, 100%
Elapsed time:        51.3s

2021/08/04 01:02:57 DEBUG : 14 go routines active
2021/08/04 01:02:57 Failed to copy with 7 errors: last error was: Update ReadFrom failed: file does not exist

Ole · August 4, 2021, 7:32pm

Thanks, nice little and easy to read example, but I still see no trace of the root cause

I will soon call in the cavalry (ncw and others) but before that I suggest you try the exact same where you also add:

--sftp-disable-concurrent-writes --sftp-disable-concurrent-reads

and finally one where you try:

--sftp-disable-concurrent-writes --sftp-use-fstat

You can see all the SFTP parameters here: https://rclone.org/sftp/

guyarad · August 4, 2021, 11:34pm

Pretty sure I've already tried but gave it another shot and the following combination actually works consistently.

Config

[REMOTE]
type = sftp
host = SFTP_HOST
user = SFTP_USER
port = 22
pass = ****
set_modtime = false
disable_concurrent_writes = true

Arguments

--transfers 1

Open questions

How can I make it work with parallel transfers? FileZilla does transfer files in parallel. Otherwise, it slows things significantly.
Running RCLONE copy again copies all the files all over again (even though ignore-times is not used). I'm guessing the root-cause is set-modtime=false. How can I use file size only?

Thanks for all your help so far!

Ole · August 5, 2021, 8:06am

That is really hard (if not impossible) to answer without knowing the SFTP server or root cause of the issue. This is the approach I would take in your situation:

First, I would try to get as close to rclone default parameters as possible while maintaining stability. That is systematically test whether it is possible remove --transfers=1 and/or set_modtime=false.

Then I would systematically test the effect of changing --checkers and --transfers. This tuning is highly influenced by the characteristics of your data and usage pattern. I therefore monitor over a longer period and then gradually tune until I find optimum (for the given task).

You can use --size-only (be aware of the risk of files modified without a change in size).

If your SFTP server supports checksums, then --checksum may be a more reliable alternative.

You can find an overview of all the flags here: https://rclone.org/flags/ and a detailed explanation here: https://rclone.org/docs/

You are welcome, glad we managed to find a stable config

guyarad · August 6, 2021, 7:14am

Thanks!
Regarding the parallelism of transfers - it seems to me that RCLONE might be doing something wrong in the way it creates the connections to the target SFTP. The reason for speculating that is the fact that FileZilla is successfully transferring multiple files in parallel (10 transfers simultaneously), and doing it pretty quickly.

ivandeex · August 6, 2021, 8:05am

That's possible. FileZilla supports only FTP/SFTP connections so they can polish these two to perfection.