Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

LogbackAppender logging log doesnt show up in stackdriver #6437

Closed
praveen4463 opened this issue Oct 4, 2019 · 7 comments
Closed

LogbackAppender logging log doesnt show up in stackdriver #6437

praveen4463 opened this issue Oct 4, 2019 · 7 comments
Assignees
Labels
api: logging Issues related to the Cloud Logging API.

Comments

@praveen4463
Copy link

praveen4463 commented Oct 4, 2019

Environment details

  1. Logback Appender for Google Cloud Logging
  2. OS type and version: distroless java image with busybox (https://github.com/GoogleContainerTools/distroless/blob/master/java/README.md)
  3. Java version: 8
  4. google-cloud-java version(s): 0.111.0-alpha

I am using stackdriver Logback loggging but nothing is being logged. Upon getting the thread dump I found lots of threads are waiting indefinitely.
I searched issues and found similar ones that reported similar logs where threads have been waiting indefinitely,
LoggingAppender failure #3478
LoggingHandler hangs the thread #2796

And following seems to have fixed the issue long ago,
Logging: disable severity based flush on write by default #4254

But since the same issue is occurring, it doesn't seems to be fixed (atleast for LogbackAppender). The fix had set default flushSeverity to null from ERROR, but in LogbackAppeneder, it is still set to ERROR. Even if we don't set a flushSeverity, ERROR level is default. I am referring to LogbackAppender.getFlushLevel, should the same fix be applied here?

If I don't use com.google.cloud.logging.logback.LoggingAppender and write logs to console, it gets into stackdriver though (environment GKE).

Below is the thread dump, threads seems to be waiting indefinitely.

"Gax-4" #17 daemon prio=5 os_prio=0 tid=0x00007f6c38c30000 nid=0x17 in Object.wait() [0x00007f6c0b7de000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at java.lang.Object.wait(Object.java:502)
at com.google.api.gax.batching.BlockingSemaphore.acquire(BlockingSemaphore.java:61)
- locked <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at com.google.api.gax.batching.FlowController.reserve(FlowController.java:197)
at com.google.api.gax.batching.BatchingFlowController.reserve(BatchingFlowController.java:58)
at com.google.api.gax.batching.ThresholdBatcher.add(ThresholdBatcher.java:170)
at com.google.api.gax.rpc.BatchingCallable.futureCall(BatchingCallable.java:73)
at com.google.api.gax.rpc.UnaryCallable$1.futureCall(UnaryCallable.java:126)
at com.google.api.gax.rpc.UnaryCallable.futureCall(UnaryCallable.java:87)
at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.write(GrpcLoggingRpc.java:232)
at com.google.cloud.logging.LoggingImpl.writeAsync(LoggingImpl.java:628)
at com.google.cloud.logging.LoggingImpl.writeLogEntries(LoggingImpl.java:596)
at com.google.cloud.logging.LoggingImpl.write(LoggingImpl.java:557)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:215)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:70)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.log(Logger.java:765)
at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:221)
at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:303)
at java.util.logging.Logger.log(Logger.java:738)
at java.util.logging.Logger.doLog(Logger.java:765)
at java.util.logging.Logger.log(Logger.java:876)
at com.google.common.util.concurrent.AggregateFuture$RunningState.handleException(AggregateFuture.java:195)
at com.google.common.util.concurrent.AggregateFuture$RunningState.handleOneInputDone(AggregateFuture.java:234)
at com.google.common.util.concurrent.AggregateFuture$RunningState.access$200(AggregateFuture.java:92)
at com.google.common.util.concurrent.AggregateFuture$RunningState$1.run(AggregateFuture.java:147)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:100)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:109)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
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:1015)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:179)
- locked <0x00000000dad00288> (a java.lang.Object)
at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:135)
- locked <0x00000000dad00288> (a java.lang.Object)
at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:117)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
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:1015)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:515)
at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:490)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399)
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:510)
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:66)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:630)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:518)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:692)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:681)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

