Calamari.exe swallowing errors

cmyers · 4 September 2019 15:57

When I have a “Run a script” task in a project, and the script is Powershell, and I try to invoke another command (either another ps1 file, a .bat file, a .cmd file, or even a .exe file) and that command has an error, Calamari will swallow the error and give me unhelpful output.

For example, I’m trying to install Ruby 2.5 devkit by calling .\ridk.ps1 install 1 3 and it’s throwing an error, but I can’t see what it is because this is all I get from Octopus Deploy in the deployment:

Calamari.exe : ruby.exe : > e[36msh -lc truee[0m 
At C:\Octopus\Work\20190904155242-105962-25\Bootstrap.ps1:27 char:1 
+ &  "${env:TentacleHome}\Calamari\4.14.5\Calamari.exe" run-script -sen ... 
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 
    + CategoryInfo          : NotSpecified: (ruby.exe : > e[36msh -lc truee[0m:String) [], RemoteException 
    + FullyQualifiedErrorId : NativeCommandError 
The remote script failed with exit code 1 
The action Install Ruby 2.5 devkit on SERVERNAME failed

How do I get Calamari to give me useful output so I can see why the command is failing?

NOTE: This seems to have just started recently around the time we upgraded to to 2019.2.4 or thereabouts.

cmyers · 4 September 2019 19:24

UPDATE: It appears this might be related: https://github.com/OctopusDeploy/Issues/issues/839

Certain programs (git, Ruby installer ridk, etc) write to stderr for various non-error reasons and so Octo was failing as soon as it saw the first line written to stderr. It’s not immediately obvious that’s what’s happening from the error output though.

I tried putting Write-Host ##octopus[stderr-progress] before calling ridk in my script, but that only seemed to hide the Calamari error, but it still blows up. Calamari still seems to exit as soon as the first line is written to stderr

Matt.Richardson · 5 September 2019 06:44

Hi there

Sorry to see you’re having trouble here. This is definitely not the experience we are hoping for.

We’ve looked into this before, but we haven’t had much success getting PowerShell to be more useful in returning errors. We’re going to investigate again to see if we can improve things here to surface better logs, but for now you might have success using Powershell Debugging - https://octopus.com/docs/deployment-examples/custom-scripts/debugging-powershell-scripts. This will allow you to step through the scripts and see what errors are emitted by ridk.

Let me know how you get along.

Hope that helps!

Regards,
Matt

cmyers · 5 September 2019 14:36

Matt,

Thanks for replying! I figured out what Calamari was doing - it’s failing as soon as it sees the first line written to stderr. I tried setting ##octopus[stderr-progress] and also Octopus.Action.FailScriptOnErrorOutput = false, it still would fail as soon as it saw anything on stderr. I think this is a Calamari problem or else I couldn’t figure out how to set the FailScriptOnErrorOutput properly or something like that.

I did find a workaround in my case - instead of running ridk.cmd directly, I was able to do this:

cmd.exe /c ridk.cmd install 1 3 2>&1

This tells cmd.exe to redirect stderr to stdout. Once I did that, it worked. I think that apps like ridk (Ruby dev kit installer) shouldn’t be writing to stderr as the norm like that, so I don’t think Calamari is all in the wrong here. But it would be nice to have some way of controlling Calamari’s behavior. If that variable is the correct one, then that’s great, but I wasn’t able to figure out how to use it where Calamari would respect it.

Matt.Richardson · 9 September 2019 00:19

Hi there

Thanks for getting back to me. Glad to see you got to the bottom of it.

Can you let me know what OS that you were running this on? We’ve had a few issues where stderr is causing trouble on 2019, but we haven’t been able to get to the bottom of it.

We’re looking to investigate this deeper, so hopefully we can get to the bottom of this soon.

Regards,
Matt

cmyers · 9 September 2019 20:31

Matt,

I’ve seen examples of it with “ridk.cmd” (Ruby devkit installer for Ruby 2.5 on Windows) and git.exe and now that you mention it, yes all instances of this problem I’ve seen were on Windows Server 2019 (17763.615 and 17763.678).

It seems as soon as a command writes to stderr, Calamari will write out that one line and then throw or exit. Piping stderr to stdout has been consistently working for us, so I think that’s a decent workaround for now.

I tried running a PS1 script that just has:

Write-Error "first line"
Write-Error "second line"

And I ran .\Calamari.exe run-script --script=path_to_script.ps1 and Calamari stopped immediately after the first line. I ran the test on Windows Server 2008R2 and Windows Server 2019, using the same version of Calamari (4.14.5) and got the same results. Not sure if that helps or not or if there are more variables I need to isolate maybe?

Matt.Richardson · 16 September 2019 00:36

Hi there

I’ve been investigating this a bit more off and on with some of the other engineers here, and one of them reminded me about an issue we’ve seen recently - https://github.com/OctopusDeploy/Issues/issues/5755 where behaviour changed depending on the version of .net. Are you able to let me know what versions of .net are installed on the boxes in question? (See the Microsoft docs if you need details about how to determine this.)

This might give us clues of the best way to move forward with the stderr issues

Another thing that I’ve been considering in in this is around the interation between $ErrorActionPreference and Write-Error. We set $ErrorActionPreference to stop, which makes PowerShell stop on the first error.

The one downside to this is that Write-Error then causes the script to fail.

Can you try your example above with the Write-Error lines, but modify it to:

Write-Error "first line" -ErrorAction Continue
Write-Error "second line" -ErrorAction Continue

That should give me some useful information to proceed.

Thanks,
Matt

cmyers · 17 September 2019 21:08

Hi Matt. No problem.

It proceeded past the first error!

Full output:

PS C:\Octopus\Calamari\4.14.5> .\Calamari.exe run-script --script=c:\users\administrator\desktop\errortest.ps1
##octopus[stdout-verbose]
Octopus Deploy: Calamari version 4.14.5
Environment Information:
  OperatingSystem: Microsoft Windows NT 10.0.17763.0
  OsBitVersion: x64
  Is64BitProcess: True
  CurrentUser: XXXXXX\Administrator
  MachineName: XXXXXX
  ProcessorCount: 2
  CurrentDirectory: C:\Octopus\Calamari\4.14.5
  TempDirectory: C:\Users\Administrator\AppData\Local\Temp\7\
  HostProcessName: Calamari
##octopus[stdout-warning]
The `--script` parameter is deprecated.
Please set the `Octopus.Action.Script.ScriptBody` and `Octopus.Action.Script.ScriptFileName` variable to allow for variable replacement of the script file.
##octopus[stdout-verbose]
Executing 'c:\users\administrator\desktop\errortest.ps1'
##octopus[stdout-default]
##octopus[stdout-verbose]

Name                           Value
----                           -----
PSVersion                      5.1.17763.592
PSEdition                      Desktop
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
BuildVersion                   10.0.17763.592
CLRVersion                     4.0.30319.42000
WSManStackVersion              3.0
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1



##octopus[stdout-default]
##octopus[stdout-verbose]
PowerShell Environment Information:
  OperatingSystem: Microsoft Windows NT 10.0.17763.0
  OsBitVersion: x64
  Is64BitProcess: True
  CurrentUser: XXXXXX\Administrator
  MachineName: XXXXXX
  ProcessorCount: 2
  CurrentDirectory: c:\users\administrator\desktop
  CurrentLocation: C:\users\administrator\desktop
  TempDirectory: C:\Users\Administrator\AppData\Local\Temp\7\
  HostProcessName: powershell
  TotalPhysicalMemory: 8306268 KB
  AvailablePhysicalMemory: 6294136 KB
##octopus[stdout-default]
C:\users\administrator\desktop\errortest.ps1 : first line
At C:\users\administrator\desktop\Bootstrap.errortest.ps1:872 char:1
+ . 'c:\users\administrator\desktop\errortest.ps1'
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,errortest.ps1

C:\users\administrator\desktop\errortest.ps1 : second line
At C:\users\administrator\desktop\Bootstrap.errortest.ps1:872 char:1
+ . 'c:\users\administrator\desktop\errortest.ps1'
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,errortest.ps1

##octopus[setVariable name="T2N0b3B1cy5BY3Rpb24uU2NyaXB0LkV4aXRDb2Rl" value="MA=="]

Matt.Richardson · 18 September 2019 07:34

Hi there

Thanks for sending that through - that’s useful.

Are you able to confirm the .net version on each of those boxes? That should give me another breadcrumb on the trail.

Thanks,
Matt

cmyers · 18 September 2019 18:17

Oops, I thought the .NET version was in the output from the previous command but that’s just the CLR version, sorry.

C:\Windows\Microsoft.NET\Framework\v4.0.30319>reg query "HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\NET Framework Setup\NDP\v4\full" /v Release

HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\NET Framework Setup\NDP\v4\full
    Release    REG_DWORD    0x70bf6

That’s 461814 in hex.

According to the MS KB article you linked, that’s 4.7.2 which is consistent with shipping with Windows Server 2019 (1803) [this server has 1809 though]

Matt.Richardson · 9 October 2019 00:27

Hi there

Sorry for the delay - I’ve been on leave.

It looks like you’ve hit the issue I mentioned above - on 1809 and .net 4.7.2, powershell terminates early. In 2019.9.0, we’re printing out a warning about this scenario, but unfortunately, the best answer there is to upgrade to .net 4.8.0.

Also, we’ve looking to spec out and improve how we handle errors like this, so keep your eyes peeled.

Hope that helps.

Regards,
Matt

system · 8 November 2019 00:31

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.