ESP32で市場で発生したExceptionを検知して解析する方法

こんにちは。IoT開発チームで組み込みソフトウェアエンジニアをやっているいまみーです。

hacomonoはウェルネス産業向けのVirtical SaaS企業ということもあり、ソフトウェア開発が中心となっている会社ではありますが、そんな弊社にはIoT開発を行う部門があり、回路設計から、中に組み込むファームウェア、それらハードウェアが収まる筐体開発まで、、モノに纏わる領域も自社開発を行なっている、SaaS業界でも珍しいスタートアップです。

今回は、そんなIoT領域でも、組み込み開発に関するテーマで書いていきたいと思います。

マイコンでデバイスを開発する場合、プログラミングのミスや、他の要因によるさまざまな障害に対処しなければならないことがあります。その中でも、プログラマーが意図せずして、アドレス例外やアライメント例外など様々なバグを引き起こしてしまいデバイスが再起動する。もしくは、ちゃんと実装・テストはしたつもりだけど、組み込み機器という物理世界と密接に関わる特性ゆえ、市場により異なるさまざまな環境に晒されることで想定外のバグが起こってしまった、、なんて事は、組み込みの世界では往々にしてある事です。

弊社がIoTデバイスの開発で採用しているESP-IDFにも、Exception発生時にトレースを出力してくれる機能があります。

Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4000c2e4  PS      : 0x00060e30  A0      : 0x800d4329  A1      : 0x3ffb4990  
A2      : 0x00000000  A3      : 0x3ffb49a0  A4      : 0x000000ff  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x00000000  A8      : 0x00000000  A9      : 0x00000001  
A10     : 0x383f8000  A11     : 0x3ffb1fb0  A12     : 0x00060220  A13     : 0x00060223  
A14     : 0x3ffb06d0  A15     : 0x0000cdcd  SAR     : 0x0000001b  EXCCAUSE: 0x0000001d  
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x0000000e  

Backtrace: 0x4000c2e1:0x3ffb4990 0x400d4326:0x3ffb49a0 0x400d4303:0x3ffb4ac0 0x400e45d2:0x3ffb4ae0

一見すると、意味不明な16進数の羅列ですが、これがアドレスとソースコードの該当する行が対応する形となっていて、Espressifが提供しているツールで解析にかけると、 Exceptionの発生位置を特定することが出来るものになっています。

./xtensa-esp32-elf-addr2line -pfiaC -e ~/../build/firmware.elf 0x4000c2e1:0x3ffb4990 0x400d4326:0x3ffb49a0 0x400d4303:0x3ffb4ac0 0x400e45d2:0x3ffb4ae0

↓

0x400d4326: app_main at /../main/main.c:83　<-- 再起動しちゃったところ
0x400d4303: app_main at /../main/main.c:4
0x400e45d2: main_task at /../esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/port_common.c:131 (discriminator 2)

開発段階でこういった事が発生したらならまだしも、市場リリース後のデバイスにて発生してしまった場合に、これをどうやって検知しよう？

というのが今回の記事のテーマです。

例外発生による再起動かを見分ける方法

ESP-IDFにて、マイコンが最後にリセットした要因を取得できる方法が提供されています。

これを見ることで、起動要因を判定することができます。今回のケースで言うと、「ESP_RST_PANIC」であれば例外発生により再起動した、と判断する事ができそうです。

トレースの出力内容を取得したい

マイコンがどのような理由で起動したかを判定できるようにはなりましたが、一番欲しいのは例外発生時に出力されるBacktraceです。これを再起動前に何処かへ保存しないといけません。

そもそも、どこでトレース内容をログ出力しているのかですが、行っているのは以下の関数になります。

esp-idf/components/esp_system/port/arch/xtensa/panic_arch.c

void panic_print_backtrace(const void *f, int core)
{
    XtExcFrame *xt_frame = (XtExcFrame *) f;
    esp_backtrace_frame_t frame = {.pc = xt_frame->pc, .sp = xt_frame->a1, .next_pc = xt_frame->a0, .exc_frame = xt_frame};
    esp_backtrace_print_from_frame(100, &frame, true);
}

