Discuss (FTP), (FTP on .NET CF) and (FTPS, SFTP and SCP).
no avatar
User

Graeme

Posts

37

Joined

Fri Oct 14, 2011 8:14 pm

Location

Dublin

SFTP exception - forcibly closed by the remote host

by Graeme » Thu Apr 03, 2014 1:05 am

Hi,

We are getting the following logged several times a day for SFTP during a significant (but unpredictable) proportion of the SFTP operations that occur on a live production system.

2014-03-31 10:10:43,499 [8] [(null)] [(null)] [(null)] ERROR EnterpriseDTLog - An existing connection was forcibly closed by the remote host
System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
at Xv8GsRCUgatLkTL5nv.UHGbK3YUXY0VkrdBfY.X5yeGsgxjY(IAsyncResult )

There doesn?t appear to be any problems with the FTP operation itself ? all files being transferred appear to go successfully. However, the fact that an error is being logged causes problems as we monitor every error for support.

The following is a sample of the log immediately prior to such an instance

2014-03-31 09:55:36,415 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Opening directory /F5/PFcontent/1617/
2014-03-31 09:55:36,415 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Transmit 32 bytes
2014-03-31 09:55:36,415 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Remote window size decreased to 65152
2014-03-31 09:55:36,462 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - RepeatCallback received 68 bytes
2014-03-31 09:55:36,462 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - ProcessPacket pt=SSH_MSG_CHANNEL_DATA
2014-03-31 09:55:36,462 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - Received message (type=102,len=22)
2014-03-31 09:55:36,462 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - AddMessage(140) - added to store
2014-03-31 09:55:36,462 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Transmit 32 bytes
2014-03-31 09:55:36,462 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Remote window size decreased to 65120
2014-03-31 09:55:36,509 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - RepeatCallback received 84 bytes
2014-03-31 09:55:36,509 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - ProcessPacket pt=SSH_MSG_CHANNEL_DATA
2014-03-31 09:55:36,509 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - Received message (type=105,len=37)
2014-03-31 09:55:36,509 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - AddMessage(141) - added to store
2014-03-31 09:55:36,509 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - ChDir(actual=/F5/PFcontent/1617/)
2014-03-31 09:55:36,509 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Transmit 26 bytes
2014-03-31 09:55:36,509 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Remote window size decreased to 65094
2014-03-31 09:55:36,556 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - RepeatCallback received 68 bytes
2014-03-31 09:55:36,556 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - ProcessPacket pt=SSH_MSG_CHANNEL_DATA
2014-03-31 09:55:36,556 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - Received message (type=101,len=24)
2014-03-31 09:55:36,556 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - ErrorCode|Status=0
2014-03-31 09:55:36,556 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - AddMessage(142) - added to store
2014-03-31 09:55:36,556 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Rename('/F5/PFcontent/1617/0'=>'/F5/PFcontent/1617/9')
2014-03-31 09:55:36,556 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - ResolveRemotePath('/F5/PFcontent/1617/0'); [cwd='/F5/PFcontent/1617/']
2014-03-31 09:55:36,556 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Resolved to '/F5/PFcontent/1617/0'
2014-03-31 09:55:36,556 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - ResolveRemotePath('/F5/PFcontent/1617/9'); [cwd='/F5/PFcontent/1617/']
2014-03-31 09:55:36,556 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Resolved to '/F5/PFcontent/1617/9'
2014-03-31 09:55:36,556 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Transmit 57 bytes
2014-03-31 09:55:36,556 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Remote window size decreased to 65037
2014-03-31 09:55:36,602 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - RepeatCallback received 68 bytes
2014-03-31 09:55:36,602 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - ProcessPacket pt=SSH_MSG_CHANNEL_DATA
2014-03-31 09:55:36,602 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - Received message (type=101,len=24)
2014-03-31 09:55:36,602 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - ErrorCode|Status=0
2014-03-31 09:55:36,602 [8] [(null)] [(null)] [(null)] DEBUG EnterpriseDTLog - AddMessage(143) - added to store
2014-03-31 09:55:36,602 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Closing connection (instance=38)
2014-03-31 09:55:36,602 [28] [hd4678] [homrx3essjpr0fuvwd2okpq0] [1617] DEBUG EnterpriseDTLog - Quit() called
2014-03-31 10:10:43,499 [8] [(null)] [(null)] [(null)] ERROR EnterpriseDTLog - An existing connection was forcibly closed by the remote host
System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
at Xv8GsRCUgatLkTL5nv.UHGbK3YUXY0VkrdBfY.X5yeGsgxjY(IAsyncResult )

There are two threads showing up here ? 28 and 8 (given by the first value in ?[]?). So, our first question is are these two threads part of the same operation?

If the two threads are part of the same operation then the error occurs some 15 minutes after the connection was supposedly closed by the client. So, is there some sort of bug here in the ?Close? and ?Quit? code in the EnterpriseDT library?
no avatar
User

support2

Posts

3987

Joined

Tue May 18, 2004 8:30 am

Re: SFTP exception - forcibly closed by the remote host

by support2 » Thu Apr 03, 2014 10:49 am

Is that all the logging? I would expect to see some additional messages after Close() is called. What version are you using?
no avatar
User

Graeme

Posts

37

Joined

Fri Oct 14, 2011 8:14 pm

Location

Dublin

by Graeme » Thu Apr 03, 2014 5:38 pm

v 8.0.0.20.
no avatar
User

Graeme

Posts

37

Joined

Fri Oct 14, 2011 8:14 pm

Location

Dublin

by Graeme » Thu Apr 03, 2014 8:07 pm

Can you tell me if two threads are involved in the operation?
no avatar
User

support2

Posts

3987

Joined

Tue May 18, 2004 8:30 am

by support2 » Thu Apr 03, 2014 11:01 pm

no avatar
User

Graeme

Posts

37

Joined

Fri Oct 14, 2011 8:14 pm

Location

Dublin

by Graeme » Thu Apr 03, 2014 11:19 pm

no avatar
User

support2

Posts

3987

Joined

Tue May 18, 2004 8:30 am

by support2 » Fri Apr 04, 2014 6:46 am


Who is online

Users browsing this forum: No registered users and 16 guests

Powered by phpBB ® | phpBB3 Style by KomiDesign