Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ObjectDisposedException: Request has finished and HttpContext disposed. in Extensions.Http.AspNetCore #2417

Open
pregress opened this issue Apr 19, 2024 · 14 comments
Assignees
Labels
area: http Items related to experience improvements for HTTP triggers needs-investigation potential-bug Items opened using the bug report template, not yet triaged and confirmed as a bug

Comments

@pregress
Copy link

Description

When using the Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore version 1.2.1 we sometimes receive an ObjectDisposedException resulting in a System.InvalidOperationException: An attempt was made to transition a task to a final state when it had already completed.

Here is the stack trace of the ObjectDisposedException

Result: Failure Exception: System.ObjectDisposedException: Request has finished and HttpContext disposed. Object name: 'HttpContext'. at Microsoft.AspNetCore.Http.DefaultHttpContext.ThrowContextDisposed() at Microsoft.AspNetCore.Routing.RoutingHttpContextExtensions.GetRouteData(HttpContext httpContext) at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.FunctionsHttpProxyingMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\FunctionsMiddleware\FunctionsHttpProxyingMiddleware.cs:line 54 at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 77 at Microsoft.Azure.Functions.Worker.Handlers.InvocationHandler.InvokeAsync(InvocationRequest request) in D:\a_work\1\s\src\DotNetWorker.Grpc\Handlers\InvocationHandler.cs:line 88 Stack: at Microsoft.AspNetCore.Http.DefaultHttpContext.ThrowContextDisposed() at Microsoft.AspNetCore.Routing.RoutingHttpContextExtensions.GetRouteData(HttpContext httpContext) at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.FunctionsHttpProxyingMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\FunctionsMiddleware\FunctionsHttpProxyingMiddleware.cs:line 54 at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 77 at Microsoft.Azure.Functions.Worker.Handlers.InvocationHandler.InvokeAsync(InvocationRequest request) in D:\a_work\1\s\src\DotNetWorker.Grpc\Handlers\InvocationHandler.cs:line 88

This file hase already been changed, so line numbers are wrong. https://github.com/Azure/azure-functions-dotnet-worker/pull/2322/files/6149e16e951188e97bf7fcff6918b45ae233bde4#diff-dc49550c24c24c88566ae78776b0400d415dfc8d1a5d623571903671a953e715

The GetRouteData call in now on line 72 instead of 54.

We don't have a reproducible sample as this exception did only happens seemingly random.

As a quick fix we removed AspNetCore package from our function.

Steps to reproduce

Only saw it on a deployed linux azure function with a single instance.

@pregress pregress added the bug Something isn't working label Apr 19, 2024
@liliankasem liliankasem added needs-investigation potential-bug Items opened using the bug report template, not yet triaged and confirmed as a bug and removed bug Something isn't working labels Apr 19, 2024
@liliankasem
Copy link
Member

We don't have a reproducible sample as this exception did only happens seemingly random.

Can you share what you have and what you're currently doing? Even if it's random it would be helpful to have some steps that could help us figure out what is causing this.

@pregress
Copy link
Author

csproj file:

