Fusic Tech Blog

Fusion of Society, IT and Culture

mruby-esp32-app-mirbをESP32で動かしてみた - panicの原因を見つけるまでの過程
2021/12/15

mruby-esp32-app-mirbをESP32で動かしてみた - panicの原因を見つけるまでの過程

本記事は Ruby Advent Calendar 2021 の16日目の記事です。 昨日は @ooooooo_qさんと、 Fukuoka.rb でも時々お会いする @hasimoto1009 さんの記事でした。(まだ公開されていませんが、じきに公開されるはず!)

今回は久々にmrubyに関する記事です。

mruby logo

今年は この記事この記事 でMicroPythonに浮気して、mrubyと比較したときのMicroPythonの強さを実感した年でした。特に、イメージをダウンロードしてESP32等のデバイスにFlashするだけでPythonでデバイス制御できるのは、とても良い仕組みだと思いました。

さて、mrubyはというと残念ながらESP32で動くイメージそのものが公開されているわけではありません(もしあったら教えていただけると助かります)一方、有志の方がESP32用にポーティングしたmrubyおよびmrubyのREPLである mirb のソースコードをGitHubに公開してくれています。

このうち、mruby-esp32/mruby-esp32 は簡単に動作させることができたのですが mruby-esp32/mruby-esp32-app-mirb はESP32上でpanicが発生し、使えない状態でした。その後、さまざまな手段を尽くして原因を特定し、無事直すことができたので、本記事ではその過程をご紹介します。

最終的にはこのようにESP32上でmrubyのIRB(mirb)が動作するようになりました。

mirb on ESP32

前提知識

ESP32

ESP32-DevkitC

今回はEspressif Systems社の無線通信モジュール、ESP32-WROOM-32Eの評価基板である ESP32-DevKitC-32E (以下、ESP32)を使用して検証しています。秋月電子で1230円で販売されているので、気軽に購入できるところが良いですね。

ESP32とPCはUSBケーブルで接続します。この接続はシリアル通信と電源供給という2つの役割を担っています。

esp-idf

Espressif logo

mruby-esp32/mruby-esp32mruby-esp32/mruby-esp32-app-mirb もREADMEに書いてある手順でPC上でビルドして、デバイスにFlashします。

簡単そうに書きましたが、実際には esp-idf と呼ばれるフレームワークを使用する必要があり、ハマりどころの多い作業です。全てを書くと長くなるので、詳細はそのうち別の記事でまとめたいと思います。今回は v4.1.2 を仕様しています。

mirb

今回動かそうとしているmirbについて少しご紹介します。Rubyを使ってプログラミングをしている方であれば誰しも1度は irb を使った経験があると思います。irb はRubyのREPLであり、対話形式でプログラムを入力し、実行結果を即時確認できるので便利ですよね。

mirbirb のmruby版と思っていただければOKです。 mruby がベースとなっていることで省リソース化されているので、今回のようにリソースの乏しいデバイス上で動作させることができます。

mruby 3.0.0

mruby-esp32/mruby-esp32 では このコミット でmruby 3.0.0に対応するための修正がなされています。

一方、当初 mruby-esp32/mruby-esp32-app-mirb にはこの変更が適用されていなかったので、手元の環境で適用した状態で動作確認を開始しました。現在では 私の出したPull request がマージされているのでこの変更は適用されています。

mruby-esp32-app-mirbで発生した問題

現象

ESP32にFlashし、シリアル通信で接続すると以下のようなpanicが発生しました。

mirb - Embeddable Interactive Ruby Shell

> 1
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC      : 0x400d855e  PS      : 0x00060130  0      : 0x800d3e38  1      : 0x3ffb9ca0  
2      : 0x3ffbb358  3      : 0x00000001  4      : 0x000004c0  5      : 0x00000000  
6      : 0x000004c0  7      : 0x00000013  8      : 0x800ef5ff  9      : 0x3ffb9400  
10     : 0x3ffbb358  11     : 0x00000000  12     : 0x00000003  13     : 0x00000000  
14     : 0x00000001  15     : 0x3ffc3d30  SR     : 0x0000001f  EXCCUSE: 0x0000001c  
EXCVDDR: 0x000004c0  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0xffffffff  

