使用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")。