CI: Report full stack trace if ScriptAnalyzer throws an error and improve ScriptAnalyzer installation to not skip publisher and check and not allow clobber #236

bergmeister · 2020-06-13T12:02:04Z

Description

PR #221 reported that this repo causes PSScriptAnalyzer to sporadically throw an error.
In order to report the full error needed for analysis, report the full stack trace. In order to make this easier, I make the build run on PowerShell 7 instead, which has the built-in Get-Error cmdlet, which simplifies the reporting.

Checklist

You actually ran the code that you just wrote, especially if you did just "one last quick change".
Comment-based help added/updated, including examples.
Static analysis
is reporting back clean.
New/changed code adheres to our coding guidelines.
Changes to the manifest file follow the manifest guidance.
Unit tests were added/updated and are all passing. See testing guidelines.
Relevant usage examples have been added/updated in USAGE.md.
If desired, ensure your name is added to our Contributors list

HowardWolosky · 2020-06-13T18:40:33Z

Thanks @bergmeister -- I don't want to merge that change in because I very specifically want to have this run on PS5, but I will kick off a few rounds of CI to see if we can hit the error within the context of this PR.

HowardWolosky · 2020-06-13T18:40:36Z

/azp run PowerShellForGitHub-CI

azure-pipelines · 2020-06-13T18:40:46Z

Azure Pipelines successfully started running 1 pipeline(s).

bergmeister · 2020-06-13T18:44:09Z

@HowardWolosky Ok, but even if it happens again, just the default error message won't be enough, I need the full stack trace.
I'd be happy to adapt the script to report the stack trace for PS5, it's just a little bit more work because Get-Error doesn't exist on PS5, which I've just done now, please re-run it again please. But generally the idea is that even if it does not happen this time. The next time it happens, you'd see the full stack trace that you can then report back to me.

bergmeister · 2020-06-13T18:49:00Z

/azp run PowerShellForGitHub-CI

azure-pipelines · 2020-06-13T18:49:05Z

Commenter does not have sufficient privileges for PR 236 in repo microsoft/PowerShellForGitHub

build/pipelines/templates/run-staticAnalysis.yaml

HowardWolosky · 2020-06-13T19:06:26Z

/azp run PowerShellForGitHub-CI

azure-pipelines · 2020-06-13T19:06:36Z

Azure Pipelines successfully started running 1 pipeline(s).

…A bootstrap

HowardWolosky · 2020-06-13T19:52:55Z

Thanks!

HowardWolosky · 2020-06-13T19:52:58Z

/azp run PowerShellForGitHub-CI

azure-pipelines · 2020-06-13T19:53:08Z

Azure Pipelines successfully started running 1 pipeline(s).

HowardWolosky · 2020-06-13T21:45:20Z

/azp run PowerShellForGitHub-CI

azure-pipelines · 2020-06-13T21:45:37Z

Azure Pipelines successfully started running 1 pipeline(s).

HowardWolosky · 2020-06-14T15:55:18Z

build/pipelines/templates/run-staticAnalysis.yaml

    displayName: 'Install PSScriptAnalyzer'

  - powershell: |
-       $results = Invoke-ScriptAnalyzer -Path ./ –Recurse
+       $results = try { Invoke-ScriptAnalyzer -Path ./ –Recurse -ErrorAction Stop } catch { $StackTrace; throw }


I think that this change will prevent us from getting our published NUnit results. If that's the case, we wouldn't want to merge this in. I can run this in CI a few more times though to see if we can catch the ScriptAnalyzer bug though.

Why do you think it would prevent that? The point of re-throwing is to alert you that something bad happened during analysis so that you can then report the stack trace so that we can investigate further.
Right now, if that sporadic error happened in master, your build would be red as well, therefore I am not changing behaviour, I am only adding the additional information, which is the stack trace

This could be my misunderstanding then of how Invoke-ScriptAnalyzer behaves with -ErrorAction -Stop. I was under the impression that if it had any failures and -ErrorAction Stop was set, it would throw, causing any statements following it to not be executed.

I just tried tried to verify this myself locally though, and it looks like my understanding there was wrong. Can you just clarify under what scenarios Invoke-ScriptAnalyzer -ErrorAction Stop will result in an exception being thrown ?

Right now, if that sporadic error happened in master.

It has happened in PR CI builds as well. There isn't anything special about the master builds vs the CI builds.

Ok. Let me explain a few things first:

-ErrorAction is a so called common parameter and not specific to PSScriptAnalyzer. Binary cmdlets like Invoke-ScriptAnalyzer or advanced script functions (i.e. a function that is decorated with the [CmdletBinding()] attribute) automatically inherit those common parameters that the PowerShell engine handles/provides.

There are 2 types of errors in PowerShell: terminating and non-terminating. The idea is that when an operation fails when processing pipeline input and one input fails, one usually does not want pipeline processing to stop because of that. This is important to know because:

A catch block only catches terminating error and I know from experience that leaked exceptions from inside PSScriptAnalyzer are treated as non-terminating errors.

