记一次netty追源码找bug过程

Posted 2021-08-21 敲代码的小小酥

前言

在一次使用一个netty封装的框架时，遇到了问题。由于对netty的原理不熟悉，所以只能瞎猫碰死耗子，一点儿一点儿找原因。最后很费力的找到了问题所在。下面复盘一下通过源码找问题的过程，总结一下哪里可以很快的找到问题原因。

问题

我用nettty封装的框架做 服务端，C++同事在做客户端。C++同事向我反应连接上我的服务后，只能在服务端第一次发送心跳ping之前，向服务端发送的请求才有响应，第一次服务端发送ping之后，再发请求，就没响应了。
看到这个奇葩的bug，我就打开了项目，让C++客户端连接我的开发环境进行测试。发现服务端第一次发送ping时，可以收到客户端反馈的pong。但是从第二次开始，就收不到客户端的pong了，只是服务端在一直发ping。我猜测是这个问题导致的。问C++的同事回复pong信息有误否，C++同事很自信的说没有，由于C++同事是一位大佬，我也不敢多问，那就从我服务端找问题吧。

分析

第一次能收到pong，后面就收不到了，这听起来好像也是服务端有问题。如果客户端有问题的话，那第一次的pong也不可能发送成功。但是发送ping~pong心跳的功能，是框架封装好的，从哪里找问题呢？

首先，客户端发送pong到服务端，走的tcp协议，通过端口进行的连接。那就在项目里找，客户端连接的端口，在哪里用过，找到了如下代码:

