InvalidOperationException when canceling request

[tevoinea]

Description

I was expecting to see something along the lines of: Executed 'Functions.BlobStream' (Canceled, Id=a0055d05-6f22-46cf-8194-177a7c338e67, Duration=1983ms) but instead there's an InvalidOperationException.

Output logs:

[2024-04-03T19:00:49.837Z] Function 'BlobStream', Invocation id '5f3199e5-f368-4ffd-817a-febef800d11f': An exception was thrown by the invocation.
[2024-04-03T19:00:49.839Z] Result: Function 'BlobStream', Invocation id '5f3199e5-f368-4ffd-817a-febef800d11f': An exception was thrown by the invocation.
Exception: System.InvalidOperationException: An attempt was made to transition a task to a final state when it had already completed.
[2024-04-03T19:00:49.841Z]    at System.Threading.Tasks.TaskCompletionSource`1.SetCanceled(CancellationToken cancellationToken)
[2024-04-03T19:00:49.842Z]    at System.Threading.Tasks.TaskCompletionSource`1.SetCanceled()
[2024-04-03T19:00:49.844Z]    at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.ContextReference.CompleteFunction() in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\Coordinator\ContextReference.cs:line 59
[2024-04-03T19:00:49.845Z]    at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.DefaultHttpCoordinator.CompleteFunctionInvocation(String invocationId) in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\Coordinator\DefaultHttpCoordinator.cs:line 55
[2024-04-03T19:00:49.847Z]    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 69
[2024-04-03T19:00:49.849Z]    at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 77
Stack:    at System.Threading.Tasks.TaskCompletionSource`1.SetCanceled(CancellationToken cancellationToken)
[2024-04-03T19:00:49.850Z] Executed 'Functions.BlobStream' (Failed, Id=5f3199e5-f368-4ffd-817a-febef800d11f, Duration=839ms)
[2024-04-03T19:00:49.851Z]    at System.Threading.Tasks.TaskCompletionSource`1.SetCanceled()
[2024-04-03T19:00:49.852Z] System.Private.CoreLib: Exception while executing function: Functions.BlobStream. System.Private.CoreLib: Result: Failure
Exception: System.InvalidOperationException: An attempt was made to transition a task to a final state when it had already completed.
[2024-04-03T19:00:49.853Z]    at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.ContextReference.CompleteFunction() in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\Coordinator\ContextReference.cs:line 59
[2024-04-03T19:00:49.855Z]    at System.Threading.Tasks.TaskCompletionSource`1.SetCanceled(CancellationToken cancellationToken)
[2024-04-03T19:00:49.856Z]    at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.DefaultHttpCoordinator.CompleteFunctionInvocation(String invocationId) in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\Coordinator\DefaultHttpCoordinator.cs:line 55
[2024-04-03T19:00:49.857Z]    at System.Threading.Tasks.TaskCompletionSource`1.SetCanceled()
[2024-04-03T19:00:49.858Z]    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 69
[2024-04-03T19:00:49.860Z]    at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.ContextReference.CompleteFunction() in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\Coordinator\ContextReference.cs:line 59
[2024-04-03T19:00:49.861Z]    at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 77.
[2024-04-03T19:00:49.862Z]    at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.DefaultHttpCoordinator.CompleteFunctionInvocation(String invocationId) in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\Coordinator\DefaultHttpCoordinator.cs:line 55
[2024-04-03T19:00:49.865Z]    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 69
[2024-04-03T19:00:49.866Z]    at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 77
[2024-04-03T19:00:49.868Z]    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 System.Threading.Tasks.TaskCompletionSource`1.SetCanceled(CancellationToken cancellationToken)
[2024-04-03T19:00:49.869Z]    at System.Threading.Tasks.TaskCompletionSource`1.SetCanceled()
[2024-04-03T19:00:49.870Z]    at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.ContextReference.CompleteFunction() in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\Coordinator\ContextReference.cs:line 59
[2024-04-03T19:00:49.871Z]    at Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore.DefaultHttpCoordinator.CompleteFunctionInvocation(String invocationId) in D:\a\_work\1\s\extensions\Worker.Extensions.Http.AspNetCore\src\Coordinator\DefaultHttpCoordinator.cs:line 55
[2024-04-03T19:00:49.873Z]    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 69
[2024-04-03T19:00:49.874Z]    at Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(FunctionContext context) in D:\a\_work\1\s\src\DotNetWorker.Core\FunctionsApplication.cs:line 77
[2024-04-03T19:00:49.875Z]    at Microsoft.Azure.Functions.Worker.Handlers.InvocationHandler.InvokeAsync(InvocationRequest request) in D:\a\_work\1\s\src\DotNetWorker.Grpc\Handlers\InvocationHandler.cs:line 88.

Steps to reproduce

1. Create a new isolated-process project following the instructions here: https://learn.microsoft.com/en-us/azure/azure-functions/functions-run-local?tabs=windows%2Cisolated-process%2Cnode-v4%2Cpython-v2%2Chttp-trigger%2Ccontainer-apps&pivots=programming-language-csharp
2. Create an HttpTrigger Function using the aspnet.core integration following the instructions here: https://learn.microsoft.com/en-us/azure/azure-functions/dotnet-isolated-process-guide?tabs=windows
3. Return a FileStreamResult with a stream pointing to a large file
4. Cancel the request before it completes

