ファームウェアエンジニアの井田です。 今回はESP32系MCUで無線LANによる受信ができなくなる問題の原因と調査方法について解説します。
背景
ESP32にてそこそこ頻繁に無線LAN経由の通信を行っているときに、環境によっては急に通信ができなくなる現象が発生しました。 そこで、Wiresharkを用いて通信状況を確認すると、どうもESP32側からの送信パケットは届いているものの、ESP32へのパケットは受信されていないような状況が確認されました。
例えば、ESP32側からDNSのリクエストを投げて、ルーターが返答をしているのにも関わらず、ESP32のログ上は名前解決に失敗した状態になっています。 また、TCPによる通信も何度も再送が発生しており、よくよく見てみると、ESP32側がACKを返さないので、通信相手のサーバが再送してきているという状態でした。
現象より、ESP32の無線LANドライバが何かしらの要因で停止しているのではないかと思い、無線LANドライバ周りの調査を始めました。
調査
無線LANドライバの動作ログ調査
ESP-IDFには、無線LANドライバの各種統計情報をダンプする関数 esp_wifi_statis_dump が用意されています。使い方としては無線LANドライバの統計情報をダンプしたい場所で esp_wifi_statis_dump(WIFI_STATIS_ALL) を呼び出すだけです。
#include "esp_wifi.h" esp_wifi_statis_dump(WIFI_STATIS_ALL);
実行すると以下のようなそこそこ長い統計情報がログとして出力されます。
I (36094) wifi: BUFFER: I (36094) wifi: t max alloc total_alloc total_free fail_fc fail_oom I (36094) wifi: 1 16 16 113 113 0 0 I (36104) wifi: 2 32 0 2 2 0 0 I (36114) wifi: 3 32 0 186 186 0 0 I (36114) wifi: 4 32 0 0 0 0 0 I (36124) wifi: 5 0 0 4 4 0 0 I (36124) wifi: 6 0 0 0 0 0 0 I (36134) wifi: 7 16 0 163 163 0 0 I (36144) wifi: 8 5 5 81 81 0 0 I (36144) wifi: 9 0 0 97 129 0 0 I (36154) wifi: 10 2 2 2 2 0 0 I (36154) wifi: I (36164) wifi: LMAC TX: I (36164) wifi: tx_all lrc src age to I (36164) wifi: 227 0 0 0 0 I (36174) wifi: 0 0 0 0 0 I (36174) wifi: 59 0 0 0 0 I (36174) wifi: 0 0 0 0 0 I (36184) wifi: 0 0 0 0 0 I (36184) wifi: I (36184) wifi: LMAC RX: I (36184) wifi: ampdu mdpu mgmt ctrl frag I (36194) wifi: 63 100 84 3 0 I (36194) wifi: I (36204) wifi: HW RX: I (36204) wifi: rx_suc rx_end full#1 full#2 I (36204) wifi: f4 4c1b 0 0 I (36214) wifi: I (36214) wifi: Hardware: I (36214) wifi: rxbufbk rxcckerr ofdmerr rx_agc rxsf rx_abort rx_fcs fifofull I (36224) wifi: 0 3ea4 3f61 0 45d6 359 180 0 I (36234) wifi: afull rx_oth tkiperr samebm ack_int rts_int cts_int rifs_int I (36234) wifi: 0 d4 0 0 e5 38 4 0 I (36244) wifi: blockerr hoperr txrts txcts track trcts trigger txhung panic I (36254) wifi: 0 0 c 0 a 38 e 0 0 I (36264) wifi: I (36264) wifi: DIAG: I (36264) wifi: diag0 diag1 diag2 diag3 diag4 diag5 diag6 I (36274) wifi: a00000 0 fa00a03 0 1 5108c0 80 I (36284) wifi: diag7 diag8 diag9 diag10 diag12 diagsel I (36284) wifi: 240 0 82c000 40 0 0 I (36294) wifi: I (36294) wifi: Power save: I (36294) wifi: tbtt beacon timset dtimset tbttdrm actto txwake null1 null0 bcndly sleep wake sleept waket totalt percent I (36314) wifi: 310 265 15 25 293 32 25 92 92 2795 298 297 21483908 10877565 32361473 66.39 % I (36324) wifi: I (36324) wifi: HMAC RX: I (36324) wifi: ifx all data ctl mgmt bcn/probe I (36334) wifi: sta 244 165 0 73 69 I (36334) wifi: ap 0 0 0 0 0 I (36344) wifi: I (36344) wifi: ifx auth assoc deauth action amsdu I (36354) wifi: sta 1 1 0 2 0 I (36354) wifi: ap 0 0 0 0 0 I (36364) wifi: I (36364) wifi: HMAC TX: I (36364) wifi: sta_tx ap_tx psq_tx psq_mc psq_uc ps_uc1 reorder oos amsdu I (36374) wifi: 97 0 0 0 0 0 1
このログはまだ動作しているときのものですが、受信できない状態になると、以下のようなログになることがわかりました。
I (37514) wifi: BUFFER: I (37514) wifi: t max alloc total_alloc total_free fail_fc fail_oom I (37524) wifi: 1 16 16 116 116 0 0 I (37524) wifi: 2 32 0 2 2 0 0 I (37534) wifi: 3 32 0 203 203 0 0 I (37544) wifi: 4 32 0 0 0 0 0 I (37544) wifi: 5 0 0 4 4 0 0 I (37554) wifi: 6 0 0 0 0 0 0 I (37554) wifi: 7 16 15 185 170 0 5 I (37564) wifi: 8 5 5 87 87 0 0 I (37574) wifi: 9 0 0 100 132 0 0 I (37574) wifi: 10 2 2 2 2 0 0
BUFFER の項目には fail_oom という列があり、 t = 7 の行の fail_oom の値が正常時は 0 だったのが 5 に増えています。
この統計情報の出力内容に関してESP-IDFのドキュメントに記載は無いので内容から推測すると、 oom というくらいなのでおそらくOut Of Memoryのことであり、実際 max 列 16 に対して alloc 列 15 となっており、t = 7 の行のバッファの大半が使用中となっていることがわかります。これにより処理中に oomによる領域確保失敗が 5 回起きたのであろうと思われます。
ここまでで、無線LAN受信処理が止まるのは、ドライバがハングアップしているとかではなく、どうもバッファのリークによるものらしいということがわかりました。 無線LANドライバは各国の電波法の規制に対応するためバイナリしか提供されておらず、このバッファのリークが無線LANドライバの内部で起きているのであれば、調査するのがかなり難しくなります。
ただし通信スタックの構成上、無線LANドライバの上位のレイヤでリークしている可能性もあるため、まずはそちらを調べることにしました。
lwIPと無線LANドライバ間の受信データのやりとり
ESP-IDFではIPのプロトコル・スタックとして lwIP を使用しています。よって無線LANドライバからの受信データはlwIPが処理するはずなので、lwIPと無線LANドライバのインターフェース部分を確認してみます。対応するファイルは components/lwip/port/esp32/netif/wlanif.c です。無線LANドライバでデータを受信すると、このモジュールで定義されている wlanif_input 関数が呼び出されます。
この関数の中身をみると、197行目で pbuf_alloc(PBUF_RAW, len, PBUF_REF) を呼び出して参照タイプのpbufを確保しているのがわかります。
pbuf (Packet Buffer) はlwIPでパケットをやりとりするためのバッファを管理するための仕組みです。(lwIPのようなネットワークスタックではプロトコル・スタックの階層構造により、バッファの末尾ではなく先頭方向のデータを追加・削除もよく行うので、専用のバッファ管理機構を持っているものが多くあります。)
参照タイプのpbuf (PBUF_REF を指定したもの) は、その名の通り、その場でpbufのバッファ領域を確保するのではなく、外部で確保されたバッファを取り扱うための仕組みです。
ESP32のlwIPと無線LANドライバの実装では、無線LANドライバから渡された受信バッファをそのまま上位レイヤに渡し、使い終わったら解放のための関数を呼び出します。このとき呼び出される関数は lwIPの netif 構造体の l2_buffer_free_notify フィールドで指定された関数となり、ESP-IDFの無線LANドライバ向けの実装では、内部で無線LANの受信バッファ解放関数である esp_netif_free_rx_buffer を呼び出すようになっています。 よって、無線LAN受信バッファのリークは、lwIPだけでなく、 lwIPを使ったアプリケーションコードでも起こりうるということがわかります。
#if !ESP_L2_TO_L3_COPY /** * @brief Free resources allocated in L2 layer * * @param buf memory alloc in L2 layer * @note this function is also the callback when invoke pbuf_free */ static void lwip_netif_wifi_free_rx_buffer(struct netif *netif, void *buf) { esp_netif_t *esp_netif = esp_netif_get_handle_from_netif_impl(netif); esp_netif_free_rx_buffer(esp_netif, buf); } #endif // (省略) static void low_level_init(struct netif *netif) // 無線LANドライバ用のlwIP netifの初期化処理 { // (省略) #if !ESP_L2_TO_L3_COPY netif->l2_buffer_free_notify = lwip_netif_wifi_free_rx_buffer; // <- 無線LANバッファ解放用関数を指定している #endif } // (省略) void ESP_IRAM_ATTR wlanif_input(void *h, void *buffer, size_t len, void* eb) { // (省略) #if (ESP_L2_TO_L3_COPY == 1) p = pbuf_alloc(PBUF_RAW, len, PBUF_RAM); if (p == NULL) { esp_netif_free_rx_buffer(esp_netif, eb); return; } p->l2_owner = NULL; memcpy(p->payload, buffer, len); esp_netif_free_rx_buffer(esp_netif, eb); #else p = pbuf_alloc(PBUF_RAW, len, PBUF_REF); // 197行目 if (p == NULL){ esp_netif_free_rx_buffer(esp_netif, eb); return; } p->payload = buffer; p->l2_owner = netif; p->l2_buf = eb; #endif
さきほどの無線LANドライバとのインターフェース部分のコードで、 ESP_L2_TO_L3_COPY というマクロが何度か登場します。このマクロは lwipopts.h で #define ESP_L2_TO_L3_COPY CONFIG_LWIP_L2_TO_L3_COPY として定義されており、 CONFIG_LWIP_L2_TO_L3_COPY はIDFの設定 (menuconfigでの設定) で変更できます。デフォルトは 0 になっているため、先程の PBUF_REF を使ったコードになりますが、 1 に変更することにより、バッファを新規に確保してそこに無線LAN受信バッファの内容をコピーして無線LAN受信バッファを即座に解放するようになります。
つまり、上位レイヤの処理が原因でリークしているのであれば、 CONFIG_LWIP_L2_TO_L3_COPY を有効にすれば少なくとも無線LANドライバの受信バッファのリークは発生しなくなるはずです。
そこで、 CONFIG_LWIP_L2_TO_L3_COPY を 1 にして再度ログを取得したところ、無線LANドライバの受信バッファのリークが起きなくなりました。よって、問題は無線LANドライバではなく lwIP以上の層 ということがわかりました。
lwIPのpbufを使うAPI
ここで普段からsocket APIを使ってソフトウェアを書いている方であれば、socket系のインターフェースで下位層のリソースリークを引き起こせるような記述ができるだろうか？と疑問に思われるかもしれません。socket APIの場合、recvで指定するのはあくまでrecvを呼び出したコード側が確保したバッファであり、下位層のバッファを直接扱うことはできないからです。
実はlwIPにはsocket APIだけではなく、受信したデータを含むpbufを直接扱うことのできるコールバック型のAPIが用意されています。例えばUDPのパケット受信処理を行う udp_recv では、データ受信時に呼び出される udp_recv_fn を指定しておいて呼び出してもらう形式になります。
void udp_recv (struct udp_pcb *pcb, udp_recv_fn recv, void *recv_arg);
ここで udp_recv_fn の仕様を見ると、引数として渡された pbuf は コールバック関数側で責任を持って解放すること となっています。つまりここの実装を間違うと容易にpbufがリークするということです。
typedef void(* udp_recv_fn) (void *arg, struct udp_pcb *pcb, struct pbuf *p, const ip_addr_t *addr, u16_t port);
実際、今回発生していた不具合は、MatterのmDNSサーバーの終了処理が漏れており、UDP受信関数に渡されたpbufがリークしていたのが原因でした。
まとめ
- ESP32の無線LAN経由の通信ができなくなったときは、
esp_wifi_statis_dump関数が役に立つ esp_wifi_statis_dumpの結果、無線LANの受信バッファがリークしていた場合は上位層でpbufを扱うAPIを使っている部分を確認するとよい
Nature開発者Community
Natureのプロダクトに関する開発者向けの情報を交換する場として、 Nature開発者コミュニティ をDiscord上に立ち上げています。
matter チャネルもありますので、Remo nanoとMatterの開発に関することなど、気軽にご質問いただければと思います。
エンジニア募集中
こんな感じで問題を解決しつつ、ESP32向けのファームウェアを一緒に書いてくれる方を募集中です。
カジュアル面談もやってますので、ぜひ。
Natureのミッション、サービス、組織や文化、福利厚生についてご興味のある方は、ぜひCulture Deckをご覧ください。
更新履歴
- 2024/05/01 : 初版
