Order of initialization in Java: exception with Netty 4.0.7

Question

I am hitting a problem with Netty at class initialization. I thought static fields are always initialized before instance fields but apparently this is not the case:

Class AbstractByteBuff contains a static final ResourceLeakDetector<ByteBuf> leakDetector
Class AbstractReferenceCountedByteBuf extends AbstractByteBuff
Class UnpooledUnsafeDirectByteBuf extends AbstractReferenceCountedByteBuf

The first time an UnpooledUnsafeDirectByteBuf is created, a Null Pointer Exception is thrown in its constructor:

protected UnpooledUnsafeDirectByteBuf(ByteBufAllocator alloc, int initialCapacity, int maxCapacity) {
        super(maxCapacity);
        if (alloc == null) {
            throw new NullPointerException("alloc");
        }
        if (initialCapacity < 0) {
            throw new IllegalArgumentException("initialCapacity: " + initialCapacity);
        }
        if (maxCapacity < 0) {
            throw new IllegalArgumentException("maxCapacity: " + maxCapacity);
        }
        if (initialCapacity > maxCapacity) {
            throw new IllegalArgumentException(String.format(
                    "initialCapacity(%d) > maxCapacity(%d)", initialCapacity, maxCapacity));
        }

        this.alloc = alloc;
        setByteBuffer(ByteBuffer.allocateDirect(initialCapacity));
        leak = leakDetector.open(this);
    }

The exception is thrown from the code leak = leakDetector.open(this); . By inspecting with intellij Idea I have found out that the leakDetector variable is null. How this is possible? It's a static variable initialized in the superclass of the superclass of the current class.

The source code is available on Github, all the classes which raise the problem are available in the following package: https://github.com/netty/netty/tree/master/buffer/src/main/java/io/netty/buffer

The three sources are the following :

https://github.com/netty/netty/blob/master/buffer/src/main/java/io/netty/buffer/UnpooledUnsafeDirectByteBuf.java

https://github.com/netty/netty/blob/master/buffer/src/main/java/io/netty/buffer/AbstractReferenceCountedByteBuf.java

https://github.com/netty/netty/blob/master/buffer/src/main/java/io/netty/buffer/AbstractByteBuf.java

This last one, AbstractByteBuff, contains the leakDetector.

Please note I am not compiling the sources but just linking to Netty 4.0.7 final. Here the stackTrace:

o.netty.handler.codec.EncoderException: java.lang.NullPointerException
    at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:131)
    at io.netty.channel.DefaultChannelHandlerContext.invokeWrite(DefaultChannelHandlerContext.java:643)
    at io.netty.channel.DefaultChannelHandlerContext.write(DefaultChannelHandlerContext.java:633)
    at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:115)
    at io.netty.channel.DefaultChannelHandlerContext.invokeWrite(DefaultChannelHandlerContext.java:643)
    at io.netty.channel.DefaultChannelHandlerContext.writeAndFlush(DefaultChannelHandlerContext.java:689)
    at io.netty.channel.DefaultChannelHandlerContext.writeAndFlush(DefaultChannelHandlerContext.java:713)
    at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:893)
    at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:239)
    at com.logentries.net.NettyBasedAsyncLogger.logLine(NettyBasedAsyncLogger.java:54)
    at com.logentries.logback.LogentriesAppender.append(LogentriesAppender.java:105)
    at com.logentries.logback.LogentriesAppender.append(LogentriesAppender.java:15)
    at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85)
    at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
    at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:280)
    at ch.qos.logback.classic.Logger.callAppenders(Logger.java:267)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:449)
    at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:421)
    at ch.qos.logback.classic.Logger.debug(Logger.java:514)
    at io.netty.util.internal.logging.Slf4JLogger.debug(Slf4JLogger.java:76)
    at io.netty.util.ResourceLeakDetector.<clinit>(ResourceLeakDetector.java:37)
    at io.netty.buffer.AbstractByteBuf.<clinit>(AbstractByteBuf.java:37)
    at io.netty.buffer.UnpooledByteBufAllocator.newDirectBuffer(UnpooledByteBufAllocator.java:49)
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:132)
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:123)
    at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:76)
    at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:107)
    at io.netty.channel.DefaultChannelHandlerContext.invokeWrite(DefaultChannelHandlerContext.java:643)
    at io.netty.channel.DefaultChannelHandlerContext.write(DefaultChannelHandlerContext.java:633)
    at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:115)
    at io.netty.channel.DefaultChannelHandlerContext.invokeWrite(DefaultChannelHandlerContext.java:643)
    at io.netty.channel.DefaultChannelHandlerContext.access$2000(DefaultChannelHandlerContext.java:29)
    at io.netty.channel.DefaultChannelHandlerContext$WriteTask.run(DefaultChannelHandlerContext.java:887)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:354)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:366)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:101)
    at java.lang.Thread.run(Thread.java:662)