Therefore we would not be able to catch that exception, which you sporadically observe just by doing try { Invoke-ScriptAnalyzer } catch { 'hello' }.

You might be asking why the build is red then. This is because CI environment providers detect when a non-terminating errors occurred after a line has finished executing and fail the build as it is indication that something went wrong, which is right.

Now, in order to catch and report the exception that happens, we use -ErrorAction Stop, as this tells PowerShell to stop processing when any type of error occurs and treat them as terminating errors. This essentially allows us to get into the catch block and the reason to use -ErrorAction Stop.

Therefore to conclude, this PR does not change the behaviour, it only logs out the stacktrace additionally when an error occurs. Changing it to not re-throw to avoid the build going red would not be good because ScriptAnalyzer's analysis would be incomplete and we want to be alerted of the error and report it the next time it happens. Therefore my suggestion is to just merge the PR and report the stack trace back to me the next time it happens so that we can look into fixing it in the next version

Sounds good -- I appreciate the thorough response/help here. Getting this merged-in now and will report back the stack trace should it happen again.

…l one from PowerShell itself

HowardWolosky · 2020-06-15T15:33:38Z

/azp run PowerShellForGitHub-CI

azure-pipelines · 2020-06-15T15:34:07Z

Azure Pipelines successfully started running 1 pipeline(s).

HowardWolosky · 2020-06-26T15:21:02Z

@bergmeister - We had a hit last night, but I don't see anything useful coming out of it

