分析 kendryte K210 micropython 網絡下載 kmodel 模型時的 core dump: illegal instruction 的錯誤，進一步對從網絡 HTTP 下載文件的過程進行修復和優化。

起因

於2020年3月1日時發現 kendryte K210 的 micropython 從網絡下載大塊文件（kmodel）的存儲過程中，（大概率）隨機出現 illegal instruction 的 crash 現象。

錯誤現場

關聯 ：espcoredump、map、objdump。

錯誤類型 illegal instruction 指令解析錯誤，關聯常見錯誤 ESP32 官方文檔（五）嚴重錯誤

core dump: illegal instruction
Cause 0x0000000000000002, EPC 0xfffffff6666f7c7e
reg[00](zero ) = 0x0000000080301b28, reg[01](ra   ) = 0x7f807c76666f7c7e
reg[02](sp   ) = 0x0000000080300bd8, reg[03](gp   ) = 0x0000000080212188
reg[04](tp   ) = 0x0000000000000000, reg[05](t0   ) = 0x0000000000000019
reg[06](t1   ) = 0x0000000000001000, reg[07](t2   ) = 0x0000000000000009
reg[08](s0/fp) = 0x7d868a877476837c, reg[09](s1   ) = 0x7b6a747c826f8489
reg[10](a0   ) = 0x00000000000002d6, reg[11](a1   ) = 0x0000000080316b0a
reg[12](a2   ) = 0x00000000000002d6, reg[13](a3   ) = 0x0000000000000087
reg[14](a4   ) = 0x0000000000000284, reg[15](a5   ) = 0x000000000000055a
reg[16](a6   ) = 0x0000000000000001, reg[17](a7   ) = 0x0000000000c65d40
reg[18](s2   ) = 0x7a727b8b8a737f85, reg[19](s3   ) = 0x8474817c7a7c8a8a
reg[20](s4   ) = 0x96ff84827a7a8382, reg[21](s5   ) = 0x6d80718190608983
reg[22](s6   ) = 0x768b7f8471807976, reg[23](s7   ) = 0x83797e8e7b77818c
reg[24](s8   ) = 0x866c7d8a7e7c7a7b, reg[25](s9   ) = 0x8a847d8e78877281
reg[26](s10  ) = 0x868580848d7b7a7a, reg[27](s11  ) = 0x64887781888a877a
reg[28](t3   ) = 0x0000000000000000, reg[29](t4   ) = 0x0000000000000007
reg[30](t5   ) = 0x0000000080301b28, reg[31](t6   ) = 0x0ccccccccccccccc
freg[00](ft0 ) = 0x0000000000000000(), freg[00]() = 0x0000000080114910()
freg[02](ft2 ) = 0x0000000000000000(), freg[00]() = 0x0000000080114920()
freg[04](ft4 ) = 0x0000000000000000(), freg[00]() = 0x0000000080114930()
freg[06](ft6 ) = 0x0000000000000000(), freg[00]() = 0x0000000080114940()
freg[08](fs0 ) = 0x0000000000000000(), freg[00]() = 0x0000000080114968()
freg[10](fa0 ) = 0x0000000041200000(), freg[00]() = 0x0000000080114998()
freg[12](fa2 ) = 0x0000000000000000(), freg[00]() = 0x00000000801149c0()
freg[14](fa4 ) = 0x3733312c447a0000(), freg[-1610612736]() = 0x00000000801149d0()
freg[16](fa6 ) = 0x8faa245a00000000(), freg[-2147483648]() = 0x00000000801149e0()
freg[18](fs2 ) = 0x8e80717300000000(), freg[536870912]() = 0x0000000080114a08()
freg[20](fs4 ) = 0x8685808400000000(), freg[536870912]() = 0x0000000080114a18()
freg[22](fs6 ) = 0x866c7d8a00000000(), freg[-1073741824]() = 0x0000000080114a28()
freg[24](fs8 ) = 0x768b7f8400000000(), freg[-536870912]() = 0x0000000080114a38()
freg[26](fs10) = 0x96ff848200000000(), freg[-1610612736]() = 0x0000000080114a48()
freg[28](ft8 ) = 0x7a727b8b00000000(), freg[-536870912]() = 0x0000000080114a70()
freg[30](ft10) = 0x7d868a8700000000(), freg[-1610612736]() = 0x0000000080114a80()
W (173762547693) SYSCALL: sys_exit called by core 0 with 0x539

相關資料

寄存器基礎

[MIPS 獲得內核中當前進程的棧回溯信息]（https://www.cnblogs.com/sky-heaven/p/10386600.html）