esp-idf/components/esp_system/port/arch/xtensa/debug_helpers.c

esp_err_t IRAM_ATTR esp_backtrace_print_from_frame(int depth, const esp_backtrace_frame_t* frame, bool panic)
{
    //Check arguments
    if (depth <= 0) {
        return ESP_ERR_INVALID_ARG;
    }

    //Initialize stk_frame with first frame of stack
    esp_backtrace_frame_t stk_frame = { 0 };
    memcpy(&stk_frame, frame, sizeof(esp_backtrace_frame_t));

    print_str("\r\n\r\nBacktrace:", panic);
    print_entry(esp_cpu_process_stack_pc(stk_frame.pc), stk_frame.sp, panic);

    //Check if first frame is valid
    bool corrupted = !(esp_stack_ptr_is_sane(stk_frame.sp) &&
                       (esp_ptr_executable((void *)esp_cpu_process_stack_pc(stk_frame.pc)) ||
                        /* Ignore the first corrupted PC in case of InstrFetchProhibited */
                        (stk_frame.exc_frame && ((XtExcFrame *)stk_frame.exc_frame)->exccause == EXCCAUSE_INSTR_PROHIBITED)));

    uint32_t i = (depth <= 0) ? INT32_MAX : depth;
    while (i-- > 0 && stk_frame.next_pc != 0 && !corrupted) {
        if (!esp_backtrace_get_next_frame(&stk_frame)) {    //Get previous stack frame
            corrupted = true;
        }
        print_entry(esp_cpu_process_stack_pc(stk_frame.pc), stk_frame.sp, panic);
    }

    //Print backtrace termination marker
    esp_err_t ret = ESP_OK;
    if (corrupted) {
        print_str(" |<-CORRUPTED", panic);
        ret =  ESP_FAIL;
    } else if (stk_frame.next_pc != 0) {    //Backtrace continues
        print_str(" |<-CONTINUES", panic);
    }
    print_str("\r\n\r\n", panic);
    return ret;
}

この辺りのライブラリをハックすれば期待するものが取れそうですが、ESP-IDFに直接変更を加える事になるので、あまりやりたい方法ではありませんね。

コンパイラのwrap機能を利用する

コンパイルの時にwrapオプションを使用することで任意の関数が実行される前に、wrap関数を割り込ませて実行する、といった事が可能です。今回はこの機能を活用してみることにしました。

extern void __real_panic_print_backtrace(const void* f, int core);

// オーバーライドされる関数
void __wrap_panic_print_backtrace(const void* f, int core) {
    // 割り込ませて実行したい処理

    // 元のpanic_print_backtrace関数を呼び出す
    __real_panic_print_backtrace(f, core);
}

また、この機能を利用するには、プロジェクトのrootにあるCMakeList.txtにリンカの設定が必要になります。

cmake_minimum_required(VERSION 3.16)
set(EXTRA_COMPONENT_DIRS    ".")
include($ENV{IDF_PATH}/tools/cmake/project.cmake)
idf_build_set_property(LINK_OPTIONS "-Wl,--wrap=panic_print_backtrace" APPEND) <- 必要な設定
project(hacomono-fw)

Backtraceのデータをどこに保存するか

トレースを出力する関数をオーバーライドさせる事ができるようになったので、この関数内で保存する処理を入れれば良さそうです。

あとは、トレースの情報をどこに保存するかですが、一番手っ取り早い、RTC SLOW MEMORYを使用する事にしました。リファレンスにはディープスリープ中でもデータが消えないとありますが、リセットによる再起動でも初期化されずに値を保持してくれます。

以下は、これらの機能を利用してwrapした関数でコールスタックを保存し、再起動後にその情報を参照するコードです。

