ProtocolVersionExchange()
is the last line in the log, so we suspect it never reached the SFTP server
because we don’t get a response back, but its also considered sent so its not
retried. There seems to be no timeout for this either.
It could
even be an issue with the library (Xceed) that Neuron is using for SFTP adapters
since we suspect that this log is produced by the library.
Petri RAUTAKOSKI
We have issue with SFTP read adapter to poll data. Some times adapter just "hangs", here it means that files will not be polled anymore.
We have some logs here to provide from adapter log:
2023-06-11 09:19:53.303+02:00 [58] DEBUG - Heartbeat timer is waiting for initialization to complete
2023-06-11 09:19:53.303+02:00 [58] DEBUG - Heartbeat timer is active
2023-06-11 09:19:53.303+02:00 [58] DEBUG - Entering Heartbeat Interval for the 'Read_Orders_from_IMX_SFTP' Service
2023-06-11 09:19:57.444+02:00 [78] DEBUG - Created the SFTP Client for threadID 78
2023-06-11 09:19:57.444+02:00 [78] DEBUG - Set SFTP Operation Timeout to 30 seconds
2023-06-11 09:19:57.538+02:00 [78] DEBUG - Connected to 'files.loomis.com' on port '22'
2023-06-11 09:19:57.554+02:00 [78] DEBUG - The current folder that the Log In Session sets is '\'
2023-06-11 09:19:58.460+02:00 [3] DEBUG - Entering Client Management Interval check the 'Pub_Orders_from_IMX' Party
2023-06-11 09:19:58.460+02:00 [3] DEBUG - Creating configuration service proxy for the 'Pub_Orders_from_IMX' Party
2023-06-11 09:19:58.460+02:00 [3] DEBUG - Checking configuration versions: Old Version is '194'. Updated Version is '194'.
2023-06-11 09:19:58.460+02:00 [3] DEBUG - Exiting Client Management Interval check the 'Pub_Orders_from_IMX' Party
2023-06-11 09:19:58.679+02:00 [78] DEBUG - Disconnecting current SFTP Client
2023-06-11 09:20:03.304+02:00 [44] DEBUG - Heartbeat timer is waiting for initialization to complete
2023-06-11 09:20:03.304+02:00 [44] DEBUG - Heartbeat timer is active
2023-06-11 09:20:03.304+02:00 [44] DEBUG - Entering Heartbeat Interval for the 'Read_Orders_from_IMX_SFTP' Service
2023-06-11 09:20:08.727+02:00 [78] DEBUG - Created the SFTP Client for threadID 78
2023-06-11 09:20:08.727+02:00 [78] DEBUG - Set SFTP Operation Timeout to 30 seconds
2023-06-11 09:20:13.321+02:00 [49] DEBUG - Heartbeat timer is waiting for initialization to complete
2023-06-11 09:20:13.321+02:00 [49] DEBUG - Heartbeat timer is active
2023-06-11 09:20:13.321+02:00 [49] DEBUG - Entering Heartbeat Interval for the 'Read_Orders_from_IMX_SFTP' Service
2023-06-11 09:20:13.477+02:00 [123] DEBUG - Entering Client Management Interval check the 'Pub_Orders_from_IMX' Party
2023-06-11 09:20:13.477+02:00 [123] DEBUG - Creating configuration service proxy for the 'Pub_Orders_from_IMX' Party
2023-06-11 09:20:13.477+02:00 [123] DEBUG - Checking configuration versions: Old Version is '194'. Updated Version is '194'.
2023-06-11 09:20:13.493+02:00 [123] DEBUG - Exiting Client Management Interval check the 'Pub_Orders_from_IMX' Party
2023-06-11 09:20:23.338+02:00 [58] DEBUG - Heartbeat timer is waiting for initialization to complete
2023-06-11 09:20:23.338+02:00 [58] DEBUG - Heartbeat timer is active
2023-06-11 09:20:23.338+02:00 [58] DEBUG - Entering Heartbeat Interval for the 'Read_Orders_from_IMX_SFTP' Service
2023-06-11 09:20:28.494+02:00 [156] DEBUG - Entering Client Management Interval check the 'Pub_Orders_from_IMX' Party
2023-06-11 09:20:28.494+02:00 [156] DEBUG - Creating configuration service proxy for the 'Pub_Orders_from_IMX' Party
2023-06-11 09:20:28.494+02:00 [156] DEBUG - Checking configuration versions: Old Version is '194'. Updated Version is '194'.
2023-06-11 09:20:28.494+02:00 [156] DEBUG - Exiting Client Management Interval check the 'Pub_Orders_from_IMX' Party
2023-06-11 09:20:33.339+02:00 [3] DEBUG - Heartbeat timer is waiting for initialization to complete
2023-06-11 09:20:33.339+02:00 [3] DEBUG - Heartbeat timer is active
Here we can see that connection will halt for some reason.
We can see same for other MFT adapter, time is not equal though
2023-06-10 18:19:53.520+02:00 [90] DEBUG - Entering Heartbeat Interval for the 'Read_DK_Orders_from_IMX_SFTP' Service
2023-06-10 18:19:57.333+02:00 [74] DEBUG - Created the SFTP Client for threadID 74
2023-06-10 18:19:57.333+02:00 [74] DEBUG - Set SFTP Operation Timeout to 30 seconds
2023-06-10 18:19:57.458+02:00 [74] DEBUG - Connected to 'files.loomis.com' on port '22'
2023-06-10 18:19:57.489+02:00 [74] DEBUG - The current folder that the Log In Session sets is '\'
2023-06-10 18:19:57.521+02:00 [74] DEBUG - Disconnecting current SFTP Client
2023-06-10 18:20:03.521+02:00 [80] DEBUG - Heartbeat timer is waiting for initialization to complete
2023-06-10 18:20:03.521+02:00 [80] DEBUG - Heartbeat timer is active
2023-06-10 18:20:03.521+02:00 [80] DEBUG - Entering Heartbeat Interval for the 'Read_DK_Orders_from_IMX_SFTP' Service
2023-06-10 18:20:07.600+02:00 [74] DEBUG - Created the SFTP Client for threadID 74
2023-06-10 18:20:07.600+02:00 [74] DEBUG - Set SFTP Operation Timeout to 30 seconds
2023-06-10 18:20:07.662+02:00 [80] DEBUG - Entering Client Management Interval check the 'Pub_DK_Orders_from_IMX' Party
2023-06-10 18:20:07.662+02:00 [80] DEBUG - Creating configuration service proxy for the 'Pub_DK_Orders_from_IMX' Party
2023-06-10 18:20:07.662+02:00 [80] DEBUG - Checking configuration versions: Old Version is '194'. Updated Version is '194'.
2023-06-10 18:20:07.662+02:00 [80] DEBUG - Exiting Client Management Interval check the 'Pub_DK_Orders_from_IMX' Party
2023-06-10 18:20:13.538+02:00 [146] DEBUG - Heartbeat timer is waiting for initialization to complete
2023-06-10 18:20:13.538+02:00 [146] DEBUG - Heartbeat timer is active
2023-06-10 18:20:13.538+02:00 [146] DEBUG - Entering Heartbeat Interval for the 'Read_DK_Orders_from_IMX_SFTP' Service
2023-06-10 18:20:22.679+02:00 [117] DEBUG - Entering Client Management Interval check the 'Pub_DK_Orders_from_IMX' Party
2023-06-10 18:20:22.679+02:00 [117] DEBUG - Creating configuration service proxy for the 'Pub_DK_Orders_from_IMX' Party
2023-06-10 18:20:22.679+02:00 [117] DEBUG - Checking configuration versions: Old Version is '194'. Updated Version is '194'.
2023-06-10 18:20:22.679+02:00 [117] DEBUG - Exiting Client Management Interval check the 'Pub_DK_Orders_from_IMX' Party
2023-06-10 18:20:23.586+02:00 [80] DEBUG - Heartbeat timer is waiting for initialization to complete
2023-06-10 18:20:23.586+02:00 [80] DEBUG - Heartbeat timer is active
We have also other logs to provide. A successful initiation of communication is something like this:
SSHClient.PrepareConnect() using Socket.
SSHClientConnectionManager.Connect() starting at 6/10/2023 6:19:57 PM
SocketIOProvider.DoConnect() using sockets. Local: <any>. Host: 10.181.253.2:22
ProtocolVersionExchange() sends: SSH-2.0-Xceed.SSH.NET_6.9.22269.23370
ProtocolVersionExchange() received: SSH-2.0-GoAnywhere7.0.3
SSHClientConnectionManager.KeyExchange() initiating key exchange
etc…
Last attempt that hanged:
SSHClient.PrepareConnect() using Socket.
SSHClientConnectionManager.Connect() starting at 6/10/2023 6:20:07 PM
SocketIOProvider.DoConnect() using sockets. Local: <any>. Host: 10.181.253.2:22
ProtocolVersionExchange() sends: SSH-2.0-Xceed.SSH.NET_6.9.22269.23370
ProtocolVersionExchange() is the last line in the log, so we suspect it never reached the SFTP server because we don’t get a response back, but its also considered sent so its not retried. There seems to be no timeout for this either.
It could even be an issue with the library (Xceed) that Neuron is using for SFTP adapters since we suspect that this log is produced by the library.
We urgently need solution for this.