I created a demo repo here: https://github.com/tevoinea/FunctionBlobStreamBugDemo The only files changed were BugDemo.csproj, BlobStream.cs, and Program.cs according to the instructions outlined above.

I chose to stream a file from disk (toolz.zip) which is 500MB.

[liliankasem]

A "Canceled" state does not exist in Azure Functions. This is something we are considering for v5.x as it requires breaking changes.

[tevoinea]

I agree a 'Canceled' state would be a feature request and we could split that off from this discussion.

There still remains the underlying issue that the runtime throws InvalidOperationException if a streaming request is canceled. This seems to be related to completing a task more than once. Just to be clear I'm not saying the runtime shouldn't throw on a canceled request, but that this particular exception is indicative of a bug and, if there is a bug and it's fixed, a more appropriate exception could be used like OperationCanceledException.

[liliankasem]

Will flag for investigation

[liliankasem]

@tevoinea I cloned and looked into the repro you shared:

1. I wasn't able to reproduce the error you are reporting, when I cancel the invocation I see a TaskCanceledException:

   [2024-04-09T21:50:45.362Z] Function 'BlobStream', Invocation id 'e54f114b-3688-457e-a495-9bd686798ef8': An exception was thrown by the invocation.
   [2024-04-09T21:50:45.362Z] Result: Function 'BlobStream', Invocation id 'e54f114b-3688-457e-a495-9bd686798ef8': An exception was thrown by the invocation.
   [2024-04-09T21:50:45.362Z] Exception: System.Threading.Tasks.TaskCanceledException: A task was canceled.

2. it looks like you're not subscribing to a CancellationToken - you will need to do that if you'd like to handle cancellation in your function, here are some useful resources for this:

• cancellation documentation
• cancellation sample

[tevoinea]

@liliankasem Thanks for looking into this.

1. I generated and pushed a packages.lock.json file to the repro so we can compare versions because I'm still seeing the behavior I reported.
2. Handling the CancellationToken can only help while my function is currently executing. My understanding is that my function only creates the stream object (a very quick operation), while the aspnet.core runtime is responsible for consuming the stream to return to the client. The cancellation that I'm trying to demonstrate here is happening in the runtime, so my function has no opportunity to respond to any signals from the CancellationToken.

[liliankasem]

Our packages.lock files are exactly the same packages.lock.json.

How are you invoking the function and how are you cancelling it?

[tevoinea]

I start the function app with func start, some output that might be relevant

Azure Functions Core Tools
Core Tools Version:       4.0.5571 Commit hash: N/A +9a5b604f0b846df7de3eb37b423a9eba8baa1152 (64-bit)
Function Runtime Version: 4.30.0.22097

[2024-04-10T18:12:02.323Z] Found C:\src\BugDemo\BugDemo.csproj. Using for user secrets file configuration.
[2024-04-10T18:12:04.288Z] Worker process started and initialized.

Functions:

        BlobStream: [GET] http://localhost:7071/api/BlobStream

Then in VS Code using Thunder Client https://marketplace.visualstudio.com/items?itemName=rangav.vscode-thunder-client

I have a GET request to my API (no other settings configured)

I wait ~1-2 seconds for the download to start, then I cancel the request by clicking the "Cancel Request" button while the download is executing

[pregress]

We are also suffering from this exception after upgrading our function to dotnet 8 isolated workers. Only happens on some invocations. But the strackrace shows: RoutingHttpContextExtensions.GetRouteData invokes a HttpContext when the request has finished. These seems like a bug in the SDK. Might be a different issue as this is in GetRouteData

It might be fixed with: https://github.com/Azure/azure-functions-dotnet-worker/pull/2322/files/6149e16e951188e97bf7fcff6918b45ae233bde4#diff-dc49550c24c24c88566ae78776b0400d415dfc8d1a5d623571903671a953e715

Any idea when 1.3.0 will be released?

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

[liliankasem]

@tevoinea finally had a chance to look at this again today and was able to repro this time. Debugging through, it looks like a bug in the asp net core extension on function completion (Extensions.Http.AspNetCore).

The task is already complete, but we are trying to set the result here anyway:

https://github.com/Azure/azure-functions-dotnet-worker/blob/ca7afd23f6a7f68059e00bc642c13ef9efd21dee/extensions/Worker.Extensions.Http.AspNetCore/src/Coordinator/ContextReference.cs#L59

Which leads to the InvalidOperationException exception. I've created a new issue to address a fix for this:

• https://github.com/Azure/azure-functions-dotnet-worker/issues/2413

@pregress this looks like a different problem, can you please open a new GH issue for it? Unsure of ETA for 1.3.0 but should be within the next week or two.

[pregress]

Created the bug: https://github.com/Azure/azure-functions-dotnet-worker/issues/2417

[tevoinea]

@liliankasem Awesome, thanks so much for looking into this!

[liliankasem]

No problem! @pregress - will take a look that bug soon, thanks for opening one.