logging error upon invocation exception (#1421)

release_notes.md

@@ -2,4 +2,6 @@
 <!-- Please add your release notes in the following format:
 - My change description (#PR/#issue)
 -->
-- Add query as property to HttpRequestData (#1408)
+
+- Logging an error on a function invocation exception. This error will also be logged by the host, but this allows for richer telemetry coming directly from the worker. See #1421 for details on how to disable this log if desired.
+- Add query as property to HttpRequestData (#1408)

src/DotNetWorker.Core/Diagnostics/WorkerMessage.cs

@@ -13,6 +13,10 @@ internal static class WorkerMessage
 
         internal static bool IsSystemLog => _isSystemLog.Value;
 
+        /// <summary>
+        /// Creates a delegate which can be invoked for logging a message. This message is treated as a "system" log
+        /// and forwarded to the Functions host in addition to other loggers.
+        /// </summary>
         public static Action<ILogger, Exception?> Define(LogLevel logLevel, EventId eventId, string formatString)
         {
             var log = LoggerMessage.Define(logLevel, eventId, formatString);
@@ -30,7 +34,10 @@ internal static class WorkerMessage
                 }
             };
         }
-
+        /// <summary>
+        /// Creates a delegate which can be invoked for logging a message. This message is treated as a "system" log
+        /// and forwarded to the Functions host in addition to other loggers.
+        /// </summary>
         public static Action<ILogger, T1, Exception?> Define<T1>(LogLevel logLevel, EventId eventId, string formatString)
         {
             var log = LoggerMessage.Define<T1>(logLevel, eventId, formatString);
@@ -49,6 +56,10 @@ internal static class WorkerMessage
             };
         }
 
+        /// <summary>
+        /// Creates a delegate which can be invoked for logging a message. This message is treated as a "system" log
+        /// and forwarded to the Functions host in addition to other loggers.
+        /// </summary>
         public static Action<ILogger, T1, T2, Exception?> Define<T1, T2>(LogLevel logLevel, EventId eventId, string formatString)
         {
             var log = LoggerMessage.Define<T1, T2>(logLevel, eventId, formatString);

src/DotNetWorker.Core/FunctionsApplication.Log.cs

@@ -14,10 +14,19 @@ private static class Log
                 WorkerMessage.Define<string, string>(LogLevel.Trace, new EventId(1, nameof(FunctionDefinitionCreated)),
                     "Function definition for '{functionName}' created with id '{functionid}'.");
 
+            private static readonly Action<ILogger, string, string, Exception?> _invocationError =
+                LoggerMessage.Define<string, string>(LogLevel.Error, new EventId(2, nameof(InvocationError)),
+                    "Function '{functionName}', Invocation id '{invocationId}': An exception was thrown by the invocation.");
+
             public static void FunctionDefinitionCreated(ILogger<FunctionsApplication> logger, FunctionDefinition functionDefinition)
             {
                 _functionDefinitionCreated(logger, functionDefinition.Name, functionDefinition.Id, null);
             }
+
+            public static void InvocationError(ILogger<FunctionsApplication> logger, string functionName, string invocationId, Exception exception)
+            {
+                _invocationError(logger, functionName, invocationId, exception);
+            }
         }
     }
 }

src/DotNetWorker.Core/FunctionsApplication.cs

@@ -79,7 +79,8 @@ public async Task InvokeFunctionAsync(FunctionContext context)
             catch (Exception ex)
             {
                 invokeActivity?.SetStatus(ActivityStatusCode.Error, ex.Message);
-                invokeActivity?.RecordException(ex, escaped: true);
+
+                Log.InvocationError(_logger, context.FunctionDefinition.Name, context.InvocationId, ex);
 
                 throw;
             }

test/DotNetWorkerTests/FunctionsApplicationTests.cs

