Step Acquire packages times out

[Lasse (Lazaros)]

We have four polling agents which deploy packages many times each day without any problems.
But several times each week we have problems with the “Acquire packages” step. It sometimes times out and sometimes just delays the deploy with up to 10 minutes. This step normally takes seconds to finish.

Any ideas on what we can do?

The error seen in the GUI:

And here is the same problem seen on the polling Tentacle in TRACE-mode (hope it is readable):
2021-10-22 08:54:55.6735 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:
2021-10-22 08:55:25.7106 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:
2021-10-22 08:55:55.7445 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:
2021-10-22 08:56:25.7857 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:
2021-10-22 08:56:55.8347 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:
2021-10-22 08:57:25.8700 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:
2021-10-22 08:57:26.0800 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::StartScript[1] / df02736d-4888-427b-ae57-b4e1cdc464c4
2021-10-22 08:57:26.0845 16006 13 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [no locks] Trying to acquire lock.
2021-10-22 08:57:26.0845 16006 13 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [“ServerTasks-858316” (has a read lock)] Lock taken.
2021-10-22 08:57:26.0886 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:26.6446 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::GetStatus[2] / ceacc0b6-1200-406f-a3f9-3b5093babe3d
2021-10-22 08:57:26.6714 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:27.2392 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::GetStatus[3] / 9304319d-583a-47b3-a11c-13a72e3d5f24
2021-10-22 08:57:27.2466 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:27.7996 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::GetStatus[4] / 2ccad032-0f75-4cb4-a7fc-761334a16447
2021-10-22 08:57:27.8067 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:28.3470 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::GetStatus[5] / 4d192143-cffd-4d25-bce8-0f20bf4d89e4
2021-10-22 08:57:28.3532 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:28.4178 16006 13 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [“ServerTasks-858316” (has a read lock)] Releasing lock.
2021-10-22 08:57:28.8944 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::GetStatus[6] / 3898244f-df2c-49bc-973b-1e99d363a291
2021-10-22 08:57:28.9006 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:29.1257 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::CompleteScript[7] / 86959536-44e7-4370-90ba-886a31f2cb9a
2021-10-22 08:57:29.1318 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:29.3133 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::StartScript[1] / 3d13bbbe-aa6e-4f91-b44d-e6ff540b2f0f
2021-10-22 08:57:29.3156 16006 25 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [no locks] Trying to acquire lock.
2021-10-22 08:57:29.3156 16006 25 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [“ServerTasks-858316” (has a read lock)] Lock taken.
2021-10-22 08:57:29.3199 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:29.5445 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:
2021-10-22 08:57:29.8970 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::GetStatus[2] / 9018f1a9-36b2-42a5-aad4-237ff57e4370
2021-10-22 08:57:29.9082 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:30.4861 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::GetStatus[3] / 246489c9-3f14-4522-b04b-75d2ec072a14
2021-10-22 08:57:30.4937 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:30.6818 16006 25 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [“ServerTasks-858316” (has a read lock)] Releasing lock.
2021-10-22 08:57:31.0479 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::GetStatus[4] / e95a597f-30e3-4dd4-bb61-8d61fc72730b
2021-10-22 08:57:31.0541 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 08:57:31.2871 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::CompleteScript[5] / e1a72f75-2cbf-498f-9a8a-49f53fa16e3b
2021-10-22 08:57:31.2929 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 09:14:43.3311 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received: IScriptService::StartScript[1] / eba23c9d-6146-4306-a504-893226f44c39
2021-10-22 09:14:43.3311 16006 13 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [no locks] Trying to acquire lock.
2021-10-22 09:14:43.3311 16006 13 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [“ServerTasks-858316” (has a read lock)] Lock taken.
2021-10-22 09:14:43.3385 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Sent: Halibut.Transport.Protocol.ResponseMessage
2021-10-22 09:14:43.4270 16006 7 ERROR https://octopus.zzzz.net:10943/ 7 Halibut client exception: An error occurred when sending a request to ‘https://octopus.zzzz.net:10943/’, after the request began: XYZ. Retrying in 120.0 seconds
Halibut.HalibutClientException: An error occurred when sending a request to ‘https://octopus.zzzz.net:10943/’, after the request began: XYZ
—> System.Security.Authentication.AuthenticationException: XYZ
at Halibut.Transport.Protocol.MessageExchangeStream.ExpectProceeed()
at Halibut.Transport.Protocol.MessageExchangeProtocol.ExchangeAsSubscriber(Uri subscriptionId, Func`2 incomingRequestProcessor, Int32 maxAttempts)
at Halibut.Transport.PollingClient.b__12_0(MessageExchangeProtocol protocol)
at Halibut.Transport.SecureClient.ExecuteTransaction(ExchangeAction protocolHandler, CancellationToken cancellationToken)
— End of inner exception stack trace —
at Halibut.Transport.SecureClient.HandleError(Exception lastError, Boolean retryAllowed)
at Halibut.Transport.SecureClient.ExecuteTransaction(ExchangeAction protocolHandler, CancellationToken cancellationToken)
at Halibut.Transport.PollingClient.ExecutePollingLoop(Object ignored)
2021-10-22 09:14:45.2371 16006 13 TRACE [ServerTasks-858316] [RunningScript] [Read Lock] [“ServerTasks-858316” (has a read lock)] Releasing lock.
2021-10-22 09:16:43.4657 16006 7 INFO https://octopus.zzzz.net:10943/ 7 Opening a new connection to https://octopus.zzzz.net:10943/
2021-10-22 09:16:43.5514 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Connection established to [::ffff:yyy.yyy.yyy.yyy]:10943 for https://octopus.zzzz.net:10943/
2021-10-22 09:16:43.5514 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Performing TLS handshake
2021-10-22 09:16:43.6901 16006 7 INFO https://octopus.zzzz.net:10943/ 7 Secure connection established. Server at [::ffff:yyy.yyy.yyy.yyy]:10943 identified by thumbprint: XXXXXXXXXXXXXXXXXXXXXXXXXXXXX, using protocol Tls12
2021-10-22 09:16:43.9164 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:
2021-10-22 09:16:44.0413 16006 7 TRACE https://octopus.zzzz.net:10943/ 7 Received:

[donny.bell]

Hi @Lasse,

Thank you for contacting Octopus Support. I’m sorry you are running into this issue.

With this type of error, the usual cause is an environmental issue with the network. I would recommend contacting your network team for assistance in troubleshooting.

If you have any additional questions or if we can assist with anything else, please let us know.

Best Regards,
Donny

[Lasse (Lazaros)]

Hi Donny
Thanks for the fast answer. I could have been more clear on this. Many times when we experience this issue I have been running the following command on the Tentacle machine to verify the communication:
curl -v telnet://octopus.zzzz.net:10943
This command has never failed.
I found some information about an interesting setting regarding Halibut:
<add key="Halibut.TcpClientPooledConnectionTimeout" value="00:00:00"/>
…in this ticket…

Error during Acquire Packages

we run about 20 deploys every morning to our QA and Staging environments for our multiple tenants. Most work without a problem, but each morning, one or two will fail during Acquire Packages. each server gets multiple packages, and this doesn’t necessarily occur on the first package, but often later, after several have uploaded successfully. the error is this: Uploading package Encompass.DatabaseLoggingService 2015.2.2 Beginning streaming transfer of Encompass.DatabaseLoggingService.2015.2.…

Since we have a polling agent maybe there is a similar setting for the Tentacle side of the communication?

[donny.bell]

Hi @Lasse,

Thank you for getting back to me.

In most cases we’ve seen, it’s a network device terminating the connection after being open for a certain period of time. In this scenario, we would expect that new connections will continue to work fine.

Regarding the TcpClientPooledConnectionTimeout key, I’ll check with our Product Engineer Team to see if this applies to a Polling Tentacle as well. Keep in mind that this setting is unlikely to make a difference if there’s an external networking device that’s causing this.

I’ll let you know once I hear back.

Best Regards,
Donny

[Lasse (Lazaros)]

Hi Donny
Our network team is investigating this but the problem is still present. It seems that the Tentacle is not able to recover the connection once it has been down. Only a restart of the Tentacle helps.
There are many other teams on this server and it seems that they don’t have the same problem, but they are mostly using listening tentacles.
If our (polling) Tentacle is reusing the same (failed) connection maybe something like TcpClientPooledConnectionTimeout would help us.

[donny.bell]

Hi @Lasse,

Thank you for getting back to me.

I was unable to confirm this functionality internally. However, I took a look at our Halibut code and it does appear that this is still in Halibut.

I would try adding <add key="Halibut.TcpClientPooledConnectionTimeout" value="00:00:00"/> in the <appSettings> section of Tentacle.exe.config. You’ll likely need to restart the tentacle after making this change.

Give that a try and let me know if that seems to help.

Best Regards,
Donny

[Lasse (Lazaros)]

Hi Donny
This weekend we had our Octopus server upgraded to a new version so I want to wait one week before I apply this setting. I will get back with the result.

BR
Lasse

[Lasse (Lazaros)]

@donny.bell

<add key="Halibut.TcpClientPooledConnectionTimeout" value="00:00:00"/>

Hi @donny.bell
We had the same problems even after the upgrade so I made the suggested change with the Helibut setting and it seems to have solved our problem. Thanks for your help.
BR
Lasse