[.NET 7] Client connects first time, but hangs second time (serialization not happening?)

[Kobus-Smit]

What version of gRPC and what language are you using?

Grpc.AspNetCore.Server 2.49.0 Grpc.Net.Client 2.49.0

I've also tried Grpc.AspNetCore.Server 2.50.0-dev202211150802 Grpc.Net.Client 2.50.0-dev202211150802

What operating system (Linux, Windows,...) and version?

Microsoft Windows NT 10.0.19044.0

What runtime / compiler are you using (e.g. .NET Core SDK version dotnet --info)

VS 2022 17.4.0 .NET SDK 7.0.100 Runtime Microsoft.WindowsDesktop.App 7.0.0

What did you do?

I've recently updated a solution to .NET 7 and deployed it. When I start the Kestrel hosted service, and then launch the WinForms client, everything works as expected. When I then close the WinForms client, and open it again, it hangs.

What did you expect to see?

The client connects to the service, when launched the second time as well.

What did you see instead?

When launched a second time, the client hangs. Looking at the client logs, the last entry was: Subchannel id '1' creating stream for... so it is missing Serialized 'System.Byte[]' to 19 byte message... and all the other logs from the first successful client launch.

The server logs does not contain any entries for the client's second launch.

Please find attached client and service logs.

Anything else we should know about your project / environment?

I can only reproduce this when deployed. Locally it works fine.

Any ideas why the serialization and the rest of the calls does not happen in this case?

Client-FirstTime.log Client-SecondTime.log Service.log

[Kobus-Smit]

Seems to be .NET 7 related in our case. I have recompiled the client and service targeting .NET 6 again and deployed, and it works fine.

[rafikiassumani-msft]

@Kobus-Smit can you provide an app to help us reproduce this issue?

[Kobus-Smit]

@rafikiassumani-msft I'll try to share a minimal reproducible example this weekend

[JamesNK]

Closing because of lack of activity

[Kobus-Smit]

Hi @JamesNK and @rafikiassumani-msft ,

I've created an example using the Getting Started tutorial. Grpc-Net7-Hang

Running the .NET 7 client and the .NET 7 service on my Windows 11 development computer, works as expected.

Running the .NET 7 client on our corporate customer's Windows 10 and the .NET 7 service on our corporate customer's Windows Server 2019 Datacenter in Azure, works initially, but after a long idle time, the client call hangs. Any new client calls then also hangs.

If I then target .NET 6 and recompile; Running the .NET 6 client on our corporate customer's Windows 10 and the .NET 6 service on our corporate customer's Windows Server 2019 Datacenter in Azure, works as expected.

Verbose logs:

Corporate-net6-Client.log Corporate-net6-Service.log Corporate-net7-Client.log Corporate-net7-Client2.log Corporate-net7-Service.log DevPC-net7-Client.log.txt DevPC-net7-Service.log.txt

What version of gRPC and what language are you using?

Grpc.AspNetCore.Server 2.51.0 Grpc.Net.Client 2.51.0

What operating system (Linux, Windows,...) and version?

DevPC Windows 11 Pro: Version 10.0.22621.1105 Corporate client Windows 10 Enterprise: Version 10.0.19044.2486 Corporate server (Azure) Windows Server 2019 Datacenter: Version 10.0.17763.3887

What runtime / compiler are you using (e.g. .NET Core SDK version dotnet --info)

VS 2022 17.4.4

.NET SDK: Version: 7.0.102 Commit: 4bbdd14480

Runtime Environment: OS Name: Windows OS Version: 10.0.22621 OS Platform: Windows RID: win10-x64 Base Path: C:\Program Files\dotnet\sdk\7.0.102\

Host: Version: 7.0.2 Architecture: x64 Commit: d037e070eb

.NET SDKs installed: 2.2.207 [C:\Program Files\dotnet\sdk] 3.0.100 [C:\Program Files\dotnet\sdk] 3.1.426 [C:\Program Files\dotnet\sdk] 5.0.202 [C:\Program Files\dotnet\sdk] 5.0.214 [C:\Program Files\dotnet\sdk] 5.0.303 [C:\Program Files\dotnet\sdk] 5.0.407 [C:\Program Files\dotnet\sdk] 5.0.408 [C:\Program Files\dotnet\sdk] 6.0.100-rc.2.21420.30 [C:\Program Files\dotnet\sdk] 6.0.202 [C:\Program Files\dotnet\sdk] 6.0.203 [C:\Program Files\dotnet\sdk] 6.0.302 [C:\Program Files\dotnet\sdk] 6.0.308 [C:\Program Files\dotnet\sdk] 7.0.102 [C:\Program Files\dotnet\sdk]

