Octo.exe slow startup/handshake from TeamCity (and TeamCity server)

Alexander Harris's Avatar

Alexander Harris

01 Dec, 2017 10:07 AM

Hi All,

Very similar issue to this question: http://help.octopusdeploy.com/discussions/problems/50710-slow-hands...

Initially thought it was identical and a slow "handshake" with the server. See the following log snippet from TeamCity:

[17:19:24][Step 4/4] Octopus Deploy (3m:09s)
[17:19:24][Octopus Deploy] Running command:   octo.exe create-release --server https://server.domain/octopus/ --apikey SECRET --project Project Name --enableservicemessages --version 0.0.42 --channel Continuous Integration --deployto Integration --progress --Packageversion=0.0.42
[17:19:24][Octopus Deploy] Creating Octopus Deploy release
[17:19:25][Octopus Deploy] Octopus Deploy Command Line Tool, version 3.4.2+Branch.master.Sha.869d64eaf5d2657a5daadda886a2dd697e2a024c
[17:19:25][Octopus Deploy] 
[17:19:25][Octopus Deploy] Build environment is NoneOrUnknown
[17:19:25][Octopus Deploy] Handshaking with Octopus server: https://server.domain/octopus/ 
[17:22:02][Octopus Deploy] Handshake successful. Octopus version: 3.11.4; API version: 3.0.0

NB the time between "Handshaking with Octopus server" and "Handshake successful". Following the advice in the linked question I updated the TeamCity plugin to the version linked from the release page for our current Octopus server version. Now I see that the log is slightly different:

[09:01:01][Step 4/4] Octopus Deploy (3m:10s)
[09:01:01][Octopus Deploy] Running command:   octo.exe create-release --server https://server.domain/octopus/ --apikey SECRET --project Project Name --enableservicemessages --version 0.0.43 --channel Continuous Integration --deployto Integration --progress --Packageversion 0.0.43
[09:01:01][Octopus Deploy] Creating Octopus Deploy release
[09:01:02][Octopus Deploy] Octopus Deploy Command Line Tool, version 4.11.0
[09:01:02][Octopus Deploy] 
[09:03:41][Octopus Deploy] Build environment is Handshaking with Octopus server: https://server.domain/octopus/
[09:03:41][Octopus Deploy] Handshake successful. Octopus version: 3.11.4; API version: 3.0.0

NB that the delay is about the same, but now occurs on the "blank" line before the "handshaking" log message.

Finally I updated to the most recent version of the TeamCity plugin (Octopus Deploy Command Line Tool, version 4.22.1) - the results are identical, large delay on the "blank" line.

Following this, I downloaded the latest version of the command line and manually created a release based on the above call. I observed the following:

  • Running from my local machine: Whole command executes quickly, handshake etc, take a few seconds and the rest of the deployment happens as expected.
  • Running from the build server (as myself): As above. Command executes quickly, even when a build is running and the TeamCity call is "stalled" as described.

I should note that in all cases I've been watching CPU usage etc. and the server is not under any significant load.

