PulsarClient.builder() extremely long error logger

Question

I am trying to make a pulsar client written in java, however I get an error with the logger(slf4j). I thought that it was because my PropertyConfigurator was badly made, but even if I use the defaultConfigurator I get the same extremely long error... It breaks when I'm trying to make my PulsarClient as so:

this.client = PulsarClient.builder()
              .serviceUrl(config.get("target"))
              .authentication(AuthenticationFactory.token(token))
              .build();

The error I get:

main DEBUG logging.InternalLoggerFactory - Using SLF4J as the default logging framework
 main DEBUG internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
 main DEBUG internal.PlatformDependent0 - Java version: 11
 main DEBUG internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
 main DEBUG internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
 main DEBUG internal.PlatformDependent0 - java.nio.Buffer.address: available
 main DEBUG internal.PlatformDependent0 - direct buffer constructor: unavailable
 java.lang.UnsupportedOperationException: Reflective setAccessible(true) disabled
        at org.apache.pulsar.shade.io.netty.util.internal.ReflectionUtil.trySetAccessible(ReflectionUtil.java:31)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent0$4.run(PlatformDependent0.java:233)
        at java.base/java.security.AccessController.doPrivileged(Native Method)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:227)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:289)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:92)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Native.loadNativeLibrary(Native.java:247)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Native.<clinit>(Native.java:69)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Epoll.<clinit>(Epoll.java:39)
        at org.apache.pulsar.common.util.netty.EventLoopUtil.newEventLoopGroup(EventLoopUtil.java:46)
        at org.apache.pulsar.client.impl.PulsarClientImpl.getEventLoopGroup(PulsarClientImpl.java:743)
        at org.apache.pulsar.client.impl.PulsarClientImpl.<init>(PulsarClientImpl.java:129)
        at org.apache.pulsar.client.impl.ClientBuilderImpl.build(ClientBuilderImpl.java:64)
        at demo.demo_user.main(demo_user.java:34)
main DEBUG internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
 main DEBUG internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable
 java.lang.IllegalAccessException: class org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent0$6 cannot access class jdk.internal.misc.Unsafe (in module java.base) because module java.base does not export jdk.internal.misc to unnamed module @33cb5951
        at java.base/jdk.internal.reflect.Reflection.newIllegalAccessException(Reflection.java:361)
        at java.base/java.lang.reflect.AccessibleObject.checkAccess(AccessibleObject.java:591)
        at java.base/java.lang.reflect.Method.invoke(Method.java:558)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent0$6.run(PlatformDependent0.java:347)
        at java.base/java.security.AccessController.doPrivileged(Native Method)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:338)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:289)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:92)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Native.loadNativeLibrary(Native.java:247)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Native.<clinit>(Native.java:69)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Epoll.<clinit>(Epoll.java:39)
        at org.apache.pulsar.common.util.netty.EventLoopUtil.newEventLoopGroup(EventLoopUtil.java:46)
        at org.apache.pulsar.client.impl.PulsarClientImpl.getEventLoopGroup(PulsarClientImpl.java:743)
        at org.apache.pulsar.client.impl.PulsarClientImpl.<init>(PulsarClientImpl.java:129)
        at org.apache.pulsar.client.impl.ClientBuilderImpl.build(ClientBuilderImpl.java:64)
        at demo.demo_user.main(demo_user.java:34)
main DEBUG internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): unavailable
 main DEBUG internal.PlatformDependent - sun.misc.Unsafe: available
 main DEBUG internal.PlatformDependent - maxDirectMemory: 4148166656 bytes (maybe)
 main DEBUG internal.PlatformDependent - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
 main DEBUG internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
 main DEBUG internal.PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes
 main DEBUG internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
 main DEBUG internal.CleanerJava9 - java.nio.ByteBuffer.cleaner(): available
 main DEBUG internal.PlatformDependent - -Dio.netty.noPreferDirect: false
 main DEBUG internal.NativeLibraryLoader - -Dio.netty.native.workdir: /tmp (io.netty.tmpdir)
 main DEBUG internal.NativeLibraryLoader - -Dio.netty.native.deleteLibAfterLoading: true
 main DEBUG internal.NativeLibraryLoader - -Dio.netty.native.tryPatchShadedId: true
 main DEBUG internal.NativeLibraryLoader - Unable to load the library 'org_apache_pulsar_shade_netty_transport_native_epoll_x86_64', trying other loading mechanism.
 java.lang.UnsatisfiedLinkError: no org_apache_pulsar_shade_netty_transport_native_epoll_x86_64 in java.library.path: [/usr/java/packages/lib, /usr/lib/x86_64-linux-gnu/jni, /lib/x86_64-linux-gnu, /usr/lib/x86_64-linux-gnu, /usr/lib/jni, /lib, /usr/lib]
        at java.base/java.lang.ClassLoader.loadLibrary(ClassLoader.java:2673)
        at java.base/java.lang.Runtime.loadLibrary0(Runtime.java:830)
        at java.base/java.lang.System.loadLibrary(System.java:1873)
        at org.apache.pulsar.shade.io.netty.util.internal.NativeLibraryUtil.loadLibrary(NativeLibraryUtil.java:38)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.apache.pulsar.shade.io.netty.util.internal.NativeLibraryLoader$1.run(NativeLibraryLoader.java:371)

