Added logging function name on ServiceBus exception. (#162)

[alrod]

This change is needed for the ServiceBus detector to filter ServiceBus SDK exceptions by function name. Previously all error which came for ServiceBus was logged under LogCategories.Executor category. The PR changes the category to LogCategories.CreateFunctionCategory(functionName) to populate FunctionName column in FunctionLogs.

Pull request checklist

• [x] My changes do not require documentation changes
  • [ ] Otherwise: Documentation issue linked to PR. Update documentation to reflect new configuration options
• [] My changes should not be added to the release notes for the next release
  • [x] Otherwise: I've added my notes to release_notes.md
• [x] My changes do not need to be backported to a previous version
  • [ ] Otherwise: Backport tracked by issue/PR #issue_or_pr
• [x] I have added all required tests (Unit tests, E2E tests) - No new tests needed

[sidkri]

For consistency, could you please update the description with the PR checklist we recently introduced? An example is in this PR: #143

[JoshLove-msft]

The way this is handled in the T2 extensions is by using ILogger<T> so everything is logged with a category = type name of the thing that is doing the logging. We don't include the actual function name as the category.

[sidkri]

@JoshLove-msft we need the function name to provide better diagnostics/detection information to users. How can we get similar functionality in T2?

[JoshLove-msft]

Is there a reason that it is just for this specific log instance and only the Service Bus extension? The guidance we were given by @fabiocav was to use ILogger<T> everywhere in the T2 extensions so that the category would be the fully qualified type name for logs.

/cc @pakrym @kasobol-msft

[fabiocav]

Also adding @brettsam

[JoshLove-msft]

@sidkri can you explain how this information is surfaced to users? I saw mention of a Service Bus detector, but wasn't sure what that is. Would it be enough to include the function name in the log message?

[sidkri]

@JoshLove-msft this information is surfaced via logs (app insights etc.) and also leveraged by a new Diagnostics detector we published specifically for Service Bus extension related issues. To use this detector, in the Azure portal, from any Function App resource, navigate to the "Diagnose and Solve" section and search for "Messaging Function Trigger Failure". If there are any functions that use the Service Bus extension, the service bus detector will load and show diagnostics information like triggers and exceptions. This PR adds the Function name to the exception log entry so the detector can present this important context around the exception. I'm not familiar with the suggestion about ILogger but would also like to understand.

[JoshLove-msft]

Thanks for the info. I will test out the experience in the portal when using ILogger<T> and report back. It may be that we need to include the function name as the category for errors at least. But in that case, it might be better to just use it everywhere.

[sidkri]

"ILogger everywhere in the T2 extensions so that the category would be the fully qualified type name". Ah, type name would not be the name of the Function, just the class that is emitting the log statement. Sounds like the change in this PR should also be done for the T2 extension.

[JoshLove-msft]

"ILogger everywhere in the T2 extensions so that the category would be the fully qualified type name". Ah, type name would not be the name of the Function, just the class that is emitting the log statement. Sounds like the change in this PR should also be done for the T2 extension.

Well, that is the question. Our guidance was to include the type name, not the function name, and it was across all of the T2 extensions. We can use the function name here, but it opens up the question of why wouldn't we do it for the other extensions as well.

[sidkri]

"ILogger everywhere in the T2 extensions so that the category would be the fully qualified type name". Ah, type name would not be the name of the Function, just the class that is emitting the log statement. Sounds like the change in this PR should also be done for the T2 extension.

Well, that is the question. Our guidance was to include the type name, not the function name, and it was across all of the T2 extensions. We can use the function name here, but it opens up the question of why wouldn't we do it for the other extensions as well.

I see your point now. This should definitely apply to other extensions as well when they emit logs. Functions host itself does include the Function name on each invocation but this is not done by some of the other extensions (e.g. EventHubs). I created an issue to track this for Event Hubs extension. As we light up diagnostics detectors, such enhancements become evident and we implement them so its definitely an iterative process.

[JoshLove-msft]

@sidkri, Here is what I see in the Messaging Function Trigger Failure detector when I test out a function that throws an exception with existing logging that doesn't include the function name as the log category. As you can see, the function name is included in the full exception message. Am I looking in the right place here? Is there somewhere else we would expect the function name to show up?

I also see that there is a dropdown in the UI where you can select the function that you want to view errors for. It doesn't seem like this is driven off of the category name as the logs are populated for my function. Even when I add a second function, the errors are attributed correctly without making any changes to the logging.

Timestamp : 8/6/2021 6:54:59 PM Inner Exception Type: System.Exception Total Occurrences: 394000 Latest Exception Message: Exception of type 'System.Exception' was thrown.

Full Exception : Exception while executing function: ServiceBusDemo System.Exception : Exception of type 'System.Exception' was thrown. at async Demo.ServiceBusFunction.Run(ServiceBusReceivedMessage message,ILogger log,IAsyncCollector1 collector) at C:\Users\jolov\source\repos\FunctionApp5\FunctionApp5\ServiceBusFunction.cs : 22 at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at async Microsoft.Azure.WebJobs.Host.Executors.VoidTaskMethodInvoker2.InvokeAsync[TReflected,TReturnType](TReflected instance,Object[] arguments) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\VoidTaskMethodInvoker.cs : 20 at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at async Microsoft.Azure.WebJobs.Host.Executors.FunctionInvoker`2.InvokeAsync[TReflected,TReturnValue](Object instance,Object[] arguments) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionInvoker.cs : 52 at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.InvokeWithTimeoutAsync(IFunctionInvoker invoker,ParameterHelper parameterHelper,CancellationTokenSource timeoutTokenSource,CancellationTokenSource functionCancellationTokenSource,Boolean throwOnTimeout,TimeSpan timerInterval,IFunctionInstance instance) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 555 at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithWatchersAsync(IFunctionInstanceEx instance,ParameterHelper parameterHelper,ILogger logger,CancellationTokenSource functionCancellationTokenSource) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 501 at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance,FunctionStartedMessage message,FunctionInstanceLogEntry instanceLogEntry,ParameterHelper parameterHelper,ILogger logger,CancellationToken cancellationToken) at C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 279 End of inner exception at Microsoft.Azure.WebJobs.ServiceBus.MessageProcessor.CompleteProcessingMessageAsync(ServiceBusMessageActions actions,ServiceBusReceivedMessage message,FunctionResult result,CancellationToken cancellationToken) at async Microsoft.Azure.WebJobs.ServiceBus.Listeners.ServiceBusListener.ProcessMessageAsync(ProcessMessageEventArgs args) at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at async Azure.Messaging.ServiceBus.ServiceBusProcessor.OnProcessMessageAsync(ProcessMessageEventArgs args) at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at async Azure.Messaging.ServiceBus.ReceiverManager.OnMessageHandler(ServiceBusReceivedMessage message,CancellationToken processorCancellationToken) at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at async Azure.Messaging.ServiceBus.ReceiverManager.ProcessOneMessage(ServiceBusReceivedMessage message,CancellationToken cancellationToken)