#define STACK_DEPTH 32
typedef struct {
    uint32_t pc[STACK_DEPTH];
    uint32_t sp[STACK_DEPTH];
} ExceptionInfo_t;

// RTC SLOW MEMORYに配置されます
RTC_NOINIT_ATTR static ExceptionInfo_t s_exception_info;

void __wrap_panic_print_backtrace(const void* f, int core) {
    XtExcFrame* xt_frame = (XtExcFrame*) f;
    esp_backtrace_frame_t stk_frame = { .pc = xt_frame->pc, .sp = xt_frame->a1, .next_pc = xt_frame->a0, .exc_frame = xt_frame };
    esp_backtrace_get_start(&(stk_frame.pc), &(stk_frame.sp), &(stk_frame.next_pc));

    // 最初のスタックフレームが有効か
    bool corrupted = !(esp_stack_ptr_is_sane(stk_frame.sp) &&
                       (esp_ptr_executable((void*) esp_cpu_process_stack_pc(stk_frame.pc)) ||
                        /* Ignore the first corrupted PC in case of InstrFetchProhibited */
                        (stk_frame.exc_frame && ((XtExcFrame*) stk_frame.exc_frame)->exccause == EXCCAUSE_INSTR_PROHIBITED)));

    // 最後のコールスタックから、順番に取り出していく
    uint32_t i = STACK_DEPTH;
    while (i-- > 0 && stk_frame.next_pc != 0 && !corrupted) {
        if (!esp_backtrace_get_next_frame(&stk_frame)) { // 前のスタックフレームを取得
            corrupted = true;
        }
        s_exception_info.pc[CALL_STACK_DEPTH - i] = esp_cpu_process_stack_pc(stk_frame.pc);
        s_exception_info.sp[CALL_STACK_DEPTH - i] = stk_frame.sp;
    }

    // 元のpanic_handler関数を呼び出して、このエラーの処理を終了させる
    __real_panic_print_backtrace(f, core);
}

void app_main(void) {
    // 例外発生による再起動かを判定
    esp_reset_reason_t reason = esp_reset_reason();
    if (reason == ESP_RST_PANIC) {
        char backtrace_str[1024];
        uint16_t offset = 0;
        offset += sprintf(backtrace_str + offset, "Backtrace: ");
        for (uint8_t i = 0; i < CALL_STACK_DEPTH; i++) {
            if (s_exception_info.pc[i] != 0 && s_exception_info.sp[i] != 0) {
                offset += sprintf(backtrace_str + offset, "0x%08x:0x%08x ", (unsigned int) s_exception_info.pc[i], (unsigned int) s_exception_info.sp[i]);
            }
        }
                // ダンプ
        ESP_LOGI(LOG, "%.*s", strlen(backtrace_str), backtrace_str);
    }
}

こんな感じで、Backtraceが出力されればOKです！

I (1599) [main]: Backtrace: 0x4000c2e1:0x3ffb4990 0x400d4326:0x3ffb49a0 0x400d4303:0x3ffb4ac0 0x400e45d2:0x3ffb4ae0

まとめ

弊社では、ファームウェアの例外エラーによる再起動をこのように検知し、クラウドに送信することで、異常を検知し市場のデバイスの品質改善に努めようとしています。

ただ、Backtraceと.elfをデコードして解析結果を出力するのは現状手作業で行っているので、将来的にはその辺りの自動化までがんばっていきたいですね。

少しニッチな内容ではありますが、何かご参考になれば幸いです。

株式会社hacomonoでは一緒に働く仲間を募集しています！
採用情報や採用ウィッシュリストも是非ご覧ください！

hacomono TECH BLOG

フィットネスクラブ・スクールなど施設・店舗のための会員管理・予約・決済システム「hacomono」開発チームの技術ブログ

ESP32で市場で発生したExceptionを検知して解析する方法

例外発生による再起動かを見分ける方法

トレースの出力内容を取得したい

コンパイラのwrap機能を利用する

Backtraceのデータをどこに保存するか

まとめ