(etc...) I have the good dependencies in the pom.xml, but I don't understand what is exactly breaking as the client is initializing... My log4j.properties is a basic one

 log4j.rootLogger=debug, stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%t %-5p %c{2} - %m%n

So I'm asking if anyone knows what is going on with it ? I thought that it may be a connection error but I'm not sure how to resolve the problem. Thank you in advance.

Which version of Apache Pulsar are you using? It seems that at least version 2.3.0 is required to run with Java 11 and later and to me your problem indicates that your are still using an earlier version of Apache Pulsar. — Thomas Kläger, Sep 24 '22 at 19:24

Thomas Kläger · Accepted Answer · 2022-09-25T09:17:44.503

Upon further investigation these seem to be debug level outputs from the startup of the pulsar client.

For example, the first stacktrace with the preceding message

 main DEBUG internal.PlatformDependent0 - direct buffer constructor: unavailable
 java.lang.UnsupportedOperationException: Reflective setAccessible(true) disabled
        at org.apache.pulsar.shade.io.netty.util.internal.ReflectionUtil.trySetAccessible(ReflectionUtil.java:31)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent0$4.run(PlatformDependent0.java:233)
        at java.base/java.security.AccessController.doPrivileged(Native Method)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:227)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:289)
        at org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:92)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Native.loadNativeLibrary(Native.java:247)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Native.<clinit>(Native.java:69)
        at org.apache.pulsar.shade.io.netty.channel.epoll.Epoll.<clinit>(Epoll.java:39)
        at org.apache.pulsar.common.util.netty.EventLoopUtil.newEventLoopGroup(EventLoopUtil.java:46)
        at org.apache.pulsar.client.impl.PulsarClientImpl.getEventLoopGroup(PulsarClientImpl.java:743)
        at org.apache.pulsar.client.impl.PulsarClientImpl.<init>(PulsarClientImpl.java:129)
        at org.apache.pulsar.client.impl.ClientBuilderImpl.build(ClientBuilderImpl.java:64)
        at demo.demo_user.main(demo_user.java:34)

is produced by the following source code lines (https://github.com/netty/netty/blob/netty-4.1.51.Final/common/src/main/java/io/netty/util/internal/PlatformDependent0.java#L261)

            if (maybeDirectBufferConstructor instanceof Constructor<?>) {
                address = UNSAFE.allocateMemory(1);
                // try to use the constructor now
                try {
                    ((Constructor<?>) maybeDirectBufferConstructor).newInstance(address, 1);
                    directBufferConstructor = (Constructor<?>) maybeDirectBufferConstructor;
                    logger.debug("direct buffer constructor: available");
                } catch (InstantiationException e) {
                    directBufferConstructor = null;
                } catch (IllegalAccessException e) {
                    directBufferConstructor = null;
                } catch (InvocationTargetException e) {
                    directBufferConstructor = null;
                }
            } else {
                logger.debug(
                        "direct buffer constructor: unavailable",
                        (Throwable) maybeDirectBufferConstructor);
                directBufferConstructor = null;
            }

The following lines are also debug level output from the initialization of this class (io.netty.util.internal.PlatformDependent0).

All this output comes from Netty, a library that Apache Pulsar uses internally.

Netty is testing various features of the used JVM (whether the feature is available or not) and is configuring itself accordingly so that it works properly and has the best possible performance.

What does that Reflective setAccessible(true) disabled mean?

It means that Netty tried to call java.lang.reflect.Constructor.setAccessible() (in this particular case on a constructor for java.nio.DirectByteBuffer) and the JVM did not allow this operation.

This in the end probably means that Netty cannot use DirectByteBuffer for some of its operations. But since this is a known possibility it will use some other means for its operations and therefore its nothing that you need to worry about.

(If you don't trust me then you can still dive into the internals of Apache Polar and Netty. But both projects are actively supported even on recent Java versions and therefore you should maybe trust the maintainers of those projects that they do everything to keep them working.)

If you don't want to see this debug output you have a few options:

completely disable debug level output: log4j.rootLogger=info, stdout
disable debug level output for everything from Apache Pulsar:

add log4j.logger.org.apache.pulsar=info to the log4.properties
disable debug level output for this class PlatformDependent0:

add log4j.logger.org.apache.pulsar.shade.io.netty.util.internal.PlatformDependent0=info to the log4.properties

So it means that pulsar catches an illegal connection ? Or its another thing ? Moreover do you know what the « setAccessible(true) disabled » means ? Is it an indicator that pulsar doesn’t allow connection because it broke when it opened ? — azonymous, Sep 24 '22 at 22:20
@azonymous all this happens during startup - long before the first connection is accepted. This are all internal tests for some features of the JVM that you don't need to worry about. See my updated answer. — Thomas Kläger, Sep 25 '22 at 09:19

PulsarClient.builder() extremely long error logger

1 Answers1