Binary Analysis 12 · ログとリングバッファ — 時系列の記録を復元する

Chapter 12

ログとリングバッファ — 時系列の記録を復元する

この章のゴール.

フラッシュや RAM に残ったログを、リングバッファの巻き戻りを正しく扱って時系列に並べ直せるようになること。 バイナリログ(型付きの記録)とテキストログを見分け、書き込みの途中で切れた最後の記録を扱えること。

この章で使う既出の用語(定義は各リンク先). CRC(03 章 8 節)、ELF(05 章 1 節)、スタック(07 章 7 節)、文字列(07 章 6 節)、ファイルシステム(09 章 1 節)

1. ログはなぜ解析対象になるか

機器が「止まった」「おかしい」とき、何が起きたかを最後に語るのがログである。 組み込みのログは、次のどこかに残る。

ログの解析は「記録の 1 件(レコード)の形」と「レコードの並べ方」の 2 つを解けば済む。

2. リングバッファ — 巻き戻る記録

フラッシュや RAM は有限なので、ログはリングバッファ(円環バッファ)に書かれることが多い。 決まった大きさの領域を使い、末尾まで書いたら先頭に戻って古い記録を上書きする。常に「直近の N 件」が残る仕組みである。

リングバッファ — 物理順 ≠ 時系列末尾まで書いたら先頭に戻って古いのを上書きhead(次に書く位置)常に直近の N 件物理: レコード5 6 7 | 3 4(head の後ろが最古、前が最新)。時系列: 3→4→5→6→7head の見つけ方:① 明示的ポインタ② シーケンス番号でソート(最も確実)③ 0xFF との境界④ 番号が急に小さくなる継ぎ目
リングバッファは巻き戻って上書きする。物理順と時系列は違う。シーケンス番号でソートが確実

これが解析を少し面倒にする。メモリ上の並び順 = 時系列ではないからだ。

[領域の物理的な並び]
  レコード5 レコード6 レコード7 | レコード3 レコード4
                              ↑書き込み位置(head)
[時系列]
  レコード3 → 4 → 5 → 6 → 7

書き込み位置(head)の後ろが最古、前が最新である。正しく並べるには head を見つける必要がある。

head を見つける方法

# シーケンス番号でソートするのが一番確実
records = parse_all_records(data)        # 物理順にすべて読む
records.sort(key=lambda r: r.seq)        # 連番(または timestamp)で時系列に

3. バイナリログのレコードを読む

省メモリのため、組み込みのログはバイナリ(型付きの記録)が多い。文字列 "Temperature: 21.5 C" ではなく、[timestamp][level][module_id][event_id][args...] のような固定/可変長の記録を書く。

典型的なレコードの形:

部分例
マジック / 同期バイト各レコードの頭に 0xA5 など。壊れたバッファで境界を再発見するため
タイムスタンプUnix 秒、または起動からの tick(03 章)
シーケンス番号単調増加。並べ替えと欠落検出に
レベル / モジュール / イベント IDどこで何が起きたか(数値。意味は別表)
引数温度、エラーコードなど。型は event ID で決まる
長さ / CRC可変長なら長さ、壊れ検出に CRC
バイナリログのレコード同期 A5境界再発見timestampUnix秒/tickseq並替・欠落level/mod/event数値ID引数温度・codelen/CRC壊れ検出イベント ID の意味はソース(ログマクロ)か、ビルド時生成の辞書ファイルにある省メモリのため「文字列を置かず ID だけ記録、PC 側で辞書と突き合わせ」(Zephyr dictionary logging・SystemView)。辞書がないと ID の意味が分からない最後のレコードは途中で切れている前提(電源断)。長さ/マジック不完全なら破棄、CRC 不一致も捨てる
型付き記録 [同期][時刻][seq][ID][引数][CRC]。ID の意味は辞書/ソース。最後は切れている

イベント ID の意味は、ファームウェアのソース(ログマクロの定義)か、ビルド時に生成される辞書ファイルにある。 省メモリのため「文字列をフラッシュに置かず、ID だけ記録し、PC 側で辞書と突き合わせる」方式(Zephyr の dictionary logging、SEGGER SystemView、deferred logging)が使われる。この場合、辞書がないとイベント ID の意味が分からない。辞書(ELF に埋まった文字列表、.json)を探す。

4. テキストログを読む

printf をそのまま流し込むテキストログは読みやすいが、リングバッファだと行が途中で切れて巻き戻る。

...sensor init ok\n[00:12:03] wifi conn\x00\xff\xff\xff...[00:11:58] boot\n[00:12:0
                                        ↑ここが head
strings -n 4 log.bin                     # まず読める行を全部
tr -c '[:print:]\n' ' ' < log.bin | less # 非表示バイトを空白に置換して眺める

5. 最後のレコードは切れている

書き込みの最中に電源が切れると、最後の 1 件は途中までしか書かれていない。

これは 18 章(壊れたダンプ)と同じ考え方である。

6. RAM 上のログとクラッシュダンプ

クラッシュ時に RAM ダンプ(04 章)を取ると、そこに直近のログバッファが残る。 さらに、フォールト時のレジスタ退避(スタックに積まれた R0-R3、R12、LR=戻りアドレス、PC=プログラムカウンタ、xPSR=状態レジスタ)や、ウォッチドッグ / HardFault ハンドラが専用領域に書いたクラッシュ情報("coredump"、CORE などのマジック)があることも多い。

PC と LR(03 章・07 章)が読めれば、addr2line(ELF があれば)でクラッシュした行が分かる。17 章で詳しく扱う。

7. 手を動かす

リングバッファを時系列に戻す


この章のポイント