Very slow deployments on 3.12.8

Serge's Avatar

Serge

03 May, 2017 05:52 PM

We recently upgraded from 3.11.16 to 3.12.8 w/o any issues. Shortly after we setup SSL for the octopus instance and after a bit our deployments started taking forever on the Acquire Packages step. We went from running under 10 seconds on that step to about 2+ minutes now. The odd thing is that not every project is experiencing the issue and worse yet, it seems to come and go. Some projects that were taking a while just yesterday are pretty snappy today. Others are consistently slow. We haven't tried restarting Octopus instance but we did try restarting tentacles w/o any luck. Looking at the logs I'm seeing errors around compression. Is this at all related? Any tips on how to tackle this?

Unhandled exception from web server processing GET to https://octodeploy.vbp.io/app?cb=1493831499: An operation was attempted on a nonexistent network connection
System.Net.HttpListenerException
   at System.Net.HttpResponseStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.IO.Compression.DeflateStream.PurgeBuffers(Boolean disposing)
   at System.IO.Compression.DeflateStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at System.IO.Compression.GZipStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at Octopus.Server.Web.Infrastructure.NancyCompression.<>c__DisplayClass3_0.<CompressResponse>b__0(Stream responseStream) in NancyCompression.cs:line 103
   at Octopus.Server.Web.OctopusNancyHost.OutputWithDefaultTransferEncoding(Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 356
   at Octopus.Server.Web.OctopusNancyHost.ConvertNancyResponseToResponse(NancyContext nancyRequest, Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 341
   at Nancy.NancyEngineExtensions.HandleRequest(INancyEngine nancyEngine, Request request, Func`2 preRequest, Action`1 onComplete, Action`1 onError, CancellationToken cancellationToken)
   at Octopus.Server.Web.OctopusNancyHost.Process(HttpListenerContext ctx) in OctopusNancyHost.cs:line 0
2017-05-03 12:12:02 Error
Unhandled exception from web server processing GET to https://octodeploy.vbp.io/api/events?skip=0&regardingAny=ServerTasks-33875,Deployments-17271: An operation was attempted on a nonexistent network connection
System.Net.HttpListenerException
   at System.Net.HttpResponseStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.IO.Compression.DeflateStream.PurgeBuffers(Boolean disposing)
   at System.IO.Compression.DeflateStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at System.IO.Compression.GZipStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at Octopus.Server.Web.Infrastructure.NancyCompression.<>c__DisplayClass3_0.<CompressResponse>b__0(Stream responseStream) in NancyCompression.cs:line 103
   at Octopus.Server.Web.OctopusNancyHost.OutputWithDefaultTransferEncoding(Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 356
   at Octopus.Server.Web.OctopusNancyHost.ConvertNancyResponseToResponse(NancyContext nancyRequest, Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 341
   at Nancy.NancyEngineExtensions.HandleRequest(INancyEngine nancyEngine, Request request, Func`2 preRequest, Action`1 onComplete, Action`1 onError, CancellationToken cancellationToken)
   at Octopus.Server.Web.OctopusNancyHost.Process(HttpListenerContext ctx) in OctopusNancyHost.cs:line 0
2017-05-03 12:12:02 Error
Unhandled exception from web server processing GET to https://octodeploy.vbp.io/api/projects/Projects-126: An operation was attempted on a nonexistent network connection
System.Net.HttpListenerException
   at System.Net.HttpResponseStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.IO.Compression.DeflateStream.PurgeBuffers(Boolean disposing)
   at System.IO.Compression.DeflateStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at System.IO.Compression.GZipStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at Octopus.Server.Web.Infrastructure.NancyCompression.<>c__DisplayClass3_0.<CompressResponse>b__0(Stream responseStream) in NancyCompression.cs:line 103
   at Octopus.Server.Web.OctopusNancyHost.OutputWithDefaultTransferEncoding(Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 356
   at Octopus.Server.Web.OctopusNancyHost.ConvertNancyResponseToResponse(NancyContext nancyRequest, Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 341
   at Nancy.NancyEngineExtensions.HandleRequest(INancyEngine nancyEngine, Request request, Func`2 preRequest, Action`1 onComplete, Action`1 onError, CancellationToken cancellationToken)
   at Octopus.Server.Web.OctopusNancyHost.Process(HttpListenerContext ctx) in OctopusNancyHost.cs:line 0
2017-05-03 12:12:02 Error
Unhandled exception from web server processing GET to https://octodeploy.vbp.io/api/releases/Releases-11189/progression: An operation was attempted on a nonexistent network connection
System.Net.HttpListenerException
   at System.Net.HttpResponseStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.IO.Compression.DeflateStream.PurgeBuffers(Boolean disposing)
   at System.IO.Compression.DeflateStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at System.IO.Compression.GZipStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at Octopus.Server.Web.Infrastructure.NancyCompression.<>c__DisplayClass3_0.<CompressResponse>b__0(Stream responseStream) in NancyCompression.cs:line 103
   at Octopus.Server.Web.OctopusNancyHost.OutputWithDefaultTransferEncoding(Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 356
   at Octopus.Server.Web.OctopusNancyHost.ConvertNancyResponseToResponse(NancyContext nancyRequest, Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 341
   at Nancy.NancyEngineExtensions.HandleRequest(INancyEngine nancyEngine, Request request, Func`2 preRequest, Action`1 onComplete, Action`1 onError, CancellationToken cancellationToken)
   at Octopus.Server.Web.OctopusNancyHost.Process(HttpListenerContext ctx) in OctopusNancyHost.cs:line 0
2017-05-03 12:12:02 Error
Unhandled exception from web server processing GET to https://octodeploy.vbp.io/api/useronboarding: An operation was attempted on a nonexistent network connection
System.Net.HttpListenerException
   at System.Net.HttpResponseStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at System.IO.Compression.DeflateStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at System.IO.Compression.GZipStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at Octopus.Server.Web.Infrastructure.NancyCompression.<>c__DisplayClass3_0.<CompressResponse>b__0(Stream responseStream) in NancyCompression.cs:line 103
   at Octopus.Server.Web.OctopusNancyHost.OutputWithDefaultTransferEncoding(Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 356
   at Octopus.Server.Web.OctopusNancyHost.ConvertNancyResponseToResponse(NancyContext nancyRequest, Response nancyResponse, HttpListenerResponse response) in OctopusNancyHost.cs:line 341
   at Nancy.NancyEngineExtensions.HandleRequest(INancyEngine nancyEngine, Request request, Func`2 preRequest, Action`1 onComplete, Action`1 onError, CancellationToken cancellationToken)
   at Octopus.Server.Web.OctopusNancyHost.Process(HttpListenerContext ctx) in OctopusNancyHost.cs:line 0
  1. Support Staff 1 Posted by Michael Richard... on 04 May, 2017 02:06 AM

    Michael Richardson's Avatar

    Hi Serge,

    We're sorry to hear you're experiencing performance issues. We will certainly work with you to resolve these.

    May I ask a few questions:

    • In the affected projects, roughly how steps with packages are there?
    • Do the packages come from the built-in Octopus feed, or an external feed?
    • How many machines are you deploying to?

    Would you able to attach the task log from a deployment which experienced the slow package acquisition you describe?

    When next a deployment appears to be running slowly, could you navigate to the 'Tasks' tab in the Octopus portal and see what other tasks are currently executing?

    If possible, would you be able to record a performance trace during a deployment?
    This would greatly help us to diagnose this issue.

    We apologize for any inconvenience. We will get this resolved as soon as possible.

    Regards,
    Michael

  2. 2 Posted by pventurini on 10 May, 2017 08:04 PM

    pventurini's Avatar

    I have seeing similar slowness after updating Octopus from 3.7.7 to 3.13.0. My developers are seeing deployments take almost 10 times as long as before the upgrade. Any advice on what we can do about this?

  3. 3 Posted by Serge on 10 May, 2017 09:27 PM

    Serge's Avatar

    Sorry for a super late reply. We've been messing around with our Octopus installation trying to figure this out. We're still experiencing this issue on and off.

    I'm going to say right away that turning off delta compression by setting Octopus.Acquire.DeltaCompressionEnabled to False seems to resolve the problem. However, delta compression has always been in use even in the older version of Octopus we were on. It seems that the problem has been introduced in the later versions. And, frankly, I feel a little dirty turning off something that's always worked before.

    Outside of that we don't really know what's causing this. It seems to be running slow for projects of various sizes. The issue i'm experiencing now is on a project with 6 deployment steps deploying to 1 target machine. The package size is 6MB and is getting pulled in from TeamCity nuget feed. The number of tasks running simultaneously doesn't seem to matter. It's been running slow even when Octopus is under absolutely no load with only 1 task running. We could probably run a trace. I'll see if we can do that.

  4. Support Staff 4 Posted by Michael Richard... on 11 May, 2017 12:01 AM

    Michael Richardson's Avatar

    Pablo and Serge,

    We have been unable to replicate this. We are obviously missing a piece of the puzzle, and need some more information.

    If you could supply a task log from a slow deployment, that would certainly help.

    Even better would be a performance trace taken while a deployment was running.

    I have created this secure location where you can upload files. Please update this thread if do, as we don't get automatically notified.

    Pablo: In your case is it package acquisition that is taking the time?

  5. 5 Posted by Serge on 11 May, 2017 04:09 AM

    Serge's Avatar

    Michael,
    I uploaded a redacted task log from a project experiencing the problem. I'll check tomorrow to see if we can run a performance trace.

  6. Support Staff 6 Posted by Michael Richard... on 11 May, 2017 05:28 AM

    Michael Richardson's Avatar

    Serge,

    That task log is very interesting. Thanks!

    Some analysis:

    Overall the deployment took approx 2 mins 10 seconds. I'm assuming this is worse than it was previously.

    Of that 2:10:

    • Approx 40 seconds was trying to find previous package versions on the Tentacle, to use for delta-compression.
    • Approx 40 seconds was extracting the package for deployment.
    • The rest seems to be miscellaneous, and nothing seemed significant.

    The 40 seconds for finding previous package versions seems very slow. It can be seen in the log lines below:

    23:10:00   Verbose  |         Finding earlier packages that have been uploaded to this Tentacle.
    23:10:39   Verbose  |         Found 4 earlier versions of ********** on this Tentacle
    

    I would be interested to know:

    • How does this compare to releases before you upgraded?
    • If you look in E:\Octopus\Files on your Tentacle server, how many files are in that folder?

    The 40 seconds to extract the package also seems rather slow, given it is extracting ~140 files from a ~3MB package. It can be seen in the log lines:

    23:10:47   Info     |         Deploying package:    E:\Octopus\Files\**********.1.33.2.nupkg-1162dd25-fa9b-46f4-b35d-1619f6156ad1
    23:11:26   Verbose  |         Extracting package to: E:\Octopus\Applications\**********-**********\**********\1.33.2
    23:11:26   Verbose  |         Extracted 134 files
    

    Likewise, I would be interested to know how this compares to before you upgraded. Or even between other deployments. Are these activities similarly slow in your other projects?

    I'm going to focus on the finding previous package versions for the moment, and see what we can do to improve it's performance.

    For others watching this thread, I'd be interested to know if you are seeing similar.

  7. 7 Posted by pventurini on 11 May, 2017 01:19 PM

    pventurini's Avatar

    I uploaded two raw tasks logs. One before the upgrade using version 3.7.7 and one after using version 3.13.0. It is the same deployment of a slightly different version. Task goes from 3 minutes to 10 minutes.

  8. 8 Posted by Serge on 11 May, 2017 04:43 PM

    Serge's Avatar

    Michael,

    The files directory on the target machine contains 50 packages varying in size from 600KB to 6MB. All in all, 144MB in total.

    I also uploaded logs for the same project dating a few months back, which would be prior to the Octopus upgrade.

  9. 9 Posted by Serge on 11 May, 2017 04:55 PM

    Serge's Avatar

    Michael,

    Here is a snippet from another deployment after the one I uploaded logs for last. This is a bit similar to the original logs i sent yesterday because there are earlier versions of the package on the target server.

    You can see that the duration for this step is just 2 seconds.

                        |       Success: Upload package ****** version 1.22.13
    23:15:32   Verbose  |         Octopus Deploy: Calamari version 3.3.13+Branch.master.Sha.821b4ffaf94e26f64cd9c14be2f3969587822fad
    23:15:32   Verbose  |         Name                           Value
    23:15:32   Verbose  |         ----                           -----
    23:15:32   Verbose  |         PSVersion                      4.0
    23:15:32   Verbose  |         WSManStackVersion              3.0
    23:15:32   Verbose  |         SerializationVersion           1.1.0.1
    23:15:32   Verbose  |         CLRVersion                     4.0.30319.42000
    23:15:32   Verbose  |         BuildVersion                   6.3.9600.17400
    23:15:32   Verbose  |         PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0}
    23:15:32   Verbose  |         PSRemotingProtocolVersion      2.2
    23:15:32   Verbose  |         Octopus Deploy: Calamari version 3.3.13+Branch.master.Sha.821b4ffaf94e26f64cd9c14be2f3969587822fad
    23:15:32   Verbose  |         Package ****** version 1.22.13 hash 69f85dc11aa1067b7dd164713b86c32ce3fd85a5 has not been uploaded.
    23:15:32   Verbose  |         Finding earlier packages that have been uploaded to this Tentacle.
    23:15:32   Verbose  |         Found 1 earlier version of ****** on this Tentacle
    23:15:32   Verbose  |         - 1.20.1: E:\Octopus\Files\******.1.20.1.nupkg-27eebda5-c55f-4ff8-9e0e-8ddec2802f23
    23:15:32   Verbose  |         Found no earlier versions of ******
    23:15:32   Info     |         Uploading package ******
    23:15:32   Verbose  |         Requesting upload...
    23:15:32   Info     |         Beginning streaming transfer of ******.1.22.13.nupkg-3e7c5be8-fa5a-4169-9980-c72d8e599801
    23:15:34   Info     |         Stream transfer complete
    

    Similarly here is a snippet for the package extract which is 1 second in duraiton

                        |     Success: ******
    23:15:35   Verbose  |       Octopus Server version: 3.3.14+Branch.master.Sha.94cbad9d1e5d9a9515a90f390455374b9fbe30f8
    23:15:35   Info     |       Deploying package 'E:\Octopus\Files\******.1.22.13.nupkg-3e7c5be8-fa5a-4169-9980-c72d8e599801' to machine '******:10933/'
    23:15:35   Verbose  |       Octopus Deploy: Calamari version 3.3.13+Branch.master.Sha.821b4ffaf94e26f64cd9c14be2f3969587822fad
    23:15:35   Info     |       Deploying package:    E:\Octopus\Files\******.1.22.13.nupkg-3e7c5be8-fa5a-4169-9980-c72d8e599801
    23:15:36   Verbose  |       Extracting package to: E:\Octopus\Applications\******\******\1.22.13
    23:15:36   Verbose  |       Extracted 134 files
    23:15:36   Info     |       Performing variable substitution on 'E:\Octopus\Applications\******\******\1.22.13\log4net.Release.config'
    23:15:36   Info     |       Transforming 'E:\Octopus\Applications\******\******\1.22.13\******.exe.config' using 'E:\Octopus\Applications\******\******\1.22.13\******.exe.Release.config'.
    23:15:36   Info     |       Transforming 'E:\Octopus\Applications\******\******\1.22.13\log4net.config' using 'E:\Octopus\Applications\******\******\1.22.13\log4net.Release.config'.
    23:15:36   Verbose  |       Executing Replace (transform line 4, 11)
    
  10. Support Staff 10 Posted by Michael Richard... on 15 May, 2017 06:01 AM

    Michael Richardson's Avatar

    Thank you both for those task logs.

    Being able to compare the before and after logs highlighted where performance has degraded. It made it clear the delays are on the Tentacle side. Specifically it seems to be when interacting with the file-system.

    Unfortunately, we are still unsure exactly what has caused the degradation in performance.

    I have created a custom build of Calamari (our deployment utility executable). The custom Calamari packages can be download from here. Would you be able to follow the steps in the readme here to tell your Octopus server to use the Calamari packages from the supplied location. And possibly again upload your task logs from a deployment using this custom Calamari?
    (If any of that is unclear, please let me know).

    I have some hope that this build may improve the performance, but at the very least I have added some extra diagnostics logging.

    Thank-you for your patience. I believe we are getting close.
    Because we have been unable to replicate this, we are very grateful for your cooperation!

  11. 11 Posted by Serge on 16 May, 2017 02:54 PM

    Serge's Avatar

    Michael,

    We installed the new Calamari and did several test builds. I uploaded the log file to the secure drop location. Here are a couple of interesting parts that we found.

    09:07:24   Verbose  |         Searching 'E:\Octopus\Files' recursively
    09:07:24   Verbose  |         Found 9 matching files
    09:07:24   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.13.0.nupkg-597ef3e6-0ffb-4a80-9b37-4d285801f0fb'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.14.0.nupkg-bc817466-bbdb-4154-995f-73d5726cdbab'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.15.0.nupkg-e9e74aff-5b15-47d0-b59d-a81f4b5e52bb'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.25.0.nupkg-1074779f-57c4-401e-985f-af6d465b8cf6'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.40.0.nupkg-32533d22-45d8-4e67-85d4-e5ab4947cf5e'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.41.0.nupkg-bd8f7eff-53ff-41f2-944d-35ffc86d35fe'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.45.0.nupkg-9068b9c2-8726-4658-a3a5-1aa833a3b920'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.47.0.nupkg-dc712e54-d59b-4d5e-be13-8e9464ddca4d'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.9.0.nupkg-ca71a9ad-6d99-4550-902c-953f2e5f7322'
    09:08:02   Verbose  |         Completed reading package metadata
    09:08:02   Verbose  |         Found 5 earlier versions of ****** on this Tentacle
    09:08:02   Verbose  |         - 1.17.9.0: E:\Octopus\Files\******.1.17.9.0.nupkg-ca71a9ad-6d99-4550-902c-953f2e5f7322
    09:08:02   Verbose  |         - 1.17.47.0: E:\Octopus\Files\******.1.17.47.0.nupkg-dc712e54-d59b-4d5e-be13-8e9464ddca4d
    09:08:02   Verbose  |         - 1.17.45.0: E:\Octopus\Files\******.1.17.45.0.nupkg-9068b9c2-8726-4658-a3a5-1aa833a3b920
    09:08:02   Verbose  |         - 1.17.41.0: E:\Octopus\Files\******.1.17.41.0.nupkg-bd8f7eff-53ff-41f2-944d-35ffc86d35fe
    09:08:02   Verbose  |         - 1.17.40.0: E:\Octopus\Files\******.1.17.40.0.nupkg-32533d22-45d8-4e67-85d4-e5ab4947cf5e
    09:08:02   Info     |         Found matching version 1.17.47.0: D:\Octopus\OctopusServer\PackageCache\feeds-1\******.1.17.47.0_807F2992C456F04B8F9023DB346B88A7.nupkg
    09:08:41   Info     |         Delta for package ******.1.17.48.0 successfully uploaded and applied.
    

    It looks like the performance issue is around reading nupkg metadata. In the snippet above, it's taking 38 seconds. Here is a subsequent read that's a little further down from the one above which indicates the same issue taking place again. (Also, likely unrelated and may not be an issue, but the logs show that 9 matching files were located, but only 5 of those are earlier versions.)

                        |           Success: Uploading and applying delta ******.1.17.47.0_2A473485_to_1.17.48.0_339A084F.octodelta
    09:08:03   Verbose  |             Octopus Deploy: Calamari version 3.7.59-fs-perf-diagnostics.2+Branch.fs-perf-diagnostics.Sha.97fbcaf9354bf1e42d132a96f2fd2d4bc2ecd0c8
    09:08:03   Verbose  |             Environment Information:
    09:08:03   Verbose  |             OperatingSystem: Microsoft Windows NT 6.2.9200.0
    09:08:03   Verbose  |             OsBitVersion: x64
    09:08:03   Verbose  |             Is64BitProcess: True
    09:08:03   Verbose  |             CurrentUser: NT AUTHORITY\SYSTEM
    09:08:03   Verbose  |             MachineName: ISQA-WEB01
    09:08:03   Verbose  |             ProcessorCount: 1
    09:08:03   Verbose  |             CurrentDirectory: E:\Octopus\Work\20170516140756-241
    09:08:03   Verbose  |             TempDirectory: C:\Windows\TEMP\
    09:08:03   Verbose  |             HostProcessName: Calamari
    09:08:03   Verbose  |             Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.47.0.nupkg-dc712e54-d59b-4d5e-be13-8e9464ddca4d'
    09:08:41   Verbose  |             Completed reading package metadata
    09:08:41   Verbose  |             Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.47.0.nupkg-dc712e54-d59b-4d5e-be13-8e9464ddca4d'
    09:08:41   Verbose  |             Completed reading package metadata
    09:08:41   Verbose  |             The drive containing 'E:\Octopus\Files' has 29.843 GB of free space
    09:08:41   Info     |             Applying delta to E:\Octopus\Files\******.1.17.47.0.nupkg-dc712e54-d59b-4d5e-be13-8e9464ddca4d with hash 2a473485ad8978eb302a460b1d876700ae3745f8 and storing as E:\Octopus\Files\******.1.17.48.0.nupkg-f2ca1df3-87a8-4ae3-9b51-9070d9fa7f4b
    09:08:41   Info     |             Applying delta: 0%
    09:08:41   Verbose  |             Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.48.0.nupkg-f2ca1df3-87a8-4ae3-9b51-9070d9fa7f4b'
    09:08:41   Verbose  |             Completed reading package metadata
    09:08:41   Verbose  |             Reading nupkg metadata: 'E:\Octopus\Files\******.1.17.48.0.nupkg-f2ca1df3-87a8-4ae3-9b51-9070d9fa7f4b'
    09:08:41   Verbose  |             Completed reading package metadata
    
  12. Support Staff 12 Posted by Michael Richard... on 18 May, 2017 04:20 AM

    Michael Richardson's Avatar

    After much googling and cursing (and thanks to your logs), we finally think we have a pretty good idea as to what is causing this.

    In 3.12.8, we began signing the Calamari executable. Because this is now a signed executable, when it loads signed DLL's Windows will attempt to check the Certificate Revocation List (CRL). Our hypothesis is that in your cases, this check is taking a long time (possibly due to proxies/firewalls).

    An example of this problem can be found here.

    I have built a new custom Calamari, with the CRL check disabled using the method detailed in the Optimize Authenticode section of this post.

    Would you be willing to again try the custom Calamari from here (instructions here)?

    We are very hopeful this will resolve the issue.

  13. 13 Posted by Serge on 19 May, 2017 04:15 PM

    Serge's Avatar

    Michael,

    Your response definitely made sense to our infra guys. We don't allow anything on the deployment targets to talk to the outside world. We pretty much only handle request responses on ports 80/443 from a handful of sources. So to cut to the chase, we ran the latest Calamari build and our deployment times immediately improved! So I think the CRL check was definitely the issue.

    It looks like CRL's hitting verisign for the certificates check. I'll check with our infrastructure team to see if maybe we can accommodate this. What would you say would be the direction to move forward? Will there be changes to Calamari?

    Before I forget, thank you so much for looking into this issue and getting to the bottom of it all!

  14. 14 Posted by Serge on 19 May, 2017 06:12 PM

    Serge's Avatar

    Michael,

    Just talked to our guys, we'll have OCSP/CRL checking enabled. I guess my question is should Calamari be changed to fail verification if it isn't able to communicate with verisign or complete verification in general. If that's a little excessive, should it at the very least write a warning to the logs? Just want to make sure there is something in place that makes the root cause a little bit more obvious.

  15. Support Staff 15 Posted by Michael Richard... on 22 May, 2017 07:22 AM

    Michael Richardson's Avatar

    Serge,

    I'm very glad to hear you confirm that!

    We have disabled the CRL checking in Calamari (just as in your custom build).
    This change has been released in Octopus version 3.13.7. You are of course welcome to continue using the custom build of Calamari until you decide to upgrade.

    The reason the Calamari executable was signed was to prevent certain anti-virus software from attempting to quarantine it. It was an inadvertent side-effect that the CRL checks were being made.

    Thank-you for your patience and persistence in resolving this. We really appreciate it, and we apologize sincerely for any inconvenience.

    Regards,
    Michael

  16. Paul Stovell closed this discussion on 30 Aug, 2017 09:42 AM.

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