dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.46k stars 10.03k forks source link

HttpLoggingMiddleware breaks gRPC service response #39317

Open Zetanova opened 2 years ago

Zetanova commented 2 years ago

Is there an existing issue for this?

Describe the bug

If the HttpLoggingMiddleware gets used in aspnet core 6 hosting Rest API and gRPC service then the gRPC response message gets transparently removed.

The verbose logging of Grpc.AspNetCore.Server.ServerCallHandler logs following:

...
Sending message.
Serialized 'MyService.Protos.MyResponse' to 28 byte message.
Message sent.
Request deadline stopped.
Executed endpoint 'gRPC - /MyService/MyMethod'

The verbose logging of Grpc.Net.Client.Internal.GrpcCall logs following:

...
Reading message.
No message returned.
Message not returned from unary or client streaming call.
Call failed with gRPC error status. Status code: '"Internal"', Message: 'Failed to deserialize response message.'.
Finished gRPC call.
...
An unhandled exception has occurred while executing the request.
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="Failed to deserialize response message.")

Only the outgoing response message gets somehow removed by HttpLoggingMiddleware Disabling it resolves the issue instantly

Expected Behavior

HttpLoggingMiddleware should only log normal http requests and/or give more options to enable or filter gRPC logging

Steps To Reproduce

service configuration:

public void ConfigureServices(IServiceCollection services)
        {
          //... 
          services.AddGrpc(opt =>
            {
            });

           services.AddHttpLogging(logging =>
            {
                logging.LoggingFields = HttpLoggingFields.All;
                logging.RequestBodyLogLimit = 4096;
                logging.ResponseBodyLogLimit = 4096;
            });
}

Configuration

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            if (env.IsDevelopment())
            {
                IdentityModelEventSource.ShowPII = true;

                app.UseHttpLogging();

                app.UseDeveloperExceptionPage();
                app.UseSwagger();
                app.UseSwaggerUI(c => c.SwaggerEndpoint("/swagger/v1/swagger.json", "MyService API v1"));
            }
           //...

          app.UseEndpoints(endpoints =>
            {
                //...

                endpoints.MapGrpcService<MyService>()
                    .RequireHost("*:82", "*:443");

                endpoints.MapControllers();
            });
}

Exceptions (if any)

On the gRPC Client side, inside an rest api

An unhandled exception has occurred while executing the request.
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="Failed to deserialize response message.")
   at MyService.WebApi.Controllers.MyController.PostMethod(MyRequest request, MyClient client, CancellationToken cancellationToken) in C\MyService\src\MyService.WebApi\Controllers\MyController.cs:line 70
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
   at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
   at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)

.NET Version

6.0.100

Anything else?

No response

adityamandaleeka commented 2 years ago

@wtgodbe Can you please take a look?

ghost commented 2 years ago

Thanks for contacting us.

We're moving this issue to the .NET 7 Planning milestone for future evaluation / consideration. We would like to keep this around to collect more feedback, which can help us with prioritizing this work. We will re-evaluate this issue, during our next planning meeting(s). If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

Tratcher commented 2 years ago

Prior discussion: https://github.com/dotnet/aspnetcore/issues/11305

ignj commented 2 years ago

I'm also having the same issue. As a workaround, I'm avoiding the HttpLoggingMiddleware for gRPC requests

builder.UseWhen(
            ctx => ctx.Request.ContentType != "application/grpc",
            builder =>
            {
                builder.UseHttpLogging();
            }
        );
ghost commented 2 years ago

Thanks for contacting us.

We're moving this issue to the .NET 8 Planning milestone for future evaluation / consideration. We would like to keep this around to collect more feedback, which can help us with prioritizing this work. We will re-evaluate this issue, during our next planning meeting(s). If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

wtgodbe commented 1 year ago

There's a PR for this which could be iterated on/abandoned: https://github.com/dotnet/aspnetcore/pull/39989

debuggedme commented 3 months ago

At least, some potential impacts on gRPC could be indicated on the http-logging.

alrz commented 1 week ago

This could save a few days for folks in the unlikely scenario of having both logging and gRPC at the same time..

bmwadforth commented 1 week ago

This could save a few days for folks in the unlikely scenario of having both logging and gRPC at the same time..

Because it's open source and you have stumbled across an issue I guess you could try and fix it ;)

alrz commented 1 week ago

Because it's open source and you have stumbled across an issue I guess you could try and fix it ;)

Yes I can, and yes I have, but I think this needs a little bit of design work before that could happen. For example, extended http client logger solves this by forcing you to spell out content types that you wish to log. Matter of fact I've filed https://github.com/dotnet/extensions/issues/5206 because there's features missing on both sides and no obvious reason why they have to be different.

However, my disappointment was because this is a flat out bug as both middlewares are provided out of the box. I guess https://github.com/dotnet/aspnetcore/issues/39317#issuecomment-1180514981 is the the fastest way to workaround this today vs. waiting for this to get triaged some day (and from experience, if it doesn't get triaged it won't get accepted even if there's an implementation for it, just like enumerable support for list patterns that I have a PR open for a year now)