Logging write can cause OOMs and log spam

[rockwotj]

Environment details

2. OS type and version: Linux & GKE
3. Java version: 11.0.13
4. version(s): v3.6.4

Details

Due to google/guava#2134 when flushing the logs here:

java-logging/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java

Line 883 in 7f7f488

ApiFutures.allAsList(writesToFlush).get(FLUSH_WAIT_TIMEOUT_SECONDS, TimeUnit.SECONDS);

(which calls Futures.allAsList here)

Causes logs to get flushed again (because a failure causes logging here. So more logs are buffered in memory due to the spam and our tasks OOM. I understand from #33 it is desired to allow tasks to OOM if there are logging failures, but failures in logging should not add fuel to the fire here by adding more log entries.

google/guava#2134 (comment) suggests that the following code should be replaced with:

whenAllSucceed(futures).callAsync(() -> allAsList(futures));

But since this library is indirectly using Guava Futures, whenAllSucceed also needs to be added to ApiFutures first.

Stack trace

com.google.common.util.concurrent.AggregateFuture: Got more than one input Future failure. Logging failures after the first
com.google.cloud.logging.LoggingException: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 8.732909168s. [closed=[], open=[[remote_addr=logging.googleapis.com/142.250.125.95:443]]]
	at com.google.cloud.logging.spi.v2.GrpcLoggingRpc$2.apply(GrpcLoggingRpc.java:208)
	at com.google.cloud.logging.spi.v2.GrpcLoggingRpc$2.apply(GrpcLoggingRpc.java:202)
	at com.google.api.core.ApiFutures$ApiFunctionToGuavaFunction.apply(ApiFutures.java:240)
	at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:234)
	at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:222)
	at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:133)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1277)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:1038)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:808)
	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:84)
	at com.google.api.gax.rpc.BatchExecutor$1.onFailure(BatchExecutor.java:98)
	at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:68)
	at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1133)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1277)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:1038)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:808)
	at com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:200)
	at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:135)
	at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:117)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1277)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:1038)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:808)
	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.onFailure(GrpcExceptionCallable.java:97)
	at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:68)
	at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1133)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1277)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:1038)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:808)
	at io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:564)
	at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:534)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:562)
	at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:70)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:743)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:722)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.google.api.gax.rpc.DeadlineExceededException: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 8.732909168s. [closed=[], open=[[remote_addr=logging.googleapis.com/142.250.125.95:443]]]
	at com.google.api.gax.rpc.ApiExceptionFactory.createException(ApiExceptionFactory.java:49)
	at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:72)
	at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:60)
	... 18 more
Caused by: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 8.732909168s. [closed=[], open=[[remote_addr=logging.googleapis.com/142.250.125.95:443]]]
	at io.grpc.Status.asRuntimeException(Status.java:535)
	... 10 more

[PatrykGala]

As a workaround we disabled the logger in: AggregateFuture

    <logger name="com.google.common.util.concurrent.AggregateFuture" level="OFF"/>
    <logger name="com.google.common.util.concurrent.AggregateFuture$RunningState" level="OFF"/>

(I im not sure the second line is required)

[meredithslota]

Hi there — thanks for reporting this. There was also an internal bug filed and through that bug we discovered that the issue is actually related to googleapis/sdk-platform-java#1317 which is still pending.

[cindy-peng]

Looks like the related issue is still pending: googleapis/sdk-platform-java#1317
Will update this issue once we get more progress on the pending issue.