All Exceptions Showing up as RpcException for innermessage

[JustinGrote]

Not sure if this belongs here or in the functions runtime repository, but when an exception is thrown in the Powershell Worker, when it reaches the logs/Application Insights, its innermost type is RpcException, meaning the exception type got lost in translation on the gRPC interface. This should pass through so that clear exceptions (InvalidOperationException, etc.) can be seen in application insights so issues can be triaged more quickly.

Workaround

Use the telemetry client to throw the "original" exception in a try/catch, this however leads to the dilemma of having "duplicate" exceptions for the failure, or forcing the function to succeed so as to avoid duplication (but then the consequences of that in terms of discovery, queue retry, etc.)

[Francisco-Gamino]

We will look into this. We will check to ensure we are consistent with other language, e.g., C#.

[JustinGrote]

With the recent update that added the TraceContext, I wanted to revisit this item again. Now that the parent ID trace context is provided, can errors be passed to Application Insights with the appropriate context IDs? I know I could "roll my own" solution here but ideally this would be native to the worker, so that viewing exceptions in application insights is more rich and insightful.

@SatishRanjan Since this is assigned to you, what do you think?

[AnatoliB]

@JustinGrote If you are talking about exceptions thrown by the function code, do you think https://github.com/Azure/azure-functions-powershell-worker/pull/328 addressed this problem? Or you are talking about exceptions thrown by the PS Worker internal code?

[JustinGrote]

Talking about function code exceptions. They all show up as RPCException in Application Insights, so it's hard to do any kind of fault analysis at all.

On Wed, Oct 2, 2019 at 4:27 PM Anatoli Beliaev notifications@github.com wrote:

@JustinGrote https://github.com/JustinGrote If you are talking about exceptions thrown by the function code, do you think #328 https://github.com/Azure/azure-functions-powershell-worker/pull/328 addressed this problem? Or you are talking about exceptions thrown by the PS Worker internal code?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/Azure/azure-functions-powershell-worker/issues/244?email_source=notifications&email_token=ADUNKUQPV5QIGFGS2ZVU7OLQMUU4ZA5CNFSM4HTPZWO2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEAGP7IQ#issuecomment-537722786, or mute the thread https://github.com/notifications/unsubscribe-auth/ADUNKUQHSR5CUYGCTDP2YATQMUU4ZANCNFSM4HTPZWOQ .

[JustinGrote]

@AnatoliB to expound on this item:

Given the following HTTPTrigger function:

param($Request, $TriggerMetadata)

throw 'I want to see where this failed in Application Insights'

This is what I get in App Insights:

Notes:

1. All errors are RPCException errors. I should have the original type of this error shown which is System.Management.Automation.RuntimeException. I have no way to quickly distinguish issues from each other in app insights.
3. The stack trace doesn't tell me where in my script things failed. I expect this kind of stacktrace:

   Exception             : 
   Type                        : System.Management.Automation.RuntimeException
   ErrorRecord                 : 
       Exception             : 
           Type    : System.Management.Automation.ParentContainsErrorRecordException
           Message : I want to see where this failed in Application Insights
           HResult : -2146233087
       CategoryInfo          : NotSpecified: (:) [], ParentContainsErrorRecordException
       FullyQualifiedErrorId : RuntimeException
   WasThrownFromThrowStatement : True
   Message                     : I want to see where this failed in Application Insights
   HResult                     : -2146233087
   TargetObject          : I want to see where this failed in Application Insights
   CategoryInfo          : OperationStopped: (I want to see where…pplication Insights:String) [], RuntimeException
   FullyQualifiedErrorId : I want to see where this failed in Application Insights
   InvocationInfo        : 
   ScriptLineNumber : 6
   OffsetInLine     : 1
   HistoryId        : -1
   ScriptName       : C:\Users\jgrote\Projects\ADSLUSPRTGAPI\Sandbox\run.ps1
   Line             : throw 'I want to see where this failed in Application Insights'
   PositionMessage  : At C:\Users\jgrote\Projects\ADSLUSPRTGAPI\Sandbox\run.ps1:6 char:1
                      + throw 'I want to see where this failed in Application Insights'
                      + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
   PSScriptRoot     : C:\Users\jgrote\Projects\ADSLUSPRTGAPI\Sandbox
   PSCommandPath    : C:\Users\jgrote\Projects\ADSLUSPRTGAPI\Sandbox\run.ps1
   CommandOrigin    : Internal
   ScriptStackTrace      : at <ScriptBlock>, C:\Users\jgrote\Projects\ADSLUSPRTGAPI\Sandbox\run.ps1: line 6
                       at <ScriptBlock>, <No file>: line 1

   Recommended resolution

   The worker should write a custom exception to Application Insights or logging that has the relevant stack trace information before passing it back to the host.

