Trivially duplicated reference counting bug?

[Steve Johnson]

Hi all,

I'm a newbie to this codebase although I've been using it for a little while.  I finally got around to fixing log4j initialization, and when I did, I started getting log output, which after initial startup, consists of a continual stream of this exception:

156357 2018-01-15 14:20:17,172 WARN  [LittleProxy-0-ClientToProxyWorker-2] concurrent.DefaultPromise (Slf4JLogger.java:151).warn() - An exception was thrown by org.littleshoot.proxy.impl.ConnectionFlow$2.operationComplete()
io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
 at io.netty.buffer.AbstractReferenceCountedByteBuf.release0(AbstractReferenceCountedByteBuf.java:91)
 at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:79)
 at io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpMessage.release(HttpObjectAggregator.java:417)
 at org.littleshoot.proxy.impl.ProxyToServerConnection.connectionSucceeded(ProxyToServerConnection.java:938)
 at org.littleshoot.proxy.impl.ConnectionFlow.succeed(ConnectionFlow.java:168)
 at org.littleshoot.proxy.impl.ConnectionFlow.advance(ConnectionFlow.java:88)
 at org.littleshoot.proxy.impl.ConnectionFlowStep.onSuccess(ConnectionFlowStep.java:83)
 at org.littleshoot.proxy.impl.ConnectionFlow$2.operationComplete(ConnectionFlow.java:149)
 at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
 at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:500)
 at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:479)
 at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
 at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
 at io.netty.handler.ssl.SslHandler.setHandshakeSuccess(SslHandler.java:1324)
 at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1172)
 at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1039)
 at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
 at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:357)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:343)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:336)
 at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:357)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:343)
 at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)
 at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
 at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:643)
 at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:566)
 at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:480)
 at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:442)
 at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
 at java.lang.Thread.run(Thread.java:745)

I've narrowed this down to simply adding a HttpFiltersSource  that overrides getMaximumRequestBufferSizeInBytes() to return a non-zero value.  In other words...

public class DummyCredsMappingFilterSource extends HttpFiltersSourceAdapter
{
 @Override
 public int getMaximumRequestBufferSizeInBytes()
 {
 return 512 * 1024;
 }
}


public class Launcher
{
 ...
 
 public static void main(final String... args)

 {
 ...
 bootstrap.withFiltersSource(new DummyCredsMappingFilterSource());

 ...
 }
 ...
}

My filtering code works fine, and has been doing so for some time, but I'd really like to not have to live with this spewage of warnings, both for utility and correctness.

Is this a bug, or by returning a non-zero max buffer size, am I supposed to increment a reference count somewhere, or otherwise add some additional logic?  The home page mentions this method, but says no such thing. Can anyone fill me in on what's going on here.  It seems crazy for this to be an uncaught bug, so I really wonder if I'm missing something.  TIA for any info.

...and btw, thanks to all contributors for this wonderful bit of code!

Steve

PS: I am up to date with the latest code.  I just did a merge, which consisted of a very small 4 character change that I knew wouldn't fix this when I first saw it.

[Steve Johnson]

I realized that this might not be quite that trivial to reproduce, because I had other classes wired in.  Sure enough, taking out all my code made this problem go away.  I narrowed the offending code down to adding a trivial external proxy.  I checked the test code for Little Proxy, and it seems I'm doing exactly what it's doing, so I still can't see how this isn't a bug, but it gives me more hope that there's something I should be doing and am not, which I much prefer.  Anyway, here's the additional code I'm adding into the mix to get these exceptions:

public class ExternalProxyManager implements ChainedProxyManager
{
 private static final String proxyIP = "67.220.228.92";
 private static final int proxyPort = 21234;

 protected class ExternalProxy extends ChainedProxyAdapter
 {
 private InetSocketAddress proxyAddress;

 ExternalProxy(@SuppressWarnings("unused") HttpRequest request)
 {
 try
 {
 proxyAddress = new InetSocketAddress(InetAddress.getByName(proxyIP), proxyPort);
 }
 catch (UnknownHostException e)
 {
 throw new RuntimeException("Unable to resolve proxyIP?!");
 }
 }

 @Override
 public InetSocketAddress getChainedProxyAddress()
 {
 return proxyAddress;
 }
 }

 @Override
 public void lookupChainedProxies(HttpRequest httpRequest, Queue<ChainedProxy> chainedProxies)
 {
 chainedProxies.add(new ExternalProxy(httpRequest));

 }
}



public class Launcher
{
    ...
 
    public static void main(final String... args)

    {
        ...
        bootstrap.withFiltersSource(new DummyCredsMappingFilterSource());

        bootstrap.withChainProxyManager(new ExternalProxyManager());
        ...
    }
    ...
}

[Steve Johnson]

Since I got no bites on this and I wanted to get rid of all the exceptions spewing into my logs, I added a conditional at ProxyToServerConnection.java:1078 that checks to see if the reference count is greater than zero before decrementing it.  Before doing this, I wasn't sure if this was the only place that this exception is thrown, thinking that maybe the release() calls can be made in differing orders.  But after this change, I get no underrun exceptions in my logs due to over-decrementing a reference counted object, so I guess this is MY answer for now.  

I may spend some more time looking into this issue someday, but no promises...

Steve

[Steve Johnson]

It occurred to me after making my last post that I'd reformatted the mentioned source file to conform to our coding spec before editing it, so the line number I mentioned is meanlingless.  Here's my version of the code I'm referring to:

// we're now done with the initialRequest: it's either been forwarded to the upstream server (HTTP requests), or
// completely dropped (HTTPS CONNECTs). if the initialRequest is reference counted (typically because the HttpObjectAggregator is in
// the pipeline to generate FullHttpRequests), we need to manually release it to avoid a memory leak.
if (initialRequest instanceof ReferenceCounted)
{
    ReferenceCounted rcir = (ReferenceCounted) initialRequest;
    // steve@inlet - added check of the reference count here because the ref count can be zero here, causing an
    // exception when this release() call is made.  After adding this, I'll have to see if we still have an
    // underflow problem if the ref count can be decremented in a different order and so ultimately have an
    // underrun at a different place in the code.
    if (rcir.refCnt() > 0)
        rcir.release();
}