Failed package step doesn't fail

Jeff_Mounce · 13 June 2018 21:28

When we return Exit 1 or Throw in the PostDeploy.ps1 script, the log shows exit code of 0x1 but the Octopus step doesn’t fail. What gives?

176 additional lines not shown
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\STORM.Platform.pdb).
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\WAFbizComponents.dll).
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\WAFdbComponents.dll).
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\WAFMetadata.dll).
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\WAFwebComponents.dll).
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\Webhooks.Common.dll).
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\Webhooks.Common.pdb).
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\Workflow.Platform.dll).
June 13th 2018 14:18:49Info
Info: Updating file (AdjudicationMatrix-API\bin\Workflow.Platform.pdb).
June 13th 2018 14:18:49Info
Info: Deleting file (AdjudicationMatrix-API\release-notes.json).
June 13th 2018 14:18:50Info
Warning: An error was encountered when processing operation ‘Delete File’ on ‘release-notes.json’.
June 13th 2018 14:18:50Info
Retrying operation ‘Delete’ on object filePath (AdjudicationMatrix-API\release-notes.json). Attempt 1 of 5.
June 13th 2018 14:18:51Info
Warning: An error was encountered when processing operation ‘Delete File’ on ‘release-notes.json’.
June 13th 2018 14:18:51Info
Retrying operation ‘Delete’ on object filePath (AdjudicationMatrix-API\release-notes.json). Attempt 2 of 5.
June 13th 2018 14:18:53Info
Warning: An error was encountered when processing operation ‘Delete File’ on ‘release-notes.json’.
June 13th 2018 14:18:53Info
Retrying operation ‘Delete’ on object filePath (AdjudicationMatrix-API\release-notes.json). Attempt 3 of 5.
June 13th 2018 14:18:55Info
Warning: An error was encountered when processing operation ‘Delete File’ on ‘release-notes.json’.
June 13th 2018 14:18:55Info
Retrying operation ‘Delete’ on object filePath (AdjudicationMatrix-API\release-notes.json). Attempt 4 of 5.
June 13th 2018 14:18:55Info
Warning: An error was encountered when processing operation ‘Delete File’ on ‘release-notes.json’.
June 13th 2018 14:18:55Info
Retrying operation ‘Delete’ on object filePath (AdjudicationMatrix-API\release-notes.json). Attempt 5 of 5.
June 13th 2018 14:18:55Error
Error Code: ERROR_FILE_IN_USE
June 13th 2018 14:18:55Error
More Information: Web Deploy cannot modify the file ‘release-notes.json’ on the destination because it is locked by an external process. In order to allow the publish operation to succeed, you may need to either restart your application to release the lock, or use the AppOffline rule handler for .Net applications on your next publish attempt. Learn more at: http://go.microsoft.com/fwlink/?LinkId=221672#ERROR_FILE_IN_USE.
June 13th 2018 14:18:55Error
Error: The process cannot access ‘C:\inetpub\wwwroot\AdjudicationMatrix-API\release-notes.json’ because it is being used by another process.
June 13th 2018 14:18:55Error
Error count: 1.
6 additional lines not shown
June 13th 2018 14:18:55Info
Info: True v2.0.50727 C:\Windows\assembly\GAC_MSIL\Microsoft.Web.Administrat…
June 13th 2018 14:18:55Info
Info:
June 13th 2018 14:18:55Info
Info: Copying web.config from ‘C:\Octopus\Applications\beta\amapi-beta\11.11.404\content\web.config’ to ‘C:\inetpub\wwwroot\AdjudicationMatrix-API’…
June 13th 2018 14:18:55Info
Info:
June 13th 2018 14:18:55Info
Info: Copying version file from ‘C:\Octopus\Applications\beta\amapi-beta\11.11.404\content\version.txt’ to ‘C:\inetpub\wwwroot\AdjudicationMatrix-API’…
June 13th 2018 14:18:55Info
Info:
June 13th 2018 14:18:55Info
Info: Copying release notes from ‘C:\Octopus\Applications\beta\amapi-beta\11.11.404\content\release-notes.json’ to ‘C:\inetpub\wwwroot\AdjudicationMatrix-API’…
June 13th 2018 14:18:55Info
Info:
June 13th 2018 14:18:55Info
Warning: The process cannot access the file
June 13th 2018 14:18:55Info
Warning: ‘C:\inetpub\wwwroot\AdjudicationMatrix-API\release-notes.json’ because it is
June 13th 2018 14:18:55Info
being used by another process.
June 13th 2018 14:18:55Info
At C:\Octopus\Applications\beta\amapi-beta\11.11.404\AfterUnpack.ps1:89 char:7
June 13th 2018 14:18:55Info

```
  Throw $_.Exception.Message 
```

June 13th 2018 14:18:55Info

```
  ~~~~~~~~~~~~~~~~~~~~~~~~~~ 
```

