[このブログ投稿はMediumでも試験的に公開しています: https://medium.com/antirez/a-short-tale-of-a-read-overflow-b9210d339cff]

長時間動き続けるプロセスがクラッシュするのは、かなり厄介だ。ましてそのプロセスが大量の状態をメモリに抱えているならなおさらだ。だからこそ私は、大きなパフォーマンスのオーバーヘッドなしにページ表示ごとに新しいインタプリタと新しい状態を作り、ページ生成の終わりには使ったリソースをすべて解放できるWebプログラミングフレームワークが好きなのだ。それは本質的により信頼性の高いプログラミングパラダイムで、メモリリークやディスクリプタリーク、時折起こるランダムなクラッシュすら深刻な問題にはならない。しかしRedisのようなシステムソフトウェアはスペクトルの対極に位置する。そこは決してクラッシュしてはならないものたちが占める世界だ。

数ヶ月前、同僚のDvir Volkからクラッシュレポートを受け取った。彼はRediSearchというRedisモジュールを開発中だったため、クラッシュがモジュール内のプログラミングエラー、おそらくヒープを破壊するようなものによるものなのか、それともRedis本体のバグなのかははっきりしなかった。しかし、どう見てもradix treeの実装に実際の問題があるように見えた。

=== REDIS BUG REPORT START: Cut & paste starting from here ===
# Redis 999.999.999 crashed by signal: 11
# Crashed running the instuction at: 0x7fceb6eb5af5
# Accessing address: 0x7fce9c400000
| Backtrace:
| redis-server *:7016 [cluster](raxRemoveChild+0xd3)[0x49af53]
| redis-server *:7016 [cluster](raxRemove+0x34f)[0x49b34f
| redis-server *:7016 [cluster](slotToKeyUpdateKey+0x1ad)[0x4415dd]

radix treeはmemmove()呼び出しだらけで、Redisはちょうど末尾が奇妙にゼロでパディングされたメモリアドレス、0x7fce9c400000にアクセスしようとしてクラッシュしていた。最初に思ったのは、きっとここで何か誤ったメモリ移動をしていて、アドレスがゼロで上書きされ、プログラムがそのアドレスを参照しようとしたときにクラッシュするのだろう、ということだった。

自分のradix tree実装にはかなり誇りを持っている。実装自体が理由ではない。実装するのは複雑なデータ構造ではあるが、ロケット科学というほどではないからだ。誇りに思っているのは、それに付属するfuzz testerだ。それはソースコード全体をカバーできるし（これは些細なことだ）、さらに多くの非自明な状態もカバーできる（こちらの方が断然面白い）。このfuzz testerは単にクラッシュさせるためにファジングするのではない。radix treeの辞書とイテレータの実装を、ハッシュテーブルとqsortを使ったリファレンス実装と比較するのだ。まったく同じセマンティクスを持ちつつ、短く監査しやすい実装で。クラッシュレポートを受け取った後、私はfuzz testerを改良し、Valgrindありとなしの両方で何日も走らせ、追加のデータモデルを書き、1億件のキーを使ったテストも作ったが、努力の甲斐なくクラッシュを再現できなかった。数日前に判明したことだが、私がテストしていた実装にはそもそもバグはなかったのだ。ただ当時はそのことに気づいていなかった。存在しないバグは、どうやっても見つけようがない。そこで再現に失敗した後、私は諦めた。

一週間前、ほぼ同じ内容のバグレポートをさらに2件受け取った。そしてまたしても、アドレスはゼロでパディングされていた。

Dvir crash: Accessing address: 0x7fce9c400000
Issue 4605: Accessing address: 0x7f2959e00000
Issue 4642: Accessing address: 0x7f0e9b800000

ソースコード内のあらゆるmemmove、memcpy、reallocの呼び出しを読み解き、何らかの理由でfuzz testerが捉えられなかった問題がないか突き止める時が来た。何も見つからなかったが、Redisのクラッシュレポートを詳しく見ていると、面白いことに気づいた。クラッシュ時、Redisはプロセスのメモリマップ領域を報告する。次のようなものだ。

*** Preparing to test memory region 7f0e8c400000 (255852544 bytes)

さて、0x7f0e8c400000に255852544を足すと、結果は0x7f0e9b800000になる。これはissue 4642で報告されたクラッシュでアクセスされたアドレスと完全に一致する。つまりプログラムはメモリアドレスが破損したからクラッシュしたのではなく、ヒープの終端の直後のアドレスにアクセスしたためにクラッシュしていたのだ。他のissueも確認したが、すべてのケースで同じだった。基本的にヒープの末端が、未マップなアドレスの開始地点との境界で、範囲外アクセスが行われた際に検知してクラッシュさせるメモリガードとして機能していたのだ。これはかつて特定のC向けメモリサニタイズツールがよく用いていた手法だ。そうしたツールはmalloc()のドロップイン置換を提供し、アクセス不能なメモリページの端に割り当てられたアドレスを返す。そうすることで、あらゆるオーバーフローを即座に検出できる。

プログラムがクラッシュするのは、ヒープの末尾にあるradix treeノードを解放するときだけだったため、問題がread overflowであることは容易に理解できた。でなければread overflowを検出することなど決してできない。構造体の外側だがマップされたメモリの内側にあるデータにアクセスするだけなので、バグは完全に無害で沈黙したままになる。マップされた領域の末端で同じ操作を行った場合を除いては。ようやく明確な調査対象が見つかった。このCコードの部分だ。

/* 3. Remove the edge and the pointer by memmoving the remaining children pointer and edge bytes one position before. */
int taillen = parent->size - (e - parent->data) - 1;
debugf("raxRemoveChild tail len: %d\n", taillen);
memmove(e,e+1,taillen);
/* Since we have one data byte less, also child pointers start one byte before now. */
memmove(((char*)cp)-1,cp,(parent->size-taillen-1)*sizeof(raxNode**));
/* Move the remaining "tail" pointer at the right position
as well. */
size_t valuelen = (parent->iskey && !parent->isnull) ? sizeof(void*) : 0;
memmove(((char*)c)-1,c+1,taillen*sizeof(raxNode**)+valuelen);
/* 4. Update size. */
parent->size--;

私はユーザーにクラッシュレポートを生成したredis-serverバイナリを送ってもらうよう頼み、逆アセンブルされたコードを読むと、Redisのクラッシュレポートにも含まれている多くのCPUレジスタに、まだ上記の変数が残っていることが明らかだった！CPUレジスタのRDI、RSI、RDXはmemmoveの最初の3つの引数を渡すために使われることに注意してほしい。あるクラッシュでは次のようになっていた。

parent = RBP = 7f2959dffff
Checking RDI, RSI, RDX we extract the memmove() arguments:
memmove(00007f2959dffff4,00007f2959dffffd,0000000000000008);
The memmove will go out of bound accessing up to 7f2959e00004.

これで証明は得られた。しかしそれだけではなかった。他のレジスタを調べることで、ノードヘッダも再構築でき、memmoveのカウント引数がどのように得られたかを理解できたのだ。そこで何かが明らかに間違っていた。基本的に、逆アセンブルされた実行ファイルが、私が読んでいたC関数と一致していなかったのだ。どうしてそんなことが可能なのか？バッファを越えた読み出しは起こるはずがない。状態は正常だったのだから。クラッシュしたインスタンスではカウントだけが誤って計算されていたのだ。夜だったし、このクソみたいな問題に2日間ぶっ通しで取り組んでいたので、gistを作ってTwitterに投稿し、どうしてこんなCコードがコンパイラによってこんなアセンブラに変換されるのか、誰かに説明してもらえないかと考えることにした。

幸運なことに、Node.jsで知られる友人のFedor Indutnyが助けてくれることになった。彼はすぐに、Cとアセンブラが一致しない理由は非常に明白だと気づいた。私が解析していたのは正しいCコードではなかったのだ…同じ関数のより新しいバージョンだったのだ。Fedorは手元にGCC 5.4.0を持っており、それはバグを報告したユーザーが使っていたのと同じコンパイラだったので、彼は古いバージョンのコードをそれでコンパイルしてみて、2つの生成コードのバージョンが今度は完全に一致することに気づいた。彼は私に連絡し、これが本当に最近のRedisバージョンなのか確認してきた。私は完全に確信していた。Redis 4.0.6だ。だがその後少し疑いが生じ、RedisのunstableブランチとRedis 4.0の間でrax.cのdiffを取ってみた。起きていたのは、約10ヶ月前にStreamsの実装の過程で私がこのバグをすでに修正していたということだった。unstableからバグ修正をRedis 4.0にバックポートするcherry pickingの作業中、その修正はStreamsに関するコミットの中に含まれていたため、私はずっとそれをスキップし続けていたのだ。すべてがようやくはっきりした。私は何日も、テストしていたバージョンには存在しないバグをデバッグしていたのだ。

もしこれが単なる私のくだらないミスだったのなら、なぜわざわざこのブログ投稿を書くのか？そこから学べる教訓があると信じているからだ。

一つ目の教訓は、Redisが出力できるようなクラッシュレポートが、システムソフトウェアにおける重要な資産だということだ。それにより、再現できないが実際の環境ではごく稀に発生するバグの状態を再構築できる。バグ自体はすでに修正されていたにもかかわらず、私はバグレポート、レジスタダンプ、問題のアドレス、コールスタックを見るだけで、何が起きていたのかを正確に理解できた。

二つ目の教訓は、システムプログラミングに携わりたいなら、今日にでもAMD64アセンブラを学ぶべきだということだ。少なくともコンパイラが生成したコードを楽に読み、何が起きているかを追える程度には。これはハイゼンバグの最中に何が起きているかを理解する唯一の方法であることも多い。デバッガはあまり役に立たない。GDBはクラッシュがparent->size--という命令で起きていると主張していたが、もちろんそんなことはありえない。とはいえGDBを責めるべきではない。最適化を有効にした現代のコンパイラは、ソースコードにほとんど対応付けできないようなコードを生成するのだ。

もう一つの教訓は、よくできたfuzz testingがいかに強力かということだ。fuzz testerは壊れたバージョンのバグを即座に見つけることができた。同様に、ずっと前に修正されたこのバグ以外にradix treeのクラッシュが一度も観測されていないという事実が、それ自体を物語っている。radix treeの実装は非常に複雑だが、fuzz testingのおかげで、これほど新しく複雑な実装でありながら、明らかなバグは存在しないようだ。強調したいのは、単にクラッシュを見つけるためだけにファジングするのではないということだ。それはゼロデイを見つけたいセキュリティの人々には良いだろう。システムソフトウェアにおけるファジングは、健全な操作モデルに従ってランダムな操作を実行し、その結果をリファレンス実装と比較すべきなのだ。

そして最後に、私自身への明確な教訓がある。次回フィーチャーブランチで作業し、そのブランチ固有ではない修正を行うときは、もっと慎重になる必要があるということだ。私はすべてをできるだけ早く4.0にマージするつもりで作業していた。だが実際はそうならず、radix treeの更新をStream関連の実装と同じコミットに入れてしまったことが致命的なミスだった。

まあ、おまけとして、賢い友人に助けてもらうことだ :-) あの時点では少し途方に暮れていたが、Fyodorの親切な助けがパズルの最後のピースを解き、素早く前進する手助けになった。助けを求めることを恐れないでほしい。システムソフトウェアに携わるなら、それがプログラミングの他の分野とは大きく異なることを覚えておいてほしい。ただ作業をして物事を前に進めればいいというものではない。再現すらできないことが多いバグがなぜ起きたのかを理解するために、何日も費やす覚悟が必要なのだ。ユーザーは、ソフトウェアがそのようにクラッシュする以上のものを期待するに値するのだから。