Rclone serve sftp how to avoid to store incomplete transferred files?

Help and Support
1

Hello,

I'm experimenting the rclone serve feature and I face an issue that documentation has not permitted me to process.

What is the problem you are having with rclone?

rclone serve store incomplete transferred files

What is your rclone version (output from rclone version)

rclone v1.53.3

  • os/arch: linux/amd64
  • go version: go1.15.5

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

linux amd64 debian stable
linux amd64 oracle 7

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

local is probably the correct answer (but not sure because fs is emulated by fuse)

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

On a server, I'm running :

rclone serve sftp /__served_path__ \
  -v --bwlimit 1400k --stats 2h \
  --addr  --user  --pass \
  --vfs-cache-mode writes --cache-dir /__path_vfs-cache__ --vfs-write-back 2h

/served_path can be considered as a local path

On a client with some data to backup, I'm running :

rclone \
    --sftp-host __host__ --sftp-port __port__ --sftp-user __user__ --sftp-pass __password_obscured__ \
    sync /__path_to_data__ :sftp:test_sync_20210121/ \
    -v --bwlimit 80k --max-delete 2 --transfers 1 --checkers 1 --stats 20m \
    --track-renames --track-renames-strategy leaf ---size-only --fast-list --max-transfer 300M --cutoff-mode=soft \
    --delete-after --delete-excluded

I'm not sure that --fast-list is supported/interesting for sftp backend, but no error reported

The rclone config contents with secrets removed.

empty config because parameters are on the command line

If I interrupt the rclone sync with Ctrl+C, the server will save an incomplete file.
I managed to delay the write action to backend by using "--vfs-write-back 2h".
But I will have preferred to delay until file has been completely received and checked.

As I killed the rclone sync process, the file cannot be complete and valid. I believe that chunks have been integrity checked.
Is it possible to prevent any store of incomplete transferred file ?

I can change from sftp protocol to another, but my readings let me think that sftp is the one which is the most featured.

I may be wrong but, webdav from nextcloud/owncloud has a feature like that (checksum on remote).

Regards,
Serge

rclone sync log

2021/01/22 13:48:10 INFO  : Starting bandwidth limiter at 80kBytes/s
2021/01/22 13:48:15 INFO  : sftp://__hidden_credentials__/test_sync_20210121/: Making map for --track-renames
2021/01/22 13:48:15 INFO  : sftp://__hidden_credentials__/test_sync_20210121/: Finished making map for --track-renames
2021/01/22 13:48:20 INFO  : 
Transferred:   	      860k / 9.668 MBytes, 9%, 93.068 kBytes/s, ETA 1m37s
Checks:                20 / 20, 100%
Transferred:            0 / 3, 0%
Elapsed time:        10.5s
Transferring:
 *                 L1c/1_Un_automne_avec_Pop.mp3: 19% /4.234M, 91.996k/s, 37s

2021/01/22 13:48:30 INFO  : 
Transferred:   	    1.621M / 9.668 MBytes, 17%, 86.276 kBytes/s, ETA 1m35s
Checks:                20 / 20, 100%
Transferred:            0 / 3, 0%
Elapsed time:        20.5s
Transferring:
 *                 L1c/1_Un_automne_avec_Pop.mp3: 38% /4.234M, 85.441k/s, 31s
^C

rclone serve log

2021/01/22 12:44:17 DEBUG : Creating backend with remote "__served_path__"
2021/01/22 12:44:17 DEBUG : Using config file from "/dev/null"
2021/01/22 12:44:17 INFO  : Starting bandwidth limiter at 1.367MBytes/s
2021/01/22 12:44:17 INFO  : Local file system at __served_path__: poll-interval is not supported by this remote
2021/01/22 12:44:17 DEBUG : vfs cache: root is "/__path_vfs-cache__/vfs/local/__served_path__"
2021/01/22 12:44:17 DEBUG : vfs cache: metadata root is "/__path_vfs-cache__/vfs/local/__served_path__"
2021/01/22 12:44:17 DEBUG : Creating backend with remote "/__path_vfs-cache__/vfs/local/__served_path__"
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1c: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1/L2bb: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1/L2/L3aa: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1/L2/L3/L4/L5/L6: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1/L2/L3/L4/L5: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1/L2/L3/L4: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1/L2/L3: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1/L2: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121/L1: Removing directory
2021/01/22 12:44:17 DEBUG : test_sync_20210121: Removing directory
2021/01/22 12:44:17 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/01/22 12:44:17 NOTICE: Loaded 2 authorized keys from "/home/__user__/.ssh/authorized_keys"
2021/01/22 12:44:17 DEBUG : Loaded private key from "__path_vfs-cache__/serve-sftp/id_rsa"
2021/01/22 12:44:17 NOTICE: SFTP server listening on [::]:8022
2021/01/22 12:45:17 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)