"Gax-3" #16 daemon prio=5 os_prio=0 tid=0x00007f6c1c12c800 nid=0x16 in Object.wait() [0x00007f6c08560000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at java.lang.Object.wait(Object.java:502)
at com.google.api.gax.batching.BlockingSemaphore.acquire(BlockingSemaphore.java:61)
- locked <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at com.google.api.gax.batching.FlowController.reserve(FlowController.java:197)
at com.google.api.gax.batching.BatchingFlowController.reserve(BatchingFlowController.java:58)
at com.google.api.gax.batching.ThresholdBatcher.add(ThresholdBatcher.java:170)
at com.google.api.gax.rpc.BatchingCallable.futureCall(BatchingCallable.java:73)
at com.google.api.gax.rpc.UnaryCallable$1.futureCall(UnaryCallable.java:126)
at com.google.api.gax.rpc.UnaryCallable.futureCall(UnaryCallable.java:87)
at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.write(GrpcLoggingRpc.java:232)
at com.google.cloud.logging.LoggingImpl.writeAsync(LoggingImpl.java:628)
at com.google.cloud.logging.LoggingImpl.writeLogEntries(LoggingImpl.java:596)
at com.google.cloud.logging.LoggingImpl.write(LoggingImpl.java:557)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:215)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:70)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.log(Logger.java:765)
at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:221)
at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:303)
at java.util.logging.Logger.log(Logger.java:738)
at java.util.logging.Logger.doLog(Logger.java:765)
at java.util.logging.Logger.log(Logger.java:876)
at com.google.common.util.concurrent.AggregateFuture$RunningState.handleException(AggregateFuture.java:195)
at com.google.common.util.concurrent.AggregateFuture$RunningState.handleOneInputDone(AggregateFuture.java:234)
at com.google.common.util.concurrent.AggregateFuture$RunningState.access$200(AggregateFuture.java:92)
at com.google.common.util.concurrent.AggregateFuture$RunningState$1.run(AggregateFuture.java:147)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:100)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:109)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
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:1015)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:179)
- locked <0x00000000daccec10> (a java.lang.Object)
at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:135)
- locked <0x00000000daccec10> (a java.lang.Object)
at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:117)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
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:1015)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:515)
at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:490)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399)
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:510)
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:66)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:630)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:518)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:692)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:681)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

"grpc-default-worker-ELG-1-2" #15 daemon prio=5 os_prio=0 tid=0x00007f6c0c628000 nid=0x15 in Object.wait() [0x00007f6c08862000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at java.lang.Object.wait(Object.java:502)
at com.google.api.gax.batching.BlockingSemaphore.acquire(BlockingSemaphore.java:61)
- locked <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at com.google.api.gax.batching.FlowController.reserve(FlowController.java:197)
at com.google.api.gax.batching.BatchingFlowController.reserve(BatchingFlowController.java:58)
at com.google.api.gax.batching.ThresholdBatcher.add(ThresholdBatcher.java:170)
at com.google.api.gax.rpc.BatchingCallable.futureCall(BatchingCallable.java:73)
at com.google.api.gax.rpc.UnaryCallable$1.futureCall(UnaryCallable.java:126)
at com.google.api.gax.rpc.UnaryCallable.futureCall(UnaryCallable.java:87)
at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.write(GrpcLoggingRpc.java:232)
at com.google.cloud.logging.LoggingImpl.writeAsync(LoggingImpl.java:628)
at com.google.cloud.logging.LoggingImpl.writeLogEntries(LoggingImpl.java:596)
at com.google.cloud.logging.LoggingImpl.write(LoggingImpl.java:557)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:215)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:70)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.log(Logger.java:765)
at io.grpc.netty.shaded.io.netty.util.internal.logging.LocationAwareSlf4JLogger.log(LocationAwareSlf4JLogger.java:50)
at io.grpc.netty.shaded.io.netty.util.internal.logging.LocationAwareSlf4JLogger.debug(LocationAwareSlf4JLogger.java:122)
at io.grpc.netty.shaded.io.netty.util.internal.logging.AbstractInternalLogger.log(AbstractInternalLogger.java:216)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2FrameLogger.logHeaders(Http2FrameLogger.java:77)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2InboundFrameLogger$1.onHeadersRead(Http2InboundFrameLogger.java:55)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader$2.processFragment(DefaultHttp2FrameReader.java:483)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.readHeadersFrame(DefaultHttp2FrameReader.java:491)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:254)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:160)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2InboundFrameLogger.readFrame(Http2InboundFrameLogger.java:41)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:174)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:378)
at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:438)
at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:505)
at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:444)
at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:283)
at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
at io.grpc.netty.shaded.io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1475)
at io.grpc.netty.shaded.io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1224)
at io.grpc.netty.shaded.io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1271)
at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:505)
at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:444)
at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:283)
at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
at io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1421)
at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
at io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930)
at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:794)
at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:424)
at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:326)
at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)