cause : 觸發原因

epc : exception program counter 異常程序計數器 產生異常時的PC指針的值

ra : return address 子程序的返回地址

regs : register 寄存器情況

fregs : float 寄存器情況（看 crt.s 代碼應該是 SFREG Sign flag 標記寄存器 共 32 個）

sp : sp寄存器，用來跟蹤程序執行過程。

關聯 linux kernel panic 分析方法 根據epc 定位linux kernel panic 位置。

關於內核報錯 “Unable to handle kernel paging request at virtual address” 的問題, 絕大多數都是由於程序使用了不可用的指針而引起的, 定位這類問題的辦法很簡單,也希望我的描述足夠簡單實用.

樣本分析

由於這個芯片目前比較新，也沒有現成工具，只好手工分析了。

注意編譯后得到的 maixpy.txt 和 我創建的 error.txt ，起因在這里下載文件過程中，對 socket 進行 readinto 過程中 crash 了。

我先初步確認了表層代碼的運行情況 python 最后停在了如下代碼位置，也就是從這里以后的 C 代碼之間出了問題。

        # ------------------------------------------------------------------------

        def ReadContentInto(self, buf, nbytes=None) :
            if nbytes is None :
                nbytes = len(buf)
            if nbytes > 0 :
                try :
                    print('self._socket.readinto(buf, nbytes)') # 這里。
                    x = self._socket.readinto(buf, nbytes)
                    if x < nbytes :
                        self.Close()
                    return x
                except :
                    self.Close()
            return 0

        # ------------------------------------------------------------------------

這種指令錯誤多少也都是一些指針操作出了問題，琢磨着可能是 AT 沒有應答或應答錯誤就超時處理了，對於這種情況的時候，仔細檢查代碼邏輯的 IF 判斷，大致先定位到附近。

也就是 usocket 附近，這時候注意到，它走的是 python 標准庫的 stream 流輸入和輸出。（需要懂一點 micropython 的架構）

現在存在三個方向可以繼續分析

• 繼續定位 core dump 的位置
• 繼續打 log 定位實時棧數據。
• 有時候這種問題會被靜態分析出來，如一些不被注意的警告可能隱含缺陷代碼。

階段二

目前已經知道是 usocket 模塊出了問題，也知道是 readinto 出了問題，同時也知道是底層 C 代碼出了問題。

那么單看匯編碼來看整體的函數符號情況，可以知道整個 maxipy 的代碼中只有 stream_readinto 和 mp_machine_spi_write_readinto 兩種 readinto ，但另一邊已經知道 socket 用的是 stream_readinto ，因此重點看 stream_readinto 的源碼。

並且將 000000008002a0c2 <stream_readinto>: 的地址拿到 core dump 里各種長短匹配都沒有，那么說明，stream_readinto 並不是報錯現場，它只是我們上層代碼的重點，因此繼續挖掘。

靜態分析的時候，可能會丟失動態鏈接的函數變量，因為發現 stream_readinto 匯編碼中顯式調用的 stream_readinto 的代碼只有內部，則意味着還要繼續分析其他跳轉的函數。

如 mp_stream_rw ，所以我們回到代碼，根據 core dump 的函數地址偏移來看錯誤是，暫時找不到頭緒了，說明宕機的函數地址並非在這里面。

階段三

如果 core dump 無法看到最末端的錯誤現場，按這個異常數據來看，應該是跑飛了，但某些寄存器還是會存在一些遺留的。

但我此時試着從代碼邏輯上去理解，縮小范圍判斷問題，因為是從網絡上下載數據到 flash 中，那么我先把 flash 移除，此時發現，問題實際上出在 flash 上。

那么前面的 socket 實際上就誤導了我們，說明它是兩者之間相互影響了，那么判斷變成，可能是因為 fs 的 cache 導致了宕機爆 core dump 。

那么我繼續看 core dump 的寄存器情況，這期間，我已經確認了，若是不將數據寫入 flash 則沒有問題，那么再結合最近的一些地址判斷現場。

這時從 core dump 追過去，才發現發生錯誤的現場不是最初想的那樣，所以一開始還是應該仔細核對 core dump 的值才是。

但此時觀察到相關的代碼都是 Sync 和 Write 有關的操作，看來應該是發現問題了。

那么如何修復呢？

等我繼續更新？

如果不能抓到函數現場，那我只能寫完整的 Flash 單元測試來試圖觸發這個事件了。

更新 2020年3月3日。

階段四

經過 Flash 測試后，確認並非 flash 問題。

現在開始正向捕獲錯誤，根據 core dump 的情況來看，地址已經亂了，說明跑飛的同時還經過了許多動態函數鏈。