June 13th 2018 14:18:55Info
+ CategoryInfo : OperationStopped: (The process can…nother proc
June 13th 2018 14:18:55Info
ess.:String) [], RuntimeException
June 13th 2018 14:18:55Info
+ FullyQualifiedErrorId : The process cannot access the file ‘C:\inetpub\w
June 13th 2018 14:18:55Info
wwroot\AdjudicationMatrix-API\release-notes.json’ because it is being used
June 13th 2018 14:18:55Info
by another process.
June 13th 2018 14:18:55Info

June 13th 2018 14:18:55Error
Error: The process ‘C:\Windows\system32\cmd.exe’ (command line ‘’) exited with code ‘0x1’.
June 13th 2018 14:18:55Error
Error count: 1.
June 13th 2018 14:18:55Info
Error during ‘-postSync’.
June 13th 2018 14:18:55Verbose
Adding journal entry:
June 13th 2018 14:18:55Verbose

June 13th 2018 14:18:55Verbose
Process C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe in C:\Octopus\Work\20180613211839-108794-335 exited with code 0
June 13th 2018 14:18:55Verbose
Updating manifest with output variables
June 13th 2018 14:18:55Verbose
Updating manifest with action evaluated variables
June 13th 2018 14:18:55Verbose
Planning retention policy
June 13th 2018 14:18:55Verbose
Successfully finished Deploy Application on hostname

Lawrence_Wilson · 14 June 2018 02:58

Hi Jeff,
Thanks for getting in touch! I’m sorry to hear you are seeing a deployment continue irrespective of if the post-deployment step fails.

One potential option here could be to include $ErrorActionPreference = "Stop" at the beginning of your post-deployment step. By default, PowerShell’s error action preference is to Continue. In this case, when your script encounters non-terminating errors such as file not found, or permission problems it will tell you about them but your script will continue on.

I look forward to hearing if this suggestion works for you.

Kind regards,
Lawrence.

Jeff_Mounce · 14 June 2018 03:17

We already do that.
Any unobvious suggestions?

Did you look at the log above?
Can you tell me why Octo returns 0 when the script obviously returns 1?

Jeff_Mounce · 15 June 2018 15:47

Anyone there???

Lawrence_Wilson · 17 June 2018 08:58

Hi Jeff,
Thanks for keeping in touch and letting us know you already set your error action preference to stop. I’m sorry for the long delay in getting back to you here. I have successfully reproduced the same behaviour you are seeing on my end. If I call a batch script from within an Octopus step that returns exit 0x1, the step proceeds without error. If I then run the same batch script with exit 1, this will fail as expected.

I will dig into this further on our end and I will update you further when I have more information here.

I look forward to getting in contact with you shortly.

Kind regards,
Lawrence

Jeff_Mounce · 9 July 2018 18:27

I am testing your mechanism on my end and will compare to our existing.

Jeff_Mounce · 11 July 2018 17:55

I’ve created a new project that, when deployed, exhibits the problem we see.
Please do the following steps:

Download the package
Upload the NuGet package to your Octo
Create a simple octopus project that has a single step to deploy a Nuget package with NO FEATURES
Deploy it to an IIS web server
Go to the root folder on the web server
Run cmd as admin
Delete Global.asax
Lock the file: notepad >Global.asax
Create a new release and re-deploy the package

You will see that an error is thrown but only a warning is generated by Octo.

To further prove the error is returned, run PostDeploy.ps1 directly on the target web server with PS ISE or something where you can step through it.

Lawrence_Wilson · 12 July 2018 23:06

Hi Jeff,
Thanks for sending through the detailed steps! Could you please let me know what version of Octopus Server you are using as well?

I look forward to hearing from you.

Kind regards,
Lawrence.

Jeff_Mounce · 12 July 2018 23:19

v2018.5.1

Lawrence_Wilson · 13 July 2018 14:48

Hi Jeff,
Thanks for sending through the version of your Octopus Server, I am testing these steps out in my environment and I’ll get in touch with you shortly.

Kind regards,
Lawrence.

Lawrence_Wilson · 16 July 2018 06:32

Hi Jeff,
Thanks for your patience on this one while I have been looking into it for you. I was able to reproduce the exact results you have been seeing and I believe I have found a solution here.

Octopus checks the last exit code of the entire script once it has finished to determine whether or not it had succeeded.

In testing out this behavior I modified the PostDeploy.ps1 script to check the last error code after each command, I’m able to successfully break out of the script if any of the steps fail.

In my PostDeploy.ps1 as opposed to encapsulating everything inside a try/catch statement, I would instead check the last exit code of each command after they run:

$ErrorActionPreference = "Stop"

$exe = "$PSScriptRoot\path\to.batch.cmd"
$firstCommand = "powershell .\command1.ps1"
if ($LastExitCode -ne 0) {
    throw "failed to run command1"
}
$secondCommand = "cmd.exe /C $exe"
Invoke-Expression -Command $secondCommand
if ($LastExitCode -ne 0) {
    throw "failed to run command2"
}

Our documentation on Error Handling in PowerShell Scripts talks about this in more detail but I hope this has been helpful for you!

