Slow handshake with Octopus server

wayne_x_turner's Avatar

wayne_x_turner

18 Jan, 2017 03:57 AM

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
....

  1. Support Staff 1 Posted by Dalmiro Grañas on 18 Jan, 2017 06:54 PM

    Dalmiro Grañas's Avatar

    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

  2. Support Staff 2 Posted by Dalmiro Grañas on 18 Jan, 2017 06:58 PM

    Dalmiro Grañas's Avatar

    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

  3. 3 Posted by wayne_x_turner on 19 Jan, 2017 04:13 AM

    wayne_x_turner's Avatar

    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.

  4. Support Staff 4 Posted by Dalmiro Grañas on 19 Jan, 2017 04:09 PM

    Dalmiro Grañas's Avatar

    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

  5. Paul Stovell closed this discussion on 19 Apr, 2017 02:08 PM.

Comments are currently closed for this discussion. You can start a new one.

Keyboard shortcuts

Generic

? Show this help
ESC Blurs the current field

Comment Form

r Focus the comment reply box
^ + ↩ Submit the comment

You can use Command ⌘ instead of Control ^ on Mac