Grpc-java: 'channelLogger' is already in use when updating from 1.23.x to 1.24.x

[bsideup]

What version of gRPC-Java are you using?

1.124.0

What is your environment?

Mac OS X
Java 11

What did you expect to see?

No error

What did you see instead?

java.lang.IllegalArgumentException: 'channelLogger' is already in use

io.netty.channel.ChannelPipelineException: io.grpc.netty.ProtocolNegotiators$WaitUntilActiveHandler.handlerAdded() has thrown an exception; removed.
    at io.netty.channel.DefaultChannelPipeline.callHandlerAdded0(DefaultChannelPipeline.java:624)
    at io.netty.channel.DefaultChannelPipeline.addBefore(DefaultChannelPipeline.java:269)
    at io.netty.channel.DefaultChannelPipeline.addBefore(DefaultChannelPipeline.java:237)
    at io.grpc.netty.WriteBufferingAndExceptionHandler.handlerAdded(WriteBufferingAndExceptionHandler.java:59)
    at io.netty.channel.AbstractChannelHandlerContext.callHandlerAdded(AbstractChannelHandlerContext.java:956)
    at io.netty.channel.DefaultChannelPipeline.callHandlerAdded0(DefaultChannelPipeline.java:609)
    at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:223)
    at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:381)
    at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:370)
    at io.grpc.netty.NettyServerTransport.start(NettyServerTransport.java:147)
    at io.grpc.netty.NettyServer$1.initChannel(NettyServer.java:231)
    at io.netty.channel.ChannelInitializer.initChannel(ChannelInitializer.java:129)
    at io.netty.channel.ChannelInitializer.handlerAdded(ChannelInitializer.java:112)
    at io.netty.channel.AbstractChannelHandlerContext.callHandlerAdded(AbstractChannelHandlerContext.java:956)
    at io.netty.channel.DefaultChannelPipeline.callHandlerAdded0(DefaultChannelPipeline.java:609)
    at io.netty.channel.DefaultChannelPipeline.access$100(DefaultChannelPipeline.java:46)
    at io.netty.channel.DefaultChannelPipeline$PendingHandlerAddedTask.execute(DefaultChannelPipeline.java:1463)
    at io.netty.channel.DefaultChannelPipeline.callHandlerAddedForAllHandlers(DefaultChannelPipeline.java:1115)
    at io.netty.channel.DefaultChannelPipeline.invokeHandlerAddedIfNeeded(DefaultChannelPipeline.java:650)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.register0(AbstractChannel.java:502)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.access$200(AbstractChannel.java:417)
    at io.netty.channel.AbstractChannel$AbstractUnsafe$1.run(AbstractChannel.java:474)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.lang.ExceptionInInitializerError: null
    at io.grpc.netty.ProtocolNegotiators.negotiationLogger(ProtocolNegotiators.java:82)
    at io.grpc.netty.ProtocolNegotiators.negotiationLogger(ProtocolNegotiators.java:78)
    at io.grpc.netty.ProtocolNegotiators$ProtocolNegotiationHandler.handlerAdded(ProtocolNegotiators.java:667)
    at io.netty.channel.AbstractChannelHandlerContext.callHandlerAdded(AbstractChannelHandlerContext.java:956)
    at io.netty.channel.DefaultChannelPipeline.callHandlerAdded0(DefaultChannelPipeline.java:609)
    ... 28 common frames omitted
Caused by: java.lang.IllegalArgumentException: 'channelLogger' is already in use
    at io.netty.util.ConstantPool.createOrThrow(ConstantPool.java:109)
    at io.netty.util.ConstantPool.newInstance(ConstantPool.java:91)
    at io.netty.util.AttributeKey.newInstance(AttributeKey.java:55)
    at io.grpc.netty.NettyClientTransport.<clinit>(NettyClientTransport.java:70)
    ... 33 common frames omitted

Steps to reproduce the bug

1. Clone https://github.com/bsideup/liiklus
2. Edit AbstractIntegrationTest in app/src/test/java and set useGrpc to true
3. Run SmokeTest either by delegating to Gradle in your IDE or with Gradle

[creamsoup]