Kind regards,
Lawrence.

Jeff_Mounce · 18 July 2018 18:21

That didn’t help me. Same result.
Please send me my modified PostDeploy.ps1 + NuGet package that you got to fail.

Jeff_Mounce · 18 July 2018 18:29

We are now on v2018.6.15

Lawrence_Wilson · 19 July 2018 13:26

Hi Jeff,
Thanks for keeping in touch! I just checked over my previous answer and as you have stated, the solution I gave won’t actually work for you, which I’m very sorry to say.

However, since I have a working reproduction of what you’re seeing in my environment, I’ll be able to consult with our dev team and get an answer for you shortly! I hope to get back to you by the end of tomorrow with some new developments.

I apologise for the delay in getting this one resolved!

Kind regards,
Lawrence.

Jeff_Mounce · 19 July 2018 15:04

Lawrence_Wilson · 20 July 2018 09:03

Hi Jeff,
I’m sending this message to update you on this support ticket. First of all, I want to let you know that we are still looking into what’s happening with your package and are still looking for a root cause as to why you are seeing this behaviour with your deployment.

We have also attempted to create our own package that will call a command line executable in the same way your package does (except without the addition of msdeploy, etc) and from our perspective Octopus is doing what it’s supposed to do in handling these errors. At this time, we are leaning towards the possibility that there may be something within your package that is causing this unknown behaviour.

In the meantime, I hope I can give you some information that will help you get to the bottom of this one as well.

One possible method you can use to troubleshoot this could be with our debugging PowerShell scripts. With this you can pause and step through your scripts in real time from within a deployment using the PowerShell ISE by directly connecting to the Tentacle. With this you might be able to identify some possible cause here.

Further, all of the logic to execute your PowerShell scripts is done using Calamari. We have actually open-sourced this tool and you’re welcome to check exactly how your scripts are being handled here. Specifically, the entry point for PowerShell is here. PowerShell.ps1 is what sets up all the context, and PowershellBootstrapper sets it all up. The code used to check the error code is checked here. I also have a blog post describing error codes as well if you’re interested.

I look forward to getting in touch with you shortly with any more updates!

Kind regards,
Lawrence.

Jeff_Mounce · 20 July 2018 17:46

I asked you to run my script manually on the node because you can see that it returns an exit code of 1. From my perspective, all I can do is code to your spec. If that doesn’t work, it is your problem.

So, either prove to me that my script doesn’t return an exit code of 1 or fix your code.

While I appreciate you giving me info on your open source code, I think figuring out why it doesn’t work is your job, not mine. I have other work to do for my company.

Jeff_Mounce · 30 July 2018 17:57

It’s been 10 days, Lawrence.

Are you guys asleep? on Holiday? maybe ignoring me?

Honestly, your turnaround time is pretty lame.

-Jeff

Lawrence_Wilson · 31 July 2018 05:49

Hi Jeff,
I’m very sorry for not getting back to you sooner on this one hopefully this response will help you get out of trouble though!

The reason you are seeing this behaviour is because Octopus will launch scripts in a new PowerShell session. This, combined with how msdeploy.exe will always return an exit code of 0 means that your step will have a status of successful with warnings.

Because of the fact that msdeploy.exe always returns an exit code of 0, irrespective of if there were errors encountered, we have come up with a possible workaround! Our solution is to redirect the standard error to the same place as the standard output. All you would need to do is modify your PostDeploy.ps1 script to include 2>&1 when running invoke-Expression which will fail the deployment if an error is written by msdeploy.exe

Here is a full example of what your PostDeploy.ps1 script should look like to achieve this outcome:


$ErrorActionPreference = "Stop"

Try
{
	$exe = "$PSScriptRoot\content\ExitCodesWeb.deploy.cmd"
	$cmdPreSync = "powershell -inputformat none .\BeforeUnpack.ps1"
	$cmdPostSync = "powershell -inputformat none .\AfterUnpack.ps1"
	$command = "cmd.exe /C $exe /Y ""-preSync:runCommand='$cmdPreSync',waitAttempts=50,waitInterval=5000,successReturnCodes=0"" ""-postSync:runCommand='$cmdPostSync',waitAttempts=50,waitInterval=5000,successReturnCodes=0"""
	Invoke-Expression -Command $command 2>&1
}
Catch
{
	Write-Host $_.Exception.Message
	Exit 1
}

In doing so, we are combining the error out put of msdeploy.exe with the STDOUT stream which is how we would arrive at your exception block in the event of an error with msdeploy.

I hope this has been helpful for you and let me know if the above does not help resolve your issue

Kind regards,
Lawrence.

Jeff_Mounce · 3 August 2018 15:11

This seemed to work for me. I still don’t clearly understand how the PostDeploy.ps1 wasn’t returning an exit code of 1 even if msdeploy.exe doesn’t return 1 since it hits the Catch block in my tests, but it’s ok.
If there is no more activity on this ticket in a month, it will close.