Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

LastExitCode modified by an executable that is run as part of a test and then returned by Pester resulting in CI build failure #1616

Closed
markwragg opened this issue Jun 24, 2020 · 5 comments · Fixed by #1734
Milestone

Comments

@markwragg
Copy link

markwragg commented Jun 24, 2020

1. General summary of the issue

I have been writing some infrastructure tests and to test that chocolatey was installed I was doing this:

It 'Should have installed Chocolatey' {
    { choco } | Should -Not -Throw
}

My tests were all passing, but when running in my Packer build were causing the build to fail because the Exit Code was non-zero. I eventually tracked it down to the above test and have discovered that choco sets the $LastExitCode variable to 1 even though it has effectively executed successfully (note it only seems to do this when using choco on its own, rather than with a specific command).

It seems that because none of the tests had failed, Pester wasn't setting $LastExitCode at all and so it was just being passed through with whatever choco had set it to.

I've worked around this by testing for the install of choco by just looking for the presence of the .exe on disk, but I wondered if this non-handling of $LastExitCode when all tests have passed was expected behaviour or perhaps something that should be addressed, because it caused me some confusion.

2. Describe Your Environment

Pester version : 5.0.2 C:\Program Files\WindowsPowerShell\Modules\Pester\5.0.2\Pester.psd1
PowerShell version : 5.1.17763.1007
OS version : Microsoft Windows NT 10.0.17763.0

3. Expected Behavior

I expected $LastExitCode to always be 0 if all tests have passed.

4.Current Behavior

$LastExitCode is set to the exit code of an executable that is run as part of the tests.

5. Possible Solution

Have Pester set $LastExitCode even if all tests have passed. I am assuming currently it only sets its value if failed.
However there might be reasons not to do this and i'm not sure how much of a breaking change it might be for some use cases. The problem here is more choco than Pester for returning a non-zero exit code for a valid operation. I guess in most cases when an exe returns a non-zero exit code as part of a test run its perfectly valid for that to result in a failure state outside of the environment.

If the consensus is that this shouldn't really be solved, please close this issue but i'm going to raise it anyway as it might help someone who has similar in the future.

6. Context

Pester being used for infrastructure validation tests as part of a Packer VM image build in Azure.

@asears
Copy link
Contributor

asears commented Jul 1, 2020

Not sure if Pester's responsibility to mask $LastExitCode of another process. Warning might make sense though or something added to detailed diagnostics, I've been caught with this before too and it's hard to find what's causing it.

Is $LastExitCode 1 considered an exception which Should -Throw? Probably not?

Should ErrorLevel/Exit codes be masked by Pester tests? As a test framework, I would expect artifacts be torn down and state reset to original post test.

There's some TODOs around this

Had a similar issue with git.exe throwing errors for things that weren't errors in our build pipelines.

I see that this mock example would set the last exit code, perhaps it could be reset in your test script after calling choco?

function choco.exe {}
Mock -CommandName choco.exe -MockWith { $Global:LASTEXITCODE = 1 }

#415 has a workaround.

function Invoke-ExternalCommand {

    # Reset $result in case it's used somewhere else
    $result = $null

    # Reset $LASTEXITCODE in case it was tripped somewhere
    $Global:LASTEXITCODE = 0

    $result = & $command $arguments  

    if ($LASTEXITCODE -ne 0) {
        Throw "Something bad happened while executing $command. Details: $($result | Out-String)"
    }

    Write-Verbose "$($result | Out-String)"
}

# Called from other functions like this: 
Invoke-ExternalCommand MSTest.exe @(
                "/testcontainer:$testContainer",
                "/resultsfile:$outputFile")

From the Chocolatey page

[x] usePackageExitCodes - Use Package Exit Codes - Package scripts can provide exit codes. With this on, package exit codes will be what choco uses for exit when non-zero (this value can come from a dependency package). Chocolatey defines valid exit codes as 0, 1605, 1614, 1641, 3010. With this feature off, choco will exit with 0, 1, or -1 (matching previous behavior). Available in 0.9.10+.
[ ] useEnhancedExitCodes - Use Enhanced Exit Codes - Chocolatey is able to provide enhanced exit codes surrounding list, search, info, outdated and other commands that don't deal directly with package operations. To see enhanced exit codes and their meanings, please run choco [cmdname] -?. With this feature off, choco will exit with 0, 1, or -1 (matching previous behavior). Available in 0.10.12+. Default off in 0.10.14+.
[ ] exitOnRebootDetected - Exit On Reboot Detected - Stop running install, upgrade, or uninstall when a reboot request is detected. Requires 'usePackageExitCodes' feature to be turned on. Will exit with either 350 or 1604. When it exits with 350, it means pending reboot discovered prior to running operation. When it exits with 1604, it means some work completed prior to reboot request being detected. Available in 0.10.12+.

#1527 , #1042 #1021 mentions.

@nohwnd
Copy link
Member

nohwnd commented Jul 27, 2020

Hmm yeah, Pester should exit with 0 as long as no test is failed, so we should probably set the exit code to 0 explicitly.

As for asserting LastExitCode != 0, that seems like something that could be bolted on -Throw, but I can't think of a good name for the switch now.

