OData / AspNetCoreOData

ASP.NET Core OData: A server library built upon ODataLib and ASP.NET Core
Other
454 stars 158 forks source link

oData 8.0.12 with .NET7 reports an error in complex query #799

Open HJoost opened 1 year ago

HJoost commented 1 year ago

When executing this query: http://c-logic-api-ef-odata.it.cube.eu/odata/DboTblPAKopf?$top=20&$apply=filter(startswith(concat(cast(paArtNr%2C%27Edm.String%27)%2CpaBez)%2C%275%27))%2Fgroupby((paArtNr%2CpaBez))

I get the following error:

System.InvalidOperationException Headers are read-only, response has already started.

0 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpHeaders 0 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseHeaders 0 Microsoft.AspNetCore.Http.DefaultHttpResponse 80 Cube.CLogic.API_EF_OData.Logging.UnhandledErrorMiddleware+ d4 82 Cube.CLogic.API_EF_OData.Logging.UnhandledErrorMiddleware+ d4 37 Cube.CLogic.API_EF_OData.Logging.UnhandledErrorMiddleware+ d3 0 Microsoft.AspNetCore.Authorization.AuthorizationMiddleware+ d9 0 Microsoft.AspNetCore.Authentication.AuthenticationMiddleware+ d6 0 Elastic.Apm.AspNetCore.ApmMiddleware+ d5

Assemblies affected "Microsoft.AspNetCore.Mvc.NewtonsoftJson" Version="7.0.1" "Microsoft.AspNetCore.OData" Version="8.0.12" "Microsoft.AspNetCore.OData.NewtonsoftJson" Version="8.0.12" "Microsoft.OData.Edm" Version="7.12.5" "Newtonsoft.Json" Version="13.0.2"

Before upgrading it worked without problems, old versions: "Microsoft.AspNetCore.Mvc.NewtonsoftJson" Version="6.0.7" "Microsoft.AspNetCore.OData" Version="8.0.4" "Microsoft.AspNetCore.OData.NewtonsoftJson" Version="8.0.4" "Microsoft.OData.Edm" Version="7.9.4" "Newtonsoft.Json" Version="13.0.2"

Describe the bug The complex query above leads to an InvalidOperationException "Headers are read-only, response has already started. "

Reproduce steps executing this query: http://c-logic-api-ef-odata.it.cube.eu/odata/DboTblPAKopf?$top=20&$apply=filter(startswith(concat(cast(paArtNr%2C%27Edm.String%27)%2CpaBez)%2C%275%27))%2Fgroupby((paArtNr%2CpaBez)

Request/Response http://c-logic-api-ef-odata.it.cube.eu/odata/DboTblPAKopf?$top=20&$apply=filter(startswith(concat(cast(paArtNr%2C%27Edm.String%27)%2CpaBez)%2C%275%27))%2Fgroupby((paArtNr%2CpaBez)))

Expected behavior Return valid odata json response

xuzhg commented 1 year ago

@HJoost Can you help test the following:

"Microsoft.AspNetCore.Mvc.NewtonsoftJson" Version="6.0.7" "Microsoft.AspNetCore.OData" Version="8.0.12" "Microsoft.AspNetCore.OData.NewtonsoftJson" Version="8.0.12" "Microsoft.OData.Edm" Version="7.12.5" "Newtonsoft.Json" Version="13.0.2"

By the way, do you mind to share us your source codes of 'UnhandledErrorMiddleware'?

HJoost commented 1 year ago

@xuzhg I've just tested it with the suggested Nuget versions, but the problem is still present:

image

` public class UnhandledErrorMiddleware { private readonly RequestDelegate _next; private readonly ILogger _logger;

    public UnhandledErrorMiddleware(
        RequestDelegate next,
        ILogger<UnhandledErrorMiddleware> logger)
    {
        _next = next;
        _logger = logger;
    }

    public async Task Invoke(HttpContext context)
    {
        try
        {
            try { context.Request.EnableBuffering(); } catch { }
            await _next(context);
        }
        catch (Exception ex)
        {
            await HandleExceptionAsync(context, ex);
        }
    }

    private async Task HandleExceptionAsync(HttpContext context, Exception ex)
    {
        // 500 if unexpected
        var code = HttpStatusCode.InternalServerError;

        context.Request.Body.Position = 0;
        await using var requestStream = new MemoryStream();
        await context.Request.Body.CopyToAsync(requestStream);

        // Get Request Infos
        var request = new LogHttpRequest
        {
            Url = context.Request.Path,
            Method = context.Request.Method,
            Headers = string.Join(";", context.Request.Headers.Where(x => x.Key != "Authorization").Select(x => x.Key + "=" + x.Value).ToArray()),
            Body = ReadStreamInChunks(requestStream)
        };

        // Create Log Guid for Elastic Reference
        var payload = new UnhandledError()
        {
            LogId = Guid.NewGuid(),
            Message = "Unexpected Error"
        };

        // Log to Elastic
        _logger.LogError("[{GUID}] Unhandled Error {User}, {CallerMemberName}, {RequestHeaders}, {RequestMethod}, {RequestUrl}, {AdditionalInfo}",
            payload.LogId,
            Helpers.UserHelper.GetWindowsbenutzer(context.User),
            "ErrorMiddleware",
            request.Headers,
            request.Method,
            request.Url,
            new { StackTrace = GetFullMessage(ex, true) });

        // Return 500 response with payload
        var result = JsonConvert.SerializeObject(payload);
        context.Response.ContentType = "application/json";
        context.Response.StatusCode = (int)code;
        await context.Response.WriteAsync(result);
    }

    private string GetFullMessage(Exception ex, bool verbose = false, bool forceNotVerbose = false, string separator = "\n<br>")
    {
        string ausgabe = ex.GetType().FullName + ": " + ex.Message + separator;
        if (ex.InnerException != null) ausgabe += GetFullMessage(ex.InnerException);
        if (verbose && !forceNotVerbose) ausgabe += separator + ex.StackTrace;
        return ausgabe;
    }

    private static string ReadStreamInChunks(Stream stream)
    {
        const int readChunkBufferLength = 4096;

        stream.Seek(0, SeekOrigin.Begin);

        using var textWriter = new StringWriter();
        using var reader = new StreamReader(stream);

        var readChunk = new char[readChunkBufferLength];
        int readChunkLength;

        do
        {
            readChunkLength = reader.ReadBlock(readChunk, 0,readChunkBufferLength);
            textWriter.Write(readChunk, 0, readChunkLength);
        } while (readChunkLength > 0);

        return textWriter.ToString();
    }`
julealgon commented 1 year ago

@HJoost it would be nice if you could create a minimal example of your problem, one that didn't have all this extra custom code and configuration around it.

Keep in mind that it is much easier to isolate the issue in a small, focused sample, than it is in a full working solution with a lot of moving parts.

The same goes for package versions. If you could spot precisely which of the version updates caused this (instead of listing several differences) that would be awesome.

HJoost commented 1 year ago

@julealgon I just tried to make small sample and guess what. I can't reproduce the issue... The only thing different is, that I used some static in code data instead of ef core with sql server. I will extend this tomorrow, hoping to the get same error.

HJoost commented 1 year ago

After some further testing I noticed that the "System.InvalidOperationException Headers are read-only, response has already started." exception is only a symptom not the cause.

When I set a breakpoint in the "UnhandledErrorMiddleware" there I can find this exception: image

The exception is related to the groupby: https://localhost:44363/odata/DboTblPAKopf?$top=20&$apply=filter(startswith(concat(cast(paArtNr%2C%27Edm.String%27)%2CpaBez)%2C%275%27))%2Fgroupby((paArtNr)) --> 500

