Strange error log using 1.56.0 about connection timeout

What is the problem you are having with rclone?

I'm using like rclone sync localPath sftpPath
with 1.56.0, I got a new non-blocking error log (3 times)
2021/08/05 22:26:45 ERROR : sftp://...: Discarding closed SSH connection: read tcp ... i/o timeout
I also use --transfers 1 --checkers 4, so connection may be closed by remote
As indicated, in logs sftp server is rclone 1.54.1
Thes 3 lines weren't present with previous versions (tested with 1.54.1)

What is your rclone version (output from rclone version)

rclone v1.56.0

  • os/version: debian 10.10 (64 bit)
  • os/kernel: 4.19.0-17-amd64 (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.16.5
  • go/linking: static
  • go/tags: none

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

linux debian amd64

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

sftp (provided by rclone serve)

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

rclone --config /dev/null sync localPath/ :sftp:remoteDir/ --sftp-host __hidden_ip__ --sftp-port __hidden_port__ --sftp-user __hidden_username__ --sftp-pass hiddenPass --max-delete 2 --transfers 1 --checkers 4 --stats 2m --track-renames --track-renames-strategy leaf --size-only --max-transfer 30M --cutoff-mode=soft --delete-after --delete-excluded -vv

The rclone config contents with secrets removed.

no config (settings on command line)

A log from the command with the -vv flag

2021/08/05 22:14:50 INFO  : Starting bandwidth limiter at 80Ki Byte/s
2021/08/05 22:14:50 DEBUG : rclone: Version "v1.56.0" starting with parameters ["rclone" "--config" "/dev/null" "sync" "localPath/" ":sftp:remoteDir/" "--sftp-host" "__hidden_ip__" "--sftp-port" "__hidden_port__" "--sftp-user" "__hidden_username__" "--sftp-pass" "hiddenPass" "--max-delete" "2" "--transfers" "1" "--checkers" "4" "--stats" "2m" "--track-renames" "--track-renames-strategy" "leaf" "--size-only" "--max-transfer" "30M" "--cutoff-mode=soft" "--delete-after" "--delete-excluded" "-vv"]
2021/08/05 22:14:50 DEBUG : Creating backend with remote "localPath/"
2021/08/05 22:14:50 DEBUG : Using config file from ""
2021/08/05 22:14:50 DEBUG : Creating backend with remote ":sftp:remoteDir/"
2021/08/05 22:14:50 DEBUG : :sftp: detected overridden config - adding "{bxU9x}" suffix to name
2021/08/05 22:14:50 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: New connection __local_ip__:54760->__hidden_ip__:__hidden_port__ to "SSH-2.0-rclone/v1.54.1"
2021/08/05 22:14:50 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Using absolute root directory "/share_muzik"
2021/08/05 22:14:50 DEBUG : fs cache: renaming cache item ":sftp:remoteDir/" to be canonical ":sftp{bxU9x}:remoteDir/"
2021/08/05 22:14:50 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: checking "md5sum" command: "d41d8cd98f00b204e9800998ecf8427e  -"
2021/08/05 22:14:51 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: checking "sha1sum" command: "da39a3ee5e6b4b0d3255bfef95601890afd80709  -"
2021/08/05 22:14:51 DEBUG : Saving config "md5sum_command" in section ":sftp" of the config file
2021/08/05 22:14:51 DEBUG : Saving config "sha1sum_command" in section ":sftp" of the config file
2021/08/05 22:14:51 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: New connection __local_ip__:54766->__hidden_ip__:__hidden_port__ to "SSH-2.0-rclone/v1.54.1"
2021/08/05 22:14:51 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: New connection __local_ip__:54768->__hidden_ip__:__hidden_port__ to "SSH-2.0-rclone/v1.54.1"
2021/08/05 22:14:51 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: New connection __local_ip__:54770->__hidden_ip__:__hidden_port__ to "SSH-2.0-rclone/v1.54.1"
...
2021/08/05 22:17:30 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Waiting for renames to finish
2021/08/05 22:17:30 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Waiting for transfers to finish
2021/08/05 22:18:30 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Not closing 4 unused connections as 1 transfers in progress
2021/08/05 22:18:50 INFO  : 
Transferred:   	   10.309Mi / 47.103 MiByte, 22%, 98.074 KiByte/s, ETA 6m24s
Checks:              9843 / 9843, 100%
Transferred:            0 / 3, 0%
Elapsed time:       4m0.4s
Transferring:
 * PopRock/Melusine/Melus…_-_Le_cruel_amant.flac: 58% /17.755Mi, 98.075Ki/s, 1m17s

2021/08/05 22:19:30 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Not closing 4 unused connections as 1 transfers in progress
2021/08/05 22:20:28 DEBUG : sftp cmd = /remoteDir/PopRock/Melusine/Melusine-2016_-_Melusine_1978-1981_\[cl_cdrip\]/18_-_Melusine_-_Le_cruel_amant.flac
2021/08/05 22:20:28 DEBUG : PopRock/Melusine/Melusine-2016_-_Melusine_1978-1981_[cl_cdrip]/18_-_Melusine_-_Le_cruel_amant.flac: Failed to calculate md5 hash: Process exited with status 1 (unexpected non file)
2021/08/05 22:20:28 INFO  : PopRock/Melusine/Melusine-2016_-_Melusine_1978-1981_[cl_cdrip]/18_-_Melusine_-_Le_cruel_amant.flac: Copied (new)
2021/08/05 22:20:50 INFO  : 
Transferred:   	   19.689Mi / 47.103 MiByte, 42%, 79.810 KiByte/s, ETA 5m51s
Checks:              9843 / 9843, 100%
Transferred:            1 / 3, 33%
Elapsed time:       6m0.4s
Transferring:
 * PopRock/Melusine/Melus…es___Branles_gays.flac:  6% /29.344Mi, 86.446Ki/s, 5m24s

2021/08/05 22:21:28 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Not closing 4 unused connections as 1 transfers in progress
2021/08/05 22:22:28 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Not closing 4 unused connections as 1 transfers in progress
2021/08/05 22:22:50 INFO  : 
Transferred:   	   29.064Mi / 47.103 MiByte, 62%, 79.515 KiByte/s, ETA 3m52s
Checks:              9843 / 9843, 100%
Transferred:            1 / 3, 33%
Elapsed time:       8m0.4s
Transferring:
 * PopRock/Melusine/Melus…es___Branles_gays.flac: 38% /29.344Mi, 79.484Ki/s, 3m52s

2021/08/05 22:23:28 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Not closing 4 unused connections as 1 transfers in progress
2021/08/05 22:24:28 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Not closing 4 unused connections as 1 transfers in progress
2021/08/05 22:24:50 INFO  : 
Transferred:   	   38.439Mi / 47.103 MiByte, 82%, 79.515 KiByte/s, ETA 1m51s
Checks:              9843 / 9843, 100%
Transferred:            1 / 3, 33%
Elapsed time:      10m0.4s
Transferring:
 * PopRock/Melusine/Melus…es___Branles_gays.flac: 70% /29.344Mi, 79.479Ki/s, 1m51s

2021/08/05 22:25:28 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Not closing 4 unused connections as 1 transfers in progress
2021/08/05 22:26:28 DEBUG : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Not closing 4 unused connections as 1 transfers in progress
2021/08/05 22:26:45 ERROR : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Discarding closed SSH connection: read tcp __local_ip__:54760->__hidden_ip__:__hidden_port__: i/o timeout
2021/08/05 22:26:45 ERROR : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Discarding closed SSH connection: read tcp __local_ip__:54770->__hidden_ip__:__hidden_port__: i/o timeout
2021/08/05 22:26:45 ERROR : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: Discarding closed SSH connection: read tcp __local_ip__:54766->__hidden_ip__:__hidden_port__: i/o timeout
2021/08/05 22:26:50 DEBUG : sftp cmd = /remoteDir/PopRock/Melusine/Melusine-2016_-_Melusine_1978-1981_\[cl_cdrip\]/19_-_Melusine_-_Helas_mon_ami_Jacques___Branles_gays.flac
2021/08/05 22:26:50 DEBUG : PopRock/Melusine/Melusine-2016_-_Melusine_1978-1981_[cl_cdrip]/19_-_Melusine_-_Helas_mon_ami_Jacques___Branles_gays.flac: Failed to calculate md5 hash: Process exited with status 1 (unexpected non file)
2021/08/05 22:26:50 INFO  : PopRock/Melusine/Melusine-2016_-_Melusine_1978-1981_[cl_cdrip]/19_-_Melusine_-_Helas_mon_ami_Jacques___Branles_gays.flac: Copied (new)
2021/08/05 22:26:50 NOTICE: Max transfer limit reached as set by --max-transfer - stopping transfers
2021/08/05 22:26:50 ERROR : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: not deleting files as there were IO errors
2021/08/05 22:26:50 ERROR : sftp://__hidden_username__@__hidden_ip__:__hidden_port__/remoteDir/: not deleting directories as there were IO errors
2021/08/05 22:26:50 ERROR : Can't retry any of the errors - not attempting retries
2021/08/05 22:26:50 INFO  : 
Transferred:   	   47.099Mi / 47.099 MiByte, 100%, 79.515 KiByte/s, ETA 0s
Errors:                 2 (no need to retry)
Checks:              9843 / 9843, 100%
Transferred:            2 / 2, 100%
Elapsed time:      12m0.2s

2021/08/05 22:26:50 DEBUG : 13 go routines active
2021/08/05 22:26:50 Failed to sync with 2 errors: last error was: Max transfer limit reached as set by --max-transfer


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