ELF file SH256: 608162a60d98441b

Backtrace: 0x400d855b:0x3ffb9ca0 0x400d3e35:0x3ffb9ce0 0x400d3f00:0x3ffbb130 0x40085159:0x3ffbb160

Rebooting...

mirbの起動自体はうまくいってそうなのですが、プロンプトに対して Enter キーを押すとpanicが発生しています。エラーの内容を見る限り、不正なメモリ領域へアクセスしたものと推測されます。

原因

原因はmrubyで「値」を保持する mrb_value の構造が、 mrubymruby-esp32-app-mirb で異なっていたことでした。

mruby-esp32-app-mirb をビルドすると、以下の図のように mruby-esp32-app-mirb に含まれるプログラムと、mruby および mrbgems のソースコード一式がコンパイル・リンクされます。

mruby-esp32-app-mirb

特筆すべき点として、mirbをESP32上で動作させるためには、 mruby に含まれている mirb.c の一部の関数をESP32で動作するよう書き換える必要があります。mruby-esp32-app-mirb ではこれを実現するため、mirb.c をincludeしてマクロを使って別の関数に置き換える、という戦略をとっています。

mruby は上述の「mruby 3.0.0対応」にて、MRB_NO_BOXING を指定しています。このときの mrb_value は以下のようになります。

union mrb_value_union {
#ifndef MRB_NO_FLOAT
  mrb_float f;
#endif
  void *p;
  mrb_int i;
  mrb_sym sym;
};

typedef struct mrb_value {
  union mrb_value_union value;
  enum mrb_vtype tt;
} mrb_value;

一方、 mruby-esp32-app-mirb では MRB_NO_BOXING のような指定はしていません。指定をしていない場合は MRB_WORD_BOXING が適用されます。

#if !defined(MRB_NAN_BOXING) && !defined(MRB_WORD_BOXING) && !defined(MRB_NO_BOXING)
# define MRB_WORD_BOXING
#endif

このときの mrb_value の構造は以下の通りです。 MRB_NO_BOXING を指定したときとは全く異なりますね。

/*
 * mrb_value representation:
 *
 *   nil   : ...0000 0000 (all bits are 0)
 *   false : ...0000 0100 (mrb_fixnum(v) != 0)
 *   true  : ...0000 1100
 *   undef : ...0001 0100
 *   fixnum: ...IIII III1
 *   symbol: ...SSSS SS10 (use only upper 32-bit as symbol value on 64-bit CPU)
 *   object: ...PPPP P000 (any bits are 1)
 */
typedef struct mrb_value {
  uintptr_t w;
} mrb_value;

これにより、 mruby-esp32-app-mirb 側でビルドした mirb.cMRB_WORD_BOXINGmrb_value を渡しているにもかかわらず、mruby 側では渡された mrb_valueMRB_NO_BOXING だと解釈してアクセスし、確保されていないメモリ領域へのアクセス→panicが発生しました。

mruby-esp32-app-mirb 不具合発生のメカニズム

対策

mruby-esp32-app-mirb のコンパイルオプションに MRB_NO_BOXING を追加し、 mrb_value を同じデータ構造で扱うよう修正しました。具体的な方法は Pull request を参照ください。

どうやって原因を見つけ出したか?

原因がわかってしまえば対策自体は簡単だったのですが、今回の現象は「デバイス上でしか再現しない」「パッと見でどこが原因なのかわからない」といった現象だったので、調査に苦戦しました。一本道で原因を特定できたわけでもありませんし、実際には数日を要して原因に辿り着いています。

そんな状況から以下にして原因に辿り着いたのか、まとめていきます。

panicのログから問題の発生箇所を特定する

最初は「パッと見でどこが原因なのかわからない」という問題の対処からはじめました。しかし、PCで動作するRubyアプリケーションとは異なり、デバイス上で動作するプログラムをステップ実行したり中断したりするのはなかなか大変です。本格的に実践するためには JTAG と呼ばれる専用の機器を接続して、デバッグ環境を準備する必要があります。

