Context Key not set in gRPC worker thread

[garrettjonesgoogle]

Please answer these questions before submitting your issue.

What version of gRPC are you using?

1.01

What JVM are you using (java -version)?

openjdk version "1.8.0_102"
OpenJDK Runtime Environment (build 1.8.0_102)
OpenJDK 64-Bit Server VM (build 25.102-b01, mixed mode)

What did you do?

If possible, provide a recipe for reproducing the error.

• Turned on FINE logging
• Used the Logging client in google-cloud-java
• Used the code recommended in Deadlock in grpc due to recursive grpc call #2515 to set a Context Key in my main thread

What did you expect to see?

I expected to see the Context Key set in the gRPC worker thread.

What did you see instead?

The key was not set.

Here are the stack traces where I expected it to be set, but it wasn't:

java.lang.Exception
        at com.google.cloud.logging.LoggingHandler.publish(LoggingHandler.java:315)
        at java.util.logging.Logger.log(Logger.java:738)
        at io.netty.util.internal.logging.JdkLogger.log(JdkLogger.java:606)
        at io.netty.util.internal.logging.JdkLogger.debug(JdkLogger.java:186)
        at io.netty.util.internal.logging.AbstractInternalLogger.log(AbstractInternalLogger.java:147)
        at io.netty.handler.codec.http2.Http2FrameLogger.log(Http2FrameLogger.java:183)
        at io.netty.handler.codec.http2.Http2FrameLogger.logSettings(Http2FrameLogger.java:111)
        at io.netty.handler.codec.http2.Http2OutboundFrameLogger.writeSettings(Http2OutboundFrameLogger.java:81)
        at io.netty.handler.codec.http2.DefaultHttp2ConnectionEncoder.writeSettings(DefaultHttp2ConnectionEncoder.java:246)
        at io.netty.handler.codec.http2.DecoratingHttp2FrameWriter.writeSettings(DecoratingHttp2FrameWriter.java:70)
        at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.sendPreface(Http2ConnectionHandler.java:324)
        at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.channelActive(Http2ConnectionHandler.java:224)
        at io.netty.handler.codec.http2.Http2ConnectionHandler.channelActive(Http2ConnectionHandler.java:363)
        at io.grpc.netty.AbstractNettyHandler.channelActive(AbstractNettyHandler.java:78)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:223)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:209)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:202)
        at io.netty.handler.ssl.SslHandler.channelActive(SslHandler.java:1398)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:223)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:209)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:202)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelActive(DefaultChannelPipeline.java:1322)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:223)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:209)
        at io.netty.channel.DefaultChannelPipeline.fireChannelActive(DefaultChannelPipeline.java:902)
        at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:305)
        at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:335)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:588)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:512)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:426)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:398)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:877)
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
        at java.lang.Thread.run(Thread.java:745)

second:

java.lang.Exception
        at com.google.cloud.logging.LoggingHandler.publish(LoggingHandler.java:315)
        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:851)
        at io.grpc.internal.TransportSet.startNewTransport(TransportSet.java:217)
        at io.grpc.internal.TransportSet.obtainActiveTransport(TransportSet.java:192)
        at io.grpc.internal.ManagedChannelImpl$3.getTransport(ManagedChannelImpl.java:637)
        at io.grpc.internal.ManagedChannelImpl$3.getTransport(ManagedChannelImpl.java:579)
        at io.grpc.DummyLoadBalancerFactory$DummyLoadBalancer$1.get(DummyLoadBalancerFactory.java:135)
        at io.grpc.internal.DelayedClientTransport$2.run(DelayedClientTransport.java:262)
        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:295)
        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:745)

[garrettjonesgoogle]

FYI this is a GA-blocker for google-cloud-logging.

[ejona86]

This can't be fixed. The transport code works on multiple RPCs at the same time. In addition, both backtraces you provided don't have to relate to any RPC since they are connection startup.

[garrettjonesgoogle]

