Webapi: Synchronous operations after batch request

[kaihueb]

some OData batch requests result into internal error since synchronous calls are are not allowd in .net core 3.1

Assemblies affected

Microsoft.AspNetCore.OData (7.3.0)
.net core 3.1

Reproduce steps

call OData batch request with JSON body/response e.g.

{
    "requests": [
        {
            "Id": "1",
            "method": "DELETE",
            "headers": {
                "odata-version": "4.01",
                "content-type": "application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false"
            },
            "url": "Entity(6)",
            "body": ""
        }
    ]
}

where the entity does'nt exists and the controller is returning NotFound()

Expected result

with the the workarround (disable check) I get the expected result, without this setting I get an internal error

webBuilder.ConfigureKestrel(options =>
{
options.AllowSynchronousIO = true;
});

Actual result

Internal error

Additional detail

System.InvalidOperationException: Synchronous operations are disallowed. Call WriteAsync or set AllowSynchronousIO to true instead.
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseStream.Write(Byte[] buffer, Int32 offset, Int32 count)
at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder)
at Microsoft.OData.JsonLight.ODataJsonLightBatchWriter.FlushSynchronously()
at Microsoft.OData.ODataBatchWriter.Flush()
at Microsoft.OData.ODataBatchWriter.WriteEndBatch()
at Microsoft.AspNet.OData.Batch.ODataBatchContent.WriteToResponseMessageAsync(IODataResponseMessage responseMessage)
at Microsoft.AspNet.OData.Batch.DefaultODataBatchHandler.ProcessBatchAsync(HttpContext context, RequestDelegate nextHandler)
at Microsoft.AspNet.OData.Batch.ODataBatchMiddleware.Invoke(HttpContext context)
at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsTContext

[xuzhg]

@kaihueb Thanks for reaching us.

We do have the similar configuration in our codes at:
https://github.com/OData/WebApi/blob/4eb6b7fee55d8a8f4382eef643ba3f3a5226d270/src/Microsoft.AspNetCore.OData/Formatter/ODataInputFormatter.cs#L123-L127

It seems we forgot to add similar codes for $batch. We will investigate it and close the gap.

[mikepizzo]

We try to write the batch stuff asynchronously so that we don't have to set AllowSynchronousIO for the overall batch. However, there appear to be some bugs in our batch async logic, where we call synchronous methods. I have a fix.

[hfaran]

@mikepizzo @xuzhg We're still seeing some errors related to this even with the new 7.4.0 release. Here is the particular stack trace; looks like there is still sync IO being used in places:

    System.InvalidOperationException: An error occurred while processing this request. ---> System.AggregateException: One or more errors occurred. (Synchronous operations are disallowed. Call WriteAsync or set AllowSynchronousIO to true.) ---> System.InvalidOperationException: Synchronous operations are disallowed. Call WriteAsync or set AllowSynchronousIO to true.
  Stack Trace: 
    ResponseBodyWriterStream.Write(Byte[] buffer, Int32 offset, Int32 count)
    MessageStreamWrappingStream.Write(Byte[] buffer, Int32 offset, Int32 count)
    AsyncBufferedStream.FlushSync()
    ODataRawOutputContext.FlushBuffers()
    ODataMultipartMixedBatchWriter.StreamRequested()
    ODataBatchOperationMessage.GetStream()
    ODataBatchResponseItem.WriteMessageAsync(ODataBatchWriter writer, HttpContext context, Boolean asyncWriter)
    ODataBatchContent.WriteToResponseMessageAsync(IODataResponseMessage responseMessage)
    DefaultODataBatchHandler.ProcessBatchAsync(HttpContext context, RequestDelegate nextHandler)
    ODataBatchMiddleware.Invoke(HttpContext context)
    <<UseBranchWithServices>b__1>d.MoveNext() line 77
    --- End of stack trace from previous location where exception was thrown ---
    <<UseBranchWithServices>b__3>d.MoveNext() line 92
    --- End of stack trace from previous location where exception was thrown ---
    MapMiddleware.Invoke(HttpContext context)

[mikepizzo]

Thanks for the report; stack trace helped find the call to synchronous GetStream, which resulted in a sychronous write down further down the stack. Verified that calling GetStreamAsync() calls the right async write methods further down the stack. Would love to have you check nightlies once this is checked in to make sure we didn't miss any other cases.

