Azure / Azure/azure-functions-host

Unexpected error in logs - Unable to load metadata for function 'WarmUp'

Open
#10,020 0 comments 0 reactions 0 assignees View on GitHub
area: flex-consumption bug needs-investigation
Dominant language
C#
Stars
2k
Forks
482
Avg merge
2d 10h
Merged PRs (30d)
36

Description

Intermittently seeing the following error on both 4.1031.2.2 and 4.1033.6.6. All below queries should be on **wawscus**

```
Executed 'Functions.WarmUp' (Failed, Id=c23b4660-e688-4512-bd64-d3dd9f6b9a2c, Duration=10ms)

System.InvalidOperationException : Unable to load metadata for function 'WarmUp'.
at Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.FunctionInstanceLogger.StartFunction(FunctionInstanceLogEntry item) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Diagnostics/FunctionInstanceLogger.cs : 82
at Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.FunctionInstanceLogger.AddAsync(FunctionInstanceLogEntry item,CancellationToken cancellationToken) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Diagnostics/FunctionInstanceLogger.cs : 58
at async Microsoft.Azure.WebJobs.Host.Loggers.CompositeFunctionEventCollector.AddAsync(FunctionInstanceLogEntry item,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Loggers\CompositeFunctionEventCollector.cs : 21
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 106
```

```
FunctionsLogs
| where PreciseTimeStamp >= datetime(2024-04-16T21:11:24.6744650Z) and PreciseTimeStamp <= datetime(2024-04-17T17:29:20.8651330Z)
| where Role == "Legion.FunctionsWorkerPod"
| where Details hasprefix "System.InvalidOperationException : Unable to load metadata for function 'WarmUp'"
```
My application does not have a function called `WarmUp`. This error is likely due to a rare race condition, because I only see this error a handful of times across more than 10,000 instances that ran this app in the last 24 hours.

Right at the same time, I see the following null ref which is probably a clue.
```
System.NullReferenceException : Object reference not set to an instance of an object.
at Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.FunctionInstanceLogger.EndFunction(FunctionInstanceLogEntry item) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Diagnostics/FunctionInstanceLogger.cs : 107
at Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.FunctionInstanceLogger.AddAsync(FunctionInstanceLogEntry item,CancellationToken cancellationToken) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Diagnostics/FunctionInstanceLogger.cs : 62
at async Microsoft.Azure.WebJobs.Host.Loggers.CompositeFunctionEventCollector.AddAsync(FunctionInstanceLogEntry item,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Loggers\CompositeFunctionEventCollector.cs : 21
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs : 129
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.ShutdownFunctionExecutor.TryExecuteAsync(IFunctionInstance instance,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\ShutdownFunctionExecutor.cs : 23
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutorExtensions.TryExecuteAsync(IFunctionExecutor executor,Func`1 instanceFactory,ILoggerFactory loggerFactory,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutorExtensions.cs : 50
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.JobHost.CallAsyncCore(IFunctionDefinition function,Object functionKey,IDictionary`2 arguments,CancellationToken cancellationToken) at D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\JobHost.cs : 260
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Script.WebHost.Features.FunctionExecutionFeature.ExecuteAsync(HttpRequest request,CancellationToken cancellationToken) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Features/FunctionExecutionFeature.cs : 75
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Script.WebHost.Middleware.FunctionInvocationMiddleware.GetResultAsync(HttpContext context,IFunctionExecutionFeature functionExecution) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Middleware/FunctionInvocationMiddleware.cs : 144
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Script.WebHost.Middleware.FunctionInvocationMiddleware.Invoke(HttpContext context) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Middleware/FunctionInvocationMiddleware.cs : 58
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Script.WebHost.Middleware.JobHostEasyAuthMiddleware.<>c.<-ctor>b__2_0(??) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Middleware/JobHostEasyAuthMiddleware.cs : 30
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Script.WebHost.Middleware.JobHostEasyAuthMiddleware.Invoke(HttpContext context,RequestDelegate next) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Middleware/JobHostEasyAuthMiddleware.cs : 47
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at async Microsoft.Azure.WebJobs.Script.WebHost.Middleware.ExceptionMiddleware.Invoke(HttpContext context) at /src/azure-functions-host/src/WebJobs.Script.WebHost/Middleware/ExceptionMiddleware.cs : 27
```

It looks like this error is a on a disposal codepath as part of specialization

PreciseTimeStamp | Summary | HostInstanceId
-- | -- | --
2024-04-17 17:20:24.3553085 | Disposing ScriptHost. | 91e47cfc-2892-487f-89c0-5a8cc6a39fcc
2024-04-17 17:20:24.3553224 | Executed 'Functions.WarmUp' (Failed, Id=c23b4660-e688-4512-bd64-d3dd9f6b9a2c, Duration=10ms) | 91e47cfc-2892-487f-89c0-5a8cc6a39fcc

The error does not appear to have major impact. Log analysis shows that the application continues to handle other function invocations OK.

```
FunctionsLogs
| where PreciseTimeStamp >= datetime(2024-04-17T17:13:19.9884853Z) and PreciseTimeStamp <= datetime(2024-04-17 17:20:24.3558240)
| where RoleInstance == "d69b2ca6-3046-48b5-a776-9ba30b7a9595"
```
Also I checked my app insights and I couldn't see this error. Likely because the error occurred for the placeholder scripthost.

Contributor guide

Open the contributing guide

Research direction

Start by reading FunctionInstanceLogger.cs at lines 58, 62, 82, 107 and the surrounding FunctionExecutor call paths shown in the traces. Investigate how disposal during specialization can leave function metadata or log entries unavailable, using the WarmUp failure and concurrent null reference as the reproduction clues. Done means the rare logging errors no longer occur while other invocations continue normally.

Written by the indexing model from the issue text.

Assessment

Tech stack
azure, csharp
Domain
backend, cloud
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
42/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.