@@ -0,0 +1,138 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using System.Diagnostics;
+using System.Linq;
+using System.Threading.Tasks;
+using Microsoft.Azure.Functions.Worker.Diagnostics;
+using Microsoft.Azure.Functions.Worker.Middleware;
+using Microsoft.Azure.Functions.Worker.Pipeline;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
+using Microsoft.Extensions.Options;
+using Moq;
+using Xunit;
+
+namespace Microsoft.Azure.Functions.Worker.Tests
+{
+    public class FunctionsApplicationTests
+    {
+        [Fact]
+        public async Task InvokeAsync_LogsException()
+        {
+            static Task InvokeWithError(FunctionContext context)
+            {
+                throw new InvalidOperationException("boom!");
+            }
+
+            var logger = TestLogger<FunctionsApplication>.Create();
+            var app = CreateApplication(InvokeWithError, logger);
+
+            var context = new TestFunctionContext();
+
+            await Assert.ThrowsAsync<InvalidOperationException>(() => app.InvokeFunctionAsync(context));
+
+            var message = logger.GetLogMessages().Single();
+
+            var name = message.State.Single(p => p.Key == "functionName").Value;
+            Assert.Equal(context.FunctionDefinition.Name, name.ToString());
+
+            var invocation = message.State.Single(p => p.Key == "invocationId").Value;
+            Assert.Equal(context.InvocationId, invocation.ToString());
+
+            Assert.Equal(LogLevel.Error, message.Level);
+            Assert.IsType<InvalidOperationException>(message.Exception);
+            Assert.Equal("boom!", message.Exception.Message);
+            Assert.Equal("InvocationError", message.EventId.Name);
+            Assert.Equal(2, message.EventId.Id);
+        }
+
+        [Fact]
+        public async Task InvokeAsync_RecordsActivity()
+        {
+            var context = new TestFunctionContext();
+
+            using ActivityListener listener = CreateListener(activity =>
+            {
+                AssertActivity(activity, context);
+
+                Assert.Equal(ActivityStatusCode.Unset, activity.Status);
+                Assert.Null(activity.StatusDescription);
+
+                Assert.Empty(activity.Events);
+            });
+
+            static Task Invoke(FunctionContext context)
+            {
+                return Task.CompletedTask;
+            }
+
+            var logger = NullLogger<FunctionsApplication>.Instance;
+            var app = CreateApplication(Invoke, logger);
+
+            await app.InvokeFunctionAsync(context);
+        }
+
+        [Fact]
+        public async Task InvokeAsync_OnError_RecordsActivity()
+        {
+            var context = new TestFunctionContext();
+
+            using ActivityListener listener = CreateListener(activity =>
+            {
+                AssertActivity(activity, context);
+
+                Assert.Equal(ActivityStatusCode.Error, activity.Status);
+                Assert.Equal("boom!", activity.StatusDescription);
+
+                // we are not currently recording exceptions here
+                Assert.Empty(activity.Events);
+            });
+
+            static Task InvokeWithError(FunctionContext context)
+            {
+                throw new InvalidOperationException("boom!");
+            }
+
+            var logger = NullLogger<FunctionsApplication>.Instance;
+            var app = CreateApplication(InvokeWithError, logger);
+
+            await Assert.ThrowsAsync<InvalidOperationException>(() => app.InvokeFunctionAsync(context));
+        }
+
+        private static void AssertActivity(Activity activity, FunctionContext context)
+        {
+            Assert.Equal("Invoke", activity.DisplayName);
+            Assert.Equal(2, activity.Tags.Count());
+            Assert.Equal("https://opentelemetry.io/schemas/1.17.0", activity.Tags.Single(k => k.Key == "az.schema_url").Value);
+            Assert.Equal(context.InvocationId, activity.Tags.Single(k => k.Key == "faas.execution").Value);
+        }
+
+        private static FunctionsApplication CreateApplication(FunctionExecutionDelegate invoke, ILogger<FunctionsApplication> logger)
+        {
+            var options = new OptionsWrapper<WorkerOptions>(new WorkerOptions());
+            var contextFactory = new Mock<IFunctionContextFactory>();
+            var diagnostics = new Mock<IWorkerDiagnostics>();
+            var activityFactory = new FunctionActivitySourceFactory(new OptionsWrapper<WorkerOptions>(new WorkerOptions()));
+
+            return new FunctionsApplication(invoke, contextFactory.Object, options, logger, diagnostics.Object, activityFactory);
+        }
+
+        private static ActivityListener CreateListener(Action<Activity> onStopped)
+        {
+            var listener = new ActivityListener
+            {
+                ShouldListenTo = source => source.Name.StartsWith(TraceConstants.FunctionsActivitySource),
+                ActivityStarted = activity => { },
+                ActivityStopped = onStopped,
+                Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData,
+                SampleUsingParentId = (ref ActivityCreationOptions<string> _) => ActivitySamplingResult.AllData
+            };
+
+            ActivitySource.AddActivityListener(listener);
+
+            return listener;
+        }
+    }
+}