为了账号安全，请及时绑定邮箱和手机立即绑定
首页 手记 一次糟心的排错历程

一次糟心的排错历程

标签：
Java 职场生活

背景

我们这个项目是针对环境监测的，某个展馆中配有N个设备和N个显示屏终端，每个终端根据实际情况显示不同的检测数据项。设备端通过UDP方式向服务端上传数据，服务端通过websocket方式向终端主动推送实时的检测数据。

发现问题

就在前些天，收到现场实施人员的消息，问我们是不是程序出问题了（估计实施没有看过如何与程序员沟通的指南），我一口回绝说：怎么可能！（嘁，程序员都是好面子的，哪有承认自己的程序有BUG的，一定是甲方不会用，误操作引起的）。后来经过一番沟通，才了解了事情的来龙去脉：现场实施接到甲方的反馈，展馆中的屏幕经常会“卡死”（数据不更新），只有在重启过后才能正常工作，但是过个三五分钟后屏幕又会卡死。因为甲方一直拿着这个作为理由，对我们的项目拒绝验收，所以我们需要抓紧解决这个问题。
图片描述

复现问题

发现问题后，第一时间查看程序日志，通过日志可以看到这个展馆的设备频繁的上线、下线

2018-10-09 15:07:11 [cn.com.xx.websocket.UsrSocketServer:51] INFO  - xx上线
2018-10-09 15:16:30 [cn.com.xx.websocket.UsrSocketServer:51] INFO  - xx上线
2018-10-09 15:16:33 [cn.com.xx.websocket.UsrSocketServer:74] INFO  - xx下线
2018-10-09 15:17:00 [cn.com.xx.websocket.UsrSocketServer:74] INFO  - xx下线
2018-10-09 15:17:02 [cn.com.xx.websocket.UsrSocketServer:51] INFO  - xx上线
2018-10-09 15:17:12 [cn.com.xx.websocket.UsrSocketServer:51] INFO  - xx上线
2018-10-09 15:17:17 [cn.com.xx.websocket.UsrSocketServer:74] INFO  - xx下线
2018-10-09 15:19:00 [cn.com.xx.websocket.UsrSocketServer:74] INFO  - xx下线

然后就是尝试复现这个问题，因为只有复现了问题，才能针对问题寻找解决办法。

随即我在本地、手机、pad上测试，但都无法复现这个问题（复现的流程在后面会详细解释），
图片描述
可是现场那边一直反馈存在问题，没办法，针对这种情况，只能尝试着各个方面分析、调试，看看是否真的存在问题。

分析问题

依据以往的经验，推断可能会有以下几种原因：

  1. 现场的网络情况有问题，可能网路不稳定（坑）
  2. 设备出问题，无法上传数据
  3. 程序出BUG了（虽然极不愿意接受这种情况，但不得不排除可能会有这种原因）
    • UDP Server出现问题
    • websocket客户端出现问题
    • websocket服务端出现问题，不能正常推送

tips：至于为什么第一条会备注“坑”，后面会解释

解决问题

有了基本的推断，接下来就是根据推断逐一排查。

网络问题

因为这种情况有过先例，所以第一反映就是现场网络出现了问题。通过和现场人员沟通，他给出的结论是：现场网络没问题，通过显示屏终端可以打开网页，并且设备的信号灯一直在闪（信号灯闪烁说明正在进行数据传输）。

虽然还是怀疑网络出现问题，但从现场人员的反馈来看，应该不是网络问题。

设备问题

前面提到了设备的信号灯一直在工作，并且通过后台查看设备的实时数据也是一直在更新的，因此也就排除了设备的问题。

程序问题

既然上面两种都已经排除了，那最后一种可能就是程序出BUG了（偶买噶的，小心脏砰砰砰的乱跳~~）。循着这种思路，尝试着过一遍代码，看看是不是程序真的出问题了。

UDP Server出现问题

UDP存在的问题主要是：无法正常处理设备上传的数据。查看日志后发现了有时候会报内存泄露的异常：

[io.netty.util.internal.logging.Slf4JLogger:171] ERROR - LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records: 
Created at:
 io.netty.buffer.AdvancedLeakAwareByteBuf.readBytes(AdvancedLeakAwareByteBuf.java:496)
 cn.com.xx.udp.UsrUdpServer$ConsoleHandler.channelRead0(UsrUdpServer.java:114)
 cn.com.xx.udp.UsrUdpServer$ConsoleHandler.channelRead0(UsrUdpServer.java:100)
 io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
 io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
 io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
 io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
 io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414)
 io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
 io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
 io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945)
 io.netty.channel.nio.AbstractNioMessageChannel$NioMessageUnsafe.read(AbstractNioMessageChannel.java:93)
 io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
 io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
 io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
 io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
 io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
 io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 java.lang.Thread.run(Thread.java:748)

根据提示可知，在GC前未调用release释放资源，查看相关代码

ByteBuf buf = (ByteBuf) packet.copy().content();
byte[] req = new byte[buf.readableBytes()];

Netty官方Api中说明了如果指定的消息实现了引用计数器，请尝试手动调用ReferenceCounted.release()释放。

