LoggingHandler hangs the thread

[sparhomenko]

Our application is running on Google Kubernetes Engine using gcr.io/google-appengine/jetty image and used com.google.cloud.logging.LoggingHandler to publish logs on Stackdriver. We noticed some worker threads becoming unresponsive over time. When the pod is shutting down we can see the following exception for each:

java.lang.RuntimeException: java.lang.InterruptedException
	at com.google.cloud.logging.LoggingImpl.flush(LoggingImpl.java:545)
	at com.google.cloud.logging.LoggingImpl.write(LoggingImpl.java:525)
	at com.google.cloud.logging.LoggingHandler.publish(LoggingHandler.java:273)
	at java.util.logging.Logger.log(Logger.java:738)
	at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:582)
	at org.slf4j.impl.JDK14LoggerAdapter.error(JDK14LoggerAdapter.java:500)
        ...
Caused by: java.lang.InterruptedException
	at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:449)
	at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get(AbstractFuture.java:79)
	at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
	at com.google.cloud.logging.LoggingImpl.flush(LoggingImpl.java:543)
	... 30 more

We'll try to extract a thread dump to see why the future never completes, but the issue seems dangerous by itself: LoggingImpl.java:543 uses the non-timeout version of Future.get() which can cause any logger call to block the current thread forever unless interrupted. Would it be possible to use the timeout version with a reasonably big timeout, e.g. 60 seconds?

[pongad]

This seems related to #1795. The underlying client provides no way to initiate a flush.

@sparhomenko Do you have a sense of how long we're waiting? The above bug might cause us to wait a few seconds, but it shouldn't cause a prolonged hang. I agree that the wait with no timeout is a problem, but I want to understand the problem better before sending fixes.

[sparhomenko]

@pongad Longest one we observed so far was 2.5 hours until manually interrupted. We're not sure what caused the future to hang for so long. The issue seems to be intermittently reproducible, I'll try to get more diagnostic information next time we hit it.

[pongad]

@sparhomenko Yikes! 2.5 hours is WAY beyond reasonable. I now suspect some kind of propagation problem somewhere. Maybe we don't properly complete the future for something. I'll try to dig into this as well, but a repro would be greatly appreciated.

Hi @pongad, Im now about to use google cloud logging API for logging in a multiThreaded java app, it'll be having near to 5k threads running concurrently, so any updates plz?

[pongad]

@tamersaleh I unfortunately don't have concrete progress to share yet. We plan to simplify the batching logic. The simplification should let us smoke out many of these bugs.

[sparhomenko]

@pongad I'm afraid we are not able to reproduce the issue anymore. The only useful thing we found was that on the pods where this was reproducible LoggingHandler actually stopped providing any logs after this exception occurred:

java.lang.RuntimeException: com.google.cloud.logging.LoggingException: io.grpc.StatusRuntimeException: UNAVAILABLE: 503:Service Unavailable
	at com.google.cloud.logging.LoggingImpl$7.onFailure(LoggingImpl.java:577)
	at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:52)
	at com.google.common.util.concurrent.Futures$6.run(Futures.java:1764)
	at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:634)
	at com.google.common.util.concurrent.Futures$AbstractChainingFuture.run(Futures.java:1405)
	at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:634)
	at com.google.common.util.concurrent.Futures$AbstractCatchingFuture.run(Futures.java:794)
	at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:634)
	at com.google.api.core.AbstractApiFuture$InternalSettableFuture.setException(AbstractApiFuture.java:96)
	at com.google.api.core.AbstractApiFuture.setException(AbstractApiFuture.java:78)
	at com.google.api.gax.grpc.BatchedRequestIssuer.sendResult(BatchedRequestIssuer.java:68)
	at com.google.api.gax.grpc.BatchExecutor$1.onFailure(BatchExecutor.java:96)
	at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:52)
	at com.google.common.util.concurrent.Futures$6.run(Futures.java:1764)
	at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:634)
	at com.google.api.gax.retrying.RetryingFutureImpl.executeAttempt(RetryingFutureImpl.java:142)
	at com.google.api.gax.retrying.RetryingFutureImpl.access$500(RetryingFutureImpl.java:58)
	at com.google.api.gax.retrying.RetryingFutureImpl$AttemptFutureCallback.onFailure(RetryingFutureImpl.java:176)
	at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:52)
	at com.google.common.util.concurrent.Futures$6.run(Futures.java:1764)
	at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:634)
	at com.google.api.core.AbstractApiFuture$InternalSettableFuture.setException(AbstractApiFuture.java:96)
	at com.google.api.core.AbstractApiFuture.setException(AbstractApiFuture.java:78)
	at com.google.api.gax.grpc.ExceptionTransformingCallable$ExceptionTransformingFuture.onFailure(ExceptionTransformingCallable.java:108)
	at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:52)
	at com.google.common.util.concurrent.Futures$6.run(Futures.java:1764)
	at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:634)
	at io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:463)
	at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:439)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:428)
	at io.grpc.internal.ClientCallImpl.access$100(ClientCallImpl.java:76)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:514)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:431)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:546)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:52)
	at io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:152)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.google.cloud.logging.LoggingException: io.grpc.StatusRuntimeException: UNAVAILABLE: 503:Service Unavailable
	at com.google.cloud.logging.spi.v2.GrpcLoggingRpc$1.apply(GrpcLoggingRpc.java:141)
	at com.google.cloud.logging.spi.v2.GrpcLoggingRpc$1.apply(GrpcLoggingRpc.java:135)
	at com.google.api.core.ApiFutures$GaxFunctionToGuavaFunction.apply(ApiFutures.java:124)
	at com.google.common.util.concurrent.Futures$CatchingFuture.doFallback(Futures.java:842)
	at com.google.common.util.concurrent.Futures$CatchingFuture.doFallback(Futures.java:834)
	at com.google.common.util.concurrent.Futures$AbstractCatchingFuture.run(Futures.java:789)
	... 48 more
Caused by: com.google.api.gax.grpc.ApiException: io.grpc.StatusRuntimeException: UNAVAILABLE: 503:Service Unavailable
	... 23 more
Caused by: io.grpc.StatusRuntimeException: UNAVAILABLE: 503:Service Unavailable
	at io.grpc.Status.asRuntimeException(Status.java:540)
	... 15 more

These might have been caused by us producing too many logs, which we are not doing anymore.

One other suspicious thing is that latest version of google-appengine Docker image we use is still using a pretty old version of google-cloud-logging and related dependencies. So the issue might have been triggered by a problem in that version, or by a classpath conflict between the provided dependencies and the newer ones we package in our WAR.

[dansomething]

FWIW, we have experienced similar issues using both JUL and Logback as our client for google-cloud-logging. The hangs seem to correlate with GRPC connection issues. We have sadly never been able to reliably reproduce the issue. We eventually had to give up on using the "Enhanced Stackdriver Logging" feature of the jetty-runtime.

Here some stracktraces from our logs if that helps.

java.lang.RuntimeException: com.google.cloud.logging.LoggingException: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 49999922530ns at com.google.cloud.logging.LoggingImpl$7.onFailure(LoggingImpl.java:577) at
 com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:61) at
 com.google.common.util.concurrent.Futures$4.run(Futures.java:1123) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:112) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:134) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.api.core.AbstractApiFuture$InternalSettableFuture.setException(AbstractApiFuture.java:95) at
 com.google.api.core.AbstractApiFuture.setException(AbstractApiFuture.java:77) at
 com.google.api.gax.rpc.BatchedFuture.setException(BatchedFuture.java:55) at
 com.google.api.gax.rpc.BatchedRequestIssuer.sendResult(BatchedRequestIssuer.java:82) at
 com.google.api.gax.rpc.BatchExecutor$1.onFailure(BatchExecutor.java:96) at
 com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:61) at
 com.google.common.util.concurrent.Futures$4.run(Futures.java:1123) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:157) at
 com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:134) at
 com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:116) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.api.core.AbstractApiFuture$InternalSettableFuture.setException(AbstractApiFuture.java:95) at
 com.google.api.core.AbstractApiFuture.setException(AbstractApiFuture.java:77) at
 com.google.api.gax.grpc.GrpcExceptionCallable$ExceptionTransformingFuture.setException(GrpcExceptionCallable.java:117) at
 com.google.api.gax.grpc.GrpcExceptionCallable$ExceptionTransformingFuture.onFailure(GrpcExceptionCallable.java:101) at
 com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:61) at
 com.google.common.util.concurrent.Futures$4.run(Futures.java:1123) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:458) at
 io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:433) at
 io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:41) at
 io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:339) at
 io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:443) at
 io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:63) at
 io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:525) at
 io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:446) at
 io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:557) at
 io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) at
 io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:107) at
 java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at
 java.util.concurrent.FutureTask.run(FutureTask.java:266) at
 java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at
 java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at
 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at
 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at
 java.lang.Thread.run(Thread.java:748) Caused by: com.google.cloud.logging.LoggingException: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 49999922530ns at com.google.cloud.logging.spi.v2.GrpcLoggingRpc$2.apply(GrpcLoggingRpc.java:155) at
 com.google.cloud.logging.spi.v2.GrpcLoggingRpc$2.apply(GrpcLoggingRpc.java:149) at
 com.google.api.core.ApiFutures$GaxFunctionToGuavaFunction.apply(ApiFutures.java:153) at
 com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:205) at
 com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:193) at
 com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:132)

