Deadlock under load caused by Wait() in GoogleAdsGrpcInterceptor

[jesuissur]

Under some load in asynchronous context, our call to service like GoogleAdsService through GoogleAdsServiceClient lock our app with threads starvation.

Steps to Reproduce:
Put some load and watch it fails.
We do not have the stack trace anymore, but all of our threads were blocked at this method on a Wait() operation: Google.Ads.GoogleAds.Interceptors.GoogleAdsGrpcInterceptor.AsyncUnaryCall

Expected behavior:
Asynchronous operations should not lock

Client library version and API version:
Client library version: v.11.0.0
Google Ads API version: N/A
.NET version: .Net 6
Operating system (Linux, Windows, ...) and version (if the bug is platform-specific): Windows App service on Azure

Workaround:
We built our own version with the logging code removed and everything is now fine

public override AsyncUnaryCall<TResponse> AsyncUnaryCall<TRequest, TResponse>(
            TRequest request, ClientInterceptorContext<TRequest, TResponse> context,
            AsyncUnaryCallContinuation<TRequest, TResponse> continuationCallback)
        {
            AsyncUnaryCall<TResponse> call = continuationCallback(request, context);

            //Task t = call.ResponseAsync.ContinueWith(
            //    delegate (Task<TResponse> oldTask)
            //    {
            //        loggingHandler.HandleAsyncUnaryLogging(request, context, oldTask, call);
            //    });
            //t.Wait();  <------------- We should never Wait in an async context

            return UnaryRpcInterceptor.Intercept(call);
        }

[AnashOommen]

Hi @jesuissur you don't need to recompile a custom version, you can temporarily turn off logging instead. Set the relevant logging level to off.

https://developers.google.com/google-ads/api/docs/client-libs/dotnet/logging#configuration
https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.sourcelevels?view=net-6.0

I can see why this issue can happen, but TBH this is the first time I've seen anyone report it. So I need a bit more investigation to see what's happening.

[jesuissur]

Hi @AnashOommen

We rescued some stack trace. Our code is calling googleAdsServiceClient.SearchAsync(...) and while we iterate the results PagedAsyncEnumerable<SearchGoogleAdsResponse, GoogleAdsRow> it locks with this stack trace

HelperMethodFrame_1OBJ
System.Threading.Monitor.Wait
System.Threading.ManualResetEventSlim.Wait
System.Threading.Tasks.Task.SpinThenBlockingWait
System.Threading.Tasks.Task.InternalWaitCore
System.Threading.Tasks.Task.Wait
System.Threading.Tasks.Task.Wait
Google.Ads.GoogleAds.Interceptors.GoogleAdsGrpcInterceptor.AsyncUnaryCall[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]]
Grpc.Core.Interceptors.InterceptingCallInvoker.AsyncUnaryCall[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]]
Grpc.Core.Interceptors.InterceptingCallInvoker.<AsyncUnaryCall>b__4_0[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]]
Grpc.Core.ClientBase+ClientBaseConfiguration+ClientBaseConfigurationInterceptor.AsyncUnaryCall[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]]
Grpc.Core.Interceptors.InterceptingCallInvoker.AsyncUnaryCall[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]]
Google.Ads.GoogleAds.V10.Services.GoogleAdsService+GoogleAdsServiceClient.SearchAsync
Google.Api.Gax.Grpc.ApiCall+GrpcCallAdapter`2[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].CallAsync
Google.Api.Gax.Grpc.ApiCallRetryExtensions+<>c__DisplayClass0_0`2+<<WithRetry>b__0>d[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].MoveNext
System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[Google.Api.Gax.Grpc.ApiCallRetryExtensions+<>c__DisplayClass0_0`2+<<WithRetry>b__0>d[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]], Google.Api.Gax.Grpc]]
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, System.Private.CoreLib]].Start[[Google.Api.Gax.Grpc.ApiCallRetryExtensions+<>c__DisplayClass0_0`2+<<WithRetry>b__0>d[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]], Google.Api.Gax.Grpc]]
Google.Api.Gax.Grpc.ApiCallRetryExtensions+<>c__DisplayClass0_0`2[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].<WithRetry>b__0
Google.Api.Gax.Grpc.ApiCall`2+<>c__DisplayClass10_0[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].<WithCallSettingsOverlay>b__0
Google.Api.Gax.Grpc.ResponseAsyncEnumerable`3+ResponseAsyncEnumerator+<MoveNextAsync>d__10[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].MoveNext
System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[Google.Api.Gax.Grpc.ResponseAsyncEnumerable`3+ResponseAsyncEnumerator+<MoveNextAsync>d__10[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]], Google.Api.Gax.Grpc]]
System.Runtime.CompilerServices.AsyncValueTaskMethodBuilder`1[[System.Boolean, System.Private.CoreLib]].Start[[Google.Api.Gax.Grpc.ResponseAsyncEnumerable`3+ResponseAsyncEnumerator+<MoveNextAsync>d__10[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]], Google.Api.Gax.Grpc]]
Google.Api.Gax.Grpc.ResponseAsyncEnumerable`3+ResponseAsyncEnumerator[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].MoveNextAsync

We'll eventually try to deactivate the logging with an official release.
Thanks
Phil

[AnashOommen]

Hi Phil,

Could you check if the issue is replicable with v12.0.0? I made some changes with the lifecycle of GoogleAdsInterceptor, so hopefully this isn't an issue.

[AnashOommen]

@jesuissur is this issue still present? Can I close this thread?

[jesuissur]

@AnashOommen We did not try the v12 release yet. Should come in a few weeks

[geext-dk]

I was facing an issue that has the same origin I believe:

1. GoogleAdsClient always uses GoogleAdsServiceClientFactory to create services.
2. GoogleAdsServiceClientFactory always adds GoogleAdsGrpcInterceptor.
3. GoogleAdsGrpcInterceptor always blocks the thread by executing t.Wait(), waiting for the response before returning. It's seen from the code that no config options can change that, it doesn't matter whether logging is on or off.

That basically means that (possibly) all async calls are blocking.

[AnashOommen]

I removed all the Wait() calls in v14.0.0.

[hakimio]

@AnashOommen and now we have #488 and #480 😟