Could not connect to SSH endpoint: An existing connection was forcibly closed by the remote host

Octopus Server
, ,
1

Hello

we are experiencing problems with deploying to a ssh deployment target in aws, a aws linux2 instance.

The problem is not persistant, happens between two steps, and seccond time we deploy it succeeds if you wait a minute.

step 1 aquire package ( which succeeds )
step 2 fails with error:

Could not connect to SSH endpoint: An existing connection was forcibly closed by the remote host:

14:50:42 Verbose | Could not connect to SSH endpoint: An existing connection was forcibly closed by the remote host.
| Octopus.Server.Orchestration.Targets.Ssh.SshEndpointConnectionException
| at Octopus.Server.Orchestration.Targets.Ssh.Connectivity.SshClientFactory.EstablishConnection[TClient](Func2 clientConstructor, ITaskLog taskLog) in SshClientFactory.cs:line 117 | at Octopus.Server.Orchestration.Targets.Ssh.Connectivity.SshClientFactory.EstablishSshConnection(ITaskLog taskLog) in SshClientFactory.cs:line 63 | at Octopus.Server.Orchestration.Targets.Ssh.Connectivity.ConnectionScope.GetSshClient() in ConnectionScope.cs:line 67 | at Octopus.Server.Orchestration.Targets.Ssh.SshRemoteEndpointFacade.EnsureDirectoryExists(String path, StringBuilder error) in SshRemoteEndpointFacade.cs:line 142 | at Octopus.Server.Orchestration.Targets.Ssh.SshRemoteEndpointFacade.UploadFile(String remotePath, DataStream upload, ITaskLog taskLog) in SshRemoteEndpointFacade.cs:line 75 | at Octopus.Server.Orchestration.Targets.Ssh.SshRemoteEndpointFacade.UploadFile(ScriptFile scriptFile, ITaskLog taskLog) in SshRemoteEndpointFacade.cs:line 89 | at System.Collections.Generic.List1.ForEach(Action1 action) | at Octopus.Server.Orchestration.Targets.Ssh.SshRemoteEndpointFacade.UploadExecuteDownload(StartScriptCommand command, ITaskLog taskLog) in SshRemoteEndpointFacade.cs:line 128 | at Octopus.Server.Orchestration.ServerTasks.Deploy.ActionExecution.Immediate.ExecutionTargets.SshBashExecutionTarget.Execute(ScriptCollection bootstrapperScripts, IReadOnlyList1 boostrapperArguments, IReadOnlyList1 files, Nullable1 forceIsolationLevel, Boolean raw, ITaskLog taskLog, Nullable1 isolationMutexTimeout) in SshBashExecutionTarget.cs:line 81 | at Octopus.Server.Orchestration.ServerTasks.Deploy.ActionExecution.Immediate.ImmediateExecutor.RunOnTarget(ScriptCollection finalBootstrapperScripts, String platform, IBootstrapperScriptGenerator bootstrapperScriptGenerator, IReadOnlyList1 bootstrapperArguments, IReadOnlyList1 allFiles, Nullable1 isolation, Nullable1 isolationMutexTimeout, CalamariFlavour flavour, IReadOnlyList1 deploymentTools, ExecutionTargetDetails executionTargetDetails, CalamariPlatformConstraint calamariPlatformConstraint, ITaskLog taskLog) in ImmediateExecutor.cs:line 229
| at Octopus.Server.Orchestration.ServerTasks.Deploy.ActionExecution.Immediate.ImmediateExecutor.ExecuteCalamari(CalamariFlavour calamariFlavour, String calamariCommand, IReadOnlyList1 calamariArguments, IReadOnlyList1 files, IReadOnlyList1 deploymentTools, VariableCollection extraVariables, TargetManifest targetManifest, CalamariPlatformConstraint calamariPlatformConstraint, Nullable1 isolationMutexTimeout, ITaskLog taskLog) in ImmediateExecutor.cs:line 178
| at Octopus.Server.Orchestration.ServerTasks.Deploy.ActionExecution.CommandBuilders.CalamariCommandBuilder.Execute(ITaskLog taskLog) in CalamariCommandBuilder.cs:line 147
| at Octopus.Server.Orchestration.ServerTasks.Deploy.Steps.Script.ScriptActionHandler.ExecuteWithDefaultScriptHandler(IActionHandlerContext context, ITaskLog taskLog) in ScriptActionHandler.cs:line 61
| at Octopus.Server.Orchestration.ServerTasks.Deploy.ActionDispatch.NewActionDispatcher.<>c__DisplayClass15_0.<Execute in NewActionDispatcher.cs:line 205
| at Octopus.Server.Infrastructure.EitherAsyncOrSync.Execute(CancellationToken cancellationToken) in EitherAsyncOrSync.cs:line 38
| at Octopus.Server.Orchestration.ServerTasks.Deploy.Guidance.ExecuteWithoutGuidance(EitherAsyncOrSync callback, String actionName, Boolean actionIsRequiredToRun, ITaskLog taskLog, CancellationToken cancellationToken) in Guidance.cs:line 116
| at Octopus.Server.Orchestration.ServerTasks.Deploy.Guidance.Execute(EitherAsyncOrSync callback, String actionName, Boolean actionIsRequiredToRun, ITaskLog taskLog, Maybe1 callbackOnExclude, CancellationToken cancellationToken) in Guidance.cs:line 67 | at Octopus.Server.Orchestration.ServerTasks.Deploy.ActionDispatch.NewActionDispatcher.Execute(ActionCommand command, Maybe1 inContextOf, IExecutor executor, TargetManifest targetManifest, Maybe1 stagedPackagePath, IActionAndTargetScopedVariables variables, ITaskLog taskLog, Maybe1 guidanceExcludeCallback, CancellationToken cancellationToken) in NewActionDispatcher.cs:line 211
| at Octopus.Server.Orchestration.ServerTasks.Deploy.ActionDispatch.NewActionDispatcher.ExecuteOnDeploymentTarget(ActionCommand command, DeploymentTarget deploymentTarget, Maybe1 guidanceExcludeCallback, ITaskLog taskLogForTarget, ITaskLog taskLogRoot, CancellationToken cancellationToken) in NewActionDispatcher.cs:line 121 | at Octopus.Server.Orchestration.ServerTasks.Deploy.ActionDispatch.NewActionDispatcher.Dispatch(ActionCommand command, DeploymentTarget deploymentTarget, ITaskLog taskLogForTarget, ITaskLog taskLogRoot, Maybe1 guidanceExcludeCallback, CancellationToken cancellationToken) in NewActionDispatcher.cs:line 92
| at Octopus.Server.Orchestration.ServerTasks.Deploy.ExecutionTaskController1.<>c__DisplayClass38_2.<ExecuteActionAndInitLoggingContext in ExecutionTaskController.cs:line 601 | at Octopus.Server.Infrastructure.EitherAsyncOrSync.Execute(CancellationToken cancellationToken) in EitherAsyncOrSync.cs:line 38 | at Octopus.Server.Orchestration.ServerTasks.Deploy.Guidance.ExecuteWithoutGuidance(EitherAsyncOrSync callback, String actionName, Boolean actionIsRequiredToRun, ITaskLog taskLog, CancellationToken cancellationToken) in Guidance.cs:line 116 | at Octopus.Server.Orchestration.ServerTasks.Deploy.Guidance.Execute(EitherAsyncOrSync callback, String actionName, Boolean actionIsRequiredToRun, ITaskLog taskLog, Maybe1 callbackOnExclude, CancellationToken cancellationToken) in Guidance.cs:line 67
| at Octopus.Server.Orchestration.ServerTasks.Deploy.ExecutionTaskController1.<>c__DisplayClass38_1.<ExecuteActionAndInitLoggingContext in ExecutionTaskController.cs:line 607 | at Octopus.Server.Infrastructure.Orchestration.UnitsOfWork.UnitOfWorkExecutor.<>c__DisplayClass4_02.<Execute in UnitOfWorkExecutor.cs:line 74
| at Octopus.Core.Infrastructure.UnitsOfWork.UnitOfWorkExtensionMethods.DoAsync(IUnitOfWork unitOfWork, Func1 action, CancellationToken cancellationToken, String name) in UnitOfWorkExtensionMethods.cs:line 73 | at Octopus.Core.Infrastructure.UnitsOfWork.UnitOfWorkExtensionMethods.DoAsync(IUnitOfWork unitOfWork, Func1 action, CancellationToken cancellationToken, String name) in UnitOfWorkExtensionMethods.cs:line 73
| at Octopus.Server.Infrastructure.Orchestration.UnitsOfWork.UnitOfWorkExecutor.Execute[T1,T2](Func4 action, CancellationToken cancellationToken, String name) in UnitOfWorkExecutor.cs:line 75 | at Octopus.Server.Orchestration.ServerTasks.Deploy.ExecutionTaskController1.<>c__DisplayClass38_0.<ExecuteActionAndInitLoggingContext in ExecutionTaskController.cs:line 608
| at Octopus.Server.Orchestration.ServerTasks.Deploy.ExecutionTaskController1.ExecuteWithTransientErrorDetection(Func2 action, ITaskLog taskLog, CancellationToken cancellationToken, DeploymentTarget deploymentTarget) in ExecutionTaskController.cs:line 753
| at Octopus.Server.Orchestration.ServerTasks.Deploy.ExecutionTaskController1.ExecuteActionAndInitLoggingContext(PlannedStep step, DeploymentTarget targetContext, PlannedAction action, ITaskLog taskLogForTarget, ITaskLog taskLogRoot, CancellationToken cancellationToken) in ExecutionTaskController.cs:line 626 | --Inner Exception-- | An existing connection was forcibly closed by the remote host. | System.Net.Sockets.SocketException | at Renci.SshNet.Abstractions.SocketAbstraction.Read(Socket socket, Byte[] buffer, Int32 offset, Int32 size, TimeSpan readTimeout) | at Renci.SshNet.Connection.ProtocolVersionExchange.SocketReadLine(Socket socket, TimeSpan timeout, List1 buffer)
| at Renci.SshNet.Connection.ProtocolVersionExchange.Start(String clientVersion, Socket socket, TimeSpan timeout)
| at Renci.SshNet.Session.Connect()
| at Renci.SshNet.BaseClient.CreateAndConnectSession()
| at Renci.SshNet.BaseClient.Connect()
| at Octopus.Server.Orchestration.Targets.Ssh.Connectivity.SshClientFactory.EstablishConnection[TClient](Func`2 clientConstructor, ITaskLog taskLog) in SshClientFactory.cs:line 117

hope that you can help us.
regards
Morten - JP/Politikens hus

5

Hi Morten,

Thank you for reaching out to us with your query.

It sounds like the Octopus Server and the SSH target are configured correctly as the connection does work some of the time. This, in combination with the error below, would suggest that the issue is with something on the target forcibly closing the connection:

Could not connect to SSH endpoint: An existing connection was forcibly closed by the remote host.

The most likely explanation for this is that the SSH server is misconfigured or there is some form of security software intermittently blocking the connection.

Could you please check the firewall logs and the SSH logs on the target server and advise if they contain any explanation for why the disconnection is occurring?

Best Regards,

Charles

6

Hi Charles,

Thank you for a quick response, I got I debug log from ssh … it might just put an extra confusing wrinkle on this issue, in my not so expert opinion it looks like the ssh logs are telling us that the source is resetting the connection:

I have change the actual source ip with “source-ip” and the actual destination ip with “destination ip”

Here is an example where we get the connection error

Sep 24 11:54:36 ip-destination sshd[18103]: debug1: Forked child 19564.

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: Set /proc/self/oom_score_adj to 0

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: inetd sockets after dupping: 3, 3

Sep 24 11:54:36 ip-destination sshd[19564]: Connection from source-ip port 55276 on destination-ip port 22

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: Client protocol version 2.0; client software version Renci.SshNet.SshClient.0.0.1

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: no match: Renci.SshNet.SshClient.0.0.1

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: Local version string SSH-2.0-OpenSSH_7.4

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: Enabling compatibility mode for protocol 2.0

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: SELinux support disabled [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: permanently_set_uid: 74/74 [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: SSH2_MSG_KEXINIT sent [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: SSH2_MSG_KEXINIT received [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: kex: algorithm: curve25519-sha256 [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: kex: host key algorithm: ssh-ed25519 [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: kex: client->server cipher: aes256-ctr MAC: hmac-sha1 compression: none [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: kex: server->client cipher: aes256-ctr MAC: hmac-sha1 compression: none [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: kex: curve25519-sha256 need=32 dh_need=32 [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: kex: curve25519-sha256 need=32 dh_need=32 [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: rekey after 4294967296 blocks [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: SSH2_MSG_NEWKEYS sent [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]

connection error here

Sep 24 11:54:36 ip-destination sshd[19564]: Connection reset by source-ip port 55276 [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: do_cleanup [preauth]

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: monitor_read_log: child log fd closed

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: do_cleanup

Sep 24 11:54:36 ip-destination sshd[19564]: debug1: Killing privsep child 19565

Here is an example where everything goes fine

Sep 24 12:10:22 ip-destination sshd[19629]: debug1: Forked child 20243.

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: Set /proc/self/oom_score_adj to 0

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: inetd sockets after dupping: 3, 3

Sep 24 12:10:22 ip-destination sshd[20243]: Connection from source-ip port 54861 on destination-ip port 22

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: Client protocol version 2.0; client software version Renci.SshNet.SshClient.0.0.1

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: no match: Renci.SshNet.SshClient.0.0.1

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: Local version string SSH-2.0-OpenSSH_7.4

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: Enabling compatibility mode for protocol 2.0

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: SELinux support disabled [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: permanently_set_uid: 74/74 [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: SSH2_MSG_KEXINIT sent [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: SSH2_MSG_KEXINIT received [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: kex: algorithm: curve25519-sha256 [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: kex: host key algorithm: ssh-ed25519 [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: kex: client->server cipher: aes256-ctr MAC: hmac-sha1 compression: none [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: kex: server->client cipher: aes256-ctr MAC: hmac-sha1 compression: none [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: kex: curve25519-sha256 need=32 dh_need=32 [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: kex: curve25519-sha256 need=32 dh_need=32 [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: rekey after 4294967296 blocks [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: SSH2_MSG_NEWKEYS sent [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]

connection succesful

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: SSH2_MSG_NEWKEYS received [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: rekey after 4294967296 blocks [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: KEX done [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: userauth-request for user ec2-user service ssh-connection method none [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: attempt 0 failures 0 [preauth]

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: PAM: initializing for “ec2-user”

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: PAM: setting PAM_RHOST to “source-ip”

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: PAM: setting PAM_TTY to “ssh”

Sep 24 12:10:22 ip-destination sshd[20243]: debug1: userauth-request for user ec2-user service ssh-connection method publickey [preauth]

Regards,

Morten

7

Hi Morten,

Thank you for getting back to me with these logs.

It sounds like both the server and client are reporting that their counterpart closed the connection, which could suggest something that sits between them is breaking the connection. The most likely culprit would be some form of security software or appliance.

Could you please advise if there are any firewalls, intrusion protection systems or other security products sitting between the two systems and if so have they logged anything? This could include standalone products or products installed on one or both of the machines in question.

Best Regards,

Charles

1 Like
8

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