Rclone check over SFTP failure to calculate md5 hash for large files

jdogzz · November 14, 2021, 4:22pm

What is the problem you are having with rclone?

When running rclone check with an stfp remote, large files can fail to check. It appears to be the same problem previously reported here (I can't reply on that thread so I opened this one):

Two problems crop up: 1. The hash fails to be computed on the remote. 2. rclone still claims the files are matching at the very end even though the hashing failed.

Reading through the referenced thread above, @ncw had concluded with this being fixed as of the 1.57.0 release, so it seems the problem persists in some form as I am trying that release and the latest beta. It's also worth noting that the troubleshooting in that thread pointed to connections being prematurely closed as the issue, while I see my log reporting it's refusing to close the connections as there are sessions still active, so it would seem the problem lies elsewhere. I have also verified that by direct command on the sftp server, I can run md5sum on the file successfully.

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

I have tried with rclone 1.57.0 and rclone v1.58.0-beta.5885.4c93378f0.

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

Microsoft Windows 11 Home 2009 (64 bit)

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

SFTP

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

rclone check --one-way -vv --checkers 1 --log-file onebyone.txt "D:/Staging2/folderwithreallybigfile/thereallybigfile" "sftpserver:/folderwithreallybigfile"

The rclone config contents with secrets removed.

[mysftpserver]
Enter configuration password:
password:
type = sftp
host = mysftpserver
user = mysftpuser
pass = *** ENCRYPTED ***
key_file_pass = *** ENCRYPTED ***
use_insecure_cipher = true
md5sum_command = md5sum
sha1sum_command = sha1sum

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

2021/11/14 07:19:15 DEBUG : rclone: Version "v1.58.0-beta.5885.4c93378f0" starting with parameters ["rclone" "check" "--one-way" "-vv" "--checkers" "1" "--log-file" "onebyone.txt" "D:/Staging2/Staging2/folderwithreallybigfile/thereallybigfile" "sftpserver:/folderwithreallybigfile"]
2021/11/14 07:19:15 DEBUG : Creating backend with remote "D:/Staging2/Staging2/folderwithreallybigfile/thereallybigfile"
2021/11/14 07:19:20 DEBUG : Using config file from "C:\\Users\\myuser\\.rclone.conf"
2021/11/14 07:19:20 DEBUG : fs cache: adding new entry for parent of "D:/Staging2/Staging2/folderwithreallybigfile/thereallybigfile", "//?/D:/Staging2/Staging2/folderwithreallybigfile"
2021/11/14 07:19:20 DEBUG : Creating backend with remote "mysftpserver:/folderwithreallybigfile"
2021/11/14 07:19:20 DEBUG : sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: New connection mysftpserver:51494->mysftpserver:22 to "SSH-2.0-OpenSSH_8.4p1 Debian-5"
2021/11/14 07:19:20 INFO  : Using md5 for hash comparisons
2021/11/14 07:19:20 DEBUG : sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: Waiting for checks to finish
2021/11/14 07:19:20 DEBUG : somefile: Excluded
2021/11/14 07:20:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       1m4.8s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:20:20 DEBUG : sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: Not closing 1 unused connections as 1 sessions active
2021/11/14 07:21:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       2m4.7s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:21:20 DEBUG : sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: Not closing 1 unused connections as 1 sessions active
2021/11/14 07:22:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       3m4.7s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:22:20 DEBUG : sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: Not closing 1 unused connections as 1 sessions active
2021/11/14 07:23:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       4m4.7s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:23:20 DEBUG : sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: Not closing 1 unused connections as 1 sessions active
2021/11/14 07:24:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       5m4.7s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:24:20 DEBUG : sftp cmd = /folderwithreallybigfile/thereallybigfile
2021/11/14 07:24:20 DEBUG : thereallybigfile: Failed to calculate md5 hash: wait: remote command exited without exit status or exit signal ()
2021/11/14 07:24:20 DEBUG : sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: closing 1 unused connections
2021/11/14 07:25:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       6m4.7s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:26:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       7m4.7s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:27:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       8m4.7s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:28:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 0 / 1, 0%
Elapsed time:       9m4.7s
Checking:
 *                                    thereallybigfile: checking

2021/11/14 07:28:21 DEBUG : thereallybigfile: OK - could not check hash
2021/11/14 07:28:21 NOTICE: sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: 0 differences found
2021/11/14 07:28:21 NOTICE: sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: 1 hashes could not be checked
2021/11/14 07:28:21 NOTICE: sftp://mysftpuser@mysftpserver:22//folderwithreallybigfile: 1 matching files
2021/11/14 07:28:21 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:       9m5.6s

2021/11/14 07:28:21 DEBUG : 3 go routines active

asdffdsa · November 14, 2021, 4:31pm

hello and welcome to the forum,

what is the size of that file?
have you tested using smaller sized files?
do you know the largest file size that rclone check worked on?

just wanted to point out that rclone can function as a sftp server, rclone serve sftp

jdogzz · November 14, 2021, 4:47pm

The size of the file in the logged test above was 74.0 GB.
I ran the check initially on a wide set of folders and 2 large files threw the hash failure error, while the rest of the 1524 files (ranging from KB to double digit GB) were successful.
I'm not sure what exactly is triggering the failure as I actually had files in between the sizes of the 2 failed files, and then later I couldn't get the same failure on the smaller one. To be precise, the two failures were initially 74.0 GB and 26.6 GB, while a 51.1 GB file (among others) succeeded. Then on a retrial, the 26.6 GB file succeeded.

asdffdsa · November 14, 2021, 5:30pm

have you checked the logs for the sftp server?

jdogzz · November 14, 2021, 7:11pm

I have worked my way through increasing levels of logging from the sftp server and I am not able to see where it's going wrong, save the timing. Here is the log at DEBUG3 level:

Nov 14 10:51:15 pve sftp-server[821244]: session opened for local user mysftpuser from [mysftpserver]
Nov 14 10:51:15 pve sftp-server[821244]: received client version 3
Nov 14 10:51:15 pve sftp-server[821244]: debug3: request 1: realpath
Nov 14 10:51:15 pve sftp-server[821244]: realpath "."
Nov 14 10:51:15 pve sftp-server[821244]: debug1: request 1: sent names count 1
Nov 14 10:51:15 pve sftp-server[821244]: debug3: request 2: stat
Nov 14 10:51:15 pve sftp-server[821244]: stat name "/folderwithreallybigfile"
Nov 14 10:51:15 pve sftp-server[821244]: debug1: request 2: sent attrib have 0xf
Nov 14 10:51:15 pve sftp-server[821244]: debug3: request 3: stat
Nov 14 10:51:15 pve sftp-server[821244]: stat name "/folderwithreallybigfile"
Nov 14 10:51:15 pve sftp-server[821244]: debug1: request 3: sent attrib have 0xf
Nov 14 10:51:15 pve sftp-server[821244]: debug3: request 4: opendir
Nov 14 10:51:15 pve sftp-server[821244]: opendir "/folderwithreallybigfile"
Nov 14 10:51:15 pve sftp-server[821244]: debug1: request 4: sent handle handle 0
Nov 14 10:51:15 pve sftp-server[821244]: debug1: request 5: readdir "/folderwithreallybigfile" (handle 0)
Nov 14 10:51:15 pve sftp-server[821244]: debug1: request 5: sent names count 27
Nov 14 10:51:15 pve sftp-server[821244]: debug1: request 6: readdir "/folderwithreallybigfile" (handle 0)
Nov 14 10:51:15 pve sftp-server[821244]: debug3: request 6: sent status 1
Nov 14 10:51:15 pve sftp-server[821244]: sent status End of file
Nov 14 10:51:15 pve sftp-server[821244]: debug3: request 7: close handle 0
Nov 14 10:51:15 pve sftp-server[821244]: closedir "/folderwithreallybigfile"
Nov 14 10:51:15 pve sftp-server[821244]: debug3: request 7: sent status 0
Nov 14 10:51:15 pve sftp-server[821244]: sent status Success
Nov 14 10:56:15 pve sftp-server[821244]: debug1: read eof
Nov 14 10:56:15 pve sftp-server[821244]: session closed for local user mysftpuser from [mysftpserver]

Now, I notice that every one of my failures has failed exactly 300 seconds after the start (the rclone log I gave in my initial post shows the same timing as the sftp server logs). I actually did get it to succeed once, and the rclone output showed it returned the hash at 290 seconds from launch, just under the wire of this 300 second limit. I believe the conditions under which it succeeded were when the server load was smaller (other activities going on, but according to the server statistics at no point is the machine even close to redlining in CPU or RAM usage, it's just a heavier load of processing) and by resuming the same activities I was able to get it to fail again by apparently pushing the computation time above 300 seconds. I'm now googling around to see if I can track down the source of the limit.

asdffdsa · November 14, 2021, 7:40pm

i can confirm the 300 seconds.
i took at the rclone source code, did not see anything in the sftp backend.
so this seems to be a sftp server issue, perhaps some default setting

can you tell me more about the sftp server?
i am using the sftp server hosted by rsync.net
SSH-2.0-OpenSSH_8.2-hpn14v15 FreeBSD-openssh-portable-8.2.p1_1,1

2021/11/14 14:17:54 DEBUG : rclone: Version "v1.57.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone.exe" "check" "D:\\xxx" "rsync:/data2/home/xxx/xxx" "--one-way" "--progress" "--log-file=log.sftp.txt" "--log-level=DEBUG"]
2021/11/14 14:17:54 DEBUG : Creating backend with remote "D:\\xxx"
2021/11/14 14:17:54 DEBUG : Using config file from "c:\\data\\rclone\\scripts\\rclone.conf"
2021/11/14 14:17:54 DEBUG : fs cache: renaming cache item "D:\\xxx" to be canonical "//?/D:/xxx"
2021/11/14 14:17:54 DEBUG : Creating backend with remote "rsync:/data2/home/xxx/xxx"
2021/11/14 14:17:54 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: New connection 192.168.62.234:62845->xxx.xxx.xxx.xxx:22 to "SSH-2.0-OpenSSH_8.2-hpn14v15 FreeBSD-openssh-portable-8.2.p1_1,1"
2021/11/14 14:17:55 INFO  : Using md5 for hash comparisons
2021/11/14 14:17:55 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Waiting for checks to finish
2021/11/14 14:18:55 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 14:19:55 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 14:20:55 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 14:21:55 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 14:22:55 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 14:22:55 DEBUG : sftp cmd = /data2/home/xxx/xxx/xxx.xxx
2021/11/14 14:22:55 DEBUG : xxx.xxx: Failed to calculate md5 hash: wait: remote command exited without exit status or exit signal ()
2021/11/14 14:22:55 DEBUG : xxx.xxx: OK - could not check hash
2021/11/14 14:22:55 NOTICE: sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: 0 differences found
2021/11/14 14:22:55 NOTICE: sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: 1 hashes could not be checked
2021/11/14 14:22:55 NOTICE: sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: 1 matching files
2021/11/14 14:22:55 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:       5m1.6s

jdogzz · November 14, 2021, 7:54pm

Thanks for the replication. My sftp server is a proxmox 7.0-13 server with out of the box configuration (except for turning on the sftp-server logging). I did find this post which touches on timeout parameters, none of which are specified explicitly in my config file:

Curiously, as a comment in the top post asks about, the man page for sshd_config states that if only default parameters are in use, then no timeout should be present.

asdffdsa · November 14, 2021, 8:04pm

at rsync.net, i do not have access to /etc

maybe you can check into this?
https://patrickmn.com/aside/how-to-keep-alive-ssh-sessions/

ncw · November 14, 2021, 10:47pm

Try increasing the --timeout parameter. This is 5m by default.

If that works then we can come up with a better fix.

asdffdsa · November 14, 2021, 11:34pm

--timeout=0 worked, the rclone check took eight minutes

i did not try --timeout, as per the docs,
"Note that --timeout isn't supported (but --contimeout is)."
and i guess that statement is not correct because i tested using --contimeout=60m and still had the 5m issue.

2021/11/14 18:20:43 DEBUG : rclone: Version "v1.57.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone.exe" "check" "D:\\xxx" "rsync:/data2/home/xxx/xxx" "--one-way" "--progress" "--log-file=log.sftp.check.txt" "--log-level=DEBUG" "--timeout=0"]
2021/11/14 18:20:43 DEBUG : Creating backend with remote "D:\\xxx"
2021/11/14 18:20:43 DEBUG : Using config file from "c:\\data\\rclone\\scripts\\rclone.conf"
2021/11/14 18:20:43 DEBUG : fs cache: renaming cache item "D:\\xxx" to be canonical "//?/D:/xxx"
2021/11/14 18:20:43 DEBUG : Creating backend with remote "rsync:/data2/home/xxx/xxx"
2021/11/14 18:20:44 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: New connection 192.168.113.2:51356->xxx.xxx.xxx.xxx:22 to "SSH-2.0-OpenSSH_8.2-hpn14v15 FreeBSD-openssh-portable-8.2.p1_1,1"
2021/11/14 18:20:45 INFO  : Using md5 for hash comparisons
2021/11/14 18:20:45 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Waiting for checks to finish
2021/11/14 18:21:45 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 18:22:45 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 18:23:45 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 18:24:45 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 18:25:45 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 18:26:45 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 18:27:45 DEBUG : sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: Not closing 1 unused connections as 1 sessions active
2021/11/14 18:28:34 DEBUG : sftp cmd = /data2/home/xxx/xxx/xxx.xxx
2021/11/14 18:28:34 DEBUG : sftp output = "1771697eee6dcdd5c1bede29313347a8 /data2/home/xxx/xxx/xxx.xxx\n"
2021/11/14 18:28:34 DEBUG : sftp hash = "1771697eee6dcdd5c1bede29313347a8"
2021/11/14 18:28:34 DEBUG : xxx.xxx: md5 = 1771697eee6dcdd5c1bede29313347a8 OK
2021/11/14 18:28:34 DEBUG : xxx.xxx: OK
2021/11/14 18:28:34 NOTICE: sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: 0 differences found
2021/11/14 18:28:34 NOTICE: sftp://xxx@usw-s003.rsync.net:22//data2/home/xxx/xxx: 1 matching files
2021/11/14 18:28:34 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:      7m51.4s

