01 ByteToMessageDecoder 里面直接 in 到 out 导致 IllegalReferenceCountException: refCnt: 0, decrement: 1前言测试代码问题的调试问题的处理方式

100 阅读 0 评论 66 点赞

我是靠谱客的博主从容外套，最近开发中收集的这篇文章主要介绍01 ByteToMessageDecoder 里面直接 in 到 out 导致 IllegalReferenceCountException: refCnt: 0, decrement: 1前言测试代码问题的调试问题的处理方式，觉得挺不错的，现在分享给大家，希望可以做个参考。

概述

前言

最近在添加一个做一个客户端输入, 输出的日志打印的时候出现了这样的一个问题

我就新增了一个 LogInputInterceptor, 其作用是直接原样输出客户端的输出, 以十六进制的形式输出

然后添加了这一个 LogInputInterceptor 之后就报错了, 呵呵一时之间很是奇怪, 调试了一下发现是 byteBuffer 被 free 掉了

呵呵, 然后稍微跟了一下代码, 才发现各个线程在处理客户端请求的时候, 默认情况下每一个线程对应的 readBuffer 是线程级别隔离的, 同一个线程多次处理请求, 使用的 readBuffer 是同一个

测试代码

LoginInterceptor 的代码如下, 主要是输出一个日志, 然后基于 out 传递给下游 ChannelInbountHandler

/**
 * LogInputInterceptor
 *
 * @author Jerry.X.He <970655147@qq.com>
 * @version 1.0
 * @date 2021-09-18 19:48
 */
public class LogInputInterceptor extends ByteToMessageDecoder {

    public static Logger LOGGER = LoggerFactory.getLogger(LogInputInterceptor.class);

    @Override
    protected void decode(ChannelHandlerContext ctx, ByteBuf in, List<Object> out) throws Exception {
        LOGGER.info("[LogInputInterceptor] received bytes : {} ", ByteBufUtil.hexDump(in.copy()));
//        out.add(in.copy());
//        in.skipBytes(in.readableBytes());
        out.add(in);
    }

}

输出的错误日志大概是如下

[nioEventLoopGroup-3-1] INFO com.hx.net.interceptor.common.LogInputInterceptor - [LogInputInterceptor] received bytes : 48656c6c6f20576f726c6407
[nioEventLoopGroup-3-1] INFO com.hx.net.protocol.Test01StringWithSepProtocol -  server received : Hello World
[nioEventLoopGroup-3-1] INFO com.hx.net.interceptor.common.LogOutputInterceptor - [LogOutputInterceptor] sent bytes : 48656c6c6f20576f726c6407
[nioEventLoopGroup-3-1] WARN io.netty.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.handler.codec.DecoderException: LogInputInterceptor.decode() did not read anything but decoded a message.
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:460)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	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.lang.Thread.run(Thread.java:748)
[nioEventLoopGroup-3-1] WARN io.netty.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
	at io.netty.util.internal.ReferenceCountUpdater.toLiveRealRefCnt(ReferenceCountUpdater.java:74)
	at io.netty.util.internal.ReferenceCountUpdater.release(ReferenceCountUpdater.java:138)
	at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:100)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:285)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	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.lang.Thread.run(Thread.java:748)

问题的调试

我们来看一下 ByteToMessageDecoder 的处理, 第一次进入的时候, 更新 cumulation 为输入的 msg[注意这个 msg]

然后后面服务器这边第二次进入 ByteToMessageDecoder 的时候, 我们发现这里的 msg 还是 @1962, 并且 cumulation 也还是 @1962

然后进入 cumulation = cumulator.cumulate(ctx.alloc(), cumulation, data) 的时候, 返回了 cumulation, 并且释放了 in[传入的是msg], 所以 cumulation 最终得到的还是 @1962, 并且 ByteBuffer 已经被释放了, 这才导致的上面的这个报错

为什么传入的 msg 同一个线程都一样?

参见 msg 分配空间的地方, AbstractNioByteChannel$NioByteUnsafe.read 中 byteBuf = allocHandle.allocate(allocator)

newInstance:41, PooledUnsafeDirectByteBuf (io.netty.buffer)
newByteBuf:660, PoolArena$DirectArena (io.netty.buffer)
allocate:127, PoolArena (io.netty.buffer)
newDirectBuffer:378, PooledByteBufAllocator (io.netty.buffer)
directBuffer:187, AbstractByteBufAllocator (io.netty.buffer)
directBuffer:178, AbstractByteBufAllocator (io.netty.buffer)
ioBuffer:139, AbstractByteBufAllocator (io.netty.buffer)
allocate:114, DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle (io.netty.channel)
read:150, AbstractNioByteChannel$NioByteUnsafe (io.netty.channel.nio)
processSelectedKey:714, NioEventLoop (io.netty.channel.nio)
processSelectedKeysOptimized:650, NioEventLoop (io.netty.channel.nio)
processSelectedTKeys:576, NioEventLoop (io.netty.channel.nio)
run:493, NioEventLoop (io.netty.channel.nio)
run:989, SingleThreadEventExecutor$4 (io.netty.util.concurrent)
run:74, ThreadExecutorMap$2 (io.netty.util.internal)
run:30, FastThreadLocalRunnable (io.netty.util.concurrent)
run:748, Thread (java.lang)

问题的处理方式

消费完 in 中的数据, 然后后面的 finally 释放并重置了 cumulation

public class LogInputInterceptor extends ByteToMessageDecoder {

    public static Logger LOGGER = LoggerFactory.getLogger(LogInputInterceptor.class);

    @Override
    protected void decode(ChannelHandlerContext ctx, ByteBuf in, List<Object> out) throws Exception {
        LOGGER.info("[LogInputInterceptor] received bytes : {} ", ByteBufUtil.hexDump(in.copy()));
        out.add(in.copy());
        in.skipBytes(in.readableBytes());
//        out.add(in);
    }

}

呵呵一个小小的细节问题, 可能会让你头疼半天

完