What is the problem you are having with rclone?
Situation:
- RClone mount (via fstab) that uses FTP backend with explicit TLS
- Backend is a Synology NAS (lftp server)
- Most files are handled exact the way that is expected
Problem:
- Sometimes a file does not get transferred. Like I have on now that is used for further descriptions. In the attached logs you will find the following:
- The file export-2023-02-28_backup_3.zip was created locally and is not yet transferred to ftp://192.168.2.102:21/dms_backup
- To force some reactions the file export-2023-02-28_backup_3.zip is copied locally to export20230228backup3.zip.
- After the transfer began there was an error (see logs below) followed by ongoing errors for every new transfer-attempt.
When I connect to the FTP backend with Filezilla in the meanwhile there is a short timeframe when both files seem to be present at the backend:
My interpretation of this obervation and the logs is that the files are really stored temporarily and then get deleted afterwards.
Run the command 'rclone version' and share the full output of the command.
rclone v1.61.0
- os/version: debian 11.5 (64 bit)
- os/kernel: 5.15.64-1-pve (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.19.4
- go/linking: static
- go/tags: none
Which cloud storage system are you using? (eg Google Drive)
FTP with explicit TLS on local Synology
The command you were trying to run (eg rclone copy /tmp remote:tmp
)
fstab mount
The rclone config contents with secrets removed.
[nas_dms]
type = ftp
host = 192.168.2.102
user = ....
pass = ...
explicit_tls = true
no_check_certificate = true
A log from the command with the -vv
flag
Log when the file was freshly copied:
[...]
2023/03/03 13:21:10 DEBUG : &{export20230228backup3.zip (rw)}: >Write: written=112983, err=<nil>
2023/03/03 13:21:10 DEBUG : &{export20230228backup3.zip (rw)}: Flush:
2023/03/03 13:21:10 DEBUG : export20230228backup3.zip(0xc000359a80): RWFileHandle.Flush
2023/03/03 13:21:10 DEBUG : &{export20230228backup3.zip (rw)}: >Flush: err=<nil>
2023/03/03 13:21:10 DEBUG : &{export20230228backup3.zip (rw)}: Release:
2023/03/03 13:21:10 DEBUG : &{export-2023-02-28_backup_3.zip (rw)}: Flush:
2023/03/03 13:21:10 DEBUG : export20230228backup3.zip(0xc000359a80): RWFileHandle.Release
2023/03/03 13:21:10 DEBUG : export-2023-02-28_backup_3.zip(0xc000359980): RWFileHandle.Flush
2023/03/03 13:21:10 DEBUG : export20230228backup3.zip(0xc000359a80): close:
2023/03/03 13:21:10 DEBUG : &{export-2023-02-28_backup_3.zip (rw)}: >Flush: err=<nil>
2023/03/03 13:21:10 DEBUG : &{export-2023-02-28_backup_3.zip (rw)}: Release:
2023/03/03 13:21:10 DEBUG : export-2023-02-28_backup_3.zip(0xc000359980): RWFileHandle.Release
2023/03/03 13:21:10 DEBUG : export-2023-02-28_backup_3.zip(0xc000359980): close:
2023/03/03 13:21:10 DEBUG : vfs cache: looking for range={Pos:0 Size:21608791} in [{Pos:0 Size:21608791}] - present true
2023/03/03 13:21:10 DEBUG : export20230228backup3.zip: vfs cache: setting modification time to 2023-03-03 13:21:10.672726844 +0100 CET m=+16552.994441777
2023/03/03 13:21:10 INFO : export20230228backup3.zip: vfs cache: queuing for upload in 5s
2023/03/03 13:21:10 DEBUG : export-2023-02-28_backup_3.zip: vfs cache: setting modification time to 2023-03-03 13:09:17.600887116 +0100 CET m=+15839.922602049
2023/03/03 13:21:10 INFO : export-2023-02-28_backup_3.zip: vfs cache: queuing for upload in 5s
2023/03/03 13:21:10 DEBUG : export-2023-02-28_backup_3.zip(0xc000359980): >close: err=<nil>
2023/03/03 13:21:10 DEBUG : &{export-2023-02-28_backup_3.zip (rw)}: >Release: err=<nil>
2023/03/03 13:21:10 DEBUG : export20230228backup3.zip(0xc000359a80): >close: err=<nil>
2023/03/03 13:21:10 DEBUG : &{export20230228backup3.zip (rw)}: >Release: err=<nil>
2023/03/03 13:21:12 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item export-2023-02-28_backup.zip not removed, freed 0 bytes
2023/03/03 13:21:12 INFO : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 20.608Mi (was 20.608Mi)
2023/03/03 13:21:15 DEBUG : export-2023-02-28_backup_3.zip: vfs cache: starting upload
2023/03/03 13:21:15 DEBUG : export20230228backup3.zip: vfs cache: starting upload
2023/03/03 13:21:15 DEBUG : ftp://192.168.2.102:21/dms_backup: Connecting to FTP server
2023/03/03 13:21:15 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:21")
2023/03/03 13:21:15 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/03/03 13:21:15 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:55884")
2023/03/03 13:21:15 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*tls.Conn, err=<nil>
2023/03/03 13:21:15 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:55733")
2023/03/03 13:21:15 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*tls.Conn, err=<nil>
2023/03/03 13:21:16 DEBUG : ftp://192.168.2.102:21/dms_backup: Connecting to FTP server
2023/03/03 13:21:16 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:21")
2023/03/03 13:21:16 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/03/03 13:21:17 DEBUG : export-2023-02-28_backup_3.zip: Removed after failed upload: 1 error occurred:
2023/03/03 13:21:17 ERROR : export-2023-02-28_backup_3.zip: Failed to copy: update stor: 1 error occurred:
2023/03/03 13:21:17 ERROR : export-2023-02-28_backup_3.zip: vfs cache: failed to upload try #8, will retry in 5m0s: vfs cache: failed to transfer file from cache to remote: update stor: 1 error occurred:
2023/03/03 13:21:17 DEBUG : export20230228backup3.zip: Removed after failed upload: 1 error occurred:
2023/03/03 13:21:17 ERROR : export20230228backup3.zip: Failed to copy: update stor: 1 error occurred:
2023/03/03 13:21:17 ERROR : export20230228backup3.zip: vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: update stor: 1 error occurred:
2023/03/03 13:21:17 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item export20230228backup3.zip not removed, freed 0 bytes
2023/03/03 13:21:17 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item export20230228backup3.zip not removed, freed 0 bytes
2023/03/03 13:21:17 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item export-2023-02-28_backup.zip not removed, freed 0 bytes
2023/03/03 13:21:17 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item export-2023-02-28_backup_3.zip not removed, freed 0 bytes
2023/03/03 13:21:17 INFO : vfs cache: cleaned: objects 4 (was 4) in use 4, to upload 4, uploading 0, total size 82.431Mi (was 82.431Mi)
2023/03/03 13:21:20 DEBUG : : Statfs:
2023/03/03 13:21:20 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/03/03 13:21:27 DEBUG : export20230228backup3.zip: vfs cache: starting upload
2023/03/03 13:21:27 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:55740")
2023/03/03 13:21:27 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*tls.Conn, err=<nil>
2023/03/03 13:21:28 DEBUG : ftp://192.168.2.102:21/dms_backup: Connecting to FTP server
2023/03/03 13:21:28 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:21")
2023/03/03 13:21:28 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/03/03 13:21:28 DEBUG : export20230228backup3.zip: Removed after failed upload: 1 error occurred:
2023/03/03 13:21:28 ERROR : export20230228backup3.zip: Failed to copy: update stor: 1 error occurred:
2023/03/03 13:21:28 ERROR : export20230228backup3.zip: vfs cache: failed to upload try #2, will retry in 20s: vfs cache: failed to transfer file from cache to remote: update stor: 1 error occurred:
2023/03/03 13:21:48 DEBUG : export20230228backup3.zip: vfs cache: starting upload
2023/03/03 13:21:48 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:55616")
2023/03/03 13:21:48 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*tls.Conn, err=<nil>
2023/03/03 13:21:49 DEBUG : ftp://192.168.2.102:21/dms_backup: Connecting to FTP server
2023/03/03 13:21:49 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:21")
2023/03/03 13:21:49 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/03/03 13:21:49 DEBUG : export20230228backup3.zip: Removed after failed upload: 1 error occurred:
2023/03/03 13:21:49 ERROR : export20230228backup3.zip: Failed to copy: update stor: 1 error occurred:
2023/03/03 13:21:49 ERROR : export20230228backup3.zip: vfs cache: failed to upload try #3, will retry in 40s: vfs cache: failed to transfer file from cache to remote: update stor: 1 error occurred:
2023/03/03 13:21:50 DEBUG : : Statfs:
2023/03/03 13:21:50 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
Repeated errors after the file was copied:
2023/03/03 15:41:50 DEBUG : export-2023-02-28_backup_3.zip: vfs cache: starting upload
2023/03/03 15:41:50 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:55896")
2023/03/03 15:41:50 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*tls.Conn, err=<nil>
2023/03/03 15:41:50 DEBUG : : Statfs:
2023/03/03 15:41:50 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/03/03 15:41:51 DEBUG : ftp://192.168.2.102:21/dms_backup: Connecting to FTP server
2023/03/03 15:41:51 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:21")
2023/03/03 15:41:51 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/03/03 15:41:51 DEBUG : export-2023-02-28_backup_3.zip: Removed after failed upload: 1 error occurred:
* 426 Data connection: No such file or directory.
2023/03/03 15:41:51 ERROR : export-2023-02-28_backup_3.zip: Failed to copy: update stor: 1 error occurred:
* 426 Data connection: No such file or directory.
2023/03/03 15:41:51 ERROR : export-2023-02-28_backup_3.zip: vfs cache: failed to upload try #36, will retry in 5m0s: vfs cache: failed to transfer file from cache to remote: update stor: 1 error occurred:
* 426 Data connection: No such file or directory.
2023/03/03 15:42:05 DEBUG : export20230228backup3.zip: vfs cache: starting upload
2023/03/03 15:42:05 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:55810")
2023/03/03 15:42:05 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*tls.Conn, err=<nil>
2023/03/03 15:42:06 DEBUG : ftp://192.168.2.102:21/dms_backup: Connecting to FTP server
2023/03/03 15:42:06 DEBUG : ftp://192.168.2.102:21/dms_backup: dial("tcp","192.168.2.102:21")
2023/03/03 15:42:06 DEBUG : ftp://192.168.2.102:21/dms_backup: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/03/03 15:42:06 DEBUG : export20230228backup3.zip: Removed after failed upload: 1 error occurred:
* 426 Data connection: No such file or directory.