jdogzz · November 15, 2021, 5:57am

I can confirm that the addition of the --timeout=0 flag worked for me.

ncw · November 15, 2021, 12:29pm

Great

OK, that definitely needs fixing!

The --timeout support kind of got in through the back door which is why the docs didn't get updated.

I just looked through the code and we set timeout on all the ssh connections which is a good idea for data transfer but not so good for running remote commands like md5sum.

Can you have a go with this - what this does is send keepalives every minute when rclone is running a shell command which should stop the timeout kicking in without needing to use the --timeout flag.

v1.58.0-beta.5888.c1f3f4e58.fix-sftp-hash-timeout on branch fix-sftp-hash-timeout (uploaded in 15-30 mins)

asdffdsa · November 15, 2021, 2:24pm

that worked!

2021/11/15 09:04:23 DEBUG : rclone: Version "v1.58.0-beta.5888.c1f3f4e58.fix-sftp-hash-timeout" starting with parameters ["d:\\data\\rclone\\exe\\windows\\rclone-v1.58.0-beta.5888.c1f3f4e58.fix-sftp-hash-timeout-windows-amd64\\rclone.exe" "check" "D:\\folder" "rsync:/data2/home/xxxx/folder" "--one-way" "--progress" "--log-file=log.sftp.check.txt" "--log-level=DEBUG"]
2021/11/15 09:04:23 DEBUG : Creating backend with remote "D:\\folder"
2021/11/15 09:04:23 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/11/15 09:04:23 DEBUG : fs cache: renaming cache item "D:\\folder" to be canonical "//?/D:/folder"
2021/11/15 09:04:23 DEBUG : Creating backend with remote "rsync:/data2/home/xxxx/folder"
2021/11/15 09:04:25 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: New connection 192.168.1.6:54638->216.66.77.199:22 to "SSH-2.0-OpenSSH_8.2-hpn14v15 FreeBSD-openssh-portable-8.2.p1_1,1"
2021/11/15 09:04:25 INFO  : Using md5 for hash comparisons
2021/11/15 09:04:25 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Waiting for checks to finish
2021/11/15 09:04:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Running remote command: md5 -r /data2/home/xxxx/folder/xxx.xxx
2021/11/15 09:05:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Not closing 0 unused connections as 1 sessions active
2021/11/15 09:06:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Not closing 0 unused connections as 1 sessions active
2021/11/15 09:07:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Not closing 0 unused connections as 1 sessions active
2021/11/15 09:08:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Not closing 0 unused connections as 1 sessions active
2021/11/15 09:09:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Not closing 0 unused connections as 1 sessions active
2021/11/15 09:10:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Not closing 0 unused connections as 1 sessions active
2021/11/15 09:11:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Not closing 0 unused connections as 1 sessions active
2021/11/15 09:12:26 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Not closing 0 unused connections as 1 sessions active
2021/11/15 09:12:59 DEBUG : sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: Remote command result: 1771697eee6dcdd5c1bede29313347a8 /data2/home/xxxx/folder/xxx.xxx
2021/11/15 09:12:59 DEBUG : xxx.xxx: md5 = 1771697eee6dcdd5c1bede29313347a8 OK
2021/11/15 09:12:59 DEBUG : xxx.xxx: OK
2021/11/15 09:12:59 NOTICE: sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: 0 differences found
2021/11/15 09:12:59 NOTICE: sftp://xxxx@usw-s003.rsync.net:22//data2/home/xxxx/folder: 1 matching files
2021/11/15 09:12:59 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:      8m36.1s