Try to call ReferenceCounted.release() if the specified message implements ReferenceCounted. If the specified message doesn’t implement ReferenceCounted, this method does nothing.

在代码中并没有手动释放buf，导致内存泄露。添加以下代码即可解决这一问题

ReferenceCountUtil.release(buf);

图片描述

扯得多了，话题切换到本文的主题：UDP Server这边从接收数据到解析、入库再到推送通知，未发现明显问题。主要是系统不止服务了这一个展馆，还有其他展馆也在使用，但是其他展馆的数据都是正常的。所以，基本能排除UDPServer的问题。

这个时候我再次向现场确认了网络情况是否正常，得到的结论仍然是确定网络没问题。好吧…

图片描述

Websocket客户端出现问题了

(function ($) {
    $.extend({
        websocket: {
   _this: null,
            init: function (options) {
                this._this = new WebSocket(host);

                this._this.onopen = function (event) {
                    console.log("与服务器连接成功...");
                }

    // 链接关闭后，会自动重连，直到网络畅通为止
                this._this.onclose = function () {
     setTimeout(function () {
      // 重连...
     }, 5000);
                }
            }
        }
    });
})(dwz);

如上（伪代码），因为我在编写websocket客户端时，加上了断线重连的的逻辑，所以理论上来说，只要断网后重新联网，不应该收不到推送的消息，那么在实施反馈现场网络良好的前提下为什么总是反复停止推送？那么还有什么原因会造成这种现象呢？百度关键词“websocket卡顿”，网上有说因为ws推送频率太高，页面渲染频繁造成页面卡顿；还有说是因为设备内存不够等等，基本都排除掉。没办法，前端也发现不出什么问题，最后就只剩下服务端了。

Websocket服务端出现问题了

首先进行例行检查，项目的依赖spring-boot-starter-websocket有了，ServerEndpointExporterbean也注入了，@ServerEndpoint注解声明也是完好的，从@OnOpen中用户上线、记录用户状态到@OnClose中用户下线，清除用户状态等处理逻辑也是没问题的。

确认了业务流程正常的情况下，本地启动前台程序通过链接后台服务进行自测。测试结果也是显示一切正常，server端能正常接收数据并推送数据，client端也能正常接收数据并渲染到页面上。

看似一切流程都是正常的，但现场那边还是一直在反馈屏幕卡死的问题。

到这一步我脑海中就已经有个大大的问号了，反复在问自己：究竟哪儿出问题了？看来仅仅靠浏览器端模拟测试并不能复现真实的应用场景，那么接下来就需要找一台真实的终端机器进行测试。可喜的是确实有一台测试机，可悲的是这台测试机有问题（这是废话，凑字数用的( ╯□╰ )），没办法，最后在自己手机和测试pad机中安装了线上的应用。经过测试，手机和pad上的程序运行都没有问题。

What the fuck~!!!

走到这一步还没找到问题的原因，那就只能仔细分析分析系统日志了。通过日志可以看到有时候websocket会报出SocketTimeoutException异常：

2018-10-09 15:30:22 [cn.com.xx.websocket.UsrSocketServer:51] INFO  - xx上线
2018-10-09 15:31:12 [cn.com.xx.websocket.UsrSocketServer:74] INFO  - xx下线
java.io.IOException: java.net.SocketTimeoutException
 at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:315)
 at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:250)
 at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendString(WsRemoteEndpointImplBase.java:191)
 at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:37)
 at cn.com.xx.websocket.UsrSocketServer.sendMessage(UsrSocketServer.java:95)
 at cn.com.xx.websocket.UsrSocketServer.sendMessage(UsrSocketServer.java:103)
 at cn.com.xx.websocket.UsrSocketServer.sendMessage(UsrSocketServer.java:128)
 at cn.com.xx.websocket.UsrSocketServer.updateMessage(UsrSocketServer.java:170)
 at cn.com.xx.udp.UsrUdpServer.notifyObserver(UsrUdpServer.java:74)
 at cn.com.xx.udp.UsrUdpServer$ConsoleHandler.channelRead0(UsrUdpServer.java:123)
 at cn.com.xx.udp.UsrUdpServer$ConsoleHandler.channelRead0(UsrUdpServer.java:100)
 at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
 at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
 at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945)
 at io.netty.channel.nio.AbstractNioMessageChannel$NioMessageUnsafe.read(AbstractNioMessageChannel.java:93)
 at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
 at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
 at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
 at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
 at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.SocketTimeoutException
 at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:134)
 at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157)
 at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1259)
 at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670)
 at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:607)
 at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:597)
 at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:95)
 at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:494)
 at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:309)
 ... 26 more

图片描述

心想，是不是因为这个问题导致的消息推送失败？那么先解决这个异常吧。根据异常栈信息，查找WsRemoteEndpointImplBase.sendMessageBlock方法，可以找到这个异常所在的位置，如下：

