Improve FunctionExecutor error handling

src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs

@@ -124,20 +124,24 @@ public async Task<IDelayedException> TryExecuteAsync(IFunctionInstance functionI
                         functionStartedMessage.EndTime = DateTimeOffset.UtcNow;
                     }
 
-                    // If function started was logged, don't cancel calls to log function completed.
-                    bool loggedStartedEvent = functionStartedMessageId != null;
-                    _functionInstanceLogger.LogFunctionCompleted(functionStartedMessage);
-
-                    if (instanceLogEntry != null)
+                    try
                     {
-                        CompleteInstanceLogEntry(instanceLogEntry, functionStartedMessage.Arguments, exceptionInfo);
-                        await _functionEventCollector.AddAsync(instanceLogEntry);
-                        _resultsLogger?.LogFunctionResult(instanceLogEntry);
+                        _functionInstanceLogger.LogFunctionCompleted(functionStartedMessage);
                     }
-
-                    if (loggedStartedEvent)
+                    finally
                     {
-                        _functionInstanceLogger.DeleteLogFunctionStarted(functionStartedMessageId);
+                        if (instanceLogEntry != null)
+                        {
+                            // it's important that we always complete the log entry even in the event of an exceptions above
+                            CompleteInstanceLogEntry(instanceLogEntry, functionStartedMessage.Arguments, exceptionInfo);
+                            await _functionEventCollector.AddAsync(instanceLogEntry);
+                            _resultsLogger?.LogFunctionResult(instanceLogEntry);
+                        }
+
+                        if (functionStartedMessageId != null)
+                        {
+                            _functionInstanceLogger.DeleteLogFunctionStarted(functionStartedMessageId);
+                        }
                     }
                 }
 

test/Microsoft.Azure.WebJobs.Host.UnitTests/Executors/FunctionExecutorTests.cs

@@ -486,6 +486,62 @@ public async Task TryExecuteAsync_DefaultActivity_Expected()
             Assert.Contains(testListener.Activities, a => a.OperationName == "TestFunction");
         }
 
+        [Fact]
+        public async Task TryExecuteAsync_LoggingPipelineException_CompletesInvocation()
+        {
+            var triggerData = new TriggeredFunctionData
+            {
+                TriggerValue = 123,
+                TriggerDetails = new Dictionary<string, string>()
+            };
+            var functionDescriptor = FunctionExecutorTestHelper.GetFunctionDescriptor();
+            var functionInstance = FunctionExecutorTestHelper.CreateFunctionInstance(Guid.NewGuid(), triggerData.TriggerDetails, false, functionDescriptor, 1000);
+            var parameterHelper = new FunctionExecutor.ParameterHelper((IFunctionInstanceEx)functionInstance);
+
+            // simulate a low level logging pipeline exception
+            var exceptionToThrow = new Exception("Logging failure");
+            var mockFunctionInstanceLogger = new Mock<IFunctionInstanceLogger>();
+            mockFunctionInstanceLogger.Setup(p => p.LogFunctionCompleted(It.IsAny<FunctionCompletedMessage>())).Throws(exceptionToThrow);
+
+            var mockFunctionOutputLogger = new NullFunctionOutputLogger();
+            var mockExceptionHandler = new Mock<IWebJobsExceptionHandler>();
+            var eventCollector = new TestFunctionInstanceLogEntryCollector();
+            var mockConcurrencyManager = new Mock<ConcurrencyManager>();
+
+            ILoggerFactory loggerFactory = new LoggerFactory();
+            TestLoggerProvider loggerProvider = new TestLoggerProvider();
+            loggerFactory.AddProvider(loggerProvider);
+
+            var executor = new FunctionExecutor(
+                mockFunctionInstanceLogger.Object,
+                mockFunctionOutputLogger,
+                mockExceptionHandler.Object,
+                eventCollector,
+                mockConcurrencyManager.Object,
+                loggerFactory,
+                null,
+                null);
+
+            executor.HostOutputMessage = new HostStartedMessage();
+
+            // invoke the function
+            // verify the exception is surfaced
+            var ex = await Assert.ThrowsAsync<Exception>(() => executor.TryExecuteAsync(functionInstance, CancellationToken.None));
+            Assert.Same(exceptionToThrow, ex);
+
+            // verify that the function invocation was marked as completed in the event log
+            var eventLogEntries = eventCollector.Entries.ToArray();
+            Assert.Equal(3, eventLogEntries.Length);
+            var entry = eventLogEntries.Last();
+            Assert.True(entry.IsCompleted);
+
+            // verify expected log entries
+            var log = loggerProvider.GetAllLogMessages().Single();
+            Assert.Equal(LogLevel.Information, log.Level);
+            Assert.Equal("Host.Results", log.Category);
+            Assert.Equal(functionInstance.Id, log.GetStateValue<Guid>("InvocationId"));
+        }
+
         private void RunOnFunctionTimeoutTest(bool isDebugging, string expectedMessage)
         {
             System.Timers.Timer timer = new System.Timers.Timer(TimeSpan.FromMinutes(1).TotalMilliseconds);
@@ -567,4 +623,23 @@ public void Dispose()
             _listener.Dispose();
         }
     }
+
+    internal class TestFunctionInstanceLogEntryCollector : IAsyncCollector<FunctionInstanceLogEntry>
+    {
+        private readonly List<FunctionInstanceLogEntry> _entries = new();
+
+        public IReadOnlyList<FunctionInstanceLogEntry> Entries => _entries;
+
+        public Task AddAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken = default)
+        {
+            _entries.Add(item);
+            return Task.CompletedTask;
+        }
+
+        public Task FlushAsync(CancellationToken cancellationToken = default)
+        {
+            // No-op for test collector
+            return Task.CompletedTask;
+        }
+    }
 }

test/Microsoft.Azure.WebJobs.Host.UnitTests/Filters/FunctionFilterTests.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Linq;
 using System.Text;
 using System.Threading;
@@ -351,7 +352,7 @@ static async Task CallExpectFailureAsync(JobHost host)
                 // Verify exception message comes at _throwAtPhase
                 // Last exception wins.
                 var e2 = e.InnerException ?? e;
-                var lastThrowPhase = _throwAtPhase.Split(';').Reverse().First();
+                var lastThrowPhase = ((IEnumerable<string>)_throwAtPhase.Split(';')).Reverse().First();
                 Assert.True(e2.Message.Contains(lastThrowPhase));
             }
             Assert.False(succeed); // Expected method to fail