From e1e0a3faf0e86f7dbb86538a9c045f346ac052cb Mon Sep 17 00:00:00 2001 From: Mathew Charles Date: Tue, 18 Nov 2025 14:27:08 -0800 Subject: [PATCH] Improve FunctionExecutor error handling --- .../Executors/FunctionExecutor.cs | 26 ++++--- .../Executors/FunctionExecutorTests.cs | 75 +++++++++++++++++++ .../Filters/FunctionFilterTests.cs | 3 +- 3 files changed, 92 insertions(+), 12 deletions(-) diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs index 77cdcdf19..2f0931252 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs @@ -124,20 +124,24 @@ public async Task 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); + } } } diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Executors/FunctionExecutorTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Executors/FunctionExecutorTests.cs index 965e116ac..316316268 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Executors/FunctionExecutorTests.cs +++ b/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() + }; + 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(); + mockFunctionInstanceLogger.Setup(p => p.LogFunctionCompleted(It.IsAny())).Throws(exceptionToThrow); + + var mockFunctionOutputLogger = new NullFunctionOutputLogger(); + var mockExceptionHandler = new Mock(); + var eventCollector = new TestFunctionInstanceLogEntryCollector(); + var mockConcurrencyManager = new Mock(); + + 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(() => 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("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 + { + private readonly List _entries = new(); + + public IReadOnlyList 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; + } + } } \ No newline at end of file diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Filters/FunctionFilterTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Filters/FunctionFilterTests.cs index b8333972a..f2adfb09a 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Filters/FunctionFilterTests.cs +++ b/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)_throwAtPhase.Split(';')).Reverse().First(); Assert.True(e2.Message.Contains(lastThrowPhase)); } Assert.False(succeed); // Expected method to fail