截至目前，追蹤函數鏈為

stream_readinto
-> mp_stream_read_exactly
-> mp_stream_rw
-> io_func == socket_stream_read typedef mp_uint_t (*io_func_t)(mp_obj_t obj, void *buf, mp_uint_t size, int errcode);
mp_uint_t (recv)(struct _mod_network_socket_obj_t *socket, byte *buf, mp_uint_t len, int _errno);
-> self->nic_type->recv(self, (byte)buf, size, errcode);
-> esp8285_socket_recv

MP_THREAD_GIL_ENTER

mp_uint_t out_sz = io_func(stream, buf, size, errcode);

out_sz 468

socket_stream_read

MP_THREAD_GIL_EXIT

self->nic_type->recv 80044422
core dump: illegal instruction

明日繼續 這會必須用 printk 了。

更新 2020年3月5日

uart_stream->read(nic->uart_obj,temp_buff + temp_buff_len,1,&errcode);

又一次新增了 machine_uart_read ，見鬼，怎么還不到頭。

但是運氣很好的是函數棧終於退出來了，終於不閃退了，但是問題也來了。

• 如果是串口接收緩沖區問題，則調大，並沒有符合預期，不是。

• 如果是函數棧不夠大，測試了一下，調大 ld 文件的棧空間，發現不是。

最后判斷一個情況，當把 printk 導入后，有時候發現函數執行后結束了也沒有回到調用函數位置，那么應該是函數內部的指針誤操作，破壞了函數棧內容，導致函數執行完成后回不去，所以 epc 和 ra 的地址才會如此混亂。

那么，要么繼續檢查 machine_uart_read 的指針操作，要么回到上層檢查可能的指針誤操作。

幸運的是已經發現大致存在的錯誤了。

還沒辦法根除問題，想來還是得拿靜態分析工具來預處理一下函數。

繼續，更新 2020年3月5日。

繼續，2020年3月6日 02點39分 更新

經過了一天的排查和修復，姑且不會再爆 core dump 了，現在是看到 AT 8285 的驅動代碼出了問題。

問題應該是 int recvPkg(esp8285_objnic,char out_buff, uint32_t out_buff_len, uint32_t data_len, uint32_t timeout, char coming_mux_id, bool* peer_closed, bool first_time_recv) 這個關鍵函數的設計有缺陷

在經過了一天的測試后發現幾個現象，大致確認了問題的發生原因。

• esp_recv 函數 調用 recvPkg 后無法回到調用處。
• 數據量大的時候才會發生這個問題。

在面對大量數據傳輸的時候，在棧上動態申請的數組地址越界訪問，這也就導致了 ra 地址不正常，導致無法回到上層函數。

我本來應該早點懷疑的，看到 ra 寄存器地址混亂的時候，我就該想象函數棧被破壞了，然后無法回到調用的函數位置，函數棧能被破壞，肯定是函數內部申請的數組指針被誤操作破壞了，所以才會出現混亂的數據

然后看圖的時候，發現有很多處訪問地址不檢查的代碼，我心都快涼了。

整個循環都沒有注意保護緩沖區的訪問，直接就進行 temp_buff[temp_buff_len] 的操作，而實際上應該先 temp_buff_len < sizeof(temp_buff) 鎖定邊界后才操作好吧。

最后先把棧上申請的緩沖區移到堆了，也就是 static 處理，至少越界不會破壞函數棧了，所以這時候沒有再出現 core dump 了，先這樣處理了，然后之后再做邏輯代碼的修復。

更新 2020年3月6日

估計還是得修復一下代碼的細節，理一下思路再改代碼。

今天繼續修復，檢查發現，緩存區確實存在操作不當的長度，先不做邊界檢查，了解邏輯代碼后。

簡單擴大一下緩沖區（前面通信調試時發現存在大於 1024 的情況），現在又出現新的錯誤，但這次總算是正常了，core dump 的 misaligned load 錯誤，這次數據沒有混亂了，很快就定位問題了。

看一下代碼的實現應該是做了雙緩沖，第一層先解開數據，第二層則是合並第一層解開的數據，從而供應給上層 micropython 的接口。

階段五

已經修復大部分問題。

修復方案：

自上次修復緩沖區的變量，防止溢出后就解決了，但 flash 的下載超時的問題仍然沒解決。

現在做一下問題的總結，有如下幾種驗證和現象。

