最近入職了一家生產機器人的公司，我們做的軟件就是運行在這個機器人上的，機器人服務有個特點就是里面的軟件要連續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的泄露，哈哈