<Project Sdk="Microsoft.NET.Sdk">
	<PropertyGroup>
		<TargetFramework>net8.0</TargetFramework>
		<AzureFunctionsVersion>v4</AzureFunctionsVersion>
		<OutputType>Exe</OutputType>
		<ImplicitUsings>enable</ImplicitUsings>
		<Nullable>enable</Nullable>
		<PublishReadyToRun>true</PublishReadyToRun>
	</PropertyGroup>
  <ItemGroup>
	  <FrameworkReference Include="Microsoft.AspNetCore.App" />
	  <PackageReference Include="Azure.Extensions.AspNetCore.Configuration.Secrets" Version="1.3.1" />
	  <PackageReference Include="Microsoft.Azure.Functions.Worker" Version="1.21.0" />
	  <PackageReference Include="Microsoft.Azure.Functions.Worker.Extensions.Http" Version="3.1.0" />
	  <PackageReference Include="Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore" Version="1.2.1" />
	  <PackageReference Include="Microsoft.Azure.Functions.Worker.Extensions.ServiceBus" Version="5.17.0" />
	  <PackageReference Include="Microsoft.Azure.Functions.Worker.Extensions.Timer" Version="4.3.0" />
	  <PackageReference Include="Microsoft.Azure.Functions.Worker.Sdk" Version="1.17.2" />
	  <PackageReference Include="Microsoft.ApplicationInsights.WorkerService" Version="2.22.0" />
	  <PackageReference Include="Microsoft.Azure.Functions.Worker.ApplicationInsights" Version="1.2.0" />
	  <PackageReference Include="AspNetCore.HealthChecks.AzureServiceBus" Version="8.0.0" />
	  <PackageReference Include="AspNetCore.HealthChecks.Publisher.ApplicationInsights" Version="8.0.0" />
	  <PackageReference Include="AspNetCore.HealthChecks.UI.Client" Version="8.0.0" />
	  <PackageReference Include="Microsoft.Bcl.AsyncInterfaces" Version="8.0.0" />
	  <PackageReference Include="Worker.Extensions.HttpTelemetryProcessor" Version="1.0.2" />
  </ItemGroup>

  <ItemGroup>
    <None Update="appsettings.json">
      <CopyToOutputDirectory>Always</CopyToOutputDirectory>
    </None>
    <None Update="appsettings.Production.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
    </None>
    <None Update="appsettings.Staging.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
    </None>
    <None Update="host.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
    </None>
	<None Update="local.settings.json">
	  <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
	  <CopyToPublishDirectory>Never</CopyToPublishDirectory>
	</None>
  </ItemGroup>
  <PropertyGroup>
    <_FunctionsSkipCleanOutput>true</_FunctionsSkipCleanOutput>
  </PropertyGroup>
	<ItemGroup>
		<Using Include="System.Threading.ExecutionContext" Alias="ExecutionContext" />
	</ItemGroup>
</Project>

Trimmed down function raising object desposed function:

public class BrokenFunction(IRequestProcessor requestProcessor,
    IRequestReader requestReader, IAuthenticationService authenticationService,
    ILogger<BrokenFunction> logger) : AuthorizedFunction(authenticationService)
{
    [Function("BrokenFunction")]
    public async Task<IActionResult> Run([HttpTrigger(AuthorizationLevel.Function, "get", "post", Route = null)] HttpRequest httpRequest, ExecutionContext executionContext)
    {
        var result = await AuthorizeAsync(httpRequest);
        if (!result.Succeeded)
        {
            logger.LogWarning(result.Failure, "Unauthenticated request");
            return new UnauthorizedResult();
        }

        try
        {
            var request = await requestReader.ReadRequest(logger, httpRequest);
            using var scope = logger.BeginScope(new Dictionary<string, object>
            {
                ["RequestId"] = request.RequestId,
                ["Email"] = httpRequest.HttpContext.User.FindFirst(ClaimTypes.Email)?.Value,
                ["CustomerId"] = httpRequest.HttpContext.User.FindFirst("customer_id")?.Value,
            });
            var response = await requestProcessor.ProcessRequest(logger, request);
            var serializerSettings = SerializerSettings.GetSettings();
            var jsonResponse = JsonConvert.SerializeObject(response, serializerSettings);
            logger.LogInformation("response: {json}", jsonResponse);
            return new OkObjectResult(response);
        }
        catch (UnauthorizedAccessException)
        {
            return new UnauthorizedResult();
        }
    }
}

public abstract class AuthorizedFunction(IAuthenticationService authenticationService)
{
    protected async Task<AuthenticateResult> AuthorizeAsync(HttpRequest httpRequest)
    {
        var result = await authenticationService.AuthenticateAsync(httpRequest.HttpContext, null);
        if (result.Succeeded)
        {
            httpRequest.HttpContext.User = result.Principal;
        }

        return result;
    }
}