Workaround

I had to make my own Application Insights client with Microsoft.ApplicationInsights.WorkerService and read the instrumentation key from an env variable, and then trap thrown errors and write my own custom exception to Application Insights before passing it along. I get duplicate error reports (my error and the rpc exception) but at least I have better error information to work with.

[AnatoliB]

Thank you @JustinGrote, I understand the issue.

I just want to make sure you know that the data you are asking for is in a different table in Application Insights:

traces
| where timestamp > ago(1h)
| where message startswith "EXCEPTION:" 
| project timestamp, message

EXCEPTION: I want to see where this failed in Application Insights
At D:\home\site\wwwroot\HttpTrigger2\run.ps1:3 char:1
+ throw 'I want to see where this failed in Application Insights'
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo          : OperationStopped: (I want to see where\u2026pplication Insights:String) [], RuntimeException
+ FullyQualifiedErrorId : I want to see where this failed in Application Insights

Script stack trace:
   at <ScriptBlock>, D:\home\site\wwwroot\HttpTrigger2\run.ps1: line 3

System.Management.Automation.RuntimeException: I want to see where this failed in Application Insights

The format of this data is different from your example because I took it from a PS6 app. As soon as we deploy PS7 support to Azure, it will be using the Get-Error cmdlet to format exceptions, so it will match your example. But, even now, you can see the stack trace including the function source code line.

So, is this issue about making these exceptions go to the exceptions table instead of (or in addition to) the traces table? In this case, making the worker write exceptions data directly to Application Insights seems to be the most practical solution. It may take some time for us to implement this, though. If you already have a solution that you could share in the meantime, we will appreciate it.

[JustinGrote]

I do have a solution that basically uses trap to intercept the errors. I'll prepare a module and an article as a workaround.

[JustinGrote]

I opened https://github.com/Azure/azure-functions-host/issues/5821 to hopefully resolve this at a more fundamental level where the worker can just log the exception via iLogger and the type will transparently pass down the grpc tunnel, that way all workers can take advantage.

If they don't implement, then "plan B" recommendation is either:

1. Add a handler for exceptions that logs the detailed Powershell exception including the ScriptStackTrace
2. Just use an AppInsights Powershell Module to trap/log the exceptions at the Powershell level (not ideal)

[JustinGrote]

Also @AnatoliB I was aware of that workaround, the problem is to correlate it to an actual exception when you're hunting for bugs requires a complex inner join Kusto query, and it just shouldn't be necessary to do that if the exception can just be richly logged natively.

[JustinGrote]

Ultimately it would be rad to add support to the application insights vscode extension to do Codelens support for Powershell, so I can click on a line and see how many times it failed on that line.

https://marketplace.visualstudio.com/items?itemName=VisualStudioOnlineApplicationInsights.application-insights

[JustinGrote]

Now tracked here: https://github.com/Azure/azure-functions-host/issues/6284

[sledoux]

Any updates on this? Appears to still be an issue, kind of hard to do error analysis in app insight when everything is wrapped in an RPC exception. Not really a fan of duplicating all the exceptions using the telemetry client, but it's the best option right now.

[JustinGrote]

This is still an issue. It theoretically would have been solved by https://github.com/Azure/azure-functions-host/pull/8314 but it wasn't.