Warnings in GRPC ClientSubscriber Pubsub

[kamisoft-fr]

Environment details

OS: doesn't seem to matter (tested it in Windows 11 as well as in a Ubuntu Docker container)
.NET version: net8.0
Package name and version: Google.Cloud.PubSub.V1, Version 3.12.0

Steps to reproduce

Download sample from https://github.com/kamisoft-fr/GooglePubsubSampleApp
shorter version: #12965

Replace with your GCP settings : projectid & topicName
subcription name can be left as is

Run it

Open the "Output" window
Now wait for about 70 seconds. After that, Visual Studio begins to log occurring exceptions:

15:39:19 dbug: Microsoft.Extensions.Hosting.Internal.Host[1] Hosting starting
15:39:19 trce: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Starting duplex streaming API call to StreamingPull.
15:39:19 trce: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Starting duplex streaming API call to StreamingPull.
15:39:19 trce: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Starting duplex streaming API call to StreamingPull.
15:39:19 trce: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Starting duplex streaming API call to StreamingPull.
15:39:19 trce: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Starting duplex streaming API call to StreamingPull.
15:39:19 info: Microsoft.Hosting.Lifetime[0] Application started. Press Ctrl+C to shut down.
15:39:19 info: Microsoft.Hosting.Lifetime[0] Hosting environment: development
15:39:19 dbug: Microsoft.Extensions.Hosting.Internal.Host[2] Hosting started
15:40:22 warn: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Recoverable error in streaming pull; will retry. System.AggregateException: One or more errors occurred. (Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]")) ---> Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]") at Grpc.Net.Client.Internal.HttpContentClientStreamReader2.MoveNextCore(CancellationToken cancellationToken) --- End of inner exception stack trace --- 15:40:22 warn: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Recoverable error in streaming pull; will retry. System.AggregateException: One or more errors occurred. (Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]")) ---> Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]") at Grpc.Net.Client.Internal.HttpContentClientStreamReader2.MoveNextCore(CancellationToken cancellationToken) --- End of inner exception stack trace ---
15:40:22 dbug: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Delaying for 0s before streaming pull call.
15:40:22 dbug: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Delaying for 0s before streaming pull call.
15:40:22 trce: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Starting duplex streaming API call to StreamingPull.
15:40:22 trce: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Starting duplex streaming API call to StreamingPull.
15:40:27 warn: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Recoverable error in streaming pull; will retry. System.AggregateException: One or more errors occurred. (Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]")) ---> Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]") at Grpc.Net.Client.Internal.HttpContentClientStreamReader`2.MoveNextCore(CancellationToken cancellationToken) --- End of inner exception stack trace ---
15:40:27 dbug: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Delaying for 0s before streaming pull call.
15:40:27 trce: Common.Infrastructure.Pubsub.Google.GoogleChannelSubscriber[0] Starting duplex streaming API call to StreamingPull.

Thanks!

[jskeet]

There's a lot of code in that repro repository. I'm going to try to create a much shorter version.

I strongly suspect this is just a matter of warnings being logged by https://github.com/googleapis/google-cloud-dotnet/blob/main/apis/Google.Cloud.PubSub.V1/Google.Cloud.PubSub.V1/SubscriberClientImpl.SingleChannel.cs#L356, and that should quite possibly be a debug level log instead (given that it's being retried automatically).

[jskeet]

Right, here's the rather shorter version: #12965

There are two potential aspects here:

• Sometimes I see more of an exception/retry loop than I'd expect (although it does always recover)
• The fact that it's being logged as a warning when I suspect that restarting the pull once every minute or so is "working as intended" is non-ideal

The latter is really easy to fix by just changing it to "debug" warning level. The first will need more investigation.

[kamisoft-fr]

Hi Jon,
indeed that's a much shorter version than mine ! Thank you for taking the time to do it.
and now we can both reproduce the issue.
This confirms that it is not a misuse of the library on my part, which could have been the case :)

BTW after reproducing with your sample, the root cause seems to be the "moveNextTask" faulted with "System.Net.Quic.QuicException: The connection timed out from inactivity"

So I searched & found this recently merged fix on .NET QUIC : dotnet/runtime#102147

Or may be this opened on HTTP3 issue : dotnet/runtime#87478

All QUIC "timeout" issues are reported here https://github.com/dotnet/runtime/issues?q=is%3Aopen+label%3Aarea-System.Net.Quic+timeout

My local logs

2024-05-15T19:37:42.566Z info: Timing[0] Starting subscriber
2024-05-15T19:38:52.193Z warn: Subscriber[0] Recoverable error in streaming pull; will retry. System.AggregateException: One or more errors occurred. (Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]")) ---> Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]") at Grpc.Net.Client.Internal.HttpContentClientStreamReader2.MoveNextCore(CancellationToken cancellationToken) --- End of inner exception stack trace --- 2024-05-15T19:38:52.193Z warn: Subscriber[0] Recoverable error in streaming pull; will retry. System.AggregateException: One or more errors occurred. (Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]")) ---> Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]") at Grpc.Net.Client.Internal.HttpContentClientStreamReader2.MoveNextCore(CancellationToken cancellationToken) --- End of inner exception stack trace ---
2024-05-15T19:38:53.539Z warn: Subscriber[0] Recoverable error in streaming pull; will retry. System.AggregateException: One or more errors occurred. (Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]")) ---> Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="The service was unable to fulfill your request. Please try again. [code=8a75]") at Grpc.Net.Client.Internal.HttpContentClientStreamReader`2.MoveNextCore(CancellationToken cancellationToken) --- End of inner exception stack trace ---

