記錄一次hard fault on handler的解決過程

背景

最近在做一個OTA的功能時，遇到一個hard fault on handler的問題，前前后后排查了將近2天，才將此問題解決，因此做一個記錄，方便其它工程師，遇到此類問題的時候有個參考。

環境

rt-thread v4.1.0
lwip2.1.2
cJSON-lastest
使能了posix的select和poll
CmBacktrace v1.3.0
使能了ulog組件

問題和排查過程
最開始遇到問題的時候，報以下錯誤

psr: 0xa100000f
r00: 0xffffffff
r01: 0x2000def4
r02: 0xffffffff
r03: 0x7fffffff
r04: 0x00000000
r05: 0x20017f18
r06: 0x20000358
r07: 0xdeadbeef
r08: 0x00000000
r09: 0x00000001
r10: 0xdeadbeef
r11: 0xdeadbeef
r12: 0x00000000
lr: 0x08042ed9
pc: 0x08042ef8
hard fault on handler
bus fault:
SCB_CFSR_BFSR:0x82 PRECISERR SCB->BFAR:FFFFFFFF

使用CmBacktrace軟件包定位問題

后來在論壇搜索相關的關鍵詞，有人推薦使用CmBacktrace軟件包，于是去安裝此軟件包，但是安裝了以后，報如下錯誤

thread pri status sp stack size max used left tick error

rf_led 10 suspend 0x00000080 0x00000100 50% 0x0000000a 000
rf_send 10 suspend 0x000000a0 0x00000800 16% 0x00000009 000
rf_read 10 suspend 0x000000c0 0x00000200 39% 0x00000003 000
可以看到，CmBacktrace沒有打印完全，這時候我又去CmBacktrace的github倉庫，看有沒有人提相關的issue,發現是因為我打開了ulog組件導致的，具體可以參考這個issue

Usage fault下沒輸出關鍵的call_stack信息

然后我按照鏈接，手動修改CmBacktrace的打印宏定義為rt_kprintf，使用CmBacktrace的cmb_test的除零測試命令測試以后，可以正常打印了,這時候我太開心了，以為問題基本上可以定位了，然而我發現我高興的還是太早了。

在cmb_test正常以后，當我把問題再次復現時，CmBacktrace打印的信息，還是不全，和之前完全沒有變化?。?！如下所示。

thread pri status sp stack size max used left tick error

rf_led 10 suspend 0x00000080 0x00000100 50% 0x0000000a 000
rf_send 10 suspend 0x000000a0 0x00000800 16% 0x00000009 000
rf_read 10 suspend 0x000000c0 0x00000200 39% 0x00000003 000

這就非常奇怪了，明明使用CmBacktrace的除零測試是OK的，為什么還是打印不正常呢？

使用PC和LR反推

看樣子是不能用CmBacktrace了，也許是我使用的姿勢不對，也許是其他問題，那就只能靠自己了。

我試著按照文章的方法去排查，結果發現復現問題的時候，是在rtthread的timer里面，如下圖所示

這就讓我犯難了，這不會是rt-thread的問題吧，rt-thread這么多年了，難道我一用就出問題？

不破不立

不可能，絕對不可能，一定是我用的姿勢不對，再換一個姿勢吧，不破不立，由于我的代碼是分模塊的，于是我就將自己感覺有問題的模塊，一個一個注釋掉，如下圖所示，從后面往前面一個一個注釋，每注釋一個模塊，我就看看是否還會發生hardfualt

當我把ota_init模塊注釋掉的時候，發現hardfualt沒了，這…這怎么可能呢，這個模塊我之前測試過的呀，跑了兩天都是正常的。

然后我發現，設備每次出現hardfault的時候，系統的tick都是553600ms左右,如下所示，換算成分鐘也就是9分鐘這樣，9分鐘，9分鐘，9分鐘，9分鐘的時候還沒有出現hardfualt，我的ota模塊，是每10分鐘去服務器拉取一次做版本檢測，這么說，是這里的問題了？

| /

