Endpoint 'gRPC - Unimplemented service'

[kwaazaar]

I have a service that is not behaving as it should. While troubleshooting it, I noticed this debug output:

Endpoint 'gRPC - Unimplemented service' with route pattern '{unimplementedService}/{unimplementedMethod}' is valid for the request path ... (the path of the non-working service).

What does this mean? I register my Grpc-service using endpoints.MapGrpcService<InforARIService>();

The actual issue I was troubleshooting is that the Grpc-service is invoked, does it's work correctly and returns a class with two string properties. However, on the wire the response is empty (so the client gets a serialization error):

HTTP/1.1 200 OK
Content-Length: 0
Content-Type: application/grpc-web
Date: Fri, 08 Apr 2022 09:23:39 GMT
Server: Kestrel
Request-Context: appId=cid-v1:87cb2164-3464-497d-a7b4-80e9471bf6c3
Grpc-Status: 0
X-Content-Type-Options: nosniff
Strict-Transport-Security: max-age=31536000

[kwaazaar]

I notice the same in the logs of this issue: #1120 (comment)

[JamesNK]

That log message doesn't mean anything useful. All gRPC requests will match against that wildcard route, but then narrow down to the actual gRPC services.

Please provide complete logs for your app.

[kwaazaar]

The request sent to the service:

POST https://kubernetes.docker.internal:7120/Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest HTTP/1.1
User-Agent: grpc-dotnet/2.43.0 (.NET Framework; CLR 4.0.30319.42000; netstandard2.0; windows; x64)
TE: trailers
grpc-accept-encoding: identity,gzip
Content-Type: application/grpc-web
Host: kubernetes.docker.internal:7120
Request-Id: |2be2ccd74073458b3a96325a1ff43d85.2493711b3f4ad350.
traceparent: 00-2be2ccd74073458b3a96325a1ff43d85-2493711b3f4ad350-00
Content-Length: 842
Expect: 100-continue

   �E
 �<?xml version="1.0" encoding="utf-16"?>
<DescriptiveContentRequest xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <Security>
    <UsernameToken Id="1" xmlns="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-secext-1.0.xsd">
      <Username>IRU_Robert</Username>
      <Password>hoi</Password>
    </UsernameToken>
  </Security>
  <TimeStamp>2022-01-01T00:00:00</TimeStamp>
  <CorrelationID>2</CorrelationID>
  <RelatesToCorrelationID>1</RelatesToCorrelationID>
  <ReplyTo>
    <Address xmlns="http://www.w3.org/2005/08/addressing">https://to.me/webhook</Address>
  </ReplyTo>
  <OTA_HotelDescriptiveContentNotifRQ />
</DescriptiveContentRequest>�cMiddleware.Cloud.Integrations.Synxis.Contracts.Reservations.Htng.Ota2010A.DescriptiveContentRequest

Logs of the service:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 POST https://kubernetes.docker.internal:7120/Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest application/grpc-web 842
dbug: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[1]
      POST requests are not supported
dbug: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[1]
      POST requests are not supported
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
      3 candidate(s) found for the request path '/Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest'
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1005]
      Endpoint 'gRPC - /Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest' with route pattern '/Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest' is valid for the request path '/Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest'
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1005]
      Endpoint 'gRPC - Unimplemented method for Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc' with route pattern 'Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/{unimplementedMethod}' is valid for the request path '/Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest'
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1005]
      Endpoint 'gRPC - Unimplemented service' with route pattern '{unimplementedService}/{unimplementedMethod}' is valid for the request path '/Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest'
dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
      Request matched endpoint 'gRPC - /Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest'
dbug: Grpc.AspNetCore.Web.Internal.GrpcWebMiddleware[1]
      Detected gRPC-Web request from content-type 'application/grpc-web'.
dbug: Microsoft.AspNetCore.ResponseCaching.ResponseCachingMiddleware[1]
      The request cannot be served from cache because it uses the HTTP method: POST.
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'gRPC - /Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest'
dbug: Grpc.AspNetCore.Server.ServerCallHandler[10]
      Reading message.
dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMGRGQGLFULU", Request id "0HMGRGQGLFULU:00000002": started reading request body.
dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMGRGQGLFULU", Request id "0HMGRGQGLFULU:00000002": done reading request body.
trce: Grpc.AspNetCore.Server.ServerCallHandler[12]
      Deserializing 837 byte message to 'Middleware.Cloud.Shared.Definition.Models.ServiceModels.GrpcXmlMessage`1[Middleware.Cloud.Integrations.Synxis.Contracts.Reservations.Htng.Ota2010A.DescriptiveContentRequest]'.
trce: Grpc.AspNetCore.Server.ServerCallHandler[13]
      Received message.
dbug: Grpc.AspNetCore.Server.ServerCallHandler[15]
      Sending message.
trce: Grpc.AspNetCore.Server.ServerCallHandler[18]
      Serialized 'Middleware.Cloud.Shared.Definition.Models.ServiceModels.GrpcXmlMessage`1[Middleware.Cloud.Integrations.Synxis.Contracts.Reservations.Htng.Ota2010A.DescriptiveContentResponse]' to 584 byte message.
trce: Grpc.AspNetCore.Server.ServerCallHandler[16]
      Message sent.
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'gRPC - /Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest'
dbug: Grpc.AspNetCore.Web.Internal.GrpcWebMiddleware[3]
      Sending gRPC-Web response with content-type 'application/grpc-web'.
dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[9]
      Connection id "0HMGRGQGLFULU" completed keep alive response.
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 POST https://kubernetes.docker.internal:7120/Middleware.Cloud.Integrations.Synxis.Contracts.Profiles.Htng.Ota200305.Grpc.Ota2010AGrpc/DescriptiveContent_SubmitRequest application/grpc-web 842 - 200 0 application/grpc-web 11086.5925ms