[jskeet]

I don't think this is a QUIC issue, as otherwise pinning to HTTP/2.0 would have fixed it. I'll validate that though, and also try on .NET 6 (as we've seen some differences in behavior there)

[kamisoft-fr]

I don't think this is a QUIC issue, as otherwise pinning to HTTP/2.0 would have fixed it. I'll validate that though, and also try on .NET 6 (as we've seen some differences in behavior there)

right, finally failure happens here
https://github.com/grpc/grpc-dotnet/blob/ef1f0d209c3e40c923a6f5830871402eecded030/src/Grpc.Net.Client/Internal/HttpContentClientStreamReader.cs#L177

as per screenshot

[jskeet]

Well, that's where the exception is being thrown. But the underlying question is why the status code is Unavailable at that point. That could have a number of actual causes.

I'm hoping to find time to investigate more today.

[jskeet]

Okay, a few more pieces of information:

• As I mentioned before, the fact that these are shown as warnings is probably a mistake, given that it doesn't actually indicate that anything's wrong. I'll reduce the level to debug.
• The reason we're seeing lots of failures is because the library starts multiple clients. This can be configured via SubscriberClientBuilder.ClientCount, but normally it's fine to leave it alone. I'm going to suggest that we add a "client index" to the log entries from SubscriberClient so we can easily tell the clients apart (while still using a single ILogger instance).
• I've tried with .NET 6, .NET 8 and Grpc.Core - in all cases, I see each StreamingPull call fail after 60-120 seconds. I'm going to ask the Pub/Sub team if that's expected. The QUIC stream timing out may mean there are two different causes for the failure, which isn't idea.
• There's a further complication that we can't currently tell the difference between "this is a real failure, please back off exponentially" and "yup, the stream just timed out, it's fine", so between calls to StreamingPull we're backing off exponentially if the pull fails without seeing any messages. Again, I'm going to ask the Pub/Sub team whether there's some better way of determining the cause of the stream being broken.

@kamisoft-fr: Other than the backoff aspect (which maxes out at 30s, so you could get a delay in seeing messages due to that if there's been a previous long spell of inactivity) I suspect the library is actually behaving fine in terms of processing subscriptions, and you shouldn't see any application-level issues. Have you noticed any semantic problems, or was it just the warning logs that were causing concern?

[jskeet]

A note on QUIC: it looks like the QUIC stream usually times out after 60 seconds; disabling QUIC increases the pull time to about 90 seconds usually. If we get more control over QUIC timeouts in the future, we'll probably increase that automatically (and use keep-alive) - but I don't think it makes a particularly material difference here.

[kamisoft-fr]

@kamisoft-fr: Other than the backoff aspect (which maxes out at 30s, so you could get a delay in seeing messages due to that if there's been a previous long spell of inactivity) I suspect the library is actually behaving fine in terms of processing subscriptions, and you shouldn't see any application-level issues. Have you noticed any semantic problems, or was it just the warning logs that were causing concern?

I would say the main issue is that it gets worse over time. After a few tens of minutes, we have exceptions logged with stack traces every 2-3 seconds, which slows down the system.
Regarding the application side, we are indeed receiving the Pub/Sub messages as expected, but this is still under verification

[jskeet]

I would say the main issue is that it gets worse over time. After a few tens of minutes, we have exceptions logged with stack traces every 2-3 seconds, which slows down the system.

Ooh, that's interesting an unexpected. I wouldn't expect it to get worse over time. I'll try running my code for longer to see if I can reproduce this.

[kamisoft-fr]

Here is an example on my machine