"grpc-default-worker-ELG-1-1" #13 daemon prio=5 os_prio=0 tid=0x00007f6c0c616800 nid=0x13 runnable [0x00007f6c08a66000]
java.lang.Thread.State: RUNNABLE
at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait0(Native Method)
at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait(Native.java:96)
at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:276)
at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:305)
at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)

"Gax-2" #12 daemon prio=5 os_prio=0 tid=0x00007f6c38bb4800 nid=0x12 in Object.wait() [0x00007f6c08b64000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at java.lang.Object.wait(Object.java:502)
at com.google.api.gax.batching.BlockingSemaphore.acquire(BlockingSemaphore.java:61)
- locked <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at com.google.api.gax.batching.FlowController.reserve(FlowController.java:197)
at com.google.api.gax.batching.BatchingFlowController.reserve(BatchingFlowController.java:58)
at com.google.api.gax.batching.ThresholdBatcher.add(ThresholdBatcher.java:170)
at com.google.api.gax.rpc.BatchingCallable.futureCall(BatchingCallable.java:73)
at com.google.api.gax.rpc.UnaryCallable$1.futureCall(UnaryCallable.java:126)
at com.google.api.gax.rpc.UnaryCallable.futureCall(UnaryCallable.java:87)
at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.write(GrpcLoggingRpc.java:232)
at com.google.cloud.logging.LoggingImpl.writeAsync(LoggingImpl.java:628)
at com.google.cloud.logging.LoggingImpl.writeLogEntries(LoggingImpl.java:596)
at com.google.cloud.logging.LoggingImpl.write(LoggingImpl.java:557)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:215)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:70)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.log(Logger.java:765)
at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:221)
at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:303)
at java.util.logging.Logger.log(Logger.java:738)
at java.util.logging.Logger.doLog(Logger.java:765)
at java.util.logging.Logger.log(Logger.java:876)
at com.google.common.util.concurrent.AggregateFuture$RunningState.handleException(AggregateFuture.java:195)
at com.google.common.util.concurrent.AggregateFuture$RunningState.handleOneInputDone(AggregateFuture.java:234)
at com.google.common.util.concurrent.AggregateFuture$RunningState.access$200(AggregateFuture.java:92)
at com.google.common.util.concurrent.AggregateFuture$RunningState$1.run(AggregateFuture.java:147)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:100)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:109)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
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:1015)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:179)
- locked <0x00000000dad00328> (a java.lang.Object)
at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:135)
- locked <0x00000000dad00328> (a java.lang.Object)
at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:117)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
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:1015)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:515)
at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:490)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399)
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:510)
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:66)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:630)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:518)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:692)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:681)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