Ok I have a general workaround to my grpc-thread-calling-logger-which-calls-grpc woes, which is to have the logger use the bundling feature in GAX, which essentially offloads all grpc logging to a distinct thread from the thread that added the log (don't worry, it uses thread pooling). This means that one-time logs (such as the ones above for establishing the transport) are fine, because they won't repeat. There is only one log left causing a problem:

java.lang.Exception
        at com.google.api.gax.bundling.ThresholdBundler.add(ThresholdBundler.java:161)
        at com.google.api.gax.bundling.ThresholdBundlingForwarder.addToNextBundle(ThresholdBundlingForwarder.java:73)
        at com.google.api.gax.grpc.BundlingCallable.futureCall(BundlingCallable.java:71)
        at com.google.api.gax.grpc.UnaryCallable.futureCall(UnaryCallable.java:238)
        at com.google.api.gax.grpc.UnaryCallable.futureCall(UnaryCallable.java:249)
        at com.google.cloud.logging.spi.DefaultLoggingRpc.write(DefaultLoggingRpc.java:202)
        at com.google.cloud.logging.LoggingImpl.writeAsync(LoggingImpl.java:504)
        at com.google.cloud.logging.LoggingHandler.write(LoggingHandler.java:387)
        at com.google.cloud.logging.LoggingHandler.flush(LoggingHandler.java:412)
        at com.google.cloud.logging.LoggingHandler.publish(LoggingHandler.java:323)
        at java.util.logging.Logger.log(Logger.java:738)
        at io.netty.util.internal.logging.JdkLogger.log(JdkLogger.java:606)
        at io.netty.util.internal.logging.JdkLogger.debug(JdkLogger.java:186)
        at io.netty.util.internal.logging.AbstractInternalLogger.log(AbstractInternalLogger.java:147)
        at io.netty.handler.codec.http2.Http2FrameLogger.log(Http2FrameLogger.java:183)
        at io.netty.handler.codec.http2.Http2FrameLogger.logData(Http2FrameLogger.java:65)
        at io.netty.handler.codec.http2.Http2OutboundFrameLogger.writeData(Http2OutboundFrameLogger.java:43)
        at io.netty.handler.codec.http2.DefaultHttp2ConnectionEncoder$FlowControlledData.write(DefaultHttp2ConnectionEncoder.java:379)
        at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$FlowState.writeAllocatedBytes(DefaultHttp2RemoteFlowController.java:360)
        at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$WritabilityMonitor$1.write(DefaultHttp2RemoteFlowController.java:550)
        at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor$State.write(WeightedFairQueueByteDistributor.java:248)
        at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor.distribute(WeightedFairQueueByteDistributor.java:151)
        at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor.distributeToChildren(WeightedFairQueueByteDistributor.java:183)
        at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor.distribute(WeightedFairQueueByteDistributor.java:130)
        at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$WritabilityMonitor.writePendingBytes(DefaultHttp2RemoteFlowController.java:631)
        at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController.writePendingBytes(DefaultHttp2RemoteFlowController.java:255)
        at io.netty.handler.codec.http2.Http2ConnectionHandler.flush(Http2ConnectionHandler.java:161)
        at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:786)
        at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:778)
        at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:759)
        at io.netty.channel.DefaultChannelPipeline.flush(DefaultChannelPipeline.java:974)
        at io.netty.channel.AbstractChannel.flush(AbstractChannel.java:244)
        at io.grpc.netty.WriteQueue.flush(WriteQueue.java:139)
        at io.grpc.netty.WriteQueue.access$000(WriteQueue.java:49)
        at io.grpc.netty.WriteQueue$1.run(WriteQueue.java:61)
        at io.netty.util.concurrent.SingleThreadEventExecutor.safeExecute(SingleThreadEventExecutor.java:451)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:418)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:401)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:877)
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
        at java.lang.Thread.run(Thread.java:745)

LoggerName: io.grpc.netty.NettyClientHandler
SourceClassName: io.netty.handler.codec.http2.Http2FrameLogger

This is an oddball case - it seems to be some kind of logger class that calls a logger passed into it. Is there a recommended way to turn off frame logging? Or, do I just have to hack around it like this:

  public void publish(LogRecord record) {
      if (record.getSourceClassName().equals("io.netty.handler.codec.http2.Http2FrameLogger")) {
        return;
      }
      ...
  }

I don't necessarily want to turn off all logging from the io.grpc.netty.NettyClientHandler logger, unless this is really the only thing it's ever going to log.

[garrettjonesgoogle]

Some guidance would be helpful here so I could proceed to fix the issue at the google-cloud-java level.

[ejona86]

I'd suggest providing your own event loop to the NettyChannelBuilder used for sending logs and then detect whether you are in that event loop when logging. If you are in the event loop, don't send the log.

There may be other options, but good ones should separate the channel/code used to send logs from the rest of the application.