使用netty4.x客户端接收较大数据量报文时发生的读取不完整bug修复记录

1、先说问题

背景：服务是运行在Linux上的安全网关提供的，TCP协议发送 通过二进制编码的xml字符串 报文，报文头的第一个字段是int类型的表示字节序标记，第二个字段是int类型的表示整个报文长度。

现象：数据量较小时完全可以正常收发报文，当服务端发送的报文数据量较大时(本例是将近600k)概率性出现接收数据直接调用readComplete()方法而没有走channelRead()

跟踪：跟踪代码发现出问题时context 的 read() 方法执行中读取到一百多k(有时两百多也可能三百多，总之是还没读取到全部数据)时某次读到的数据本应该是1024字节(填满默认分配的ByteBuf)却只读到了576字节；

    netty框架代码中判断如果当前读到的字节数小于ByteBuf的size则认为是读取完成，因此调用了readComplete()方法，出错。。。

解决方案：在ClientHandler类添加一个标记flag，用于是否正常读取数据判断。channelRead()方法正常调用则将其置为true；readComplete方法中添加一个判断只有当flag为true时关闭context否则继续调用ctx.read()。

2、再上核心代码

Client：

ClientHandler clientHandler = new ClientHandler(this);
            bootstrap.group(eventLoop)
                    .channel(NioSocketChannel.class)
                    .option(ChannelOption.TCP_NODELAY, true)
                    .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 3000)
                    .option(ChannelOption.MAX_MESSAGES_PER_READ, Integer.MAX_VALUE)
                    .handler(new ClientChannelInitializer(clientHandler));
            
            ChannelFuture f = bootstrap.connect(host, port).sync();

            f.channel().closeFuture().sync();

private class ClientChannelInitializer extends ChannelInitializer<SocketChannel> {
        private ClientHandler clientHandler;

        public ClientChannelInitializer(ClientHandler clientHandler) {
            this.clientHandler = clientHandler;
        }

        @Override
        protected void initChannel(SocketChannel socketChannel) throws Exception {

            socketChannel.pipeline().addLast(new SplDecoder());
            socketChannel.pipeline().addLast(clientHandler);
            channel = socketChannel;
        }
    }

// 解决问题前 initChannel的实现是这样的，使用了netty内部的长度字段解码器
@Override
protected void initChannel(SocketChannel ch) throws Exception {
    ch.pipeline().addLast(new LengthFieldBasedFrameDecoder(Integer.MAX_VALUE,4,4,-8,0));
    ch.pipeline().addLast(clientHandler);
}

 

ClientHandler：

public class ClientHandler extends ChannelInboundHandlerAdapter {

@Override
    public void channelActive(ChannelHandlerContext context) throws Exception {
        logger.info("Ready to send request...");
        ByteBuffer result = getByteBuffer();
        ByteBuf buf = Unpooled.buffer(result.remaining());
        buf.writeBytes(result);

        context.writeAndFlush(buf);
    }

    @Override
    public void channelRead(ChannelHandlerContext context, Object msg) throws Exception {
        logger.info("Get server response...");

        String[] result = (String[]) msg;

        logger.debug("response xml is : " + result[1]);
        client.setResponse(result);

        ok = true;
    }

    @Override
    public void channelReadComplete(ChannelHandlerContext ctx) throws Exception {
        ctx.flush();
        if (ok) {
            ctx.close();
        } else {
            ctx.read();
        }
    }

3、最后说解决过程

起初我怀疑是使用netty的定长字段解码器LengthFieldBasedFrameDecoder参数不当引起的，因为自认为对它理解不深；于是自己写了一个继承byteToMessageDecoder的解码器可以实现解决拆包问题和解码功能，但是问题依然概率性出现...

后来抱着试试看的态度在ClientHandler里面添加了一个实例属性ok(默认false)，在正常执行channelRead()方法后将其置为true，readComplete()方法中做判断如果ok==false调用ctx.read()，运行发现完美解决问题

因为调用read()方法是继续读取数据而不是重新读取(因为此时ctx和channel、pipline等数据状态都没变)！

在SplDecoder类中添加当前读取数据打印信息：“logger.debug("读取数据：本次" + readableBytes + "；累计" + currentLength + "；总共" + total);”；

在ctx.read()前面添加打印错误信息“****** 读取数据不完整，再次读取......”

运行正常和出错时的控制台打印信息如下(由于实际打印行数太多，我用"......"代替了部分重复行)：

Connected to the target VM, address: '127.0.0.1:62194', transport: 'socket'
log4j:WARN No appenders could be found for logger (io.netty.util.internal.logging.InternalLoggerFactory).
log4j:WARN Please initialize the log4j system properly.
读取数据：本次1024；累计1024；总共574842
读取数据：本次1024；累计2048；总共574842
读取数据：本次1024；累计3072；总共574842
......
读取数据：本次1024；累计572416；总共574842
读取数据：本次1024；累计573440；总共574842
读取数据：本次1024；累计574464；总共574842
读取数据：本次378；累计574842；总共574842
0 ~~ null
Disconnected from the target VM, address: '127.0.0.1:62194', transport: 'socket'

Process finished with exit code 0

Connected to the target VM, address: '127.0.0.1:62068', transport: 'socket'
log4j:WARN No appenders could be found for logger (io.netty.util.internal.logging.InternalLoggerFactory).
log4j:WARN Please initialize the log4j system properly.
读取数据：本次1024；累计1024；总共574842
读取数据：本次1024；累计2048；总共574842
读取数据：本次1024；累计3072；总共574842
读取数据：本次1024；累计4096；总共574842
读取数据：本次1024；累计5120；总共574842
读取数据：本次1024；累计6144；总共574842
读取数据：本次1024；累计7168；总共574842
读取数据：本次1024；累计8192；总共574842
读取数据：本次1024；累计9216；总共574842
读取数据：本次1024；累计10240；总共574842
读取数据：本次1024；累计11264；总共574842
读取数据：本次1024；累计12288；总共574842
读取数据：本次1024；累计13312；总共574842
读取数据：本次576；累计13888；总共574842
****** 读取数据不完整，再次读取......
读取数据：本次16384；累计30272；总共574842
读取数据：本次16384；累计46656；总共574842
读取数据：本次16384；累计63040；总共574842
......
读取数据：本次16384；累计554560；总共574842
读取数据：本次16384；累计570944；总共574842
读取数据：本次3898；累计574842；总共574842
0 ~~ null
Disconnected from the target VM, address: '127.0.0.1:62068', transport: 'socket'

Process finished with exit code 0

 结果最后打印0~~null表示正常结束(返回code为0错误信息为null)。

附：

问题处理前控制台打印结果

"C:\Program Files...
log4j:WARN No appenders could be found for logger (io.netty.util.internal.logging.InternalLoggerFactory).
log4j:WARN Please initialize the log4j system properly.
-1 ~~ 服务异常；Detail:java.lang.NullPointerException

Process finished with exit code 0

由于没有执行channelRead()方法，所以我获取到的数据没能执行赋值操作，报了空指针异常。

结果最后打印 -1 ~~ 服务异常；Detail:java.lang.NullPointerException 表示发生了异常(返回code为-1；错误信息为"服务异常；Detail:java.lang.NullPointerException")。