"Gax-1" #11 daemon prio=5 os_prio=0 tid=0x00007f6c38a56000 nid=0x11 in Object.wait() [0x00007f6c1b9b0000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at java.lang.Object.wait(Object.java:502)
at com.google.api.gax.batching.BlockingSemaphore.acquire(BlockingSemaphore.java:61)
- locked <0x00000000da41c248> (a com.google.api.gax.batching.BlockingSemaphore)
at com.google.api.gax.batching.FlowController.reserve(FlowController.java:197)
at com.google.api.gax.batching.BatchingFlowController.reserve(BatchingFlowController.java:58)
at com.google.api.gax.batching.ThresholdBatcher.add(ThresholdBatcher.java:170)
at com.google.api.gax.rpc.BatchingCallable.futureCall(BatchingCallable.java:73)
at com.google.api.gax.rpc.UnaryCallable$1.futureCall(UnaryCallable.java:126)
at com.google.api.gax.rpc.UnaryCallable.futureCall(UnaryCallable.java:87)
at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.write(GrpcLoggingRpc.java:232)
at com.google.cloud.logging.LoggingImpl.writeAsync(LoggingImpl.java:628)
at com.google.cloud.logging.LoggingImpl.writeLogEntries(LoggingImpl.java:596)
at com.google.cloud.logging.LoggingImpl.write(LoggingImpl.java:557)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:215)
at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:70)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.log(Logger.java:765)
at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:221)
at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:303)
at java.util.logging.Logger.log(Logger.java:738)
at java.util.logging.Logger.doLog(Logger.java:765)
at java.util.logging.Logger.log(Logger.java:876)
at com.google.common.util.concurrent.AggregateFuture$RunningState.handleException(AggregateFuture.java:195)
at com.google.common.util.concurrent.AggregateFuture$RunningState.handleOneInputDone(AggregateFuture.java:234)
at com.google.common.util.concurrent.AggregateFuture$RunningState.access$200(AggregateFuture.java:92)
at com.google.common.util.concurrent.AggregateFuture$RunningState$1.run(AggregateFuture.java:147)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:100)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:109)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
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:1015)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:179)
- locked <0x00000000dacf1a28> (a java.lang.Object)
at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:135)
- locked <0x00000000dacf1a28> (a java.lang.Object)
at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:117)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
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:1015)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
at io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:515)
at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:490)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399)
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:510)
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:66)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:630)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:518)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:692)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:681)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
@praveen4463
Copy link
Author

Due to this, I am blocked. Please refer a workaround if possible.

@codyoss codyoss added api: logging Issues related to the Cloud Logging API. status: investigating The issue is under investigation, which is determined to be non-trivial. labels Oct 4, 2019
@codyoss codyoss self-assigned this Oct 4, 2019
@codyoss
Copy link
Member

codyoss commented Oct 4, 2019

