FastImageってgemで無限ループして帰れなくなった話
先週のある夜のこと。突然NagiosさんからWebサーバのCPU使用率が急増しているとのメールが届きました。 どういうことかと思い、サーバの状態を確認してみるとRailsを動かしているunicornがCPU使用率が100%で張り付いていました。
まあそういうこともあるかなあと最初は軽く考えていて、問題のサーバをリバースプロキシから外して、ログを探してみることに。
ところが、rackのログをみても何も出力されていない。はて?と思いつつstraceでプロセスにアタッチすると、すごい勢いでopen
, read
, close
を繰り返していました。
と、そうこうしているとまたNagiosからアラートが。同じくCPU使用率が急増しているとの警告。
どうやら問題は一つのサーバでだけ起きていたわけではなくて、たまたま1つのサーバで問題がまとまって起こっていただけのよう。
とりあえず、暴走した子プロセスに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の作者さんが4時間くらいでパッチを当ててくれました。いい話。
Pathname
はRails.root.join
を使うと簡単に返ってくるのにIO
とは挙動が異なるので気をつけたいですね。