[hfaran]

Thanks @mikepizzo. I'm ready to pick up the nightly as soon as it's available.

[mikepizzo]

Fix is in PR #2149.

[robertmclaws]

Just an FYI, this bug broke RESTier in the Microsoft.AspNet.OData 7.4.0 release as well. ETA on the release?

Thanks!

[hfaran]

Just an FYI, this bug broke RESTier in the Microsoft.AspNet.OData 7.4.0 release as well. ETA on the release?

Thanks!

@robertmclaws this fix should be included in the 7.4.1 release according to the release notes: https://docs.microsoft.com/en-us/odata/changelog/webapi-7x#webapi-741

[robertmclaws]

I don't believe the issue has been fully fixed. I'm still getting issues in RESTier. For example, this test is passing: https://github.com/OData/RESTier/blob/master/src/Microsoft.Restier.Tests.AspNet/FeatureTests/BatchTests.cs

However, the code path that is presently working involves working against Entity Sets.

In another product I'm building, I have code that is working against Functions and Actions, like this:

    var oDataClient = new ODataClient(new ODataClientSettings {
        BaseUri = new Uri(Configuration["MyApp:ApiUrl"]),
        BeforeRequest = (request) =>
        {
            request.Headers.Authorization = new AuthenticationHeaderValue("Bearer", apiToken.AccessToken);
        }
    });
    var batch = new ODataBatch(oDataClient);
    var results = new Dictionary<string, SomeComplexType>();
    foreach (var id in ids)
    {
        SomeComplexType result = null;
        batch += async c =>
        {
            result = await c
                .Unbound<SomeComplexType>()
                .Function("GetSomeComplexType")
                .Set(new { primaryId = primaryObject.Id, secondaryId = secondaryObject.Id })
                .ExecuteAsSingleAsync();
            //RWM: The lambda will execute twice, once before the batch, and once after. The first time the 
            //     result will be null... so don't add those.
            if (result != null)
            {
                results.Add(secondaryObject.Id.ToString(), result);
            }
        };
    }
    await batch.ExecuteAsync();

On Microsoft.AspNet.OData 7.3.0, this executes successfully. On 7.4.1, it fails with this exception:

{
"Message":"An error has occurred.",
"ExceptionMessage":"An asynchronous operation was called on a synchronous batch reader. Calls on a batch reader instance must be either all synchronous or all asynchronous.",
"ExceptionType":"Microsoft.OData.ODataException",
"StackTrace":"   at Microsoft.OData.ODataBatchReader.VerifyCallAllowed(Boolean synchronousCall)
   at Microsoft.OData.ODataBatchReader.VerifyCanCreateOperationRequestMessage(Boolean synchronousCall)
   at Microsoft.OData.ODataBatchReader.CreateOperationRequestMessageAsync()
   at Microsoft.AspNet.OData.Batch.ODataBatchReaderExtensions.<ReadOperationInternalAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at Microsoft.Restier.AspNet.Batch.RestierBatchHandler.<ParseBatchRequestsAsync>d__1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNet.OData.Batch.DefaultODataBatchHandler.<ProcessBatchAsync>d__1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Web.Http.Batch.HttpBatchHandler.<SendAsync>d__12.MoveNext()"}

The RESTier batch code in question is here. From the call stack you can see that Async calls are happening.

I'm working on adding a unit test to ensure Action and Function batch calls work in RESTier. In the meantime, @mikepizzo Would it be possible for you to please look into this and see if you can find the issue on your end?

Thanks everyone!

[mikepizzo]

@robertmclaws -- I'll try and take a look. Can you please confirm the versions of both Microsoft.Aspnet.OData and Microsoft.OData.Core libraries? Fixes were required in both of these libraries; please let me know if this still occurs when using the latest releases of both.

[mikepizzo]

I believe the issue with RESTier turned out to be an earlier version of ODL, since the OData WebAPI stack was not requiring the latest OData Library. In the latest WebAPI OData library we increased the minimum version of ODL, so this should be resolved.

[robertmclaws]

Yes, the dependencies were overlapping and older versions of ODL were coming into the stack on NuGet restore. Moving all of the Restier dependencies to the very latest releases solved the problem.