そこで今回はpanicが発生したときのログから発生箇所の特定を試みました。ポイントは PC および Backtrace と記載されている以下の部分です。

PC      : 0x400d855e

(省略)

Backtrace: 0x400d855b:0x3ffb9ca0 0x400d3e35:0x3ffb9ce0 0x400d3f00:0x3ffbb130 0x40085159:0x3ffbb160

PC とは Program Counter の略で、panicした時点で実行していた命令のメモリ番地を指しています。このままだと単なるアドレスですが、GDBの list コマンドを使うことでソースコード上のどの行を指しているのか特定することが可能です。

問題が発生したのはデバイス上ですが、クロスコンパイラに付属するGDBに対して、デバイスに書き込んだバイナリを渡せば同様の操作が可能です。

❯ xtensa-esp32-elf-gdb build/mruby-esp32-app-mirb.elf
(gdb) list *0x400d855e
0x400d855e is in mrb_respond_to (/Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49).
44        case MRB_TT_CPTR:
45          return mrb->object_class;
46        case MRB_TT_ENV:
47          return NULL;
48        default:
49          return mrb_obj_ptr(v)->c;
50        }
51      }
52
53      /* flags:

領域外アクセスが発生したのは mrubyclass.h49行目 ということがわかりました。こちら ですね。

加えて Backtrace に列挙されているアドレスも順番に list で出力していきます。

(gdb) list *0x400d855e
0x400d855e is in mrb_respond_to (/Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49).
44        case MRB_TT_CPTR:
45          return mrb->object_class;
46        case MRB_TT_ENV:
47          return NULL;
48        default:
49          return mrb_obj_ptr(v)->c;
50        }
51      }
52
53      /* flags:
(gdb) list *0x400d855b
0x400d855b is in mrb_respond_to (/Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:45).
40      #ifndef MRB_NO_FLOAT
41        case MRB_TT_FLOAT:
42          return mrb->float_class;
43      #endif
44        case MRB_TT_CPTR:
45          return mrb->object_class;
46        case MRB_TT_ENV:
47          return NULL;
48        default:
49          return mrb_obj_ptr(v)->c;
(gdb) list *0x400d3e35
0x400d3e35 is in mirb_main (/Users/yuhei/esp/mruby-esp32-app-mirb/main/../components/mruby/mruby/mrbgems/mruby-bin-mirb/tools/mirb/mirb.c:672).
667               p(mrb, mrb_obj_value(mrb->exc), 0);
668               mrb->exc = 0;
669             }
670             else {
671               /* no */
672               if (!mrb_respond_to(mrb, result, MRB_SYM(inspect))){
673                 result = mrb_any_to_s(mrb, result);
674               }
675               p(mrb, result, 1);
676     #ifndef DISABLE_MIRB_UNDERSCORE
(gdb) list *0x400d3f00
0x400d3f00 is in mirb_task (/Users/yuhei/esp/mruby-esp32-app-mirb/main/main.c:134).
129     static void
130     mirb_task(void *pvParameter)
131     {
132       char *argv[] = {"mirb", NULL};
133
134       mirb_main(1, argv);
135
136       esp_restart();
137     }
138
(gdb) list *0x40085159
0x40085159 is in vPortTaskWrapper (/Users/yuhei/esp/esp-idf/components/freertos/port.c:143).
138
139     #if CONFIG_FREERTOS_TASK_FUNCTION_WRAPPER
140     // Wrapper to allow task functions to return (increases stack overhead by 16 bytes)
141     static void vPortTaskWrapper(TaskFunction_t pxCode, void *pvParameters)
142     {
143             pxCode(pvParameters);
144             //FreeRTOS tasks should not return. Log the task name and abort.
145             char * pcTaskName = pcTaskGetTaskName(NULL);
146             ESP_LOGE("FreeRTOS", "FreeRTOS Task \"%s\" should not return, Aborting now!", pcTaskName);
147             abort();

mirb_main タスクを起動してからエラーが発生するまでの流れがわかりましたが、ところどころ(おそらくインライン展開されているメソッド)が省略されてしまっています。また、呼び出し経路が特に異常な経路ではないので、何が原因でメモリ外アクセスが発生しているのかはまだわからないままです。

IDF monitorを接続しもっと楽にBacktraceを確認する

panicのログを追っての調査に苦戦しているとき、mruby-esp32/mruby-esp32-app-mirb の作者である @pandax381 さんの記事を見つけました。

どういった過程で今のような実装に辿り着いたのかが理解できたことも多かったですが、「 make monitor でシリアルモニタを接続できる」という点が個人的には大きな収穫でした。それまではプログラムを実機に書き込んでから、screen を使ってシリアル接続し直す、という面倒な手順を踏んでいたので、手数が減るのはありがたかったです。

さらに嬉しかったのは、 make monitor でシリアル接続すると、panicが発生したときにbacktraceが表示されたことです。

mirb - Embeddable Interactive Ruby Shell

> 
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC      : 0x400d855e  PS      : 0x00060130  A0      : 0x800d3e38  A1      : 0x3ffb9ca0  
0x400d855e: mrb_class at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49
 (inlined by) mrb_respond_to at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/src/class.c:1989

A2      : 0x3ffbb358  A3      : 0x00000000  A4      : 0x000004c0  A5      : 0x00000000  
A6      : 0x000004c0  A7      : 0x00000013  A8      : 0x800ef5ff  A9      : 0x3ffb9400  
A10     : 0x3ffbb358  A11     : 0x00000000  A12     : 0x00000000  A13     : 0x00000000  
A14     : 0x00000000  A15     : 0x3ffbd154  SAR     : 0x0000001f  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x000004c0  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0xffffffff  

ELF file SHA256: 608162a60d98441b

Backtrace: 0x400d855b:0x3ffb9ca0 0x400d3e35:0x3ffb9ce0 0x400d3f00:0x3ffbb130 0x40085159:0x3ffbb160
0x400d855b: mrb_class at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:45
 (inlined by) mrb_respond_to at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/src/class.c:1989

0x400d3e35: mirb_main at /Users/yuhei/esp/mruby-esp32-app-mirb/main/../components/mruby/mruby/mrbgems/mruby-bin-mirb/tools/mirb/mirb.c:672

0x400d3f00: mirb_task at /Users/yuhei/esp/mruby-esp32-app-mirb/main/main.c:134

0x40085159: vPortTaskWrapper at /Users/yuhei/esp/esp-idf/components/freertos/port.c:143


Rebooting...

これは後で調べてわかったのですが、make monitor を実行したとき内部的には IDF Monitor を利用して接続しています。IDF Monitorには Automatic Address Decoding と呼ばれる機能があり、出力されたアドレスを自動的にダンプしてファイル名やシンボル名を表示してくれるそうです。

これにより手作業でアドレスの変換をしなくて良くなったので、調査効率が上がりました。

panic後にGDBを起動してデータの流れを確認する

IDF Monitorの存在に気づいたことで、「他にも便利なデバッグの仕組みが用意されているのでは?」と思いドキュメントを読み漁ったところ、 GDB Stub というページを発見しました。

make menuconfig にて CONFIG_ESP_SYSTEM_PANIC_GDBSTUBenable にしておくとpanicが発生したときにGDBが自動起動する、という素晴らしい機能です。

実際に試したところ、本当にGDBが起動しました。

mirb - Embeddable Interactive Ruby Shell

> 
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

(省略)

Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "--host=x86_64-host_apple-darwin12 --target=xtensa-esp32-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /Users/yuhei/esp/mruby-esp32-app-mirb/build/mruby-esp32-app-mirb.elf...done.
Remote debugging using /dev/cu.usbserial-110
0x400d8eea in mrb_class (v=..., mrb=0x3ffbb918) at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49
49          return mrb_obj_ptr(v)->c;
(gdb) 

あらためてスタックトレースを確認し、各フレームでの変数の値を確認します。

(gdb) backtrace
#0  0x400d8eea in mrb_class (v=..., mrb=0x3ffbb918) at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49
#1  mrb_respond_to (mrb=0x3ffbb918, obj=..., mid=10) at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/src/class.c:1989
#2  0x400d47c4 in mirb_main (argc=<optimized out>, argv=<optimized out>) at /Users/yuhei/esp/mruby-esp32-app-mirb/main/../components/mruby/mruby/mrbgems/mruby-bin-mirb/tools/mirb/mirb.c:672
#3  0x400d488f in mirb_task (pvParameter=0x0) at /Users/yuhei/esp/mruby-esp32-app-mirb/main/main.c:134
#4  0x4008516c in vPortTaskWrapper (pxCode=0x400d487c <mirb_task>, pvParameters=0x0) at /Users/yuhei/esp/esp-idf/components/freertos/port.c:143
(gdb) f 2
#2  0x400d47c4 in mirb_main (argc=<optimized out>, argv=<optimized out>) at /Users/yuhei/esp/mruby-esp32-app-mirb/main/../components/mruby/mruby/mrbgems/mruby-bin-mirb/tools/mirb/mirb.c:672
672               if (!mrb_respond_to(mrb, result, MRB_SYM(inspect))){
(gdb) print result
$7 = 0
(gdb) f 1
#1  mrb_respond_to (mrb=0x3ffbb918, obj=..., mid=10) at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/src/class.c:1989
1989      return mrb_obj_respond_to(mrb, mrb_class(mrb, obj), mid);
(gdb) print obj
$8 = {value = {f = 6.007838253429558e-321, p = 0x4c0, i = 1216, sym = 1216}, tt = 4278190080}

mrb_respond_to の第2引数を呼び出し元( result )と呼び出し先( obj )でそれぞれ print したのですが、呼び出し元では 0 、呼び出し先では {value = {f = 6.007838253429558e-321, p = 0x4c0, i = 1216, sym = 1216}, tt = 4278190080} が出力されました。

同じ変数なのに値も構造も変わってしまっているのはなぜか?を追求した結果、呼び出し元には MRB_NO_BOXING が適用されていないという根本原因にたどり着くことができました。

今回の調査で得られた教訓

「開発環境のドキュメントをしっかり読みましょう」という点に尽きますね。Backtraceのログだけでは原因特定に至らなかったと思いますし、仮に特定できたとしても膨大な時間がかかっていたと思います。

ESP32がJTAG無しでここまでデバッグできるということに正直驚きました。私自身普段からIoTシステムの開発に携わっていて、実証実験フェーズではデバイス側のプログラムを書くこともあるので、ESP32を積極的に利用したいと思いました。

おわりに

書く前から予想はしていましたが、Rubyの話はあまり出てきませんでしたね。ただ、「形は違えど普段使っているRubyも中身はこういったC言語で実装されていること」、「小さなデバイスでも動作するmrubyというOSSがあること」だけでも、覚えていてもらえると執筆者としては嬉しいです。

mrubyがMicroPythonに負けないよう、個人的には何かしら貢献を続けていきたいところです。


さて、最後に Lチカ クリスマスらしいイルミネーションのGIFを貼っておきます。

mrubyでLチカ

mruby-esp32/mruby-esp32-gpiomruby-esp32/mruby-esp32-systemを使って、mirbに以下のようなプログラムを入力をすることでLEDを制御しています。

include ESP32::GPIO

red = GPIO_NUM_25
green = GPIO_NUM_32
blue = GPIO_NUM_27

pinMode(red, OUTPUT)
pinMode(green, OUTPUT)
pinMode(blue, OUTPUT)

loop do
  digitalWrite(red, HIGH)
  ESP32::System.delay(500)

  digitalWrite(blue, LOW)
  ESP32::System.delay(500)

  digitalWrite(green, HIGH)
  ESP32::System.delay(500)

  digitalWrite(red, LOW)
  ESP32::System.delay(500)
	
  digitalWrite(blue, HIGH)
  ESP32::System.delay(500)

  digitalWrite(green, LOW)
  ESP32::System.delay(500)
end

みなさんもぜひお試しください!

参考文献

yuuu

yuuu

2018年の年明けに組込み畑からやってきた、2児の父 兼 Webエンジニアです。 mockmockの開発・運用を担当しており、組込みエンジニア時代の経験を活かしてデバイスをプログラミングしたり、簡易的なIoTシステムを作ったりしています。主な開発言語はRuby、時々Go。