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

'channelLogger' is already in use when updating from 1.23.x to 1.24.x #6707

Closed
bsideup opened this issue Feb 13, 2020 · 10 comments · Fixed by #7048
Closed

'channelLogger' is already in use when updating from 1.23.x to 1.24.x #6707

bsideup opened this issue Feb 13, 2020 · 10 comments · Fixed by #7048
Assignees
Labels
Milestone

Comments

@bsideup
Copy link

bsideup commented Feb 13, 2020

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
@bsideup bsideup added the bug label Feb 13, 2020
@creamsoup creamsoup self-assigned this Feb 14, 2020
@creamsoup
Copy link
Contributor

creamsoup commented Feb 14, 2020

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
Copy link
Contributor

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
Copy link
Author

bsideup commented Feb 14, 2020

@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
Copy link
Contributor

creamsoup commented Feb 14, 2020

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
Copy link
Author

bsideup commented Feb 15, 2020

@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
Copy link
Contributor

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 ejona86 closed this as completed Feb 25, 2020
@ejona86 ejona86 reopened this May 19, 2020
@ejona86 ejona86 added this to the Next milestone May 19, 2020
@ejona86
Copy link
Member

ejona86 commented May 19, 2020

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
Copy link
Author

bsideup commented May 19, 2020

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
Copy link
Member

ejona86 commented May 19, 2020

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
Copy link
Member

ejona86 commented May 21, 2020

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.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
3 participants