@Bean(destroyMethod = "destroy")
	public CIMNiosocketAcceptor getNioSocketAcceptor(@Value("${cim.app.port}") int port,
													 @Value("${cim.websocket.port}") int websocketPort) {

		return new CIMNioSocketAcceptor.Builder()
				.setAppPort(port)
				.setWebsocketPort(websocketPort)
				.setOuterRequestHandler(this)
				.build();

SpringBoot项目，将端口信息存入了CIMNioSocketAcceptor对象。那么由此可以猜测，肯定是由这个类，建立的连接，监听的消息。这里的代码只是构建出了这个类，并放入了Spring容器中。那我们要找这个类在哪里调用了呢？ 与上面的方法在同一个类中，我们找到了调用CIMNioSocketAcceptor的地方，如下代码:

public void onApplicationEvent(ApplicationStartedEvent applicationStartedEvent) {

		Map<String, CIMRequestHandler> beans =  applicationContext.getBeansOfType(CIMRequestHandler.class);

		for (Map.Entry<String, CIMRequestHandler> entry : beans.entrySet()) {

			CIMRequestHandler handler = entry.getValue();

			CIMHandler annotation = handler.getClass().getAnnotation(CIMHandler.class);

			if (annotation != null){
				handlerMap.put(annotation.key(),handler);
			}
		}


		applicationContext.getBean(CIMNioSocketAcceptor.class).bind();

		sessionService.deleteLocalhost();
	}

这个方法利用了Spring的事件功能，调用了CIMNioSocketAcceptor类的bind方法，那我们看bind方法的源码：

 private void bindAppPort() {
        this.createAppEventGroup();
        ServerBootstrap bootstrap = this.createServerBootstrap(this.appBossGroup, this.appWorkerGroup);
        bootstrap.childHandler(new ChannelInitializer<SocketChannel>() {
            public void initChannel(SocketChannel ch) {
                ch.pipeline().addLast(new ChannelHandler[]{new AppMessageDecoder()});
                ch.pipeline().addLast(new ChannelHandler[]{new AppMessageEncoder()});
                ch.pipeline().addLast(new ChannelHandler[]{CIMNioSocketAcceptor.this.loggingHandler});
                ch.pipeline().addLast(new ChannelHandler[]{new IdleStateHandler(CIMNioSocketAcceptor.this.readIdle.getSeconds(), CIMNioSocketAcceptor.this.writeIdle.getSeconds(), 0L, TimeUnit.SECONDS)});
                ch.pipeline().addLast(new ChannelHandler[]{CIMNioSocketAcceptor.this});
            }
        });
        ChannelFuture channelFuture = bootstrap.bind(this.appPort).syncUninterruptibly();
        channelFuture.channel().newSucceededFuture().addListener((future) -> {
            String logBanner = "\\n\\n* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *\\n*                                                                                   *\\n*                                                                                   *\\n*                   App Socket Server started on port {}.                        *\\n*                                                                                   *\\n*                                                                                   *\\n* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *\\n";
            LOGGER.info(logBanner, this.appPort);
        });
        channelFuture.channel().closeFuture().addListener((future) -> {
            this.destroy(this.appBossGroup, this.appWorkerGroup);
        });
    }

这里应该是用到了netty的通信原理，什么channel啊，管道啊等等概念，由于我对netty和网络不太熟悉，所以这里并没有看出什么有用的东西来。后面有时间再学习网络和netty的知识。总之这里没有找到问题所在。
那么接下来，往哪里找呢，找到的调用CIMNioSocketAcceptor的方法就一个bind，还没看出猫腻来。那么我们再进行分析，既然是这个类绑定了客户端连接的端口，那么客户端发送pong信息，大概率是这个类来接收并处理。于是，我把这个类每个方法都打上了断点，看进哪个方法。
最终，断点进入了如下的方法:

public void userEventTriggered(ChannelHandlerContext ctx, Object evt) {
        if (evt instanceof IdleStateEvent) {
            IdleStateEvent idleEvent = (IdleStateEvent)evt;
            String uid = (String)ctx.channel().attr(ChannelAttr.UID).get();
            if (idleEvent.state() == IdleState.WRITER_IDLE && uid == null) {
                ctx.close();
            } else {
                Integer pingCount;
                if (idleEvent.state() == IdleState.WRITER_IDLE && uid != null) {
                    pingCount = (Integer)ctx.channel().attr(ChannelAttr.PING_COUNT).get();
                    ctx.channel().attr(ChannelAttr.PING_COUNT).set(pingCount == null ? 1 : pingCount + 1);
                    ctx.channel().writeAndFlush(Ping.getInstance());
                } else {
                    pingCount = (Integer)ctx.channel().attr(ChannelAttr.PING_COUNT).get();
                    if (idleEvent.state() == IdleState.READER_IDLE && pingCount != null && pingCount >= 3) {
                        ctx.close();
                        LOGGER.info("{} pong timeout.", ctx.channel());
                    }

                }
            }
        }
    }

通过一顿分析发现，这个方法，并不是接收客户端发送pong的。而是服务端主动发送ping消息的方法。
但是服务端发送ping的方法没问题的，所以，这个方法也不是问题所在。
但是这里，有个细节，帮我解决了问题。再这个方法里，服务给客户端发送ping时，是调用了一个PING的对象，如图:

那么给客户端发送pong时，肯定也有个PONG对象，一搜，还真有：

于是，在Pong的方法里打断点，第一次能收到pong时，不就进pong的断点了吗，然后再一步一步往下执行代码，不就找到是哪里调用的pong了吗。这样，就可以找到哪里在发送pong信息了。通过这个方法，最终找到了这个方法:

这个类，在CIMNioSocketAcceptor的bind方法中就已经出现了，但是由于不知道原理，所以绕了一大圈，才找到这个类。最终，通过这个类排查出了问题，原来是同事发送的pong消息的数据格式有问题。pong的长度是4，同事发的数据包长度位标识写成了3，所以每次解析pong时，都少解析一位。而下一次解析时，又从上次的位置继续解析(ByteBuf原理)，就造成了解析错乱，所以在日志中没有打印出pong。

升华

1.由这次追源码可以看出，我们不需要全部看懂源码，而是采用这种技巧和推测，找到我们想要的源码。由Ping对象推理Pong对象，就是用了一个技巧。
2.现在复盘来看，因为服务端一直在发ping消息，而客户端就第一次回复。可以猜测，服务端是接收到客户端发送的pong消息了。因为如果收不到pong消息，服务端发送几次之后，就自动断开了，不会一直发送的。所以由此推测，是收到了pong消息，但是解析出错了。所以还是要找解析pong的地方。