@asears You posted link to a TODO, but it links to the whole file which has few thousands of lines, which one did you mean?

@nohwnd nohwnd added this to the 5.1 milestone Jul 27, 2020
@asears
Copy link
Contributor

asears commented Jul 30, 2020

Yeah, there's a few TODOs in that file. Don't know if any affect this particular issue.

 TODO: no callbacks are provided because we are not transitioning between any states,
it might be nice to add a parameter to indicate that we run in the same scope
so we can avoid getting and setting the scope on scriptblock that already has that
scope, which is _potentially_ slow because of reflection, it would also allow
making the transition callbacks mandatory unless the parameter is provided

https://github.com/pester/Pester/blob/v5.0/src/Pester.Runtime.psm1#L247

TODO:  this condition works but needs to be revisited. when the parent fails the test is marked as failed, because it should have run but it did not,and but there is no error in the test result, in such case all tests should probably add error or a flag that indicates that the parent failed, or a log or something, but error is probably the best

https://github.com/pester/Pester/blob/v5.0/src/Pester.Runtime.psm1#L1966

 TODO: revisit this because this will probably act weird as we jump between session states

https://github.com/pester/Pester/blob/v5.0/src/Pester.Runtime.psm1#L1689

TODO: this it potentially unreliable, because supressed errors are written to Error as well. And the errors are captured only from the caller state. So let's use it only as a useful indicator during migration and see how it works in production code.

https://github.com/pester/Pester/blob/v5.0/src/Pester.Runtime.psm1#L1696

The last one was the one that caught my eye as something to check. Looking at them now, I don't know that any of these are particularly relevant for this issue.

As a side note, might be worthwhile removing some of the commented code lines from codebase and putting those in another branch, or using a feature toggle to ease testing & debugging.

Would this particular "feature" be clearing any executable error codes for the test run and returning a status code / errorlevel of 0 if all tests are successful?

-ResetLastExitCodeVariable ?

Is it Pester's business to reset the LastExitCode Environment Variable at all or something to just warn on, or should -throw in a strict test if $LASTEXITCODE != 0? Currently it seems to be only used in the build and release scripts internal to Pester. Might be worthwhile to look at how this should behave in Azure Devops pipeline task or see if it could just be warned on after an executable is run, and set after Invoke-Pester is run vs. changing functionality.

I think the problem is not that it isn't being captured or reset on exit, it's that it's hard to discover what exe is causing this issue and the test isn't failing due to LASTEXITCODE being 1, but the Devops Pipeline is.

It's a case of "polluted environment?"

There's some issues around this in choco.

https://github.com/chocolatey/choco/search?q=LastExitCode&type=Issues
chocolatey/choco#1036

The workaround for choco is choco -v.
chocolatey/choco#1529

There might be a fix in progress though that was mentioned last year.
chocolatey/chocolatey-licensed-issues#52

It would be good to test that all environment variables and state before and after a Pester run are equal, and Pester-specific internal variables are disposed of after each test in an Azure Devops pipeline and new variables are surfaced somehow. There were some warnings from PSScriptAnalyzer about reusing reserved variables.

Was seeing some issues with PesterConfiguration but nothing I could repro.

@fflaten
Copy link
Collaborator

fflaten commented Oct 16, 2020

I thought ExitCodes wasn't really a PowerShell thing, but more of a backwards compatibility feature for legacy-applications. Maybe I'm wrong, but keeping that assumption in mind...

Hmm yeah, Pester should exit with 0 as long as no test is failed, so we should probably set the exit code to 0 explicitly.

Not sure if you meant to always exit or only when using Run.Exit/-CI, but I'd recommend the latter, to only use exit codes when required. Should be enough to remove the -and 'Failed' -eq $run.Result criteria that's currently stopping the 0 from being returned? 0 failed = lastexitcode 0 = everyone happy.

Pester/src/Pester.ps1

Lines 1135 to 1137 in 8d55526

if ($PesterPreference.Run.Exit.Value -and 'Failed' -eq $run.Result) {
exit ($run.FailedCount + $run.FailedBlocksCount + $run.FailedContainersCount)
}

As for asserting LastExitCode != 0, that seems like something that could be bolted on -Throw, but I can't think of a good name for the switch now.

Won't a second assertion in the test cover this scenario? If they care to check it, they might as well do it explicitly.

Describe "LastExitCode Demos" {
    It 'Fails due to lastexit code' {
        { cmd /c exit /b 1 } | Should -Not -Throw
        $LASTEXITCODE | Should -Be 0
    }

    It 'Works since next legacy app reset the lastexitCode' {
        { cmd /c exit /b 1 } | Should -Not -Throw
        { cmd /c echo hello world } | Should -Not -Throw
        $LASTEXITCODE | Should -Be 0
    }
}

@nohwnd
Copy link
Member

nohwnd commented Oct 24, 2020

@fflaten I mean setting the exit code explicitly ([System.Environment]::ExitCode) even if we don't exit, but maybe in that case it is not needed and we can just exit with 0 if we enable exiting.

As for the assertion, yeah that is possible with -Be but I think I was thinking about { cmd /c echo hello world } | Should -ExitWithExitCode 10, but script block is not really necessary and it would be a custom operator with pretty narrow usage. Your solution is imho good enough.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants