Deno のめっちゃ難しいバグを修正した

2022年4月、Deno に以下のバグが報告されました。

fetch API を使って 300KB ぐらいあるファイルをアップロードすると、一定確率でアップロードされたファイルが壊れるというバグの報告です。

報告者によれば、1.20.6 まではバグは発生しておらず、1.21.0 から発生するようになったという事です。1.20.6 の次のリリースが 1.21.0 なので、パッチバージョン1個分まで、バグの発生時期が特定されている状態です。

fetch 周りは自分はほぼ実装していないので「担当範囲ではない」感覚だったので、普通にスルーしていました。

自分に限らず、Deno Land コアチームの誰もこの issue にピンと来る人が居なかったようで、stale ボット (数ヶ月進捗の無い issue を自動的にクローズしようとするボット) に2回もクローズされかけていました。Deno の stale ボットはクローズ1週間前に「クローズするよ〜」というコメントを付けてきて、それに対して誰かが反応すると、クローズを阻止することが出来ます。issue 報告者が2回クローズを阻止しているということは、この issue で本当に困っているという事が分かります。

本当に困っている人がいるらしい issue を5ヶ月も放置しているのは流石にまずい気がしたので、バグの現象に対して心当たりはないものの、もう少し issue を triage してみようと思い、バグの発生したバージョンをコミットレベルで特定する作業を始めてみました。

1.20.6 - 1.21.0 の間ということまでは分かっているので、その間のコミットを眺めて見ます。ザーッと眺めていくと以下の PR が何となく目に止まりました。

ファイル読み込みのパフォーマンスを上げるために、tokio 周りのファイル操作を弄っている PR です。PR の内容自体を完全には理解できないものの、とりあえず怪しそうです。

Deno は main ブランチのすべてのコミットについて、リリースビルドを自動生成しており、クラウドストレージにバイナリを保存しています。deno upgrade --canary --version <commmit_hash> というコマンドで、main ブランチの任意のコミット時点のバージョンに戻すことが出来ます。

上の PR の前後のバージョンで現象をチェックしてみたところ、案の定、上の PR から現象が始まっている事が特定されました。その事を以下のようにコメントしました。

上のコメントを受けて、社内チャットで Bartek から Divy に「ちょっとこの issue 見てくれるかな?」というようなコメントが飛んでいました。個人的には、これできっと解決されるだろうと予想していました。

しかしどうやら Divy も特にピンと来るものが無かったらしく、更に2週間ほど issue が放置されます。その後メンテナと issue 報告者の間でちょっとしたコメントのやり取りがあった影響で、もう一度 issue の存在を思い出しました。

issue の重要性を考えると、今回は本当に真面目に取り組まないとこの issue は一生解決されないような気がしたのと、起こっている現象がかなり興味深いものだったので、純粋に原因を知りたいという気持ちが強くなりました。

この issue はきちんと再現コード付きで報告されている issue でした。しかし、問題はその再現コードがかなり長く、本当の問題がどこなのかがパッと見て分からない状態になっていました。fetch でアップロードして、md5 ハッシュを取ると壊れるのですが、fetch の中の multipart form の生成を自前でやっていたり、ファイルの受け取りは oak という 3rd party フレームワークで行っていたり、色んな場所に犯人の可能性が潜んでいるように見えます(こういう、再現コードの中で動いてるパーツが多すぎることはメンテナから放置されやすい一因になります)。

とりあえず、再現コードのリファクタリングを始めて、問題の可能性箇所を絞っていく作業に取り掛かりました。まずクライアントとサーバーで別スクリプトになっていた再現コードを1ファイルにまとめ、1ファイルの中でサーバー起動、ファイルアップロード、md5 の比較をすべて行うように修正しました。また、oak の利用をやめて、標準モジュールの http サーバーでアップロードを受け取るように修正しました。

そこまでやって分かったことは、oak には問題がない (標準 http サーバーでも同じ問題が起こる)。壊れたファイルは、ファイルのサイズが減ったり増えたりせず、ファイルサイズは必ず正しいサイズになる (中身がちょっとだけズレている)、というような事が分かってきました。

また、ファイルアップロード用のマルチパートリクエストを作る際に、ファイルのバイトストリームから、multipart form のバイトストリームに変換するのですが、その際に使う変換の仕方を変えるとバグが起こらなくなる、という事を発見しました。そこまで分かった時点で、では、その問題が起こるストリームのユーティリティ(iterateReader)がバグっているのではないかと思い、iterateReader だけを使った状態の md5 ハッシュを取ってみると、何回やっても正しい md5 にしかなりません。ここでまた振り出しに戻ってしまいました。