.NET runtimes installed: Microsoft.AspNetCore.All 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All] Microsoft.AspNetCore.All 2.2.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All] Microsoft.AspNetCore.App 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 2.2.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 3.0.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 3.1.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 3.1.19 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 3.1.24 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 3.1.27 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 3.1.32 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 5.0.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 5.0.10 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 5.0.16 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 6.0.0-rc.2.21419.24 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 6.0.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 6.0.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 6.0.7 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 6.0.10 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.NETCore.App 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 2.2.8 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 3.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 3.1.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 3.1.19 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 3.1.20 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 3.1.22 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 3.1.24 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 3.1.27 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 3.1.32 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 5.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 5.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 5.0.10 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 5.0.13 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 5.0.16 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.0-rc.2.21420.10 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.7 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.10 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.12 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.WindowsDesktop.App 3.0.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 3.1.19 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 3.1.20 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 3.1.22 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 3.1.24 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 3.1.27 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 3.1.32 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 5.0.4 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 5.0.5 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 5.0.10 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 5.0.13 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 5.0.16 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.0-rc.2.21419.14 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.4 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.5 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.7 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.10 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found: arm64 [C:\Program Files\dotnet] registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\arm64\InstallLocation] x86 [C:\Program Files (x86)\dotnet] registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables: Not set

global.json file: Not found

Learn more: https://aka.ms/dotnet/info

Download .NET: https://aka.ms/dotnet/download

Corporate-net7-Service.log DevPC-net7-Client.log.txt DevPC-net7-Service.log.txt

[Kobus-Smit]

Hi @JamesNK & @rafikiassumani-msft

I've added a branch that use keep alive pings, hoping it would address the isue.

But still the same hanging occurs with .NET 7 (where .NET 6 keeps working).

I've discovered that .NET 7 client and .NET 6 service works, but a .NET 7 client and .NET 7 service hangs,

Please see new logs:

Corporate-net7-Client-WithKeepAlive-net7-Service.log Corporate-net7-Service-WithKeepAlive.log

Corporate-net7-Client-WithKeepAlive-net6-Service.log Corporate-net6-Service-WithKeepAlive.log

Interesting, it appears there were only 11 pings sent to the net7 service, and 5 pings sent to the net6 service, before a SocketException occurred that stopped the connection, and no more pings were sent?

The net6 service however still responded after more than an hour idle time, but there net7 service had zero logs around the idle time.

I've also captured the traffic when calling the service after the long idle time. I can share the Wireshark logs if needed?

Any other ideas or suggestions would be much appreciated!

[JamesNK]

I ran the app locally, and I couldn't reproduce the issue.

Unfortunately, looking at the logs, I don't see anything immediately wrong. The point where it hangs has a lot of interactions between grpc-dotnet code, and SocketsHttpHandler code from .NET.

I have a PR to add more logging. It might provide more information about what is going on: https://github.com/grpc/grpc-dotnet/pull/2047

Another idea, and something you can try immediately, is to enable logging in SocketsHttpHandler. Getting its logging could be useful if the hang is happening inside .NET 7. I have a helper class for setting it up so its logs are written to Microsoft.Extensions.Logging: https://github.com/grpc/grpc-dotnet/blob/0f9300c43901ad82fdb4dfb7cf1d11b34d2cf077/test/Shared/HttpEventSourceListener.cs

Just create it in Program.cs after the logger factory: using var httpEventSource = new HttpEventSourceListener(loggerFactory);

[Kobus-Smit]

Thanks @JamesNK

I've added SocketsHttpHandler logging https://github.com/Kobus-Smit/Grpc-Net7-Hang/commit/768309020c8c8077369f0a52d404ba3378746cf0 and compiled against grpc-dotnet's master containing your additional logging https://github.com/Kobus-Smit/Grpc-Net7-Hang/commit/eb820aea446792f11d89a3399adb9b47888a9e93