2021/11/15 09:12:59 DEBUG : 13 go routines active

jdogzz · November 17, 2021, 2:54am

I have a mixed report having tested out the new beta build @ncw provided. First, my tests showed no failures to calculate the md5sum, so that appears to have worked. However, second, the tests showed a large number of failures when running checks when I tried a check on folders containing collectively a few thousand files. From the vv logs, what I'm seeing is the program will work perfectly for a time, successfully calculating md5sums for the checks, then I see a line like:

2021/11/16 12:22:55 DEBUG : sftp://mysftpuser@mysftpserver:22//afoldername: closing 13 unused connections

after which there will be repeated failures like

2021/11/16 12:22:59 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:22:59 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:22:59 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:22:59 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:22:59 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:00 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:00 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:00 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:01 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:02 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:02 DEBUG : Failed to send keep alive: write tcp mylocalip:61623->mysftpserver:22: use of closed network connection
2021/11/16 12:23:03 DEBUG : Failed to send keep alive: write tcp mylocalip:61623->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:04 DEBUG : Failed to send keep alive: write tcp mylocalip:61623->mysftpserver:22: use of closed network connection
2021/11/16 12:23:06 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:06 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:06 DEBUG : Failed to send keep alive: read tcp mylocalip:61616->mysftpserver:22: use of closed network connection
2021/11/16 12:23:07 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:07 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:08 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:08 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:09 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:10 DEBUG : Failed to send keep alive: read tcp mylocalip:61616->mysftpserver:22: use of closed network connection
2021/11/16 12:23:10 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:11 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:11 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:11 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:12 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:13 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:14 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:14 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:14 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:15 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:16 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:16 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:17 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:17 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:17 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:17 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:17 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:17 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:17 DEBUG : Failed to send keep alive: write tcp mylocalip:61623->mysftpserver:22: use of closed network connection
2021/11/16 12:23:18 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:18 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:18 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:18 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:18 DEBUG : Failed to send keep alive: write tcp mylocalip:61623->mysftpserver:22: use of closed network connection
2021/11/16 12:23:18 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:19 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:20 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:21 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:21 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:22 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:22 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:22 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:23 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:23 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:23 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:23 DEBUG : Failed to send keep alive: read tcp mylocalip:61616->mysftpserver:22: use of closed network connection
2021/11/16 12:23:24 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:24 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:24 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:24 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:25 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:25 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:25 DEBUG : Failed to send keep alive: read tcp mylocalip:61616->mysftpserver:22: use of closed network connection
2021/11/16 12:23:25 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:25 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61619->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:26 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:27 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:27 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:27 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:27 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:27 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:27 DEBUG : Failed to send keep alive: read tcp mylocalip:61619->mysftpserver:22: use of closed network connection
2021/11/16 12:23:27 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:28 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:28 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:28 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:28 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:28 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:28 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:29 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:30 DEBUG : Failed to send keep alive: read tcp mylocalip:61619->mysftpserver:22: use of closed network connection
2021/11/16 12:23:30 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:30 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:30 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:30 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:31 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:31 DEBUG : Failed to send keep alive: read tcp mylocalip:61619->mysftpserver:22: use of closed network connection
2021/11/16 12:23:31 DEBUG : Failed to send keep alive: read tcp mylocalip:61616->mysftpserver:22: use of closed network connection
2021/11/16 12:23:31 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:31 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:32 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:32 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:32 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:32 DEBUG : Failed to send keep alive: write tcp mylocalip:61623->mysftpserver:22: use of closed network connection
2021/11/16 12:23:32 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:32 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:32 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:32 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:33 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:33 DEBUG : Failed to send keep alive: read tcp mylocalip:61622->mysftpserver:22: use of closed network connection
2021/11/16 12:23:33 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:33 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:33 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:34 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:35 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:35 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:35 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:35 DEBUG : Failed to send keep alive: read tcp mylocalip:61619->mysftpserver:22: use of closed network connection
2021/11/16 12:23:35 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:36 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:36 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:36 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:36 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: read tcp mylocalip:61622->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:37 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61620->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: EOF
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61620->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: write tcp mylocalip:61621->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61620->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61620->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61620->mysftpserver:22: use of closed network connection
2021/11/16 12:23:38 DEBUG : Failed to send keep alive: read tcp mylocalip:61620->mysftpserver:22: use of closed network connection
2021/11/16 12:23:39 DEBUG : Failed to send keep alive: read tcp mylocalip:61620->mysftpserver:22: use of closed network connection
2021/11/16 12:23:39 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:39 DEBUG : Failed to send keep alive: write tcp mylocalip:61618->mysftpserver:22: use of closed network connection
2021/11/16 12:23:39 DEBUG : Failed to send keep alive: read tcp mylocalip:61613->mysftpserver:22: use of closed network connection
2021/11/16 12:23:39 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:39 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:39 DEBUG : Failed to send keep alive: read tcp mylocalip:61612->mysftpserver:22: use of closed network connection
2021/11/16 12:23:40 DEBUG : Failed to send keep alive: read tcp mylocalip:61611->mysftpserver:22: use of closed network connection
2021/11/16 12:23:40 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:40 DEBUG : Failed to send keep alive: read tcp mylocalip:61617->mysftpserver:22: use of closed network connection
2021/11/16 12:23:40 DEBUG : Failed to send keep alive: read tcp mylocalip:61614->mysftpserver:22: use of closed network connection
2021/11/16 12:23:40 DEBUG : Failed to send keep alive: read tcp mylocalip:61615->mysftpserver:22: use of closed network connection
2021/11/16 12:23:41 DEBUG : Failed to send keep alive: read tcp mylocalip:61620->mysftpserver:22: use of closed network connection