2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: ssh auth "none" from "SSH-2.0-rclone/v1.53.3": ssh: no auth passed yet
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Password login attempt for bcs_sftp
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: ssh auth "password" from "SSH-2.0-rclone/v1.53.3": OK
2021/01/22 12:48:10 INFO  : serve sftp __ip__:44958->10.0.0.2:8022: SSH login from bcs_sftp using SSH-2.0-rclone/v1.53.3
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Incoming channel: session
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Channel accepted
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Request: subsystem
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Subsystem: sftp
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022:  - accepted: true
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Starting SFTP server
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Incoming channel: session
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Channel accepted
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Request: exec
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022:  - accepted: true
2021/01/22 12:48:10 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: exec command: binary = "md5sum", args = ""
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Incoming channel: session
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Channel accepted
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: Request: exec
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022:  - accepted: true
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: exec command: binary = "sha1sum", args = ""
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: ssh auth "none" from "SSH-2.0-rclone/v1.53.3": ssh: no auth passed yet
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: Password login attempt for bcs_sftp
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: ssh auth "password" from "SSH-2.0-rclone/v1.53.3": OK
2021/01/22 12:48:11 INFO  : serve sftp __ip__:44962->10.0.0.2:8022: SSH login from bcs_sftp using SSH-2.0-rclone/v1.53.3
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: Incoming channel: session
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: Channel accepted
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: Request: subsystem
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: Subsystem: sftp
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022:  - accepted: true
2021/01/22 12:48:11 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: Starting SFTP server
2021/01/22 12:48:12 DEBUG : /test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: newRWFileHandle: 
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): openPending: 
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: truncate to size=1110016
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c: Added virtual directory entry vAdd: "1_Un_automne_avec_Pop.mp3"
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >openPending: err=<nil>
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: truncate to size=0
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: cancelling writeback (uploading false) 0xc00029a150 item 1
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: >newRWFileHandle: err=<nil>
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c: Added virtual directory entry vAdd: "1_Un_automne_avec_Pop.mp3"
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: >Open: fd=test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3 (rw), err=<nil>
2021/01/22 12:48:12 DEBUG : /test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: >OpenFile: fd=test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3 (rw), err=<nil>
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=4096, off=0
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=4096, err=<nil>
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=8192, off=4096
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=8192, err=<nil>
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=16384, off=12288
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=16384, err=<nil>
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=28672
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=61440
2021/01/22 12:48:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:13 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=94208
2021/01/22 12:48:13 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:13 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=126976
2021/01/22 12:48:13 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:13 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=159744
2021/01/22 12:48:13 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:14 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=192512
2021/01/22 12:48:14 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:14 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=225280
2021/01/22 12:48:14 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:14 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=258048
2021/01/22 12:48:14 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:15 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=290816
2021/01/22 12:48:15 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:15 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=323584
2021/01/22 12:48:15 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:15 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=356352
2021/01/22 12:48:15 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:15 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=389120
2021/01/22 12:48:15 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:16 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=421888
2021/01/22 12:48:16 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:16 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=454656
2021/01/22 12:48:16 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:17 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=487424
2021/01/22 12:48:17 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:17 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=520192
2021/01/22 12:48:17 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:17 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3 not removed, freed 0 bytes
2021/01/22 12:48:17 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 540k (was 540k)
2021/01/22 12:48:17 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=552960
2021/01/22 12:48:17 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:18 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=585728
2021/01/22 12:48:18 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:18 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=618496
2021/01/22 12:48:18 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:19 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=651264
2021/01/22 12:48:19 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:19 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=684032
2021/01/22 12:48:19 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:19 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=716800
2021/01/22 12:48:19 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:20 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=749568
2021/01/22 12:48:20 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:20 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=782336
2021/01/22 12:48:20 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:21 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=815104
2021/01/22 12:48:21 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:21 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=847872
2021/01/22 12:48:21 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:21 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=880640
2021/01/22 12:48:21 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:22 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=913408
2021/01/22 12:48:22 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:22 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=946176
2021/01/22 12:48:22 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:23 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=978944
2021/01/22 12:48:23 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:23 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1011712
2021/01/22 12:48:23 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:23 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1044480
2021/01/22 12:48:23 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:24 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1077248
2021/01/22 12:48:24 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:24 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1110016
2021/01/22 12:48:24 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:25 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1142784
2021/01/22 12:48:25 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:25 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1175552
2021/01/22 12:48:25 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:25 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1208320
2021/01/22 12:48:25 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:26 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1241088
2021/01/22 12:48:26 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:26 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1273856
2021/01/22 12:48:26 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:27 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1306624
2021/01/22 12:48:27 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:27 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1339392
2021/01/22 12:48:27 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:27 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1372160
2021/01/22 12:48:27 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:28 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1404928
2021/01/22 12:48:28 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:28 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1437696
2021/01/22 12:48:28 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:29 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1470464
2021/01/22 12:48:29 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:29 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1503232
2021/01/22 12:48:29 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:29 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1536000
2021/01/22 12:48:29 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:30 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1568768
2021/01/22 12:48:30 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:30 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1601536
2021/01/22 12:48:30 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:31 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): _writeAt: size=32768, off=1634304
2021/01/22 12:48:31 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >_writeAt: n=32768, err=<nil>
2021/01/22 12:48:31 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): close: 
2021/01/22 12:48:31 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: setting modification time to 2021-01-22 12:48:31.037547223 +0000 GMT m=+253.440625353
2021/01/22 12:48:31 INFO  : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: queuing for upload in 2h0m0s
2021/01/22 12:48:31 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0000a15c0): >close: err=<nil>
2021/01/22 12:48:31 DEBUG : serve sftp __ip__:44962->10.0.0.2:8022: exited session
2021/01/22 12:48:31 DEBUG : serve sftp __ip__:44958->10.0.0.2:8022: exited session