java.lang.RuntimeException: com.google.cloud.logging.LoggingException: io.grpc.StatusRuntimeException: UNAVAILABLE: Authentication backend unavailable. at com.google.cloud.logging.LoggingImpl$7.onFailure(LoggingImpl.java:577) at
 com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:61) at
 com.google.common.util.concurrent.Futures$4.run(Futures.java:1123) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:112) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:134) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.api.core.AbstractApiFuture$InternalSettableFuture.setException(AbstractApiFuture.java:95) at
 com.google.api.core.AbstractApiFuture.setException(AbstractApiFuture.java:77) at
 com.google.api.gax.rpc.BatchedFuture.setException(BatchedFuture.java:55) at
 com.google.api.gax.rpc.BatchedRequestIssuer.sendResult(BatchedRequestIssuer.java:82) at
 com.google.api.gax.rpc.BatchExecutor$1.onFailure(BatchExecutor.java:96) at
 com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:61) at
 com.google.common.util.concurrent.Futures$4.run(Futures.java:1123) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:157) at
 com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:134) at
 com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:116) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 com.google.api.core.AbstractApiFuture$InternalSettableFuture.setException(AbstractApiFuture.java:95) at
 com.google.api.core.AbstractApiFuture.setException(AbstractApiFuture.java:77) at
 com.google.api.gax.grpc.GrpcExceptionCallable$ExceptionTransformingFuture.setException(GrpcExceptionCallable.java:117) at
 com.google.api.gax.grpc.GrpcExceptionCallable$ExceptionTransformingFuture.onFailure(GrpcExceptionCallable.java:101) at
 com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:61) at
 com.google.common.util.concurrent.Futures$4.run(Futures.java:1123) at
 com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) at
 com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) at
 com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) at
 com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) at
 io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:458) at
 io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:433) at
 io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:41) at
 io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:339) at
 io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:443) at
 io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:63) at
 io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:525) at
 io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:446) at
 io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:557) at
 io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) at
 io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:107) at
 java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at
 java.util.concurrent.FutureTask.run(FutureTask.java:266) at
 java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at
 java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at
 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at
 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at
 java.lang.Thread.run(Thread.java:748) Caused by: com.google.cloud.logging.LoggingException: io.grpc.StatusRuntimeException: UNAVAILABLE: Authentication backend unavailable. at com.google.cloud.logging.spi.v2.GrpcLoggingRpc$2.apply(GrpcLoggingRpc.java:155) at
 com.google.cloud.logging.spi.v2.GrpcLoggingRpc$2.apply(GrpcLoggingRpc.java:149) at
 com.google.api.core.ApiFutures$GaxFunctionToGuavaFunction.apply(ApiFutures.java:153) at
 com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:205) at
 com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:193) at
 com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:132)

@pongad my experience with cloud logging is just that, when I'm trying to call logging.write(Collections.singleton(logEntry)), it doesn't seem like its called asynchronously, and it makes 90% of my threads in a BLOCKED state

[pongad]

The method taking 1min to timeout is curious. That's the deadline we set on our RPCs but Logging shouldn't take that long. This might be related to threads being in BLOCKED state; if threads are blocked, they can't service RPC.

Could you share with us the stack trace of the BLOCKED threads?

@garrettjonesgoogle FYI