Slow handshake with Octopus server

Legacy Execution
1

Hi Octopus gurus,

We’re currently having issues with octo.exe commands taking a long time to execute. It looks like the “Handshaking with Octopus server” step is taking about 20 seconds to complete. Because we have a large number of packages, releases etc. this has added around 20 minutes total to our build process.

The issue started quite suddenly with all of our step times jumping from ~2 seconds per octo.exe command to ~22 seconds per octo.exe command.

I’ve included sample logs below from a couple of different octo.exe commands. You can see from the timestamps on each line that there is a significant delay between “Handshaking with Octopus server” and “Handshake successful”.

Any ideas what might be causing this?

Thanks,
Wayne.

Pushing a nuget package manually from the command line:

c:\Temp>octo push --server=http://server/ --apiKey=(key) --package=TestNugetPackage.1.0.0.nupkg --replace-existing
2017-01-18 14:44:58.436 - Octopus Deploy Command Line Tool, version 3.3.16+Branch.master.Sha.47e0e502fcd994db2415887dc3bf8b3f248962a7
2017-01-18 14:44:58.438 -
2017-01-18 14:44:58.586 - Handshaking with Octopus server: http://server/
2017-01-18 14:45:28.255 - Handshake successful. Octopus version: 3.7.12; API version: 3.0.0
2017-01-18 14:45:28.301 - Authenticated as: Octopus Deploy od@domain (a service account)
2017-01-18 14:45:28.301 - Pushing package: c:\Temp\TestNugetPackage.1.0.0.nupkg…
2017-01-18 14:45:29.420 - Push successful

Creating a release through the TeamCity runner:

[Octopus Deploy] Running command: octo.exe create-release --server http://server/ --apikey=(key) --project Full Deploy --enableservicemessages --version 1.0.0.948 --channel 1.0.0 --packageversion=1.0.0.948 --releasenotesfile=C:\Win32App\BuildAgent\temp\buildTmp\releasenotesfile_111.txt --ignoreexisting
[12:50:50][Octopus Deploy] Creating Octopus Deploy release
[12:50:50][Octopus Deploy] Octopus Deploy Command Line Tool, version 3.4.2+Branch.master.Sha.869d64eaf5d2657a5daadda886a2dd697e2a024c
[12:50:50][Octopus Deploy]
[12:50:50][Octopus Deploy] Build environment is NoneOrUnknown
[12:50:50][Octopus Deploy] Handshaking with Octopus server: http://server/
[12:51:11][Octopus Deploy] Handshake successful. Octopus version: 3.7.12; API version: 3.0.0
[12:51:11][Octopus Deploy] Authenticated as: “Octopus Deploy” <“od@domain”> “(a service account)”
[12:51:11][Octopus Deploy] This Octopus Server “supports” channels
…

2

Hi Wayne,

Thanks for reaching out!

The 2 main reasons I can think about for this delay are:

A) VM Performance - For this you could check:

  • Is the Octopus Server having RAM/CPU/Disk IO spikes?
  • Is the SQL VM having RAM/CPU/Disk IO spikes?

B) Network Performance

  • Do you get the same kind of delay if you execute Octo.exe from your workstation instead of from the build server?
  • Same question but from the Octopus Server itself.

That info should give us a good starting point for the troubleshooting.

Regards,
Dalmiro

3

Actually, as soon as I sent that reply I noticed that you are running a fairly recent version of the Octopus Server (3.7.12) with a rather old version of Octo.exe(3.3.16). The version of Octo.exe that the TeamCity runner uses comes bundled in with the TeamCity plugin we provide. So before you test all that above, I recommend you to upgrade to the latest version of the plugin and give that a try to see it it helps with the overall timing.

You can get the latest plugin from here: https://octopus.com/downloads

4

Hi Dalmiro,

Interesting… I’ve run the same command from a different server as you suggested and it only seems to be running slowly from that one machine. The weird part is that the two servers (both physical) have identical specs, are in the same network location and neither is showing any resource problems. So I can’t see any reason why it would run so much slower from one than the other.

I’ve also monitored the octo.exe command while it runs using Wireshark and procmon and it seems that the delay is happening before it tries to talk to the Octopus server.

I’ll try upgrading to a newer version of the plugin and see if that resolves the issue on the slow server. Otherwise I’ll dig a bit deeper on the affected server and see what else I can find.

Thanks!

Cheers,
Wayne.

5

Hi Wayne,

If you want, send me a screenshot of the Wireshark monitoring where I can see the HTTP calls that were made to the Octopus server by the octo.exe process and add a mark or something where the delay takes place. I can pass that image around the team and see if anyone ever saw something similar.

But first I’ll recommend you to upgrade the plugin.

Cheers,
Dalmiro