RT - Thread Operating System
/ | 4.1.0 build Jan 6 2023 17:42:12
2006 - 2022 Copyright by RT-Thread team
lwIP-2.1.2 initialized!
[4416] I/sal.skt: Socket Abstraction Layer initialize success.
[4574] I/rfid_config: reader.id : 4403061904001
[4579] I/rfid_config: reader.beep : 0
[4584] I/rfid_config: report.interval : 60
[4588] I/rfid_config: reader.power : 10
[4594] D/ota_module: ota_flag == ERASE_IAP_FLAG
msh />[4715] D/rfid_module: rfid_report tag
[65630] D/rfid_module: rfid_report tag
[126649] D/rfid_module: rfid_report tag
[187613] D/rfid_module: rfid_report tag
[248612] D/rfid_module: rfid_report tag
[309611] D/rfid_module: rfid_report tag
[370595] D/rfid_module: rfid_report tag
[430629] D/rfid_module: rfid_report tag
[491631] D/rfid_module: rfid_report tag
[552598] D/rfid_module: rfid_report tag
thread pri status sp stack size max used left tick error

tcp_ser 10 suspend 0x000001d8 0x00000800 25% 0x0000000a 000
udp_ser 10 suspend 0x00000228 0x00000400 53% 0x0000000a 000
rf_led 10 suspend 0x00000080 0x00000100 50% 0x0000000a 000
rf_send 10 suspend 0x000000a0 0x00000800 16% 0x00000003 000
rf_read 10 suspend 0x000000c0 0x00000200 37% 0x00000004 000
| /

RT - Thread Operating System
/ | 4.1.0 build Jan 6 2023 17:42:12
2006 - 2022 Copyright by RT-Thread team
lwIP-2.1.2 initialized!
[4416] I/sal.skt: Socket Abstraction Layer initialize success.
[4574] I/rfid_config: reader.id : 4403061904001
[4579] I/rfid_config: reader.beep : 0
[4584] I/rfid_config: report.interval : 60
[4588] I/rfid_config: reader.power : 10
[4594] D/ota_module: ota_flag == ERASE_IAP_FLAG
msh />[4716] D/rfid_module: rfid_report tag
[65642] D/rfid_module: rfid_report tag
[126601] D/rfid_module: rfid_report tag
[151604] D/rfid_module: rfid_report tag
[187619] D/rfid_module: rfid_report tag
[248596] D/rfid_module: rfid_report tag
[309616] D/rfid_module: rfid_report tag
[370621] D/rfid_module: rfid_report tag
[431620] D/rfid_module: rfid_report tag
[492616] D/rfid_module: rfid_report tag
[553600] D/rfid_module: rfid_report tag
thread pri status sp stack size max used left tick error

rf_led 10 suspend 0x00000080 0x00000100 50% 0x0000000a 000
rf_send 10 suspend 0x000000a0 0x00000800 16% 0x00000009 000
rf_read 10 suspend 0x000000c0 0x00000200 39% 0x00000003 000

于是我把OTA的時間改成每10秒一次，果然10秒以后，就出現了hardfault

峰回路轉

那么問題很明確了，就是這個OTA模塊的問題，于是我在OTA模塊里面打斷點排查，發現在socket里面，發送UDP數據包的時候，就出現了hardfault，如下所示

這會是數組越界導致的嗎？于是我開始排查在這個udp發送函數前面的代碼，仔細排查以后，沒發現有數組越界的現象。線索又斷了….怎么辦呢？我左思右想，問題就出現在這，到底是什么原因？

柳暗花明

udp發送，udp發送，會不會是這個線程爆棧了，于是我瞟了一眼這個線程的棧大小，哎喲我去，512字節。

thread = rt_thread_create("ota", ota_thread, RT_NULL, 512, 10, 10);
那我就改一下吧，改1024試試，果然，正常了….松了一口氣…