Without the group by, it works: https://localhost:44363/odata/DboTblPAKopf?$top=20&$apply=filter(startswith(concat(cast(paArtNr%2C%27Edm.String%27)%2CpaBez)%2C%275%27)) --> 200

julealgon commented 1 year ago

@HJoost would you mind sharing the full stacktrace for that exception?

HJoost commented 1 year ago

@julealgon Yes for sure: bei System.Linq.Expressions.Expression.ValidateCallInstanceType(Type instanceType, MethodInfo method) bei System.Linq.Expressions.Expression.ValidateAccessor(Expression instance, MethodInfo method, ParameterInfo[] indexes, ReadOnlyCollection1& arguments, String paramName) bei System.Linq.Expressions.Expression.ValidateIndexedProperty(Expression instance, PropertyInfo indexer, String paramName, ReadOnlyCollection1& argList) bei System.Linq.Expressions.Expression.MakeIndex(Expression instance, PropertyInfo indexer, IEnumerable1 arguments) bei Microsoft.EntityFrameworkCore.Query.RelationalSqlTranslatingExpressionVisitor.TranslateInternal(Expression expression) bei Microsoft.EntityFrameworkCore.Query.RelationalSqlTranslatingExpressionVisitor.Translate(Expression expression) bei Microsoft.EntityFrameworkCore.Query.RelationalQueryableMethodTranslatingExpressionVisitor.TranslateExpression(Expression expression) bei Microsoft.EntityFrameworkCore.Query.RelationalQueryableMethodTranslatingExpressionVisitor.TranslateLambdaExpression(ShapedQueryExpression shapedQueryExpression, LambdaExpression lambdaExpression) bei Microsoft.EntityFrameworkCore.Query.RelationalQueryableMethodTranslatingExpressionVisitor.TranslateOrderBy(ShapedQueryExpression source, LambdaExpression keySelector, Boolean ascending) bei Microsoft.EntityFrameworkCore.Query.QueryableMethodTranslatingExpressionVisitor.VisitMethodCall(MethodCallExpression methodCallExpression) bei Thinktecture.EntityFrameworkCore.Query.ThinktectureSqlServerQueryableMethodTranslatingExpressionVisitor.VisitMethodCall(MethodCallExpression methodCallExpression) bei Microsoft.EntityFrameworkCore.Query.QueryableMethodTranslatingExpressionVisitor.VisitMethodCall(MethodCallExpression methodCallExpression) bei Thinktecture.EntityFrameworkCore.Query.ThinktectureSqlServerQueryableMethodTranslatingExpressionVisitor.VisitMethodCall(MethodCallExpression methodCallExpression) bei Microsoft.EntityFrameworkCore.Query.QueryableMethodTranslatingExpressionVisitor.VisitMethodCall(MethodCallExpression methodCallExpression) bei Thinktecture.EntityFrameworkCore.Query.ThinktectureSqlServerQueryableMethodTranslatingExpressionVisitor.VisitMethodCall(MethodCallExpression methodCallExpression) bei Microsoft.EntityFrameworkCore.Query.QueryCompilationContext.CreateQueryExecutor[TResult](Expression query) bei Microsoft.EntityFrameworkCore.Storage.Database.CompileQuery[TResult](Expression query, Boolean async) bei Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.CompileQueryCore[TResult](IDatabase database, Expression query, IModel model, Boolean async) bei Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.<>cDisplayClass9_01.<Execute>b__0() bei Microsoft.EntityFrameworkCore.Query.Internal.CompiledQueryCache.GetOrAddQuery[TResult](Object cacheKey, Func1 compiler) bei Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.Execute[TResult](Expression query) bei Microsoft.EntityFrameworkCore.Query.Internal.EntityQueryProvider.Execute[TResult](Expression expression) bei Microsoft.EntityFrameworkCore.Query.Internal.EntityQueryable`1.System.Collections.IEnumerable.GetEnumerator() bei Microsoft.AspNetCore.OData.Formatter.Serialization.ODataResourceSetSerializer.d4.MoveNext() bei Microsoft.AspNetCore.OData.Formatter.Serialization.ODataResourceSetSerializer.d3.MoveNext() bei Microsoft.AspNetCore.OData.Formatter.Serialization.ODataResourceSetSerializer.d2.MoveNext() bei Microsoft.AspNetCore.OData.Formatter.ODataOutputFormatterHelper.d1.MoveNext() bei Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<g__Logged|22_0>d.MoveNext() bei Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<gAwaited|30_0>d2.MoveNext() bei Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResultExecutedContextSealed context) bei Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.ResultNext[TFilter,TFilterAsync](State& next, Scope& scope, Object& state, Boolean& isCompleted) bei Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeResultFilters() --- Ende der Stapelüberwachung vom vorhergehenden Ort --- bei Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<<InvokeFilterPipelineAsync>g__Awaited|20_0>d.MoveNext() bei Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<<InvokeAsync>g__Logged|17_1>d.MoveNext() bei Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<<InvokeAsync>g__Logged|17_1>d.MoveNext() bei Microsoft.AspNetCore.Routing.EndpointMiddleware.<<Invoke>g__AwaitRequestTask|6_0>d.MoveNext() bei Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.<Invoke>d__5.MoveNext() bei Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.<Invoke>d__4.MoveNext() bei Cube.CLogic.API_EF_OData.Logging.UnhandledErrorMiddleware.<Invoke>d__3.MoveNext() in C:\VS_Projekte\C-Logic\Cube.CLogic.API_EF_OData\Logging\UnhandledErrorMiddleware.cs: Zeile31

What I also noticed, the problem occures only when using $top and $groupby with $apply.

Works: https://localhost:44363/odata/DboTblPAKopf?$top=20&$apply=filter(startswith(paBez%2C%275%27)) Works: https://localhost:44363/odata/DboTblPAKopf?$apply=filter(startswith(paBez%2C%275%27))%2Fgroupby((paArtNr%2CpaBez)) Works not: https://localhost:44363/odata/DboTblPAKopf?$top=20&$apply=filter(startswith(paBez%2C%275%27))%2Fgroupby((paArtNr%2CpaBez))

A colleague told me he thinks it is related to this issue: https://github.com/OData/AspNetCoreOData/issues/420

xuzhg commented 1 year ago

@HJoost do you have a chance to take a look this comment: https://github.com/OData/AspNetCoreOData/issues/420#issuecomment-1343281828

HJoost commented 1 year ago

@xuzhg I've just taken a look on the comment mentioned above. In my opinion it is not related to this issue here, because the $top does not depend on a property of the result.

xuzhg commented 1 year ago

@HJoost If you can't share us a repo, would you please share me

1) The metadata (CSDL, using $metadata to get) 2) Your startup setting codes 3) Your controllers.

Thanks.

HJoost commented 1 year ago

oDataIssue799.zip

Here is a demonstration sample. It has a git repo with 2 commits of interest:

Request for testing: https://localhost:59578/odata/WeatherForecast?$top=20&$apply=filter(startswith(concat(cast(ID%2C%27Edm.String%27)%2CCountry)%2C%273%27))%2Fgroupby((ID%2CCountry))

Make sure to start via docker compose, because otherwise you don't have sql server running.

HJoost commented 1 year ago

@xuzhg Have you already verified the bug in my sample?

HJoost commented 1 year ago

I'm a bit frustrated. I spent quite some time to build this sample and now nobody does have a look on it 👎

beastplus commented 1 year ago

i have same issue . it seems that $top can not work with $apply groupby .net 6 ef core 6.0.8 AspNetCoreOData 8.0.12

beastplus commented 1 year ago

it's weird that AspNetCoreOData 8.0.4 works fine. https://github.com/OData/AspNetCoreOData/issues/420#issuecomment-1088385497

HJoost commented 1 year ago

@xuzhg any news on the resolving of this bug?