Behind the scenes some other api's are being called. They can be slow, but we could not correlate duration vs ObjectDisposedexception.

@Rihab8
Copy link

Rihab8 commented Jul 1, 2024

Hi , I got the similar exception,

Result: Function 'LaunchSubscriptionInstance', Invocation id 'c822cd42-d803-408c-9556-294a93a21f24': An exception was thrown by the invocation.
Exception: System.ObjectDisposedException: Request has finished and HttpContext disposed.
Object name: 'HttpContext'.
   at Microsoft.AspNetCore.Http.DefaultHttpContext.ThrowContextDisposed()
   at Microsoft.AspNetCore.Http.DefaultHttpContext.get_Features()
   at Microsoft.AspNetCore.Routing.RoutingHttpContextExtensions.GetRouteData(HttpContext httpContext)
   at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.FunctionsHttpProxyingMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\FunctionsMiddleware\FunctionsHttpProxyingMiddleware.cs:line 54
   at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 89
Stack:    at Microsoft.AspNetCore.Http.DefaultHttpContext.ThrowContextDisposed()
   at Microsoft.AspNetCore.Http.DefaultHttpContext.get_Features()
   at Microsoft.AspNetCore.Routing.RoutingHttpContextExtensions.GetRouteData(HttpContext httpContext)
   at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.FunctionsHttpProxyingMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\FunctionsMiddleware\FunctionsHttpProxyingMiddleware.cs:line 54
   at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 89

when we can expect the issue fix ? and is there any short term solution or workaround for this issue

@pregress
Copy link
Author

pregress commented Jul 1, 2024

@Rihab8 We removed the dependencies to Asp.net, depending on your functions this is a viable solution or not.
If you don't have the asp.net pipeline everything works fine.

@javier-acrich
Copy link

Same issue exists in Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore version 1.3.2

@liliankasem
Copy link
Member

Sorry for the delay here, we're actively investigating a couple of issues that lead to this exception. We suspect that it's a symptom of the platform abruptly shutting down an instance. Is anyone still actively seeing this issue able to share the following info for me to check logs and investigate further?

  • UTC execution time / timestamp
  • Any invocation ID that happened around that time period
  • Region of your function app

Those 3 pieces of information are enough for us to look up your details, and they do not reveal anything of interest to anyone but the Azure Functions team (so there is no concern about posting them publicly).

@pmerineau
Copy link

Hi Lilian. Thanks for looking into this issue.
I have one for you:
Event time: 2024-11-04T19:36:04.593273Z
InvocationId: 0577cf46-de3f-47ba-9751-0750cc28ba18
Location: Canada Central

@stuartf-aida
Copy link

Hi Lilian,
Thanks from us, too:

Event time: 04/11/2024, 10:28:42.2521087 (Local time) - we're in GMT, so this happens to be == UTC, anyway
Invocation Id: a11b8045-59cf-4db2-90eb-356d561e2fb2
Location: North Europe

@liliankasem
Copy link
Member

liliankasem commented Nov 5, 2024

Thanks for sharing these apps.

App 1

@pmerineau Looking into your app, I didn't see a ObjectDisposedException within the last 90 days. Are you experiencing a different issue that what is being described in this GH issue?

I did look into the specific invocation you shared, and it looks like a cancellation related problem. Your invocation is being cancelled (likely due to client disconnect)

Sending InvocationCancel request for invocation: '0577cf46-de3f-47ba-9751-0750cc28ba18'

And your function invocation is failing, likely due to this proxy that is not forwarding the cancellation request to your app properly:

Exception while executing function: Functions.<YourFunctionName> ---> System.InvalidOperationException : Failed to proxy request with ForwarderError: RequestCanceled. System.IO.IOException : Unable to read data from the transport connection: The I/O operation has been aborted because of either a thread exit or an application request