This leads me to think there is an issue with the user account the build server is running under. The delay seems to vary between about 3 and 5 minutes. It may be worth noting that the build server has no internet access.

  • Could this be due to a network request(s) being made and blocked during the Octo startup?
  • Is there a way to force more detailed logging of the TeamCity plugin?
  • Any other suggestions of what is wrong here?
  1. 1 Posted by Alexander Harri... on 01 Dec, 2017 10:36 AM

    Alexander Harris's Avatar

    Additional information which may be helpful...

    I used Fiddler to inspect web requests on the build server and notice the following.

    When running from the command line (as myself), I see a

    CONNECT http://server.domain:443  
    200 Connection Established ()
    

    HTTP tunnel to the octopus server. This is hosted on the same server as TeamCIty incidentally.

    WHen triggering the build from TeamCity, I see no such request in Fiddler. Maybe this is an artefact of both systems being hosted on the same build server, but thought it worth mentioning.

  2. Support Staff 2 Posted by Dalmiro Grañas on 01 Dec, 2017 03:55 PM

    Dalmiro Grañas's Avatar

    Hi Alexander,

    Thanks for reaching out. I've seen this happen a couple of time when dodgy proxies/DNS are in the way. Since both TC and Octopus are hosted on the same machine, try using https://localhost/octopus/ instead of https://server.domain/octopus/. and let me know if you notice a change in the performance

    Best regards,
    Dalmiro

  3. 3 Posted by Alexander Harri... on 01 Dec, 2017 04:22 PM

    Alexander Harris's Avatar

    Hi Dalmiro,

    Thanks for the suggestion. Unfortunately, the certificate is invalid for that host name so the connection is refused.

    [16:07:17][Step 4/4] Octopus Deploy (1m)
    [16:07:17][Octopus Deploy] Running command:   octo.exe create-release --server https://localhost/octopus/ --apikey SECRET --project Project Name --enableservicemessages --version 0.0.48 --channel Continuous Integration --deployto Integration --progress --Packageversion 0.0.48
    [16:07:17][Octopus Deploy] Creating Octopus Deploy release
    [16:07:17][Octopus Deploy] Octopus Deploy Command Line Tool, version 4.22.1
    [16:07:17][Octopus Deploy] 
    [16:07:18][Octopus Deploy] Build environment is The following certificate errors were encountered when establishing the HTTPS connection to the server: RemoteCertificateNameMismatch
    [16:07:18][Octopus Deploy] Certificate subject name: CN=server.domain
    [16:07:18][Octopus Deploy] Certificate thumbprint:   B7A821F913EFA515888D5708F5B769F96C4547B3
    [16:07:19][Octopus Deploy] The following certificate errors were encountered when establishing the HTTPS connection to the server: RemoteCertificateNameMismatch
    

    The error message repeated a bunch of times then the process failed.

    I then temporarily enabled HTTP connections, both to localhost and to the domain.server address.

    • HTTP + Localhost: Instant response.
    • HTTP + server.domain: slow as before.

    This seems to confirm your suspicion (and mine) that there is something funny network related going on. You suggested proxy / DNS. Do you have any suggestions to diagnose or fix this? Obviously I don't want to leave HTTP enabled, and though I could look at getting a new certificate issued that maps to localhost I'd rather not have to do this, especially as we may move the install to a different server at some point.

    This seems suspiciously similar to issues we have had with web requests via Octopus to different servers on the network. I can't find the URL to the discussion just now, but I have asked in the past about issues where we were attempting to deploy SSRS reports and the connection to the web service URL (via powershell) was very slow / timed out and failed when run by Octopus, but not when run by my own account.

    Seems similar to me - long, variable network timeout. In that case, I suspect that it was most of the time taking longer than some internal timeout and failing, whereas here Octo.exe is just waiting until it's finished.

    Thanks again, any help HUGELY appreciated.

  4. Support Staff 4 Posted by Dalmiro Grañas on 03 Dec, 2017 11:31 PM

    Dalmiro Grañas's Avatar

    You could try adding an entry in your host file like https://server.domain/octopus/ localhost and see it that works.

  5. 5 Posted by Alexander Harri... on 06 Dec, 2017 11:03 AM

    Alexander Harris's Avatar

    Hi Dalmiro,

    I added a hosts file entry as you suggested, ended up looking like:

    127.0.0.1   server.domain
    

    Testing a ping to server.domain confirms it's getting redirected to localhost, but the deployment creation still stalls at the same point in time. Is there a way to force more verbose logging from Octo.exe?

  6. 6 Posted by Alexander Harri... on 06 Dec, 2017 02:27 PM

    Alexander Harris's Avatar

    In addition to the above, I've been trying to create an easier test to replicate this in different environments etc.

    I've come up with the following powershell script which demonstrates the problem:

    Write-Host "Addng the .dll"
    Add-Type -Path 'C:\Program Files\Octopus Deploy\Tentacle\Octopus.Client.dll' 
    
    $apikey = 'API-XABCDEFG123456' # Get this from your profile
    $octopusURI = 'https://server.domain/octopus' # Your server address
    $projectId = "project-name" # Get this from /api/projects
    
    Write-Host "Creating Endpoint"
    $endpoint = new-object Octopus.Client.OctopusServerEndpoint $octopusURI,$apikey 
    Write-Host "Creating Repository"
    $repository = new-object Octopus.Client.OctopusRepository $endpoint
    
    Write-Host "Geting project."
    $project = $repository.Projects.Get($projectId)
    Write-Host "Writing description."
    $project.Description
    

    The advantage of this powerhsell script is that I can run identical code in multiple places. Matching with previous observations I see there is a long delay at the line $repository = new-object Octopus.Client.OctopusRepository $endpoint as follows:

    • TeamCity/Octopus server. My own account. From command line. No delay.
    • TeamCity/Octopus server. TeamCity service account. From command line. Delay
    • TeamCity/Octopus server. From TeamCity build configuration. Delay
    • TeamCity/Octopus server. From Octopus deploy script console. Delay
    • Local machine. My own account. From command line. No delay.
    • Local machine. TeamCity service account. No delay.

    So it appears to be a combination of when running as the service account ON the build server that the delay happens. Does anyone have any further suggestions as to how to troubleshoot this?

  7. Support Staff 7 Posted by Dalmiro Grañas on 07 Dec, 2017 03:25 PM

    Dalmiro Grañas's Avatar

    Hi Alexander,

    Based on your investigation this definitely seems related to a combination of the User invoking the call + something odd in the network (perhaps different settings for each user). Could you try running TRACERT.exe [OctopusURL] from different locations and users and see if anything catches your attention? What we are looking for here is a pattern like a specific TPC call taking longer than usual.

  8. 8 Posted by Alexander Harri... on 08 Dec, 2017 10:55 AM

    Alexander Harris's Avatar

    Hi Dalmiro,

    I've been doing some more digging. Using TRACERT as you suggest runs with no issues in all scenarios. I took to ProcMon.exe to try and trace activity of the process and see what was happening.

    What I found was as follows: There is no network activity (as logged by ProcMon) for the process / thread in question at all until after the delay.

    I won't dump a load of logs here, but in general it's something like:

    • Powershell starting up
    • Loading files .Net dlls etc.
    • Loading registry keys
    • DELAY STARTS
    • Some threads closing and opening, but very little activity
    • DELAY ENDS
    • Network requests to the octopus endpoint.

    I compared this to a similar trace of me running it on the same machine and the pattern is the same, without the delay:

    • Powershell starting up
    • Loading files .Net dlls etc.
    • Loading registry keys
    • Network requests to the octopus endpoint.

    What I noticed was a difference in the registry keys that Powershell is reading from before the "delay".

    When I run it myself, it reads HKCU\Software\Microsoft\Windows\CurrentVersion\Internet Settings\Wpad\00-10-db-ff-20-80

    When the service account runs it via TeamCity it reads:

    HKU\<SID>\Software\Microsoft\Windows\CurrentVersion\Internet Settings\Wpad\00-10-db-ff-20-80 which it can't find.

    From what I read online, this key is to do with detection of proxy auto-configuration scripts. Is this something anyone has come across before? I will try talking with our IT guys again about this, but any suggestions would be great?

    I know I'm a bit off topic here in the sense that this is not so much an Octopus issue (though I feel this is getting more and more similar to the issue we have making power shell requests to our SSRS server).

  9. Support Staff 9 Posted by Dalmiro Grañas on 12 Dec, 2017 04:26 PM

    Dalmiro Grañas's Avatar

    Hi Alexander,

    I also looked online for that registry key and like you said it seems to be related a to a feature called Web Proxy Automated Discovery (wpad).

    This is definitely the first time we've seen this issue with octo.exe. Unfortunately we (because I discussed this issue with the whole team) ran out of ideas for this one. I even took a screenshot of last night's call where we were all trying to troubleshoot this issue. Check the attached screenshot to see how confused everyone was.

    I'm afraid at this point all I can recommend is to involve your IT guys in this issue and see what they can do about it.

    Sorry we can't be of more help.

    Best regards,
    Dalmiro

  10. 10 Posted by Alexander Harri... on 13 Dec, 2017 12:08 PM

    Alexander Harris's Avatar

    Hi Dalmiro,

    Thanks for the awesome response. The photo may now be pinned to our wall :).

    Really appreciate the help with this. I'm going to take it up with our IT guys and see if anyone there has any ideas. If we dig up anything helpful, or if we spot that I've mis-diagnosed anything I'll post an update to let you know in case it might help in future.

    Cheers,

    Alexander

Reply to this discussion

Internal reply

Formatting help / Preview (switch to plain text) No formatting (switch to Markdown)

Attaching KB article:

»

Attached Files

You can attach files up to 10MB

If you don't have an account yet, we need to confirm you're human and not a machine trying to post spam.

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