New logs: Corporate-net7-Service-2023-02-14-Run1.log Corporate-net7-Client-2023-02-14-Run1.log Corporate-net7-Service-2023-02-14-Run2.log Corporate-net7-Client-2023-02-14-Run2.log Corporate-net7-Service-2023-02-14-Run3.log Corporate-net7-Client-2023-02-14-Run3.log

Run1

Debug GrpcService1 using Visual Studio 2022 on a WinServer2019 Azure VM (with break on all exceptions) Debug GrpcGreeterClient using Visual Studio 2022 on a customer's Windows 10 VM (with break on all exceptions)

09:13:02 Service starts 09:13:33 Client starts and calls SayHello 09:13:36 Client receives reply 09:14:51 Client state Idle: Disconnected 09:14:51 Service says client closed the connection, connection stopped. No more service logs after this. 09:18:59 GrpcGreeterClientproject in VS displayed this exception

System.IO.IOException
HResult=0x80131620
Message=Unable to read data from the transport connection: The I/O operation has been aborted because of either a thread exit or an application request..
Source=System.Net.Sockets
StackTrace:
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
at System.Net.Security.SslStream.<EnsureFullTlsFrameAsync>d__157`1.MoveNext()
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
at System.Net.Security.SslStream.<ReadAsyncInternal>d__159`1.MoveNext()

Inner Exception 1:
SocketException: The I/O operation has been aborted because of either a thread exit or an application request.

09:18:59 GrpcService1 project in VS displayed this exception (But nothing is logged)

System.Net.Sockets.SocketException
HResult=0x80004005
Message=The I/O operation has been aborted because of either a thread exit or an application request.
Source=System.Net.Sockets
StackTrace:
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)

09:19:01 Clients calls SayHello and hangs

Run2

Debug GrpcService1 using Visual Studio 2022 on a WinServer2019 Azure VM (without break on all exceptions) Debug GrpcGreeterClient using Visual Studio 2022 on a customer's Windows 10 VM (without break on all exceptions)

09:20:58 Service starts 09:21:13 Client starts and calls SayHello 09:21:15 Client receives reply 09:22:29 Client state Idle: Disconnected 09:22:29 Service says client closed the connection, connection stopped 09:22:58 Client logs IOException 09:23:23 Client calls SayHello 09:23:23 Client receives reply 09:24:38 Client state Idle: Disconnected 09:24:38 Service says client closed the connection, connection stopped. No more service logs after this. 09:24:55 Client logs IOException 09:53:54 Client calls SayHello and hangs

Run3 (looks similar to Run2, but check the timestamps)

Debug GrpcService1 using Visual Studio 2022 on a WinServer2019 Azure VM (without break on all exceptions) Debug GrpcGreeterClient using Visual Studio 2022 on a customer's Windows 10 VM (without break on all exceptions)

09:55:06 Service starts 09:55:24 Client starts and calls SayHello 09:55:25 Client receives reply 09:56:40 Client state Idle: Disconnected 09:56:40 Service says client closed the connection, connection stopped 09:56:40 Client logs IOException 10:34:44 Client calls SayHello 10:34:44 Client receives reply 10:35:59 Client state Idle: Disconnected 10:35:59 Service says client closed the connection, connection stopped. No more service logs after this. 10:35:59 Client logs IOException 10:37:39 Client calls SayHello and hangs

[Kobus-Smit]

Logs for comparison, after changing the service to .NET 6. No hanging then.

Corporate-net6-Service-2023-02-18.log Corporate-net7-Client-2023-02-18.log

[Kobus-Smit]

Hi @JamesNK , was the additional logging helpful?

[JamesNK]

Sorry about the inactivity in the investigation. I looked at the logs and didn't see an obvious answer to what was happening. I'll forward this to people who work on HTTP client in .NET and see if they can help.

[Kobus-Smit]

Thanks mate

[Kobus-Smit]

Revisited this again today in preparation for .NET 8 upgrade, and I could not reproduce this issue again.

Ran the same .NET 7 client and service projects on same Azure VM of the same customer, and even after a few hours it never hanged...