2021/01/22 12:49:17 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3 not removed, freed 0 bytes
2021/01/22 12:49:17 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 1.590M (was 1.590M)
2

This is true and perhaps unfortunate.

If you retry the sync, rclone will notice that the file is incorrect and transfer it again.

Not currently, though this has come up before. This is a problem with the client and the server - the client could be naming the files with a temporary extension .uploading101923819283 say, or storing them in a different directory until ready.

SFTP is probably the best for this, I agree.

You can use the rclone check command to check checksums to see if files got transferred properly.

3

Hi,

thanks for the feedback, I will stay with sftp.
I will be a bit disappointed that software is considering a partial transfer as a completed (if it was resumable, that will have been interesting).

I noticed that when re-uploading the file (partially transfer), there is 2 attempts (so 2 transfers and the corresponding bandwidth).
first attempt is used to remove previous file.
second attempt is used to store.
If the file is still in the write cache, then first attempt will do the job.
I reproduced it multiple times, so I don't believe it is random.

Is it possible to improve and save the file on the first attempt ?

Regards,
Serge

rclone sync logs:

2021/01/22 17:44:00 ERROR : L1c/1_Un_automne_avec_Pop.mp3: corrupted on transfer: MD5 hash differ "c171aae53bab9f0a1b300e6eb0a5dd10" vs "a961155d69ef05921259db70ee7d6181"
2021/01/22 17:44:00 INFO  : L1c/1_Un_automne_avec_Pop.mp3: Removing failed copy
...
2021/01/22 17:45:10 ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: MD5 hash differ "c171aae53bab9f0a1b300e6eb0a5dd10" vs "a961155d69ef05921259db70ee7d6181"
...
2021/01/22 17:46:08 ERROR : Attempt 2/3 succeeded

rclone serve logs:

2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0002432c0): close: 
2021/01/22 16:44:00 DEBUG : vfs cache: looking for range={Pos:0 Size:4439235} in [{Pos:0 Size:4439235}] - present true
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: setting modification time to 2021-01-22 16:44:00.185871428 +0000 GMT m=+14382.588949568
2021/01/22 16:44:00 INFO  : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: queuing for upload in 2h0m0s
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc0002432c0): >close: err=<nil>
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: setting modification time to 2020-05-28 13:23:55 +0000 GMT
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: Applied pending mod time 2020-05-28 13:23:55 +0000 GMT OK
2021/01/22 16:44:00 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: Incoming channel: session
2021/01/22 16:44:00 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: Channel accepted
2021/01/22 16:44:00 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: Request: exec
2021/01/22 16:44:00 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022:  - accepted: true
2021/01/22 16:44:00 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: exec command: binary = "md5sum", args = "/test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3"
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: Remove: 
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: cancelling writeback (uploading false) 0xc00029a5b0 item 2
2021/01/22 16:44:00 INFO  : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: removed cache file as file deleted
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: removed metadata from cache as file deleted
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c: Added virtual directory entry vDel: "1_Un_automne_avec_Pop.mp3"
2021/01/22 16:44:00 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: >Remove: err=<nil>
...
2021/01/22 16:45:12 DEBUG : /test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: newRWFileHandle: 
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc000243b40): openPending: 
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: truncate to size=0
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c: Added virtual directory entry vAdd: "1_Un_automne_avec_Pop.mp3"
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc000243b40): >openPending: err=<nil>
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: >newRWFileHandle: err=<nil>
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c: Added virtual directory entry vAdd: "1_Un_automne_avec_Pop.mp3"
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: >Open: fd=test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3 (rw), err=<nil>
2021/01/22 16:45:12 DEBUG : /test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: >OpenFile: fd=test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3 (rw), err=<nil>
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc000243b40): _writeAt: size=4096, off=0
2021/01/22 16:45:12 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc000243b40): >_writeAt: n=4096, err=<nil>
...
2021/01/22 16:46:03 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc000243b40): close: 
2021/01/22 16:46:03 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: setting modification time to 2021-01-22 16:46:03.934958608 +0000 GMT m=+14506.338036738
2021/01/22 16:46:03 INFO  : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: queuing for upload in 2h0m0s
2021/01/22 16:46:03 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3(0xc000243b40): >close: err=<nil>
2021/01/22 16:46:04 DEBUG : test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3: vfs cache: setting modification time to 2020-05-28 13:23:55 +0000 GMT
2021/01/22 16:46:04 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: Incoming channel: session
2021/01/22 16:46:04 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: Channel accepted
2021/01/22 16:46:04 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: Request: exec
2021/01/22 16:46:04 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022:  - accepted: true
2021/01/22 16:46:04 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: exec command: binary = "md5sum", args = "/test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3"
2021/01/22 16:46:04 DEBUG : serve sftp __hidden_ip__:48092->10.0.0.2:8022: command "md5sum /test_sync_20210121/L1c/1_Un_automne_avec_Pop.mp3" failed with error: unexpected non file
4

I'm not sure I understand what you mean here. The partial file was left hanging around because the transfer was interrupted wasn't it? Rclone didn't consider it completed.

I'm not sure what is happening here.

Can you make a sequence of steps so I can reproduce it here please?

5

Can you make a sequence of steps so I can reproduce it here please?

1/ start rclone serve sftp
2/ start rclone sync (then control+c to stop the sync and be sure that a file is truncated)
3/ (if any write cache) wait the vfs-write-back in order to be sure file is save to backend
4/ start rclone sync again

expected results:
it retransfer the file, but :

ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: MD5 hash differ
ERROR : Attempt 2/3 succeeded

It will need 2 attempts

Did you manage to reproduce ?

6

I did...

I used

rclone serve -vv sftp --user x --pass x --vfs-cache-mode writes /tmp/sftptest/

And

rclone sync -P -vv --sftp-host localhost --sftp-port 2022 --bwlimit 100k src :sftp:

I think I see what is going on here.

  • first upload uploads a partial file
  • partial file is uploaded from vfs cache to /tmp/sftptest/
  • retry uploads a full file - this goes to the vfs cache /path/to/vfscache/1M
  • MD5SUM is checked from /tmp/sftptest/1M not /path/to/vfscache/1M
  • Checksums don't match so a retry is initiated

You can see this is the problem if you use this on the sending command

--sftp-md5sum-command none  --sftp-sha1sum-command none

Then it will only do 1 transfer not 2.

Can you please make a new issue on github about this and we'll have a go at fixing - thanks!

7

Thank you
I made a bug report :

Regards,
Serge

1 Like
8

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