If this is the issue you're trying to raise, please create a new GH issue as it is not related to this one. Thanks!

App 2

@stuartf-aida I also looked into your app. I was able to find an ObjectDisposedException exception October 18th, but it looks different to the one reported here:

Shutting down RPC server
Killing RPC server
System.ObjectDisposedException : The CancellationTokenSource has been disposed.

This error occurs during shut down (a graceful host shutdown) and is just noise with no real impact to your application. Nonetheless, we will still look into how to avoid this exception during the shutdown process. Thanks for sharing!

I also looked at the specific invocation you shared, you are experiencing the exact same problem as App 1, your invocation was cancelled leading to invocation failure with the same error:

Sending InvocationCancel request for invocation: 'a11b8045-59cf-4db2-90eb-356d561e2fb2'

Exception while executing function: Functions.<YourFunctionName> ---> System.InvalidOperationException : Failed to proxy request with ForwarderError: RequestCanceled. System.IO.IOException : Unable to read data from the transport connection: The I/O operation has been aborted because of either a thread exit or an application request

This is also not related to this specific GH issue so please open a new issue (or perhaps add on to one that @pmerineau creates?).

The error is actually happening on the Functions Host side in the RetryProxyHandler so I would suggest opening the issue in the host repo and I will continue that investigation there as well.

@stuartf-aida
Copy link

Thanks again @liliankasem
I have created
Azure/azure-functions-host#10600

fyi @pmerineau

@pmerineau
Copy link

pmerineau commented Nov 5, 2024

Hi @liliankasem,
Thanks for the infos.
We have a bunch or errors that all seem to come from a Canceled. I thought the one sent had this error. Here is one that specifically has the ObjectDisposedException

Event time: 2024-11-05T01:08:31.2502213Z
InvocationId: 9229ce81-39ee-48fc-87b7-000862e9c314
Location: Canada Central

@liliankasem
Copy link
Member

Hi @liliankasem, Thanks for the infos. We have a bunch or errors that all seem to come from a Canceled. I thought the one sent had this error. Here is one that specifically has the ObjectDisposedException

Event time: 2024-11-05T01:08:31.2502213Z InvocationId: 9229ce81-39ee-48fc-87b7-000862e9c314 Location: Canada Central

This one is also the same cancellation issue:

2024-11-05T01:08:31.2769603Z
"Summary": Executed 'Functions.<FunctionName>' (Failed, Id=9229ce81-39ee-48fc-87b7-000862e9c314, Duration=3683ms),
"Details": Microsoft.Azure.WebJobs.Host.FunctionInvocationException : Exception while executing function: Functions.<FunctionName> --
-> System.InvalidOperationException : Failed to proxy request with ForwarderError: RequestCanceled ---> 
System.Threading.Tasks.TaskCanceledException : The operation was canceled. ---> System.IO.IOException : Unable to read data from 
the transport connection: The I/O operation has been aborted because of either a thread exit or an application request.. ---> 
System.Net.Sockets.SocketException : The I/O operation has been aborted because of either a thread exit or an application request.

@dkapadia-jb
Copy link

Thanks @liliankasem
We have errors happening everyday mainly when the request is cancelled by the client.
Below is one of the invocations:

Event time: 2024-11-05T21:52:17.8987792Z
InvocationId: ec51ae6d-ec73-494f-9f55-d9b1d988a4b7
Location: Australia East

@liliankasem
Copy link
Member

liliankasem commented Nov 6, 2024

Quick update, I was able to find the root cause of the bug here (write up available in this issue).

I will work with the team on a solution for this and let folks know when it is resolved.

tldr; it's connected to cancellation: when a function invocation is cancelled, the ct is also being used by the ContextReference leading to the HttpContext being disposed when we try to handle the invocation result.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: http Items related to experience improvements for HTTP triggers needs-investigation potential-bug Items opened using the bug report template, not yet triaged and confirmed as a bug
Projects
None yet
Development

No branches or pull requests

7 participants