Automatically log ErrorRecords instead of just Exceptions

[SteveL-MSFT]

It seems that the log should be like the PowerShell transcript log to make debugging easier. Currently, if there is a non-terminating error or terminating error it is not automatically logged. For example, was using Invoke-RestMethod in my function to call a REST API but it failed. I had to wrap that in a try..catch and Write-Host the exception to understand what was failing. But this means that everyone would need to wrap their function in a try..catch.

[TylerLeonhardt]

This doesn't seem right... We were looking at a Function yesterday together that had an error from Connect-AzAccount (or was it Start-AzVM 🤔) either way... It wrote to the Error stream and that showed up in your log.

What could be the difference here?

[SteveL-MSFT]

@TylerLeonhardt you're right! Not sure what is different here, had to wrap Invoke-RestMethod in try..catch to understand why it was failing.

[TylerLeonhardt]

Could it be the difference between terminating and non-terminating errors? I feel like they're both non-terminating though...

[SteveL-MSFT]

If it's non-terminating, the try..catch would have no effect

[TylerLeonhardt]

So maybe we're not logging terminating errors properly.

[TylerLeonhardt]

I actually can't repro this issue at all - had a local function call a function in Azure and the error that irm got back was logged:

[2/6/19 11:31:08 PM] Executing 'Functions.FailHttpTrigger' (Reason='This function was programmatically called via the host APIs.', Id=37f5b069-c618-471c-a7df-8c5582eace7b)
[2/6/19 11:31:08 PM] INFORMATION: PowerShell HTTP trigger function processed a request.


[2/6/19 11:31:08 PM] ERROR: Response status code does not indicate success: 400 (Bad Request).
[2/6/19 11:31:08 PM] Result: ERROR: Response status code does not indicate success: 400 (Bad Request).
[2/6/19 11:31:08 PM] Exception: Response status code does not indicate success: 400 (Bad Request).
[2/6/19 11:31:08 PM] Stack:    at System.Management.Automation.MshCommandRuntime.ThrowTerminatingError(ErrorRecord errorRecord).


[2/6/19 11:31:08 PM] Executed 'Functions.FailHttpTrigger' (Succeeded, Id=37f5b069-c618-471c-a7df-8c5582eace7b)
[2/6/19 11:31:08 PM] Executed HTTP request: {
[2/6/19 11:31:08 PM]   "requestId": "0cfdbf28-b94e-4b4b-bd2b-e0af0e541a9e",
[2/6/19 11:31:08 PM]   "method": "GET",
[2/6/19 11:31:08 PM]   "uri": "/api/FailHttpTrigger",
[2/6/19 11:31:08 PM]   "identities": [
[2/6/19 11:31:08 PM]     {
[2/6/19 11:31:08 PM]       "type": "WebJobsAuthLevel",
[2/6/19 11:31:08 PM]       "level": "Admin"
[2/6/19 11:31:08 PM]     }
[2/6/19 11:31:08 PM]   ],
[2/6/19 11:31:08 PM]   "status": 200,
[2/6/19 11:31:08 PM]   "duration": 762
[2/6/19 11:31:08 PM] }

The code that's sending the irm:

using namespace System.Net

# Input bindings are passed in via param block.
param($Request, $TriggerMetadata)

# Write to the Azure Functions log stream.
Write-Host "PowerShell HTTP trigger function processed a request."

# Interact with query parameters or the body of the request.
irm "https://tyleonha4321.azurewebsites.net/api/MyHttpTrigger"

# Associate values to output bindings by calling 'Push-OutputBinding'.
Push-OutputBinding -Name Response -Value ([HttpResponseContext]@{
    Body = "worked"
})

[SteveL-MSFT]

The problem is you are only getting this in the logs:

[2/6/19 11:31:08 PM] ERROR: Response status code does not indicate success: 400 (Bad Request).
[2/6/19 11:31:08 PM] Result: ERROR: Response status code does not indicate success: 400 (Bad Request).
[2/6/19 11:31:08 PM] Exception: Response status code does not indicate success: 400 (Bad Request).
[2/6/19 11:31:08 PM] Stack:    at System.Management.Automation.MshCommandRuntime.ThrowTerminatingError(ErrorRecord errorRecord).

We should be logging the entire ErrorRecord to make it useful

[TylerLeonhardt]

Here's how I would solve this issue:

Modify this function:

https://github.com/Azure/azure-functions-powershell-worker/blob/dev/src/PowerShell/StreamHandler.cs#L30-L36

To print:

SCRIPT STACKTRACE
EXCEPTION MESSAGE
EXCEPTION STACK TRACE
INNER EXCEPTION MESSAGE
INNER EXCEPTION STACK TRACE
...etc

StringBuilder sb = new StringBuilder(record.ScriptStackTrace);
if(record.Exception != null)
{
    Exception e = record.Exception;
    sb.Append(e.Message);
    sb.Append(e.StackTrace);
    while(e.InnerException != null)
    {
        e = e.InnerException;
        sb.Append(e.Message);
        sb.Append(e.StackTrace);
    }
}

or something similar. P.S. this is untested code.

[JustinGrote]

Related to this, currently in the Application Insights, the stacktrace doesn't show the script line, it just shows the PipelineBase.Invoke as the last entry. This makes it really hard to track down errors in a script. The stack trace should append the in-runspace stacktrace before logging it.

Example

> 2019-06-04T19:27:52.850 [Error] Executed 'Functions.UpdatePRTGAditaasTicket-SendToAditaas' (Failed, Id=81a78e8d-9872-4276-8fa0-3b7806d8b194)
> Result: Failure
> Exception: Conversion from JSON failed with error: Unexpected character encountered while parsing value: S. Path '', line 0, position 0.

Can't see what line of code it was. Right here should be something like at run.ps1 (Line 15) and if the failure was in a module, the module stacktrace as well

> Stack:    at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input)
>    at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke)
>    at System.Management.Automation.PowerShell.Worker.CreateRunspaceIfNeededAndDoWork(Runspace rsToUse, Boolean isSync)
>    at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
>    at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
>    at System.Management.Automation.PowerShell.CoreInvoke[TOutput](IEnumerable input, PSDataCollection`1 output, PSInvocationSettings settings)
>    at System.Management.Automation.PowerShell.Invoke[T](IEnumerable input, IList`1 output, PSInvocationSettings settings)
>    at System.Management.Automation.PowerShell.Invoke[T]()
>    at Microsoft.Azure.Functions.PowerShellWorker.PowerShell.PowerShellExtensions.InvokeAndClearCommands[T](PowerShell pwsh) in C:\projects\azure-functions-powershell-worker\src\PowerShell\PowerShellExtensions.cs:line 31
>    at Microsoft.Azure.Functions.PowerShellWorker.PowerShell.PowerShellManager.InvokeFunction(AzFunctionInfo functionInfo, Hashtable triggerMetadata, IList`1 inputData) in C:\projects\azure-functions-powershell-worker\src\PowerShell\PowerShellManager.cs:line 195
>    at Microsoft.Azure.Functions.PowerShellWorker.RequestProcessor.InvokeSingleActivityFunction(PowerShellManager psManager, AzFunctionInfo functionInfo, InvocationRequest invocationRequest) in C:\projects\azure-functions-powershell-worker\src\RequestProcessor.cs:line 404
>    at Microsoft.Azure.Functions.PowerShellWorker.RequestProcessor.ProcessInvocationRequestImpl(StreamingMessage request, AzFunctionInfo functionInfo, PowerShellManager psManager) in C:\projects\azure-functions-powershell-worker\src\RequestProcessor.cs:line 288