FastImageってgemで無限ループして帰れなくなった話

先週のある夜のこと。突然NagiosさんからWebサーバのCPU使用率が急増しているとのメールが届きました。 どういうことかと思い、サーバの状態を確認してみるとRailsを動かしているunicornがCPU使用率が100%で張り付いていました。

まあそういうこともあるかなあと最初は軽く考えていて、問題のサーバをリバースプロキシから外して、ログを探してみることに。 ところが、rackのログをみても何も出力されていない。はて？と思いつつstraceでプロセスにアタッチすると、すごい勢いでopen, read, closeを繰り返していました。 と、そうこうしているとまたNagiosからアラートが。同じくCPU使用率が急増しているとの警告。 どうやら問題は一つのサーバでだけ起きていたわけではなくて、たまたま１つのサーバで問題がまとまって起こっていただけのよう。

とりあえず、暴走した子プロセスにSIGINTを送るももちろん終了してくれるはずもなく、仕方なくSIGKILLを送りつけて落としていきました。 それで一時的にはおさまるもののしばらくするとまた同じ状態に。このままでは埒が明かないということで、アプリケーションコードを調べることにしました。 あーだこーだして調べているとどうやら新しく使うようになったライブラリがあるということが判明。 それはFastImageというライブラリで画像のサイズを高速に調べるライブラリです。

fastimage https://github.com/sdsykes/fastimage

fastimageは画像ファイルのヘッダーを調べ、幅や高さを高速に調べてくれます。ImageMagickを使うことないので非常に高速です。 ですが、とある画像をアプリケーションで書いている通りにこのライブラリに渡すと無限ループが発生することがわかりました。 アプリケーションコードにはこんな感じに書かれていました。(issueにあげてもらった簡単なコードです。)

width, height = FastImage.size(Rails.root.join('test.jpg'))

どこにでもありそうなコードですがこれが罠でした。

width, height = FastImage.size('test.jpg')

こちらのコードだと何も問題が起こらない。でコードを追っていくと、:readを持っているかどうかで処理を分岐していました。 Rails.root.joinをするとPathnameを返すのですが、Pathnameはreadメソッドを持っているので、この分岐に入ります。

しばらく落ちていくと、while str = readable.read(LocalFileChunkSize)というループに入るのですが、 ここが厄介でここでのreadはIO#readかそれと同じ振る舞いをすることを想定してるっぽいのです。

IO#readは与えられたバイト数だけ読み込みを行い、内部で保持しているポジションを移動させ、 次のreadではその移動したポジションから同じように与えられたバイト数の読み込みを行います。

ところが、今回渡しているPathname#readはIO#readと振る舞いが異なりPathname#readはIO#read(length, 0)と同じ振るまい、 つまり先頭からlengthバイトの読み込みを行うだけなのです。

そのため、Pathnameを渡してしまうと、while str = readable.read(LocalFileChunkSize)は毎回ファイルの先頭のみを読み込んでしまい 無限ループしてしまうのです。 普通なら簡単に気付きそうな問題ですが、今回発覚が遅れたのは画像によってはこのループを抜けることがあるためです。 というのはこのループは先頭のヘッダーをLocalFileChunkSizeだけ読み込んで、幅と高さがあればそこで処理を終了するのですが、 無限ループに突入するのは、LocalFileChunkSizeの中に幅や高さがない場合だけなのです。

また、普通に想定通りのIOを渡した場合にはこの問題がおきないので気付きづらいというのもわからなくありません。 というわけで、知り合いを通じてfastimageにissueをあげてもらいました。

すると、FastImageの作者さんが４時間くらいでパッチを当ててくれました。いい話。

PathnameはRails.root.joinを使うと簡単に返ってくるのにIOとは挙動が異なるので気をつけたいですね。