The response of the service:

HTTP/1.1 200 OK
Content-Length: 0
Content-Type: application/grpc-web
Date: Fri, 08 Apr 2022 14:12:59 GMT
Server: Kestrel
Request-Context: appId=cid-v1:87cb2164-3464-497d-a7b4-80e9471bf6c3
Grpc-Status: 0
X-Content-Type-Options: nosniff
Strict-Transport-Security: max-age=31536000

What does that "842" in the last logline mean? Is that the number of bytes returned? If so, that would be weird as the total response, including headers is only ~288 bytes.

Edited: with loglevel for Grpc set to Trace (guess your advice does not apply here :-D), I get detailed information about the serialization of the response: "Serialized 'Middleware.Cloud.Shared.Definition.Models.ServiceModels.GrpcXmlMessage`1[Middleware.Cloud.Integrations.Synxis.Contracts.Reservations.Htng.Ota2010A.DescriptiveContentResponse]' to 584 byte message.". This shows that a response is serialized, however it does not get written to the output stream?

[kwaazaar]

So I found the issue: I use a trick to grab the request and response bodies so I can add them to Application Insights request telemetry. When I disable that logic, the service works fine. However, I don't really understand why this doesn't work, as the trick works fine for regular REST controllers.

I also looked at HttpLoggingMiddleware (which writes to ILogger, which is not what I need), but that implementation is pretty complicated.

If you have the time, I created a little repro here: https://github.com/kwaazaar/grpc-empty-response-repro

[halter73]

Thanks for the simple repro app. You can fix your issue by passing through response flushes immediately. This way the gRPC trailer-writing logic knows when the response has already started and does not incorrectly consider the response "Trailers-Only" adds the grpc-status: 0 trailer as a normal header sent before the response body instead of after the response body:

grpc-dotnet/src/Grpc.AspNetCore.Server/Internal/GrpcProtocolHelpers.cs

Lines 156 to 175 in 197b43b

	public static IHeaderDictionary GetTrailersDestination(HttpResponse response)
	{
	if (response.HasStarted)
	{
	// The response has content so write trailers to a trailing HEADERS frame
	var feature = response.HttpContext.Features.Get<IHttpResponseTrailersFeature>();
	if (feature?.Trailers == null || feature.Trailers.IsReadOnly)
	{
	throw new InvalidOperationException("Trailers are not supported for this response. The server may not support gRPC.");
	}
	return feature.Trailers;
	}
	else
	{
	// The response is "Trailers-Only". There are no gRPC messages in the response so the status
	// and other trailers can be placed in the header HEADERS frame
	return response.Headers;
	}
	}

The workaround:

class ResponseBufferingStream : MemoryStream
{
    private readonly Stream _originalResponseStream;

    public ResponseBufferingStream(Stream originalResponseStream)
    {
        _originalResponseStream = originalResponseStream;
    }

    public override Task FlushAsync(CancellationToken cancellationToken)
    {
        return _originalResponseStream.FlushAsync(cancellationToken);
    }
}

And then the following change to RequestGrabber.cs

- using var replacementResponseBody = new MemoryStream();
+ using var replacementResponseBody = new ResponseBufferingStream(originalResponseBody);

Even though ResponseBufferingStream doesn't actually flush any bytes to the response body that may have already been written to the MemoryStream, flushing the HttpResponse.Body always flushes the response headers which gives HttpResponse.HasStarted its proper value of true which is what's important here.

I did not override all the methods an app could use to try to flush the response, but I know the gRPC logic calls HttpResponse.StartAsync() which calls through to this when you replace the HttpResponse.Body stream.

I think this should probably be fixed in gRPC. If the gRPC logic independently tracked if it has written to the body instead of using response.HasStarted, the simpler MemoryStream response body replacement could still work like it does for most other kinds of requests.

---

At first, I thought this was going to a case of not flushing HttpResponse.BodyWriter before copying the response body. I was going to suggest changing the following change to RequestGrabber:

// Continue processing (additional middleware, controller, etc.)
await next(context);
+ await response.CompleteAsync();

When you replace the response body with a custom Stream, this is equivalent to the following:

// Continue processing (additional middleware, controller, etc.)
await next(context);
+ await response.BodyWriter.FlushAsync();

It still might be a good idea. Without doing this, the await replacementResponseBody.CopyToAsync(originalResponseBody) will not copy bytes that have been appended to the BodyWriter via GetMemory()/Advance() without being flushed. AFAIK, gRPC doesn't flush the BodyWriter for performance reasons when doing normal HTTP/2-based gRPC. It looks like the response does get explicitly flushed when grpc-status: 0 trailer is flushed for grpc-web responses.

I think gRPC should be calling response.CompleteAsync() or response.BodyWriter.CompleteAsync() before exiting its middleware even in the normal non-grpc-web case. This would get the same performance benefit has not flushing for non-wrapped response Streams, but it will flush the stream (without actually completing the real response) when the response Stream is wrapped. @JamesNK

Also, setting body.Position = 0; after ReadToEndAsync() is unnecessary and probably wrong, but it's not very likely to matter so early in the middleware pipeline.

Possibly related: dotnet/aspnetcore#39317

[kwaazaar]

Thanks Stephen! The fix/workaround works great. Very happy with it :-)

[halter73]

I think this should probably be fixed in gRPC. If the gRPC logic independently tracked if it has written to the body instead of using response.HasStarted, the simpler MemoryStream response body replacement could still work like it does for most other kinds of requests.

The above is why this issue is currenlty left open in the backlog in case that's not clear.