2020-06-26T02:19:52.8521926Z �[91mInvoke-ScriptAnalyzer: �[0m/home/vsts/work/_temp/fe353001-d2f6-451a-af14-8d097e0b7ff6.ps1:2
2020-06-26T02:19:52.8523813Z �[96mLine |
2020-06-26T02:19:52.8524982Z �[96m   2 | �[0m â€¦ lts = try { �[96mInvoke-ScriptAnalyzer -Settings ./PSScriptAnalyzerSetting�[0m â€¦
2020-06-26T02:19:52.8526261Z �[96m     | �[91m               ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2020-06-26T02:19:52.8527614Z �[91m�[96m     | �[91mCollection was modified; enumeration operation may not execute.
2020-06-26T02:19:52.8528576Z �[0m
2020-06-26T02:19:52.8641288Z 
2020-06-26T02:19:52.8747719Z ##[error]PowerShell exited with code '1'.
2020-06-26T02:19:52.8772870Z ##[section]Finishing: Run Static Code Analysis (PSScriptAnalyzer)

bergmeister · 2020-06-26T15:55:39Z

Hmm, interesting. Not sure why we didn't get the stack trace from try { Invoke-ScriptAnalyzer ... -ErrorAction Stop } catch { $_.Exception.StackTrace; throw } 😕. Possibilities include:

$_.Exception.StackTrace was actually null but I don't understand why, especially since I tested that behaviour locally on my Windows laptop with the same exception from a different bug. I don't think this bug or behaviour is MacOS/Unix specific
Azure DevOps interrupted too early when the exception was re-thrown and did not have enough time to capture the logged stack trace, which might be an issue the way they host PowerShell but I tried a similar command pattern in a dummy Azure DevOps build and it worked as expected.

In order to help us understand better why we don't get more information, we could add a bit more logging into the catch block so that we know a bit more.

@TylerLeonhardt This is a good example of why I don't need/want to attach to Azure DevOps agents, I rather want basic logging such as:

Full error details like Get-Error gives you, including full Stack traces
Variable capture and any other related state
Verbose and debug log available as optional build artefact
Streams (Output, Error, Verbose, etc.) logged in correct order of time (AzurePowerShell is guilty of it.
Optionally execution transcript

…fatal error (#246) Enhancing #236

X-Guardian · 2020-12-27T10:21:14Z

@bergmeister, these intermittent ScriptAnalyzer errors keep happening and are still not producing any stack trace output. It doesn't look like the catch block is executing at all:

2020-12-24T22:48:45.5720310Z �[91mInvoke-ScriptAnalyzer: �[0m/Users/runner/work/_temp/4798a0d4-2c32-4557-9229-3d17396bae90.ps1:2
2020-12-24T22:48:45.5727610Z �[96mLine |
2020-12-24T22:48:45.5729970Z �[96m   2 | �[0m â€¦ lts = try { �[96mInvoke-ScriptAnalyzer -Settings ./PSScriptAnalyzerSetting�[0m â€¦
2020-12-24T22:48:45.5732170Z �[96m     | �[91m               ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2020-12-24T22:48:45.5733610Z �[91m�[96m     | �[91mCollection was modified; enumeration operation may not execute.
2020-12-24T22:48:45.5734550Z �[0m
2020-12-24T22:48:45.6792810Z 
2020-12-24T22:48:45.6892690Z ##[error]PowerShell exited with code '1'.
2020-12-24T22:48:45.6921960Z ##[section]Finishing: Run Static Code Analysis (PSScriptAnalyzer)

Example build log here: https://dev.azure.com/ms/PowerShellForGitHub/_build/results?buildId=129530&view=logs&j=a5e52b91-c83f-5429-4a68-c246fc63a4f7&t=c9cf2fd0-7e3a-5695-1b5f-45f64bd81b9a

Report full stack trace if ScriptAnalyzer throws an error

fc1d208

bergmeister mentioned this pull request Jun 13, 2020

GitHubRepositories: Add New-GitHubRepositoryFromTemplate Function #221

Merged

8 tasks

bergmeister added 2 commits June 13, 2020 14:38

Update CONTRIBUTING.md

56aef78

Update run-staticAnalysis.yaml

e7d00a8

HowardWolosky added the build Changes related to the build infrastructure for the project. label Jun 13, 2020

Update run-staticAnalysis.yaml

36feb52

HowardWolosky reviewed Jun 13, 2020

View reviewed changes

build/pipelines/templates/run-staticAnalysis.yaml Outdated Show resolved Hide resolved

Update build/pipelines/templates/run-staticAnalysis.yaml

8e4b830

Remove redundant AllowClobber and SkipPublisherCheck switches for PSS…

8b1dd9b

…A bootstrap

bergmeister changed the title ~~Report full stack trace if ScriptAnalyzer throws an error~~ Report full stack trace if ScriptAnalyzer throws an error and improve ScriptAnalyzer installation in CI to not skip publisher and check and not allow clobber Jun 13, 2020

HowardWolosky reviewed Jun 14, 2020

View reviewed changes

bergmeister and others added 2 commits June 15, 2020 09:57

report exception specific stack trace as $StackTrace is the high leve…

d302f42

…l one from PowerShell itself

Merge branch 'master' into patch-1

a822da3

HowardWolosky approved these changes Jun 15, 2020

View reviewed changes

HowardWolosky merged commit 1f63817 into microsoft:master Jun 15, 2020

bergmeister mentioned this pull request Jun 26, 2020

Add more logging into catch block when PSScriptAnalyzer encounters a fatal error in CI #246

Merged

HowardWolosky pushed a commit that referenced this pull request Jun 26, 2020

Add more logging into catch block when PSScriptAnalyzer encounters a …

d855e80

…fatal error (#246) Enhancing #236

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CI: Report full stack trace if ScriptAnalyzer throws an error and improve ScriptAnalyzer installation to not skip publisher and check and not allow clobber #236

CI: Report full stack trace if ScriptAnalyzer throws an error and improve ScriptAnalyzer installation to not skip publisher and check and not allow clobber #236

bergmeister commented Jun 13, 2020 •

edited

Loading

HowardWolosky commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

bergmeister commented Jun 13, 2020 •

edited

Loading

bergmeister commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

HowardWolosky Jun 14, 2020 •

edited

Loading

bergmeister Jun 14, 2020

HowardWolosky Jun 14, 2020 •

edited

Loading

bergmeister Jun 15, 2020 •

edited

Loading

HowardWolosky Jun 15, 2020

HowardWolosky commented Jun 15, 2020

azure-pipelines bot commented Jun 15, 2020

HowardWolosky commented Jun 26, 2020

bergmeister commented Jun 26, 2020 •

edited

Loading

X-Guardian commented Dec 27, 2020

CI: Report full stack trace if ScriptAnalyzer throws an error and improve ScriptAnalyzer installation to not skip publisher and check and not allow clobber #236

CI: Report full stack trace if ScriptAnalyzer throws an error and improve ScriptAnalyzer installation to not skip publisher and check and not allow clobber #236

Conversation

bergmeister commented Jun 13, 2020 • edited Loading

Description

Checklist

HowardWolosky commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

bergmeister commented Jun 13, 2020 • edited Loading

bergmeister commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

HowardWolosky commented Jun 13, 2020

azure-pipelines bot commented Jun 13, 2020

HowardWolosky Jun 14, 2020 • edited Loading

Choose a reason for hiding this comment

bergmeister Jun 14, 2020

Choose a reason for hiding this comment

HowardWolosky Jun 14, 2020 • edited Loading

Choose a reason for hiding this comment

bergmeister Jun 15, 2020 • edited Loading

Choose a reason for hiding this comment

HowardWolosky Jun 15, 2020

Choose a reason for hiding this comment

HowardWolosky commented Jun 15, 2020

azure-pipelines bot commented Jun 15, 2020

HowardWolosky commented Jun 26, 2020

bergmeister commented Jun 26, 2020 • edited Loading

X-Guardian commented Dec 27, 2020

bergmeister commented Jun 13, 2020 •

edited

Loading

bergmeister commented Jun 13, 2020 •

edited

Loading

HowardWolosky Jun 14, 2020 •

edited

Loading

HowardWolosky Jun 14, 2020 •

edited

Loading

bergmeister Jun 15, 2020 •

edited

Loading

bergmeister commented Jun 26, 2020 •

edited

Loading