Hey @praveen4463 thanks for the report. With the given information I am unable to reproduce this issue. It may be possible that your logs are making it to Stackdriver and you are just not seeing them. There is an open issue when using the com.google.cloud.logging.logback.LoggingAppender that the resource.labels.namespace_id and resource.labels.container_name are not being properly sourced.(see #5765 ) Is this by chance your issue? If so your logs would should up if you remove those two filters from your search.

@codyoss codyoss added needs more info This issue needs more information from the customer to proceed. and removed status: investigating The issue is under investigation, which is determined to be non-trivial. labels Oct 4, 2019
@ajaaym
Copy link
Contributor

ajaaym commented Oct 4, 2019

@praveen4463 I think this is happening bcz Logger is being reentrant when ever error occurs in the grpc itself while writing log entries. There is no clear solution as of yet, for you to move forward, you can update your logging configuration to use different logger like console or file based for this classes com.google.api.gax.* & io.grpc.*.

@praveen4463
Copy link
Author

@codyoss @ajaaym Thanks for getting back. I applied configuration changes per @ajaaym, the thread dump now doesn't have references to those classes but the logs still aren't being logged.
Its a spring boot app packged in a container and deployed in a k8s cluster, the updated logback.xml is as following:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <springProfile name="production">
    <appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
      <log>app-zl-wzgp.log</log>
      <flushLevel>INFO</flushLevel>
    </appender>
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
    <root level="INFO">
      <appender-ref ref="STACKDRIVER" />
    </root>
    <logger name="com.google.api.gax" level="ERROR">
      <appender-ref ref="CONSOLE" />
    </logger>
    <logger name="io.grpc" level="ERROR">
      <appender-ref ref="CONSOLE" />
    </logger>
  </springProfile>
  <springProfile name="!production">
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
    <root level="INFO">
		<appender-ref ref="CONSOLE" />
	</root>
  </springProfile>

</configuration>

And here is the latest thread dump

Full thread dump OpenJDK 64-Bit Server VM (25.222-b10 mixed mode):

"DestroyJavaVM" #36 prio=5 os_prio=0 tid=0x00007fc77000d000 nid=0x6 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"http-nio-8080-Acceptor" #34 daemon prio=5 os_prio=0 tid=0x00007fc77016d000 nid=0x28 runnable [0x00007fc73ae64000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
        - locked <0x00000000db3a5e08> (a java.lang.Object)
        at org.apache.tomcat.util.net.NioEndpoint.serverSocketAccept(NioEndpoint.java:463)
        at org.apache.tomcat.util.net.NioEndpoint.serverSocketAccept(NioEndpoint.java:73)
        at org.apache.tomcat.util.net.Acceptor.run(Acceptor.java:95)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-ClientPoller" #33 daemon prio=5 os_prio=0 tid=0x00007fc77016b000 nid=0x27 runnable [0x00007fc73af65000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        - locked <0x00000000db3cbcd0> (a sun.nio.ch.Util$3)
        - locked <0x00000000db3cbcc0> (a java.util.Collections$UnmodifiableSet)
        - locked <0x00000000db3cbba8> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:708)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-10" #32 daemon prio=5 os_prio=0 tid=0x00007fc770169000 nid=0x26 waiting on condition [0x00007fc73b266000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-9" #31 daemon prio=5 os_prio=0 tid=0x00007fc770673800 nid=0x25 waiting on condition [0x00007fc73b367000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-8" #30 daemon prio=5 os_prio=0 tid=0x00007fc770671800 nid=0x24 waiting on condition [0x00007fc73b468000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-7" #29 daemon prio=5 os_prio=0 tid=0x00007fc77066f800 nid=0x23 waiting on condition [0x00007fc73b569000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-6" #28 daemon prio=5 os_prio=0 tid=0x00007fc77066d800 nid=0x22 waiting on condition [0x00007fc73b66a000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-5" #27 daemon prio=5 os_prio=0 tid=0x00007fc7702a6000 nid=0x21 waiting on condition [0x00007fc73b76b000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-4" #26 daemon prio=5 os_prio=0 tid=0x00007fc7702a4000 nid=0x20 waiting on condition [0x00007fc73b86c000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-3" #25 daemon prio=5 os_prio=0 tid=0x00007fc7702a2000 nid=0x1f waiting on condition [0x00007fc73b96d000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-2" #24 daemon prio=5 os_prio=0 tid=0x00007fc7702a0800 nid=0x1e waiting on condition [0x00007fc73ba6e000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-exec-1" #23 daemon prio=5 os_prio=0 tid=0x00007fc77029f000 nid=0x1d waiting on condition [0x00007fc73bb6f000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db3bec48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-BlockPoller" #22 daemon prio=5 os_prio=0 tid=0x00007fc77109d800 nid=0x1c runnable [0x00007fc7605c9000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        - locked <0x00000000db3a6a20> (a sun.nio.ch.Util$3)
        - locked <0x00000000db3a69a8> (a java.util.Collections$UnmodifiableSet)
        - locked <0x00000000db3a6840> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBlockingSelector.java:313)

"container-0" #21 prio=5 os_prio=0 tid=0x00007fc7711bc800 nid=0x1b waiting on condition [0x00007fc73c070000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at org.apache.catalina.core.StandardServer.await(StandardServer.java:570)
        at org.springframework.boot.web.embedded.tomcat.TomcatWebServer$1.run(TomcatWebServer.java:179)

"Catalina-utility-2" #20 prio=1 os_prio=0 tid=0x00007fc7711bb000 nid=0x1a waiting on condition [0x00007fc73c171000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db477a28> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"Catalina-utility-1" #19 prio=1 os_prio=0 tid=0x00007fc7711ba000 nid=0x19 waiting on condition [0x00007fc73cd3e000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000db477a28> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

"Gax-4" #17 daemon prio=5 os_prio=0 tid=0x00007fc7580b9000 nid=0x17 waiting on condition [0x00007fc73d03f000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d974f898> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

"Gax-3" #16 daemon prio=5 os_prio=0 tid=0x00007fc74c002000 nid=0x16 waiting on condition [0x00007fc73d140000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d974f898> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