Interspersed through the log (which grows to MB size with recording those many failures) I see successful issuings of the md5sum to the server along with successful calculated responses, so it's still chugging through the workload.

I also tried out the same provided beta with the rclone copy command, which seems to suffer significantly from these changes (at least that's my assumption from the below snippets from the log, though it could certainly be an unrelated regression). As before, it will work perfectly for a time, copying files to the server with my bandwidth saturated (all on LAN, ~100 MB/s), then I will see a pair of lines like

2021/11/16 10:24:12 ERROR : sftp://mysftpuser@mysftpserver:22//afoldername: Discarding closed SSH connection: read tcp mylocalip:61458->mysftpserver:22: i/o timeout
2021/11/16 10:24:12 ERROR : sftp://mysftpuser@mysftpserver:22//afoldername: Discarding closed SSH connection: read tcp mylocalip:61461->mysftpserver:22: i/o timeout

(in the whole log, these are the only errors I got and the only mention of closing SSH connections. Afterwards there are lines like in my previously posted log where it says it will not close connections, like

2021/11/16 11:08:52 DEBUG : sftp://mysftpuser@mysftpserver:22//afoldername: Not closing 6 unused connections as 4 sessions active

) following which the transfer speed drops to 10 MB/s. After letting it sit like that for some time to see if it would pick back up (it stayed around 10 MB/s) I cancelled the transfer, switched to 1.57, and the transfer completed with my bandwidth saturated, ~100 MB/s.

ncw · November 17, 2021, 11:59am

I did find a bug in the code which would explain the "Failed to send keep alive" messages and I've fixed that here

I'd appreciate it if you would give it a test. I'm not sure it explains the Discarding closed SSH connection errors though.

v1.58.0-beta.5893.0730eda81.fix-sftp-hash-timeout on branch fix-sftp-hash-timeout (uploaded in 15-30 mins)

jdogzz · November 21, 2021, 12:02am

After some testing this week it looks like that's fixed the errors and I haven't seen any repeats of the problems experienced at any point in my previous posts. Thank you very much!

ncw · November 22, 2021, 3:27pm

Thanks for testing.

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.58

system · December 22, 2021, 3:28pm

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