ファイルに対して iterateReader を使ってストリームに変換してもファイルは壊れない。しかし、iterateReader を使ったあとにそのバイトストリームをアップロードすると、アップロードされたファイルがたまに壊れている。そこで、バイトストリームをアップロードする処理に何らかのバグがあるのではないかと疑って、Deno の fetch API 周りの実装を追って行きました。が、読んでみると、単純に与えられたストリームをストリームのプロトコルにきちんと従って、順番にネットワーク越しに送るという処理をしており、間違いが起こる可能性が無さそうに見えました。こちらの線も無さそうです。

ここまで来て、やっと iterateReader の中身を読んでみようという気になりました。iterateReader は以下のようなユーティリティです。

export async function* iterateReader(
  r: Deno.Reader,
  options?: {
    bufSize?: number;
  },
): AsyncIterableIterator<Uint8Array> {
  const bufSize = options?.bufSize ?? DEFAULT_BUFFER_SIZE;
  const b = new Uint8Array(bufSize);
  while (true) {
    const result = await r.read(b);
    if (result === null) {
      break;
    }
    yield b.subarray(0, result);
  }
}

TypeScript の型定義のせいで少し複雑に見えるかもしれませんが、やっていることは、Reader インターフェースを実装した r を受け取って、while 文で回しながら r.read() の結果を yield し続ける、というイテレータに変換します。このユーティリティはもともとは Deno.iter() というコアの API でしたが、Deno のストリーミング処理を Reader ベースのデザインから Web Stream ベースのデザインに移行するという大きな方針変更を受けて、コアから外され、標準モジュールの1ユーティリティになったものです。歴史が長いユーティリティのため、ここにバグがあるという可能性をはじめから消して考えていたように思いますが、このユーティリティをじっくり眺めた結果バグに気づくことが出来ました。上のコードを見てどこにバグがあるか分かるでしょうか?

上のコードを少し解説すると、const b = new Uint8Array(bufSize) でデータ受け取り用のバイト列 (Uint8Array) を用意しています。while (true) で無限ループを回して、その中で、const result = await r.read(b) で、先程用意した、b の中にデータを読み込んで、result (読み込めたデータ量) が null つまりデータの終端だった場合はループを抜ける。データが有った場合は、yield b.subarray(0, result) で、読み込めたデータ分だけ、subarray で b から切り出してアウトプットするという内容です。

ここで、問題は b を作るタイミングと subarray の挙動です。b はループの外で作っているため、ループの際に毎回使いまわしています。subarray は元となる TypedArray から一部分を切り出して返す関数ですが、この「切り出し」の際に参照元となるメモリ上の ArrayBuffer はコピーせず、あくまで同じ ArrayBuffer の始まりと終わりの見方を変えたものを返しています。つまり、ここで何が起こるかというと、subarray で返した一個前のバイト列 (Uint8Array) が後続処理で使われるタイミングが遅いと、次の r.read() の呼び出しが走ってしまい、その際に一個前のバイト列 (Uint8Array) が見ているメモリ上の ArrayBuffer が上書きされるため、一個前のバイト列のデータが壊れてしまいます。この現象であれば、あくまで一個前のチャンクのデータの内容が壊れるだけで、長さ自体は変わらないため、ファイルの長さは変わらず内容だけが壊れる現象と辻褄が合います。

上の事実を確認するために、あえて、イテレータから出力されるバイト列を遅れて使う以下のような例を作ってみたところ、見事に予想通りの現象を確認することが出来ました。

import { iterateReader } from "https://deno.land/std@0.158.0/streams/conversion.ts";

const data = [new Uint8Array([1]), new Uint8Array([2])];
const reader = {
  async read(u8: Uint8Array) {
    const d = data.shift();
    if (d) {
      u8.set(d);
      return 1;
    }
    return null;
  }
}

const iter = iterateReader(reader);

for await (const d of iter) {
  setTimeout(() => {
    console.log(d);
  }, 10);
}

[1], [2] というバイト列を出力する Reader を作っていますが、使用側で、あえて setTimeout で 10ms 遅れてからそのバイト列をプリントしていますが、このコードを実行すると、[2]、[2] と表示されます。1個目のバイト列が2個目の内容で上書きされてしまっているのです。

ここまで突き止めた内容を以下のように PR としてまとめることが出来ました (b を作るタイミングをループ毎に変更しました)。

いつからこのバグが入っていたのだろうとコミット履歴をたどってみたところ、このユーティリティが最初に追加された2018年10月には既にこの実装方法になっており、ほぼ4年近くバグっていたということになります(なお Deno プロジェクト自体の始まりは 2018年5月です)。ずっとバグっていたもののおそらく現実的なユースケースでバグが顕在化する例が存在せず、上の Divy さんのパフォーマンスチューニング作業によって、ストリームの上流側が下流側より有意に速い状況が初めて生まれたためについに顕在化したという事のようです。