"grpc-default-worker-ELG-1-2" #15 daemon prio=5 os_prio=0 tid=0x00007fc7500de800 nid=0x15 runnable [0x00007fc73e442000]
   java.lang.Thread.State: RUNNABLE
        at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait0(Native Method)
        at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait(Native.java:96)
        at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:276)
        at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:305)
        at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
        at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)

"grpc-default-worker-ELG-1-1" #13 daemon prio=5 os_prio=0 tid=0x00007fc750203800 nid=0x13 runnable [0x00007fc73e644000]
   java.lang.Thread.State: RUNNABLE
        at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait0(Native Method)
        at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait(Native.java:96)
        at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:276)
        at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:305)
        at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
        at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)

"Gax-2" #12 daemon prio=5 os_prio=0 tid=0x00007fc770ce5800 nid=0x12 waiting on condition [0x00007fc73e745000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d974f898> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

"Gax-1" #11 daemon prio=5 os_prio=0 tid=0x00007fc770af0000 nid=0x11 waiting on condition [0x00007fc7747e7000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d974f898> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007fc7700b5800 nid=0xd runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fc7700b2800 nid=0xc waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fc7700b0000 nid=0xb waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fc7700ae800 nid=0xa waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fc77007d000 nid=0x9 in Object.wait() [0x00007fc775178000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000d97de8f0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
        - locked <0x00000000d97de8f0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fc77007a800 nid=0x8 in Object.wait() [0x00007fc775279000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000d97deaa8> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        - locked <0x00000000d97deaa8> (a java.lang.ref.Reference$Lock)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"VM Thread" os_prio=0 tid=0x00007fc770071000 nid=0x7 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007fc7700b8800 nid=0xe waiting on condition 

JNI global references: 1409

Heap
 def new generation   total 157376K, used 5018K [0x00000000c6200000, 0x00000000d0cc0000, 0x00000000d96a0000)
  eden space 139904K,   3% used [0x00000000c6200000, 0x00000000c66e6ab0, 0x00000000ceaa0000)
  from space 17472K,   0% used [0x00000000ceaa0000, 0x00000000ceaa0000, 0x00000000cfbb0000)
  to   space 17472K,   0% used [0x00000000cfbb0000, 0x00000000cfbb0000, 0x00000000d0cc0000)
 tenured generation   total 349568K, used 35661K [0x00000000d96a0000, 0x00000000eec00000, 0x0000000100000000)
   the space 349568K,  10% used [0x00000000d96a0000, 0x00000000db9737c0, 0x00000000db973800, 0x00000000eec00000)
 Metaspace       used 56842K, capacity 59168K, committed 59416K, reserved 1101824K
  class space    used 7230K, capacity 7668K, committed 7720K, reserved 1048576K

There is nothing else, I am using SLF4J facade to get a Logger and invoking logging methods. Per my configuration the logs should go to app-zl-wzgp.log under Global resource but nothing is being logged.

To guarantee that there is a problem, I had also tried changing the root and flushLevel to DEBUG but didn't see any logs recorded under all kubernetes components or Global resource. (@codyoss I removed those 2 filters in container logs but still didn't see logs, anyway the logs should go to Global>app-zl-wzgp.log). I then put a Console appender together with STACKDRIVER appender under production profile config. Now, as expected all the logs correctly logged into stackdriver which proved when only STACKDRIVER appender is used, nothing is getting into stackdriver but writing to stdout in GKE going into stackdriver (which is the correct behaviour).

@ajaaym ajaaym changed the title LogbackAppender logging can't log to stackdriver, threads wait indefinitely LogbackAppender logging log doesnt show up in stackdriver Oct 4, 2019
@codyoss
Copy link
Member

codyoss commented Oct 4, 2019

@praveen4463 Thanks for the reply. If it is not too much trouble do you think you could throw together a small example repo showing how to reproduce this? Given what you said I tried to boil it down to the following:

package com.example.helloworld;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
public class HelloworldApplication {
	Logger log = LoggerFactory.getLogger(HelloworldApplication.class);

	@RestController
	class HelloworldController {
		@GetMapping("/")
		String hello() {
			log.error("Testing Logback error level standard");
			return "Testing!";
		}
	}