• 最早已經在 115200 上確認下載 380KB 的模型文件可以正常獲取，說明了下載流程一般情況下是正常的，但之后開始將波特率調高到 460800 或 576000 兩者。
• 接着測試 flash 讀寫到 2M 都沒有問題，寫滿了啟動不了 micropython 是其他問題，確定了 flash 是可以正常使用。
• 如果不將 AT esp8285 下載接收的數據寫入 flash ，則會完整的下載完成，確定了下載流程是正常的。
• 如果一邊下載一邊寫入，則此時速度會下降，可以很明顯的看到下載過程的速度慢了下來，此時要么超時失敗，要么極小概率卡死什么反應也沒有，陷入了等待數據，但又無法判斷是否超時來返回 micropython 上層。

進行下載的代碼在這部分

那么我們理一下思路，當從 115200 升上來后，AT 固件給回的數據會加快，這意味着串口的接收緩沖區應該要大一些，否則 AT 被動接收的數據就會溢出，導致下載過程中在緩慢寫入 Flash 的時候，將會無視或溢出這部分 AT 給回的數據，也就造成之后的超時，因為當你不去接收數據的時候，AT 仍然在吐出數據，如果吐完了停下來，那么這時候再等待數據的程序自然是等不到了，所以超時退出。

所以為了驗證這個假設，取消了寫入 flash 操作，然后確實能夠完整獲取下載的數據，表示有一半如我所想，也就是下載數據的這個過程暫時不可控，沒有使用協議主動去要指定長度的數據，那么現在進一步驗證，假設使用 flash 寫入很慢導致超時，那么使用 sdcard 呢，結果換了 sdcard 寫入速度更快，可以明顯的看出返回變快，此時下載過程完整了，那么此時說明在這種不可控的下載過程中，寫入文件的速度應快過下載的速度，很難想象 flash 的寫入速度會低於 46kb/s ，也不知道發生了什么。

最后在下載數據傳輸過程中，存在小概率傳輸錯誤，這個在最后有提及，可能是串口傳輸的原因也可能是網絡傳輸的原因。

很奇怪的現象還有一點，如果上面的思考是正確的，那么當我試圖通過延時來模擬 file.write 寫入過程帶來的延時 5s 帶來的效果應該是不再接收到數據，但實際上還是接收到了，要么是串口緩沖區過大可以存放（類似 DMA 緩沖），要么是兩者之間，存在互斥操作，暫時還不得為知。

進一步關注以下幾處功能或變量。

read_buf_len

配置后會重新生成更大的緩沖區

配置串口的接收緩沖區，對應 esp8285 的 recvPkg 接收用，如果過小，也沒有配置 DMA 緩沖區的情況下，就會直接溢出 overflow ，代碼還沒對這種情況做處理

socket recvbuf

esp8285 的 recvPkg 接收過程中對 AT 數據的解析處理以及合並，假設 TCP 默認的數據包最大 1580 ，所以我設置為 2048 ，也許不一定有效，但調試的時候發現有時候數據長度的索引會上到 1400+ ，在來不及處理的情況下，至少有 2k 做緩沖。

（其中的代碼未做邊界檢查）

socket timeout

micropython 在 socket 層次的超時機制，因為在執行 socket.readinto 的時候會進入臨界區，此時是無法通過 Ctrl + C 退出來的，設計 socket 非阻塞很重要，絕對不能沒有嘻嘻。

如果下載的時候設置為 0 表示立即返回的話，就無法得到數據了，也許用 poll 模型會有反應？還不確定，所以至少設置為 3 ~ 5 吧。

flash speed

只分了 2M 的 flash ，但寫入速度很慢，也不知道是什么原因，也許 micropyton 的解析執行也在占用整片 flash 吧，而不單是從 flash 上分出來的 micropython VFS 在用。

sdcard speed

我用的是淘寶十塊錢的 256M 和 1G ROM 的辣雞內存卡，相比 flash 自然是空間大，且比 flash 的寫入快，回頭測一下速度。

spiffs cache

編譯出來的固件與平時的區別就是在 python 的 file.write 的時候就會直接調用 flash 將數據寫入磁盤，而不是等到 close 才寫入，這個和 C 庫 stdio 保持一致。

階段六

文件下載過程中存在幾處出錯，之后要修復。

暫時通過 AT+UART_DEF=576000,8,1,2,1 添加串口的偶校驗后，確定了下載文件是完整了的，沒有出現錯誤，也不知道會不會還有其他問題，暫時再觀望，多測試過后再確認吧。

尾聲

其實大部分問題都算是解決了，而且對整個流程也算是理了一遍，之后再出什么問題，就再解決了就好，之后應該不會怎么更新這個問題了吧 2020年3月9日。

最開始壓根不是這個問題的鴨！