try {
 if (!this.messagePartInProgress.tryAcquire(timeout, TimeUnit.MILLISECONDS)) {
  String msg = sm.getString("wsRemoteEndpoint.acquireTimeout");
  this.wsSession.doClose(new CloseReason(CloseCodes.GOING_AWAY, msg), new CloseReason(CloseCodes.CLOSED_ABNORMALLY, msg));
  throw new SocketTimeoutException(msg);
 }
} catch (InterruptedException var13) {
 // do something...
}

其中messagePartInProgress定义为：

private final Semaphore messagePartInProgress = new Semaphore(1);

tips: Semaphore信号量，用于控制对某资源访问的同一时间的并发量。

由上面代码可以看到，在阻塞模式下发送WebSocket消息时，同一时间段只能有一个线程进行访问。首先程序通过tryAcquire尝试在规定的**超时时间[1]**内获取一个许可，如果获取不到（有其他线程阻塞住了，未及时释放信号量。比如：服务端向a客户端推送数据时a异常关闭链接，此时就会被阻塞住），则抛出SocketTimeoutException异常

[1] : tomcat官方文档中有说明，默认的超时时间是20秒，可以通过org.apache.tomcat.websocket.BLOCKING_SEND_TIMEOUT属性修改默认的超时时间。

The write timeout used when sending WebSocket messages in blocking mode defaults to 20000 milliseconds (20 seconds). This may be changed by setting the property org.apache.tomcat.websocket.BLOCKING_SEND_TIMEOUT in the user properties collection attached to the WebSocket session. The value assigned to this property should be a Long and represents the timeout to use in milliseconds. For an infinite timeout, use -1.

在源码中也可以看到对阻塞时间的处理逻辑

private long getBlockingSendTimeout() {
 Object obj = this.wsSession.getUserProperties().get("org.apache.tomcat.websocket.BLOCKING_SEND_TIMEOUT");
 Long userTimeout = null;
 if (obj instanceof Long) {
  userTimeout = (Long)obj;
 }

 return userTimeout == null ? 20000L : userTimeout;
}

既然如此，那我调大一点这个值，让它延长一些时间，这样不就能给前面阻塞的线程以足够释放的时间了吗？干！
在@OnOpen中加入如下代码测试有没有效果

session.getUserProperties().put( "org.apache.tomcat.websocket.BLOCKING_SEND_TIMEOUT",25000L);

图片描述
部署、重启服务然后通知现场人员：重试一下吧！本来信心满满的等着现场人员夸我牛逼的时候才发现：理想很丰满，现实很骨感~~~几分钟后现场反馈：然并卵！

由于现场催的越来越紧，再加上我本地一直无法复现这个“BUG”，其实此时我的内心是烦躁的。
图片描述

这个时候我又想到了另外一种可能：设备兼容性。是否是因为这个展馆使用的设备与其他展馆的设备不一样，所以由于设备的兼容问题才造成websocket的异常呢？

通过沟通确认，这个展馆的设备确实大部分和其他展馆的不同，但是其中的一个设备却是和其他展馆的一样，但它也出现了这种问题。看来也不是这个原因，因此这个可能也被否定。

到了这个时候，已经找不到其他的原因了，也是到了这一步，又让我对现场的网络状况产生了深深的怀疑（虽然已经再三向现场人员确认过了），最后不得已想了一个办法：让现场人员用自己的手机开一个热点进行测试！

结果：最怕空气突然安静。问题解决了！当时我的感觉彷佛有几万匹草泥马从我面前呼啸而过！MMP!

图片描述

事儿，就是这么个事儿~~~

反思

事情过去有段时间了，虽然这件问题结束了，但我的心里却久久不能平静。为什么本来很简单的一个问题却要绕这么大一圈才用了这种最弱智的办法解决？

原因不过有二：

  1. 现场人员的问题：在没有明确网络是否稳定的情况下就轻易得出结论。这是因
  2. 我的问题：在心里明确怀疑网络问题的情况下并没有太坚持自己的观点，才造成后面这一步步多余的操作。这是果

其实我本身的问题，不光光是如上第二条所说，还有就是，如果我当初能考虑多一点，能先让现场人员完全排除网络的问题，也一样不会发生后面这些麻烦事。归根结底：自己做事欠考虑。

总结

吃一堑长一智，这种情况，我不会让它再发生第二次了。

图片描述

（tip:这篇文章已经写完好几天了，因为中间一些情况，所以到现在才发出来）

点击查看更多内容
发表于 2018.10.15 11:47， 共 6511 人浏览

本文原创发布于慕课网 ，转载请注明出处，谢谢合作

举报
20人点赞

若觉得本文不错，就分享一下吧！

评论

作者其他优质文章

正在加载中

慕冬雪

全栈工程师
手记
篇
粉丝
9131
获赞与收藏
5502

关注作者，订阅最新文章

相关文章推荐

阅读免费教程

感谢您的支持，我会继续努力的～
扫码打赏，你说多少就多少
赞赏金额会直接到老师账户
支付方式
打开微信扫一扫，即可进行扫码打赏哦
今天注册有机会得

100积分直接送

付费专栏免费学

大额优惠券免费领

立即参与 放弃机会
意见反馈 帮助中心 APP下载
官方微信

举报

0/150
提交
取消