	public static void main(String[] args) {
		SpringApplication.run(HelloworldApplication.class, args);
	}
}

My logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
        <log>app-zl-wzgp.log</log>
        <flushLevel>INFO</flushLevel>
    </appender>
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
    <root level="INFO">
        <appender-ref ref="STACKDRIVER" />
    </root>
</configuration>

Here is what I see in Stackdriver logs:

Screen Shot 2019-10-04 at 1 03 08 PM

Is there something different that you are doing to reproduce this?

@yoshi-automation yoshi-automation added the triage me I really want to be triaged. label Oct 4, 2019
@praveen4463
Copy link
Author

praveen4463 commented Oct 6, 2019

@codyoss Thank you for testing it. It turns out that my logs were loading correctly in stackdriver but with a resourceType that was unknown to me. I was checking them under resource.type="k8s_container" and resource.type="global" whereas they were under resource.type="container". The "container" resource type was taken automatically by logging agent because I didn't provide an explicit resourceType.

I noticed that you used textPayload as filter which helped me find the logs. I used it and searched a term that should've logged had something been logged into stackdriver. It returned me some logs and I found their resourceType was "container".

I added a resourceType to logback.xml as <resourceType>global</resourceType>. Now I can see the logs under Global. Thanks very much and sorry for troubling you.


If you don't mind, just one more thing as we're on it. Today I added a LoggingEventEnhancer to the appender and found that nothing gets logged If I use it. On the other hand, if I use a LoggingEnhancer, logs are getting into stackdriver correctly. Is that a known issue cause I couldn't find a related issue to LoggingEventEnhancer?

Here is the implementation of LoggingEventEnhancer that stopped logs from getting into stackdriver,

public class DefaultLoggingEventEnhancer implements LoggingEventEnhancer {
  
  private static final String LABEL_REGEX = "[a-zA-Z0-9-_.]+";
  
  @Override
  public void enhanceLogEntry(LogEntry.Builder builder, ILoggingEvent iLoggingEvent) {
    if (iLoggingEvent.getThreadName() != null && iLoggingEvent.getThreadName().matches(LABEL_REGEX)) {
      builder.addLabel("thread", iLoggingEvent.getThreadName());
    }
  }
}

this remains the same even if I use a simple implementation like,

  @Override
  public void enhanceLogEntry(LogEntry.Builder builder, ILoggingEvent iLoggingEvent) {
    builder.addLabel("thread", "thread-1");
  }


And here is the implementation of LoggingEnhancer that let logs correctly get into stackdriver,

public class DefaultLoggingEnhancer implements LoggingEnhancer {
  @Override
  public void enhanceLogEntry(LogEntry.Builder builder) {
    builder.addLabel("thread", "unknown");
  }
}

Here is the LoggingAppender with enhancer in my logback.xml,

<appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
      <log>app-zl-wzgp.log</log>
      <resourceType>global</resourceType>
      <flushLevel>INFO</flushLevel>

      <!-- When this is applied, no logs are recorded -->
      <!--<enhancer>com.zylitics.wzgp.logging.DefaultLoggingEventEnhancer</enhancer>-->
       
      <!-- When this is applied, logs are correctly recorded -->
      <!--<enhancer>com.zylitics.wzgp.logging.DefaultLoggingEnhancer</enhancer>-->
    </appender>

Would really appreciate if you shed some light over this, I'd prefer to use LoggingEventEnhancer because it provides ILoggingEvent.

@codyoss
Copy link
Member

codyoss commented Oct 6, 2019

Glad I could help.

I think this is what you are looking for. If you have further trouble feel free to open another issue.

<loggingEventEnhancer>com.zylitics.wzgp.logging.DefaultLoggingEventEnhancer</loggingEventEnhancer>

@codyoss codyoss closed this as completed Oct 6, 2019
@codyoss codyoss removed needs more info This issue needs more information from the customer to proceed. triage me I really want to be triaged. labels Oct 6, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api: logging Issues related to the Cloud Logging API.
Projects
None yet
Development

No branches or pull requests

4 participants