记录一次句柄泄漏的异常解决
最近入职了一家生产机器人的公司，我们做的软件就是运行在这个机器人上的，机器人服务有个特点就是里面的软件要连续24小时不间断服务，所以要求app能够持续的运行服务。
测试那边很久以前就记录过一个奇异的问题，就是机器人在使用一天以后，会莫名奇妙的闪退，java层有crashhandler，但是也抓不到日志，任何的日志记录工具也没有用。
从这周三开始我就开始着手解决这个问题。
为了尽快复现这种很偶然的闪退，我试了各种方案，拔网线、杀程序、制造cpu使用率极高，最后终于发现一个规律，拔掉安卓主板与底盘机器人的通信，十分钟左右就会复现突然闪退的问题，crashHandler没有日志记录。
突然很兴奋，立刻脸上数据线在命令提示符里输入以下命令
adb logcat -v time >d:log.txt
把机器上的日志输出到了d盘下的log.txt，仔细分析这个文件后发现了一个ndk导致的崩溃：
--------- beginning of crash
08-15 17:10:24.937 F/libc (27117): Fatal signal 13 (SIGPIPE), code 0 in tid 27117 (adb)
08-15 17:10:25.040 I/DEBUG ( 192): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
08-15 17:10:25.040 I/DEBUG ( 192): Build fingerprint: 'Android/rk3288/rk3288:5.1.1/LMY49F/server01051636:userdebug/test-keys'
08-15 17:10:25.040 I/DEBUG ( 192): Revision: '0'
08-15 17:10:25.041 I/DEBUG ( 192): ABI: 'arm'
08-15 17:10:25.040 W/NativeCrashListener( 572): Couldn't find ProcessRecord for pid 27117
08-15 17:10:25.024 I/debuggerd( 192): type=1400 audit(0.0:63001): avc: denied { create } for name="tombstone_08" scontext=u:r:debuggerd:s0 tcontext=u:object_r:system_data_file:s0 tclass=file permissive=1
08-15 17:10:25.041 I/DEBUG ( 192): pid: 27117, tid: 27117, name: adb >>> adb <<<
08-15 17:10:25.041 E/DEBUG ( 192): AM write failure (32 / Broken pipe)
08-15 17:10:25.041 I/DEBUG ( 192): signal 13 (SIGPIPE), code 0 (SI_USER), fault addr --------
08-15 17:10:25.034 I/debuggerd( 192): type=1400 audit(0.0:63002): avc: denied { write } for path="/data/tombstones/tombstone_08" dev="mmcblk0p13" ino=310090 scontext=u:r:debuggerd:s0 tcontext=u:object_r:system_data_file:s0 tclass=file permissive=1
安卓系统的adb导致的崩溃，我…… 这怎么可能？
这绝对不可能，肯定是什么误会导致的，再查，重启app，不到十分钟后又复现了，再抓log
*** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
Build fingerprint: 'Android/rk3288/rk3288:5.1.1/LMY49F/server01051636:userdebug/test-keys'
Revision: '0'
ABI: 'arm'
pid: 6301, tid: 10006, name: RenderThread >>> guide.yunji.com.guide <<<
signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr --------
Abort message: 'Encountered EGL error 12299 EGL_BAD_NATIVE_WINDOW during rendering'
r0 00000000 r1 00002716 r2 00000006 r3 00000000
r4 81afcdd8 r5 00000006 r6 00000018 r7 0000010c
r8 b8ef0f3c r9 81afcd28 sl b6e2357d fp 81afcdd0
ip 00002716 sp 81afc7e8 lr b6e23db1 pc b6e4a534 cpsr 600f0010
d0 ffffffffffffffff d1 0000000000000000
这次是RenderThread，安卓系统的渲染线程？这…… 难道是我们安卓版子的供应商刷的固件有问题？
我们把日志以及data/tombstone/里的文件甩给了板子供应商，但是一个tombstone文件大概有6~7M，他们问你们自己分析了吗？你们先分析下再商量，我们看了好久也没查出什么问题，然后继续查问题，继续复现崩溃
后面的崩溃的原因也都是ndk方面的，但是每次都不一样，这特么就神奇了，难道真的是板子有问题？毫无头绪
后来冷静了一下，重新梳理头绪：为什么不拔网线就要一天多才崩溃，拔了网线十分钟内就会崩溃？我们与底盘的通信到底做了什么？然后问了在这个公司工作一年多的小姑娘才知道，安卓版子与底盘通信就需要建立一个socket连接，其他的交互没有。
于是我把查问题的重点转移到了socket通信上，死盯socket通信的日志：
08-15 17:18:46.024 E/ConnectHelper(27160): initSocketSub: Exceptionjava.net.SocketException: socket failed: EMFILE (Too many open files) 08-15 17:18:46.024 W/System.err(27160): java.net.SocketException: socket failed: EMFILE (Too many open files) 08-15 17:18:46.024 W/System.err(27160): at libcore.io.IoBridge.socket(IoBridge.java:623) 08-15 17:18:46.024 W/System.err(27160): at java.net.PlainSocketImpl.create(PlainSocketImpl.java:198) 08-15 17:18:46.024 W/System.err(27160): at java.net.Socket.checkOpenAndCreate(Socket.java:687) 08-15 17:18:46.024 W/System.err(27160): at java.net.Socket.setKeepAlive(Socket.java:474) 08-15 17:18:46.024 W/System.err(27160): at com.hotelrobot.common.nethub.ConnectHelper.initSocketSub(ConnectHelper.java:187) 08-15 17:18:46.024 W/System.err(27160): at com.hotelrobot.common.nethub.ConnectHelper.initSocket(ConnectHelper.java:126) 08-15 17:18:46.024 W/System.err(27160): at com.hotelrobot.common.nethub.ConnectHelper.access$100(ConnectHelper.java:20) 08-15 17:18:46.024 W/System.err(27160): at com.hotelrobot.common.nethub.ConnectHelper$ConnectHelperHandler.handleMessage(ConnectHelper.java:117) 08-15 17:18:46.025 W/System.err(27160): at android.os.Handler.dispatchMessage(Handler.java:102) 08-15 17:18:46.025 W/System.err(27160): at android.os.Looper.loop(Looper.java:135) 08-15 17:18:46.025 W/System.err(27160): at android.os.HandlerThread.run(HandlerThread.java:61) 08-15 17:18:46.025 W/System.err(27160): Caused by: android.system.ErrnoException: socket failed: EMFILE (Too many open files)
开始的时候socket连不上底盘都会报错，错误内容一般都是 EHOSTUNREACH (No route to host)
而这次却是EMFILE (Too many open files)
这是什么鬼，然后google了一把，这个东西叫做句柄泄露。
在linux中一个文件、一个串口、一个socket、一个线程都可以是一个文件，而一个文件会占用一个句柄，linux中一个进程默认的句柄最大数值是1024，当超过这个数值，linux就会对当前的进程进行kill，而kill的对象可以是任意对象，所以会造成各种异常原因的崩溃，看到这里我就大概明白了为什么每次崩溃ndk的报错原因都不一样了，这跟板子厂商一点关系都没有啊，于是我跟厂商说了，我们的问题，你们清白了，哈哈哈。
接着，问题找到了，是句柄泄露，但是对于句柄泄露，如何查找呢？
可以使用linux下的 lsof命令，列出所有占用的句柄，
使用方式如下
adb shell su lsof
网上好多解决这个问题的都没说要用root权限，但是我的机器上如果不输入su，就打不出来全部的句柄，我也不知道为什么，还有就是lsof这个命令，可能我的安卓板子有点残废，后面加如任何的 lsof pid和grep都是无效的，每次都把全部的句柄打出来，后来google下才知道，android下的lsof命令就是残废的，好吧，没办法凑合用吧。
通过这个命令我们可以看到自己程序中句柄的序号，第一次打上我就看到，哎呀妈呀，句柄数800多了，然后发现不久后，app就闪退了，估计就到了1024了，真的这么准啊
里面输出的内容如下：
guide.yun 32566 u0_a81 515 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 517 ??? ??? ??? ??? socket:[14635912] guide.yun 32566 u0_a81 518 ??? ??? ??? ??? pipe:[14643795] guide.yun 32566 u0_a81 520 ??? ??? ??? ??? pipe:[14638969] guide.yun 32566 u0_a81 522 ??? ??? ??? ??? pipe:[14638969] guide.yun 32566 u0_a81 523 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 524 ??? ??? ??? ??? pipe:[14638726] guide.yun 32566 u0_a81 527 ??? ??? ??? ??? pipe:[14638726] guide.yun 32566 u0_a81 528 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 530 ??? ??? ??? ??? pipe:[14645682] guide.yun 32566 u0_a81 531 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 532 ??? ??? ??? ??? pipe:[14638731] guide.yun 32566 u0_a81 533 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 534 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 535 ??? ??? ??? ??? socket:[14635913] guide.yun 32566 u0_a81 536 ??? ??? ??? ??? pipe:[14643801] guide.yun 32566 u0_a81 537 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 539 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 542 ??? ??? ??? ??? pipe:[14643801] guide.yun 32566 u0_a81 543 ??? ??? ??? ??? anon_inode:[eventpoll] guide.yun 32566 u0_a81 545 ??? ??? ??? ??? socket:[14644273] guide.yun 32566 u0_a81 550 ??? ??? ??? ??? /storage/emulated/0/ads/gifDeepSleepBg.gif guide.yun 32566 u0_a81 mem ??? 00:04 0 2678 /dev/ashmem/dalvik-main
但是这些句柄都是被谁占着呢？占用最多的好像就3种：pipe、socket、anon_inode。
分别去查这三中类型的意义：pipe和socket跟linux中的通信相关，socket不用猜了，肯定是跟socket连接有关系，但是pipe呢？记得学java的输入输出六的时候有管道的概念，至于anon_inode就不知道是啥了，先从socket入手吧，看看socket有没有close，在仔细的阅读了socket这部分的逻辑代码后，很失望，每一次连接失败都close掉了，好了，放弃，继续查java的输入输出流
通过搜索项目代码中全部的inputstream、outputstream、bufferReader、fileinputstream等，还真的发现有很多的流没有关闭，大概有三四百行的代码，经过四个小时的改造后重新发版，然后测试。
昨天下午六点多开始发布，到晚上九点多走的时候还没有闪退，终于高高兴兴的回家了，看来这次的改动还是有效的。估计没啥问题了。
然而想不到的是，今天早上八点四十到了公司发现，程序还是退出了，好吧，抓日志
拿到log后分析，今天凌晨3.52分闪退了……还是没有坚持到最后啊。
于是打开程序，继续分析句柄有没有增长，lsof命令，发现句柄数还在不断增长，只是速度比修改之前慢了很多。这次不能等到他崩溃再抓日志了，因为这次可能要等十个小时左右，不太现实。
除了socket和输入输出流，还有什么会占用句柄呢？线程？只能猜测一下了，查一下线程
adb shell ps -t |grep <pid>
查一下我们程序的具体线程都有哪些，不查不要紧，一查就发现问题了，其中有个负责与底盘创建socket连接的线程的数量一直在不断的增长：
u0_a74 21569 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 21689 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 21805 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 21909 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22032 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22154 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22277 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22375 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22493 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22619 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22741 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22861 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 22962 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 23079 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 23198 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 23339 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 23456 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 23552 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 23669 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 23787 21513 918544 50684 c014570c b6e2640c S ConnectHelper u0_a74 23905 21513 918544 50684 c00827e0 b6dfb964 S Thread-1452 u0_a74 23906 21513 918544 50684 c00827e0 b6dfb964 S Thread-1453 u0_a74 23907 21513 918544 50684 c011b0bc b6e25bf4 S ConnectHelper
肯定是这个没有释放造成的，由于这是一个线程，如果不用了就关掉就好了，于是在重连socket的时候，把这个线程中断掉就好，interrupt。改了后重新发布程序。看线程有没有在涨。
然而，神奇的现象又发生了，线程居然还在涨，怎么可能，这个connecthelper没有被中断吗？为什么呢，仔细看代码才知道，这哪里是一个Thread，这是一个handlerThread，handlerThread虽然继承自Thread，但是它里面有looper，所以interrupt是不行的，这里需要调用quit()，修改后再试，果然线程数不涨了，于是兴高采烈的又发版了。
由于我们的是sdk，发出去的有多个程序在用，我修改的程序中句柄数真的就控制住了，再也不涨了，然后另外一个程序居然再次出现了多个ConnectHelper，这又是什么鬼？
于是再次分析我们的sdk代码，connectHelper作为一个线程，实质上是在一个叫做ConnectManager的管理类里去new的，ConnectManager每实例化一次，也就会多一个ConnectHelper。于是问题查找方向也就明确了，到底是谁又创建了多个ConnectManager。经过查找发现有两个地方会不断的创建新的ConnectManager，一个是我们与底盘通信的心跳service，如果连不上会每隔30s重新创建Connectmanager，并且旧的不销毁！另外一个控制机器人与底盘连接的RobotConnectAction也是一样，这两个地方都会造成ConnectManager对象的泄露从而会造成ConnectHelper泄露，找到这个问题后也就好解决了，就是在重新连接前把旧的销毁掉。
盖好后重新测试，ok了，句柄数稳定了，经过四个小时的等待，一直也没有增长，终于可以休息了。
总结下，遇到这种问题还是我们写代码不够规范造成的，输入输出流打开了一定要记得关闭，线程开启了如果不用了也要记得回收，还有一些对象如果需要重新初始化，那么旧的不用的对象也要回收，这样才能保证程序能够长久稳定的运行。我想：还好这个项目没有用到数据库，要不然可能还会遇到cursor的泄露，哈哈