原來這個線程的棧是1024字節的，后面我使用ps命令看了這個線程棧的利用率還很低，于是我改成了512字節，這也就是說，為什么我之前測試了2天這個模塊都是正常的，現在卻不行了。因為我使用ps命令的時候，那會才運行了幾分鐘，看到的線程棧利用率是沒有調用udp發送函數的，也就是說，那會看到的棧利用率，是不準的，那時候我去減小它，肯定就容易出問題了

當系統正常以后，我再次去ps，發現線程實際的棧利用率是92%，如下所示（前面的ps是沒有調用udp函數之前的，后面的ps是調用udp函數以后的，這時候的棧我設置的大小是1024），也就是說，512字節，肯定是不夠的，甚至1024都快爆了，還得增大。

thread pri status sp stack size max used left tick error

ota 10 suspend 0x0000007c 0x00000400 32% 0x00000005 000
sys_led 10 suspend 0x0000007c 0x00000100 48% 0x0000000a 000
tshell 20 running 0x00000094 0x00001000 13% 0x00000003 000
tcpip 10 suspend 0x000000d0 0x00002000 07% 0x00000014 000
etx 12 suspend 0x00000094 0x00000400 14% 0x00000010 000
erx 12 suspend 0x00000094 0x00000400 56% 0x00000010 000
sys work 23 suspend 0x00000060 0x00000800 53% 0x0000000a 000
tidle0 31 ready 0x00000048 0x00000100 45% 0x00000009 000
timer 4 suspend 0x00000064 0x00000200 24% 0x00000009 000
main 10 suspend 0x00000084 0x00000800 33% 0x0000000e 000
msh />
msh />
msh />
msh />
msh />[14598] D/udp_module: send success
[14628] D/ota_module: ota_flag == ERASE_IAP_FLAG
ps
thread pri status sp stack size max used left tick error

ota 10 suspend 0x0000007c 0x00000400 92% 0x00000001 000
sys_led 10 suspend 0x0000007c 0x00000100 48% 0x0000000a 000
tshell 20 running 0x0000020c 0x00001000 13% 0x00000007 000
tcpip 10 suspend 0x000000d0 0x00002000 07% 0x00000014 000
etx 12 suspend 0x00000094 0x00000400 14% 0x00000010 000
erx 12 suspend 0x00000094 0x00000400 56% 0x00000010 000
sys work 23 suspend 0x00000060 0x00000800 53% 0x0000000a 000
tidle0 31 ready 0x00000058 0x00000100 45% 0x00000018 000
timer 4 suspend 0x00000064 0x00000200 24% 0x00000009 000
main 10 suspend 0x00000084 0x00000800 33% 0x0000000e 000

總結

使用了網絡的線程，一定要將線程棧開大一點，512字節肯定是不夠的，最少1536字節以上
使用ps命令打印出來的線程棧最大使用率，是在代碼運行過一段時間以后，才準的，比如我的代碼中，udp發送數據是在系統啟動10分鐘以后才運行到，所以我在前面幾分鐘的時候使用的ps命令看，ota線程是沒有爆棧的，只有在運行到這個網絡發送數據的代碼，這個棧才會溢出。

因此如果有一些代碼不是立即運行的，在調試的時候，可以把這個時間提前，盡量讓系統上電以后，把所有的代碼都能跑一遍，這樣對于一些跑了一段時間才出現棧溢出的問題，比較容易復現，容易復現也就容易解決。

或者可以在調試代碼的時候，可以把線程棧設置大一些，讓代碼先能夠正常跑起來，然后跑個幾天，再去ps一下看看棧的最大利用率，幾天以后所有的代碼、流程應該基本上都跑過一遍了，這時候的棧利用率才是比較準的，這時候才去優化這個棧大小，會比較合適。

在遇到hardfault的時候，不要怕，用工具不行，我們就手動一個一個模塊去排查，把問題的范圍縮小，盡管耗費的時間會長一點，但是總會定位到問題的。

最后我想，如果rt-thread可以在棧溢出的時候，自動檢測并且定位出來就好了，比如我這個ota的線程棧溢出了，rt-thread就告訴我，xxxx線程棧溢出啦，你得開辟大一點，就好了。