the exception can only happen if theNettyClientTransport's static block is evaluated twice.
~I am not sure what caused that but i verified it via~

    static final AtomicBoolean block = new AtomicBoolean();

    @Test
    public void testNullKey() throws Exception {
      if (block.compareAndSet(false, true)) {
        return;
      }
      // original test case
      // ...
    }

~now that specific test passes.~
~my guess is one of the transient dependency mess with classloader.~

oops ignore previous message, but the problem is the static block is evaluated more than one time. also noticed that the test is executed multiple times.

[creamsoup]

this is most likely due to your test environment.

in 1.24.0, we added a handler that access NettyClientTransport.LOGGER_KEY in ProtocolNegotiators. in your test code, the static constant is evaluated twice which shouldn't happen. make sure the static variable is evaluated only once (this is likely from some messed up class loader reevaluate the io.grpc.netty.NettyClientTransport but caches netty classes (io.netty.*).

[bsideup]

@creamsoup you call it "messed up", I call it "ClassLoader isolation" 😜

There are indeed two separate ClassLoaders for gRPC - once inside the application under test, and another one to test the application.
They do share common Netty but I would not expect it to fail. I can easily see pluggable system (or OSGI) where different components use different versions of gRPC but Netty is provided by the core.

Since the logger key does not seem to be that critical, perhaps you can gracefully handle such situation?

Thanks!

[creamsoup]

oops sorry to call it messed up 😉

I believe throwing is the right behavior because applications can pass their own attributes with the same key. In this case, two same name keys most likely will have two different class types, therefore it can cause runtime exception. Gracefully handling this is error prone.

The io.netty.util.ConstantPool is from netty common artifact, that's why I think the netty common is not isolated. If those two class loaders load their own io.netty.util.ConstantPool, the issue should be gone.

[bsideup]

@creamsoup no problem :)

If those two class loaders load their own io.netty.util.ConstantPool, the issue should be gone.

I would like to mention that (unlike gRPC), Netty requires some native dependencies that cannot be isolated with classloaders. Also, as a high performant framework, it is better to reuse the global resources created by Netty. As much as I would like to not have it shared, it is almost impossible.

applications can pass their own attributes with the same key

Can the key be randomized or include the classloader's id?

[creamsoup]

Can the key be randomized or include the classloader's id?

if there is a really good reason to do so, but purely for a very specific test scenario is not a very compelling reason.

[ejona86]

This is a problem. At the very least it would break using grpc-netty and grpc-netty-shaded at the same time. Note that even without shading it is possible to load gRPC multiple times, simultaneously, from different class loaders as done in the test. We would want that to work.

To make sure "it is only us" using the AttributeKey we should use NettyClientTransport.class.getName() to make sure it is "unique to us." But we will need to coordinate with other instances of our classes (from other class loaders) to re-use instances. This is needed for two reasons:

1. To become truly unique JVM-wide, we'd have to include something unique about our ClassLoader in the name, which seems pretty hacky
2. We only want to create one instance of the AttributeKey. The ConstantPool allocates an integer for each to use a compact array, so we don't want to inflate the index

Since gRPC controls the Netty Channel, it looks safe to share the AttributeKey with other gRPC instances in other class loaders; there is no way for them to mix.

But even better: we should consider deleting the attribute. It is only used by ProtocolNegotiators, which already has access to GrpcHttp2ConnectionHandler. We could just add method to GrpcHttp2ConnectionHandler instead, which would be explicit.

[bsideup]

To become truly unique JVM-wide, we'd have to include something unique about our ClassLoader in the name, which seems pretty hacky

Singletons/constants are per-classloader. You can generate a random key and it will be constant, but only for this classloader.

[ejona86]

You can generate a random key and it will be constant, but only for this classloader.

Ah, yes, true.

Edit: Ah, yes, I also see a mention of something like that in #7048. "If this causes issues, this AttributeKey should be updated to use a new UUID (or something) each time it is loaded." I hadn't gotten to reading that yet :)

[ejona86]

At the very least it would break using grpc-netty and grpc-netty-shaded at the same time.

I realized this isn't actually true, because netty-shaded has a separate copy of Netty and thus a different static pool!

Still, we do need to work in ClassLoader environments like this.