Open axhero opened 1 year ago
HttpClient
is (or was?) very reluctant to talk non-TLS HTTP2; this might only apply to .NET Core 3.x and might be outdated, but: we can at least try...
can we try twisting it's arm? Add (early on, in the client code):
AppContext.SetSwitch("System.Net.Http.SocketsHttpHandler.Http2UnencryptedSupport", true);
(if this is the cause, then I'm going to recommend that we detect this scenario and throw a bespoke exception that tells the user what to do, so: please don't close this if this works)
Looking at this locally, I do not think the app-context flag still applies - I'll stop mentioning that. My apologies for the confusion.
Right; next things... what protocols is the server binding to? Without TLS, you cannot use Http1AndHttp2
(it should be Http2
) - although setting this up locally to investigate, I get a slightly different stack trace - it fails (as expected), but it fails differently:
Information [0]: Try to connect service 'Server' at address 'http://localhost:5080'...
Information [0]: Try to call 'PingServiceAsync' with timeout '5000' ms, message 'Hello from 'MGX''...
Debug [StartingCall]: Starting gRPC call. Method type: 'Unary', URI: 'http://localhost:5080/greet.Greeter/SayHello'.
Trace [StartingDeadlineTimeout]: Starting deadline timeout. Duration: 00:00:04.9950823.
Debug [SubchannelCreated]: Subchannel id '1' created with addresses: localhost:5080
Trace [StateChangedRegistrationCreated]: Subchannel id '1' state changed registration '1-1' created.
Debug [ChannelPickerUpdated]: Channel picker updated.
Trace [ConnectionRequested]: Subchannel id '1' connection requested.
Debug [SubchannelStateChanged]: Subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
Trace [ExecutingStateChangedRegistration]: Subchannel id '1' executing state changed registration '1-1'.
Trace [ProcessingSubchannelStateChanged]: Processing subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
Debug [ChannelStateUpdated]: Channel state updated to Connecting.
Trace [PickStarted]: Pick started.
Debug [PickResultQueued]: Picked queued.
Trace [PickWaiting]: Waiting for a new picker.
Trace [ConnectingTransport]: Subchannel id '1' connecting to transport.
Trace [ConnectingSocket]: Subchannel id '1' connecting socket to localhost:5080.
Debug [ConnectedSocket]: Subchannel id '1' connected to socket localhost:5080.
Debug [SubchannelStateChanged]: Subchannel id '1' state changed to Ready. Detail: 'Successfully connected to socket.'.
Trace [ExecutingStateChangedRegistration]: Subchannel id '1' executing state changed registration '1-1'.
Trace [ProcessingSubchannelStateChanged]: Processing subchannel id '1' state changed to Ready. Detail: 'Successfully connected to socket.'.
Debug [ChannelStateUpdated]: Channel state updated to Ready.
Debug [ChannelPickerUpdated]: Channel picker updated.
Trace [PickStarted]: Pick started.
Debug [PickResultSuccessful]: Successfully picked subchannel id '1' with address localhost:5080.
Trace [SendingRequest]: Sending request http://localhost:5080/greet.Greeter/SayHello.
Trace [StartingConnectCallback]: Starting connect callback for localhost:5080.
Trace [CreatingStream]: Subchannel id '1' creating stream for localhost:5080.
Trace [StreamCreated]: Subchannel id '1' created stream for localhost:5080. Transport has 1 active streams.
Debug [SendingMessage]: Sending message.
Trace [SerializedMessage]: Serialized 'GrpcService1.HelloRequest' to 5 byte message.
Trace [MessageSent]: Message sent.
Trace [DisposingStream]: Subchannel id '1' disposing stream for localhost:5080. Transport has 0 active streams.
Debug [SubchannelStateChanged]: Subchannel id '1' state changed to Idle. Detail: 'Disconnected.'.
Trace [ExecutingStateChangedRegistration]: Subchannel id '1' executing state changed registration '1-1'.
Trace [ProcessingSubchannelStateChanged]: Processing subchannel id '1' state changed to Idle. Detail: 'Disconnected.'.
Debug [ChannelStateUpdated]: Channel state updated to Idle.
Debug [ChannelPickerUpdated]: Channel picker updated.
Debug [ErrorStartingCall]: Error starting gRPC call.
Information [GrpcStatusError]: Call failed with gRPC error status. Status code: 'Unavailable', Message: 'Error starting gRPC call. HttpRequestException: An error occurred while sending the request. IOException: The request was aborted. Http2ConnectionException: The HTTP/2 server sent invalid data on the connection. HTTP/2 error code 'PROTOCOL_ERROR' (0x1).'.
Is there a runnable repro I can look at here?
Related to https://github.com/grpc/grpc-dotnet/issues/2190#issuecomment-1642204763
I added AppContext.SetSwitch("System.Net.Http.SocketsHttpHandler.Http2UnencryptedSupport", true);
at the first line in source code (mentioned above), but as you presumed there is no change. The log-files looks exactly like above mentioned.
Related to https://github.com/grpc/grpc-dotnet/issues/2190#issuecomment-1642250223
Http1AndHttp2
.
PS D:\X_Update\testclient03\publish> dotnet Isra.CPV.Tool.ServerServicePlainGrpcClient.dll -a http://192.168.1.200:50055
Application Configuration:
Logging:Console:LogLevel:Default = Trace
Logging:Console:LogLevel:Grpc = Trace
Logging:Console:LogLevel:Microsoft = Trace
Logging:LogLevel:Default = Trace
Logging:LogLevel:Grpc = Trace
Logging:LogLevel:Microsoft = Trace
Server:Call:All = false
Server:Grpc:Address = http://192.168.1.200:50055
Server:Grpc:Timeout = 30000
dbug: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Test Debug Log trce: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Test Trace Log info: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Test Info Log warn: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Test Warning Log fail: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Test Error Log crit: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Test Critical Log info: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] System.Environment.Version: 6.0.19 info: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] System.Runtime.InteropServices.RuntimeInformation.FrameworkDescription: .NET 6.0.19 info: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Try to connect service 'Server' at address 'http://192.168.1.200:50055'... info: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Try to call 'PingServiceAsync' with timeout '30000' ms, message 'Hello from 'DESKTOP-FM9IS86''... dbug: Grpc.Net.Client.Internal.GrpcCall[1] Starting gRPC call. Method type: 'Unary', URI: 'http://192.168.1.200:50055/Isra.CPV.Server.Communication.Grpc.Interface.Server.ServerCommunicationService/PingService'. trce: Grpc.Net.Client.Internal.GrpcCall[5] Starting deadline timeout. Duration: 00:00:29.9786692. dbug: Grpc.Net.Client.Balancer.Subchannel[1] Subchannel id '1' created with addresses: 192.168.1.200:50055 trce: Grpc.Net.Client.Balancer.Subchannel[12] Subchannel id '1' state changed registration '1-1' created. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[4] Channel picker updated. trce: Grpc.Net.Client.Balancer.Subchannel[4] Subchannel id '1' connection requested. dbug: Grpc.Net.Client.Balancer.Subchannel[11] Subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'. trce: Grpc.Net.Client.Balancer.Subchannel[14] Subchannel id '1' executing state changed registration '1-1'. trce: Grpc.Net.Client.Balancer.PickFirstBalancer[1] Processing subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[3] Channel state updated to Connecting. trce: Grpc.Net.Client.Balancer.Internal.ConnectionManager[5] Pick started. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[8] Picked queued. trce: Grpc.Net.Client.Balancer.Internal.ConnectionManager[11] Waiting for a new picker. trce: Grpc.Net.Client.Balancer.Subchannel[6] Subchannel id '1' connecting to transport. trce: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[1] Subchannel id '1' connecting socket to 192.168.1.200:50055. dbug: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[2] Subchannel id '1' connected to socket 192.168.1.200:50055. dbug: Grpc.Net.Client.Balancer.Subchannel[11] Subchannel id '1' state changed to Ready. Detail: 'Successfully connected to socket.'. trce: Grpc.Net.Client.Balancer.Subchannel[14] Subchannel id '1' executing state changed registration '1-1'. trce: Grpc.Net.Client.Balancer.PickFirstBalancer[1] Processing subchannel id '1' state changed to Ready. Detail: 'Successfully connected to socket.'. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[3] Channel state updated to Ready. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[4] Channel picker updated. trce: Grpc.Net.Client.Balancer.Internal.ConnectionManager[5] Pick started. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[6] Successfully picked subchannel id '1' with address 192.168.1.200:50055. trce: Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler[1] Sending request http://192.168.1.200:50055/Isra.CPV.Server.Communication.Grpc.Interface.Server.ServerCommunicationService/PingService. trce: Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler[2] Starting connect callback for 192.168.1.200:50055. trce: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[7] Subchannel id '1' creating stream for 192.168.1.200:50055. trce: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[11] Subchannel id '1' doesn't have a connected socket available. Connecting new stream socket for 192.168.1.200:50055. trce: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[12] Subchannel id '1' created stream for 192.168.1.200:50055. Transport has 1 active streams. dbug: Grpc.Net.Client.Internal.GrpcCall[18] Sending message. trce: Grpc.Net.Client.Internal.GrpcCall[21] Serialized 'Isra.CPV.Server.Communication.Grpc.Interface.PingServiceRequest' to 17 byte message. trce: Grpc.Net.Client.Internal.GrpcCall[19] Message sent. trce: Grpc.Net.Client.Internal.GrpcCall[2] Response headers received. dbug: Grpc.Net.Client.Internal.GrpcCall[13] Reading message. trce: Grpc.Net.Client.Internal.GrpcCall[15] Deserializing 63 byte message to 'Isra.CPV.Server.Communication.Grpc.Interface.PingServiceReply'. trce: Grpc.Net.Client.Internal.GrpcCall[16] Received message. dbug: Grpc.Net.Client.Internal.GrpcCall[4] Finished gRPC call. info: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Call 'PingService': info: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] PingMessage: DESKTOP-FM9IS86 info: Isra.CPV.Tool.ServerServicePlainGrpcClient.Program[0] Messages: Level:None, ID: Success, Text:, Details: License File: /app/data/license/server.lic trce: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[8] Subchannel id '1' disposing stream for 192.168.1.200:50055. Transport has 0 active streams. dbug: Grpc.Net.Client.Balancer.Subchannel[11] Subchannel id '1' state changed to Idle. Detail: 'Disconnected.'. trce: Grpc.Net.Client.Balancer.Subchannel[14] Subchannel id '1' executing state changed registration '1-1'. trce: Grpc.Net.Client.Balancer.PickFirstBalancer[1] Processing subchannel id '1' state changed to Idle. Detail: 'Disconnected.'. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[3] Channel state updated to Idle. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[4] Channel picker updated. dbug: Grpc.Net.Client.Balancer.Subchannel[11] Subchannel id '1' state changed to Shutdown. Detail: 'Subchannel disposed.'. trce: Grpc.Net.Client.Balancer.Subchannel[14] Subchannel id '1' executing state changed registration '1-1'. trce: Grpc.Net.Client.Balancer.PickFirstBalancer[1] Processing subchannel id '1' state changed to Shutdown. Detail: 'Subchannel disposed.'. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[3] Channel state updated to Shutdown. dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[4] Channel picker updated. trce: Grpc.Net.Client.Balancer.Subchannel[13] Subchannel id '1' state changed registration '1-1' removed. trce: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[9] Subchannel id '1' disposing transport.
So it depends on dotnet and/or that specific customer PC.
The dotnet runtime of the customer PC is:
PS C:\testclient04\publish> dotnet --info
global.json file: Not found
Host: Version: 6.0.19 Architecture: x64 Commit: e37fab9fc9
.NET SDKs installed: No SDKs were found.
.NET runtimes installed: Microsoft.NETCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.11 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.19 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.WindowsDesktop.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.19 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Download .NET: https://aka.ms/dotnet-download
Learn about .NET Runtimes and SDKs: https://aka.ms/dotnet/runtimes-sdk-info
3. sharing the test client is possible server not. Main code (except protos) is mentioned above. I'm not familiar with github, but I can try to create an repro.
I add 2 test project (VS2022, net6) and invited you. The server project shows some errors at startup. Please ignore, its only localization stuff.
What version of gRPC and what language are you using?
C#; .NET 6