Caused by: java.lang.NullPointerException
    at io.netty.buffer.UnpooledUnsafeDirectByteBuf.<init>(UnpooledUnsafeDirectByteBuf.java:72)
    at io.netty.buffer.UnpooledByteBufAllocator.newDirectBuffer(UnpooledByteBufAllocator.java:49)
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:132)
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:123)
    at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:76)
    at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:107)
    ... 36 more

how is this constructor being invoked? normal program flow, or part of some other class' static init? — jtahlborn, Aug 19 '13 at 13:46
if that's the case, then something is messed up. maybe you need to make sure all your classes are recompiled? can you show the actual exception trace and the `leakDetector` definition? — jtahlborn, Aug 19 '13 at 13:56
what's scary is that if I do a debug / step by step everything works fine. It looks like I am hitting a jvm problem with jdk 1.6u25 — Edmondo, Aug 20 '13 at 08:12

jtahlborn · Accepted Answer · 2013-08-20T18:09:36.097

The stack trace indicates your problem:

at io.netty.util.internal.logging.Slf4JLogger.debug(Slf4JLogger.java:76)
at io.netty.util.ResourceLeakDetector.<clinit>(ResourceLeakDetector.java:37)
at io.netty.buffer.AbstractByteBuf.<clinit>(AbstractByteBuf.java:37)

"<clinit>" means that the classes are in the midst of their class initialization. it looks like ResourceLeakDetector is generating a log statement during class initialization (before AbstractByteBuf's class init completes and leakDetector is assigned).

UPDATE:

Probably the most confusing part looking at the entire stack trace is that it is not apparent what has not happened yet. The key bit is that the static class initialization of UnpooledUnsafeDirectByteBuf has not yet happened! the current status of the jvm is:

UnpooledByteBufAllocator is trying to create a new instance of UnpooledUnsafeDirectByteBuf
UnpooledUnsafeDirectByteBuf class is loaded (but not initialized)
AbstractReferenceCountedByteBuf class is loaded (but not initialized) since it is the parent of UnpooledUnsafeDirectByteBuf
AbstractByteBuf class is loaded (but not initialized) since it is the parent of AbstractReferenceCountedByteBuf
AbstractByteBuf class initialization begins (since parents are inited before children), leakDetector is still null
ResourceLeakDetector class is loaded since it is referenced by AbstractByteBuf class init
ResourceLeakDetector class initialization begins, which includes a log statement
...bunch of other method calls are made...
UnpooledByteBufAllocator creates a new instance of UnpooledUnsafeDirectByteBuf (this is a recursive call to this method)
new instance of UnpooledUnsafeDirectByteBuf is allocated (the class has already been loaded, but not yet initialized)
NullPointerException

If you removed the logging call from ResourceLeakDetector class init, what would happen is:

same
same
same
same
same
same
ResourceLeakDetector class initialization runs to completion
AbstractByteBuf class initialization completes, leakDetector is now assigned
AbstractReferenceCountedByteBuf class initialization runs to completion
UnpooledUnsafeDirectByteBuf class initialization runs to completion
UnpooledByteBufAllocator creates a new instance of UnpooledUnsafeDirectByteBuf
life proceeds happily

I don't agree. I am actually coding a logger, and this might be confusing. But the cause is here: Caused by: java.lang.NullPointerException at io.netty.buffer.UnpooledUnsafeDirectByteBuf.(UnpooledUnsafeDirectByteBuf.java:72) — Edmondo, Aug 20 '13 at 14:34
@Edmondo1984 - feel free to disagree all you want, but the answer is right there in the stack trace. the stack trace is the _exact state_ of the system when the problem occurred. AbstractByteBuf line 37 is the line where leakDetector is assigned. since the assignment hasn't happened yet, leakDetector is still null. — jtahlborn, Aug 20 '13 at 14:51
yes, but why it is null if it is a final static member defined on the parent class of the current class? — Edmondo, Aug 20 '13 at 16:25
@Edmondo1984 - because the parent class has not finished class initialization yet, as you can see from the stack trace. you have a circular static dependency problem, see e.g. http://stackoverflow.com/questions/6416408/static-circular-dependency-in-java — jtahlborn, Aug 20 '13 at 16:42
Awesome ! but why does the log statement produce this effect? — Edmondo, Aug 21 '13 at 07:14
ouch I got it. My logger was called recursively from netty ... :( — Edmondo, Aug 21 '13 at 07:47

Order of initialization in Java: exception with Netty 4.0.7

1 Answers1