cyanfish / grpc-dotnet-namedpipes

Named pipe transport for gRPC in C#/.NET
Apache License 2.0
190 stars 48 forks source link

error serializing large responses on client with remote pipe #50

Open zachrybaker opened 1 year ago

zachrybaker commented 1 year ago

see issue 48 for context.

Granted this case is probably not the norm:

Remote piping (for now, going to be local soon for security reasons). The server code is 100% synchronous re-platformed mainframe code, that I bridge the async gap via Task.FromResult(data);

When I replay two week's worth of API calls, 0.19% of the calls - 1283 of them - failed on the client side (server sent "normal data"). These calls can be replayed on a local pipe successfully between a .Net6.0 server and a .Net6.0 client. Replaying them in isolation using the same client, to a remote .Net6.0 server, however, they will consistently fail, regardless of load.

A sampling of these, when traced back to the request that originated the failure, all happened to be deserializing a large-ish payload, say around 200KB when serialized to JSON. When pulling back the same collection but with a smaller size, no problem deserializing.

So I think there is something that gets fouled with the bytes payload when it is a remote pipe that isn't happening when it is not remote. Seems unlikely that I have stumbled upon a framing issue, but I guess that is possible.

System.AggregateException HResult=0x80131500 Message=One or more errors occurred. (Protocol message contained an invalid tag (zero).) Source=System.Private.CoreLib StackTrace: at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions) at System.Threading.Tasks.Task1.GetResultCore(Boolean waitCompletionNotification) at System.Threading.Tasks.Task1.get_Result() at GrpcDotNetNamedPipes.NamedPipeChannel.BlockingUnaryCall[TRequest,TResponse](Method2 method, String host, CallOptions callOptions, TRequest request) in C:\code\patterns\GrpcDotNetNamedPipes\NamedPipeChannel.cs:line 93 at Grpc.Core.Interceptors.InterceptingCallInvoker.<BlockingUnaryCall>b__3_0[TRequest,TResponse](TRequest req, ClientInterceptorContext2 ctx) at Grpc.Core.ClientBase.ClientBaseConfiguration.ClientBaseConfigurationInterceptor.BlockingUnaryCall[TRequest,TResponse](TRequest request, ClientInterceptorContext2 context, BlockingUnaryCallContinuation2 continuation) at Grpc.Core.Interceptors.InterceptingCallInvoker.BlockingUnaryCall[TRequest,TResponse](Method2 method, String host, CallOptions options, TRequest request) at Tamus.Famis.Protos.Shadow.Iasys.IasysSvc.IasysSvcClient.GetSysTableDictionaryCollection(GetSysTableDictionaryRqst request, CallOptions options) in C:\code\patterns\s\Tamus.Famis.Protos.Client\obj\Debug\netstandard2.0\protos\shadow\IasysGrpc.cs:line 1153 at Tamus.Famis.Protos.Shadow.Iasys.IasysSvc.IasysSvcClient.GetSysTableDictionaryCollection(GetSysTableDictionaryRqst request, Metadata headers, Nullable1 deadline, CancellationToken cancellationToken) in C:\code\patterns\s\Tamus.Famis.Protos.Client\obj\Debug\netstandard2.0\protos\shadow\IasysGrpc.cs:line 1142 at Tamus.Integration.Shadow.ShadowServerService.<>c__DisplayClass632_0.b__0() in C:\code\patterns\s\Tamus.Integration.Shadow.Client\ShadowServerService_Calls\ShadowServerService.Iasys.cs:line 57 at Tamus.Famis.Protos.Client.Helpers.ServiceExtensions.ThenRun[O](StartPipeFn InitializeFn, Func1 do) in C:\code\patterns\s\Tamus.Famis.Protos.Client\Helpers\ServiceExtensions.cs:line 52 at Tamus.Integration.Shadow.ShadowServerService.RunIasys[O](Func1 do) in C:\code\patterns\s\Tamus.Integration.Shadow.Client\ShadowServerService.cs:line 73 at Tamus.Integration.Shadow.ShadowServerService.GetSysTableDictionaryCollection(GetSysTableDictionaryRqst request) in C:\code\patterns\s\Tamus.Integration.Shadow.Client\ShadowServerService_Calls\ShadowServerService.Iasys.cs:line 57 at Famis.DataLayer.Sys.TableDictionaryCollection.Fill(String campusCd) in C:\code\patterns\s\Tamus.NaturalMigration.Iasys.Code.ShadowSubprograms\ZNNPDICT.TableDictionary.cs:line 86

This exception was originally thrown at this call stack: [External Code] Tamus.Famis.Protos.Shadow.Iasys.IasysSvc.Helper_DeserializeMessage(Grpc.Core.DeserializationContext, Google.Protobuf.MessageParser) in IasysGrpc.cs Tamus.Famis.Protos.Shadow.Iasys.IasysSvc..cctor.AnonymousMethod__136_23(Grpc.Core.DeserializationContext) in IasysGrpc.cs GrpcDotNetNamedPipes.Internal.Helpers.SerializationHelpers.Deserialize(Grpc.Core.Marshaller, byte[]) in SerializationHelpers.cs GrpcDotNetNamedPipes.Internal.MessageReader.Current.get() in MessageReader.cs GrpcDotNetNamedPipes.Internal.MessageReader.ReadNextMessage.AnonymousMethod0() in MessageReader.cs

Inner Exception 1: InvalidProtocolBufferException: Protocol message contained an invalid tag (zero).

cyanfish commented 1 year ago

If it's a message framing issue you could try setting TransmissionMode to Byte and see if that makes a difference.

zachrybaker commented 1 year ago

Using this branch, here's a bit more info:

2023-09-08 17:49:34.875 -05:00 [VRB] [CLIENT][80] Sending for '/shadow.Iasys.IasysSvc/GetSysTableDictionaryCollection' 2023-09-08 17:49:34.875 -05:00 [VRB] [CLIENT][80] Sending 2023-09-08 17:49:34.875 -05:00 [VRB] [CLIENT][80] Sending with 4 bytes 2023-09-08 17:49:34.991 -05:00 [VRB] [CLIENT][80] Received with 111033 bytes 2023-09-08 17:49:35.003 -05:00 [VRB] [CLIENT][80] Received with status '0' 2023-09-08 17:49:35.003 -05:00 [VRB] [CLIENT][80] Pipe disconnected 2023-09-08 17:49:35.095 -05:00 [ERR] Call to IPC failed after "00:00:00.2222476": System.AggregateException: One or more errors occurred. (Protocol message contained an invalid tag (zero).) ---> Google.Protobuf.InvalidProtocolBufferException: Protocol message contained an invalid tag (zero). at Google.Protobuf.ParsingPrimitives.ParseTag(ReadOnlySpan`1& buffer, ParserInternalState& state) at Tamus.Famis.Protos.Shadow.Iasys.GetSysTableDictionaryResp.pb::Google.Protobuf.IBufferMessage.InternalMergeFrom(ParseContext& input) in C:\code\patterns\s\Tamus.Famis.Protos.Client\obj\Debug\netstandard2.0\protos\shadow\Iasys.cs:line 10202

zachrybaker commented 1 year ago

@cyanfish the issue occurs regardless of whether or not the transmission mode is bytes or message. So framing is not the issue here.

And local-to-local pipe continues to work, bytes or message transmission mode.

Side note, it is scary how easy it is to hose a remote server when you have it in message transmission mode and have a client attempting to talk to it in bytes mode....it seems to go off the rails waiting for an end of message. I managed to make the server consume literally all the RAM, until a hard reboot was required of it. I couldn't even stop the thing.